active block modifiers took 1015ms (longer than 200ms)

User avatar
bosapara
Member
Posts: 637
Joined: Fri Apr 07, 2017 08:49

Re: active block modifiers took 1015ms (longer than 200ms)

by bosapara » Post

I had similar warning, found how to solve from this topic
About 3 days i seen warning every 2 secs: active block modifiers took
Problem was in tree mod, that used abm. Mod deleted, now nothing warnings.

Code: Select all

minetest.register_abm({
   nodenames = {"mochathicket:beech_sapling"},
   interval = 10,
   chance = 50,
   action = function(pos, node)
      local is_soil = minetest.registered_nodes[minetest.get_node({x=pos.x, y=pos.y-1, z=pos.z}).name].groups.soil
      if is_soil == nil or is_soil == 0 then return end
      print("A mocha blossom sapling grows into a tree at "..minetest.pos_to_string(pos))
      local vm = minetest.get_voxel_manip()
      local minp, maxp = vm:read_from_map({x=pos.x-16, y=pos.y, z=pos.z-16}, {x=pos.x+16, y=pos.y+16, z=pos.z+16})
      local a = VoxelArea:new{MinEdge=minp, MaxEdge=maxp}
      local data = vm:get_data()
      default.grow_tree(data, a, pos, math.random(1, 4) == 1, math.random(1,100000))
      vm:set_data(data)
      vm:write_to_map(data)
      vm:update_map()
   end
})

Starbeamrainbowlabs
Member
Posts: 66
Joined: Sat May 26, 2018 11:25
GitHub: sbrl
Location: Nowhere, Everywhere, and Somewhere inbetween
Contact:

Re: active block modifiers took 1015ms (longer than 200ms)

by Starbeamrainbowlabs » Post

Yeah, I faced similar sorts of issues. Disabling the spawning of roots from the vines mod in particular solved the problem for me - the /profiler command was very helpful in tracking that one down.

If you face performance issues when doing map generation, adding more emerge threads might help. It's the num_emerge_threads setting in minetest.conf - I've set it to 4 - the number of CPU cores I have.

User avatar
Festus1965
Member
Posts: 4181
Joined: Sun Jan 03, 2016 11:58
GitHub: Festus1965
In-game: Festus1965 Thomas Thailand Explorer
Location: Thailand ChiangMai
Contact:

Re: active block modifiers took 1015ms (longer than 200ms)

by Festus1965 » Post

I am definitely not happy with the (not) result of this discussion yet:

* Where is the Warning with more than 200ms generated ? code base
** what IS happening if abm uses more then 200 ms, just continue or stopped,
** when can the warning time be changed, say 300ms, or would it crash some thing else ?

So "active block modifiers" took longer than,
* does it mean all abm together ? or one of them ?

How to detect the right mod part with the abm as lag-check shows
* technic (7) - what machine is that, always same one or depending on loading ?
* or also moretrees (13) etc.

a abm is register like:

Code: Select all

minetest.register_abm({
   nodenames = {"mochathicket:beech_sapling"},
   interval = 10,
   chance = 50,
....
So here every 10 seconds it will run, but only every 50th time with success of doing it.
Wouldn't it be less cpu using if
* interval = 20, and change then 25, ... or
* interval = 100, and change = 5 ... as
as if I calculate right, would happen same often in the view of a 24hour lasting average, but with the advantage, if abm activates it has more sure some to do
Human has no future (climate change)
If urgend, you find me in Roblox (as CNXThomas)

wziard
Member
Posts: 127
Joined: Mon Oct 29, 2018 19:12

Re: active block modifiers took 1015ms (longer than 200ms)

by wziard » Post

Festus1965 wrote: * Where is the Warning with more than 200ms generated ? code base
Ever heard of grep ?


User avatar
Festus1965
Member
Posts: 4181
Joined: Sun Jan 03, 2016 11:58
GitHub: Festus1965
In-game: Festus1965 Thomas Thailand Explorer
Location: Thailand ChiangMai
Contact:

Re: active block modifiers took 1015ms (longer than 200ms)

by Festus1965 » Post

wziard wrote:Ever heard of grep ?
I searched the codebase on github for "active block modifiers took" without a result, and that counts, not what I have on my SSD ...

It seams to be like a guessing game here ... but found the lines , so as from 1341

Code: Select all

if (m_active_block_modifier_interval.step(dtime, m_cache_abm_interval))
		do { // breakable
			if (m_active_block_interval_overload_skip > 0) {
				ScopeProfiler sp(g_profiler, "SEnv: ABM overload skips");
				m_active_block_interval_overload_skip--;
				break;
}
...
and from 1371

Code: Select all

u32 time_ms = timer.stop(true);
			u32 max_time_ms = 200;
			if (time_ms > max_time_ms) {
				warningstream<<"active block modifiers took "
					<<time_ms<<"ms (longer than "
					<<max_time_ms<<"ms)"<<std::endl;
				m_active_block_interval_overload_skip = (time_ms / max_time_ms) + 1;
}
I think to understand, that the set 200 can be changed,
that it bigger than 200, report AND set m_active_block_interval_overload_skip ... +1,
what results in line 1343 a positive and BREAK;
so answer would be, ABMs are finished at 200 even ready or not ...

but as the report shows "time_ms" needed time, it seams more to be it did all the ABMs ready, and just warned that took longer without a cut of, or cutted of after the last ABM reached the 200 border.

But for what is that warning then good ... when I need to code again to get an answer what ABMs used most time. Here we are back at lagcheck and how to find the right part in fe. technic number shown in the () ...

(If that game is meant only for coders no problem ...one problem less for me then)

edit:
as long the setting in conf "abm_interval" = 1 and so bigger than the maybe set "u32 max_time_ms" it should work.
most report about 250-270ms, some near 360 and very less even reach 550 ... mhhhh
Human has no future (climate change)
If urgend, you find me in Roblox (as CNXThomas)

IhrFussel
Member
Posts: 78
Joined: Tue Nov 22, 2016 12:54
GitHub: IhrFussel
IRC: IhrFussel
In-game: IhrFussel

Re: active block modifiers took 1015ms (longer than 200ms)

by IhrFussel » Post

Festus1965 wrote: But for what is that warning then good ... when I need to code again to get an answer what ABMs used most time. Here we are back at lagcheck and how to find the right part in fe. technic number shown in the () ...

(If that game is meant only for coders no problem ...one problem less for me then)

edit:
as long the setting in conf "abm_interval" = 1 and so bigger than the maybe set "u32 max_time_ms" it should work.
most report about 250-270ms, some near 360 and very less even reach 550 ... mhhhh
The warning simply tells you that your machine is not fast enough to process all running ABMs within the specified time (not sure why exactly 200ms but that's roughly 2x the default server step so makes sense I guess).

On my server I get those once every few hours and they usually never exceed 300ms, so you need to profile the ABMs with the mod profiler to see which ones lag the server the most. There is no need to edit the c++ source code to fix this.

User avatar
Festus1965
Member
Posts: 4181
Joined: Sun Jan 03, 2016 11:58
GitHub: Festus1965
In-game: Festus1965 Thomas Thailand Explorer
Location: Thailand ChiangMai
Contact:

Re: active block modifiers took 1015ms (longer than 200ms)

by Festus1965 » Post

IhrFussel wrote:The warning simply tells you that your machine is not fast enough to process all running ABMs within the specified time (not sure why exactly 200ms but that's roughly 2x the default server step so makes sense I guess).
so
* that is still fast strong hardware, what mean more, mts cant be runned with more or much of bad using abm mods
* why mention server step, my one is "dedicated_server_step = 0.01" as for another reason
thought thar might be more important for abm

Code: Select all

#    Time in between active block management cycles
active_block_mgmt_interval = 1.5

#    Length of time between ABM execution cycles
abm_interval = 1.0
to make sure, abm is NOT managed before abm management is ready, so still had 1000 ms for all abm ?

but

Code: Select all

2019-03-01 08:28:51: WARNING[Server]: active block modifiers took 202ms (longer than 200ms)
2019-03-01 08:29:21: WARNING[Server]: active block modifiers took 204ms (longer than 200ms)
2019-03-01 08:29:58: WARNING[Server]: active block modifiers took 262ms (longer than 200ms)
2019-03-01 08:30:43: WARNING[Server]: active block modifiers took 212ms (longer than 200ms)
2019-03-01 08:30:58: WARNING[Server]: active block modifiers took 208ms (longer than 200ms)
2019-03-01 08:31:58: WARNING[Server]: active block modifiers took 203ms (longer than 200ms)
it happens every 30 seconds, where is that switch or what abm happen after 30 sec to overload ?

edit:
I found only 2 mod in moretrees abm set to "interval = 30" sec, one not activated homedecor and one sure not (as not in lagcheck) so I changed both of them to 45 and 50 sec.
so it is possible to nearby to calculate about the time diff off abm warning, to guess belonging abm using mod, set to that time interval ... (hope right thought).
But theese are less, most I have now one with 20 sec ... search later ...
-endedit-
IhrFussel wrote:... so you need to profile the ABMs with the mod profiler to see which ones lag the server the most.
moretrees !
* i guess also this most running rubber traps
rest mean animals and monsters off - then I have silence

Code: Select all

moretrees (2)             |       705 |         0 |    550292
moretrees (49)            |       661 |         0 |    805970
moretrees (15)            |       638 |         0 |    680649
technic (7)               |       586 |         0 |    935061
default (5)               |       294 |         0 |   1065610
nature_classic (2)        |       285 |         0 |     21919
moretrees (5)             |       222 |         0 |    398924
nature_classic (1)        |       187 |         0 |    712831
moretrees (28)            |       150 |         0 |     89912
mining_plus (1)           |       146 |         0 |     10233
moretrees (39)            |       133 |         0 |     30634
moreblocks (1)            |       112 |         0 |    537072
mobs_monster (4)          |       107 |         0 |      
as I even don't know how to fix the digit in () to a specified file/part of mod - thanks
and as long gamers don't complain it is ok - I was on Block Survival for 8 hours, compare as 25 gamer there, and lag there was up to 1.5 and the doors take there time to open. /home takes time, so far my servedr is still good at me, but need to keep it.

At the end then for what is the warning 200ms good then
Human has no future (climate change)
If urgend, you find me in Roblox (as CNXThomas)

User avatar
Festus1965
Member
Posts: 4181
Joined: Sun Jan 03, 2016 11:58
GitHub: Festus1965
In-game: Festus1965 Thomas Thailand Explorer
Location: Thailand ChiangMai
Contact:

Re: active block modifiers took 1015ms (longer than 200ms)

by Festus1965 » Post

I just made a new build for the MTS inicluding LuaJit and changed the 200ms to 300ms,
MTS is running, some lag 0.19 now with
still without mobs-monsters and -animals I just got one warning exceed 300 at start,
since then NO ANY WARNING !
more data [Server] Minetest.one Thailand (5.0.0-rc2-1af248b) aktive

edit: and also after 7 hours just 3 lonely warnings, but about 7 during paul came in, so he was activating something at his position
Human has no future (climate change)
If urgend, you find me in Roblox (as CNXThomas)

Post Reply

Who is online

Users browsing this forum: No registered users and 8 guests