It adds something like this every second to debug.txt:
Your phone or window isn't wide enough to display the code box. If it's a phone, try rotating it to landscape mode.
- Code: Select all
chlue-INFO: ABM execution time overview for ABMcycle 12
chlue-INFO: ABMs for node 'default:dirt_with_grass' took 16us for 70 processed nodes.
chlue-INFO: ABMs for node 'default:dirt' took 57us for 42 processed nodes.
chlue-INFO: ABMs for node 'default:leaves' took 4799us for 249 processed nodes.
chlue-INFO: ABMs for node 'default:apple' took 74us for 20 processed nodes.
chlue-INFO: ABMs for node 'moretrees:apple_tree_leaves' took 55us for 5 processed nodes.
chlue-INFO: ABMs for node 'moretrees:sequoia_leaves' took 1032us for 59 processed nodes.
chlue-INFO: ABMs for node 'moretrees:jungletree_leaves_green' took 131us for 6 processed nodes.
chlue-INFO: ABMs for node 'moretrees:jungletree_leaves_yellow' took 43us for 2 processed nodes.
chlue-INFO: ABMs for node 'moretrees:jungletree_leaves_red' took 22us for 1 processed nodes.
chlue-INFO: ABMs for node 'pipeworks:autocrafter' took 254196us for 14 processed nodes.
chlue-INFO: ABMs for node 'technic:quarry' took 65us for 1 processed nodes.
chlue-INFO: 260ms of 293ms (88%) were spend in ABM code
Things to keep in mind when looking at the data:
- based on simple timers, so preemption will lead to spikes
- the timer add overhead
- there are other ways a mod can hook into the game, so this does not show all
- there will be a somewhat fixed overhead for each processed node, so if many nodes are processed the error is higher than for a single long running node. (The overhead seem to be quiet low trough)
- This will really flood debug.txt, so its not suited to be run like this for a longer time period
- No idea what this counter does on windows
What I have found with this is that the pipeworks:autocrafter are a major cause of server load on my system. Everything else locked quiet as expected. I guess the function minetest.get_craft_result() is very expensive. Would be interesting to see how this code behaves on a server with big technic instalations. I guess the runtime of technic:switching_station could be issue there, too.
This is the actual patch:
Your phone or window isn't wide enough to display the code box. If it's a phone, try rotating it to landscape mode.
- Code: Select all
diff --git a/src/environment.cpp b/src/environment.cpp
index 03b4368..adb49a2 100644
--- a/src/environment.cpp
+++ b/src/environment.cpp
@@ -45,6 +45,13 @@
#define PP(x) "("<<(x).X<<","<<(x).Y<<","<<(x).Z<<")"
+typedef struct {
+ u32 duration;
+ u32 callcount;
+} ABMProfilingSample_t;
+
+typedef std::map<content_t, ABMProfilingSample_t> ABMProfilingMap_t;
+
Environment::Environment():
m_time_of_day(9000),
m_time_of_day_f(9000./24000),
@@ -707,7 +714,7 @@ class ABMHandler
}
}
}
- void apply(MapBlock *block)
+ void apply(MapBlock *block, ABMProfilingMap_t &ABMduration_list)
{
if(m_aabms.empty())
return;
@@ -780,10 +787,28 @@ class ABMHandler
u32 wider_known_count = 3*3*3 - wider_unknown_count;
active_object_count_wider += wider_unknown_count * active_object_count_wider / wider_known_count;
+ TimeTaker ABMtimer("ABMduration", NULL, PRECISION_MICRO);
+
// Call all the trigger variations
i->abm->trigger(m_env, p, n);
i->abm->trigger(m_env, p, n,
active_object_count, active_object_count_wider);
+
+ u32 time_us = ABMtimer.stop(true);
+ if (ABMduration_list.find(c) == ABMduration_list.end()) {
+ // new block
+ ABMProfilingSample_t tmp;
+ tmp.callcount = 1;
+ tmp.duration = time_us;
+ ABMduration_list[c] = tmp;
+ } else {
+ // add time
+ ABMProfilingSample_t tmp = ABMduration_list[c];
+ tmp.callcount += 1;
+ tmp.duration += time_us;
+ ABMduration_list[c] = tmp;
+ }
+
}
}
}
@@ -837,7 +862,8 @@ void ServerEnvironment::activateBlock(MapBlock *block, u32 additional_dtime)
/* Handle ActiveBlockModifiers */
ABMHandler abmhandler(m_abms, dtime_s, this, false);
- abmhandler.apply(block);
+ ABMProfilingMap_t ABMduration_list;
+ abmhandler.apply(block, ABMduration_list);
}
void ServerEnvironment::addActiveBlockModifier(ActiveBlockModifier *abm)
@@ -1211,6 +1237,8 @@ void ServerEnvironment::step(float dtime)
}
const float abm_interval = 1.0;
+ TimeTaker ABMtimer("OverallABMduration");
+ ABMProfilingMap_t ABMduration_list;
if(m_active_block_modifier_interval.step(dtime, abm_interval))
do{ // breakable
if(m_active_block_interval_overload_skip > 0){
@@ -1240,8 +1268,16 @@ void ServerEnvironment::step(float dtime)
// Set current time as timestamp
block->setTimestampNoChangedFlag(m_game_time);
/* Handle ActiveBlockModifiers */
- abmhandler.apply(block);
+ abmhandler.apply(block, ABMduration_list);
}
u32 time_ms = timer.stop(true);
@@ -1254,6 +1290,26 @@ void ServerEnvironment::step(float dtime)
}
}while(0);
+ u32 time_OverallABMduration = ABMtimer.stop(true);
+ u32 time_SpentInABMCode = 0;
+ // print gathered profiling data for last abm execution round
+ if (!ABMduration_list.empty()) {
+ static u32 ABMcycle = 0;
+ ABMcycle ++;
+ dstream<<"chlue-INFO: ABM execution time overview for ABMcycle " << ABMcycle << std::endl;
+ INodeDefManager* NodeDef = m_gamedef->getNodeDefManager();
+ for (ABMProfilingMap_t::iterator i = ABMduration_list.begin(); i != ABMduration_list.end(); i++) {
+ ContentFeatures ContentFeature = NodeDef->get(i->first);
+ ABMProfilingSample_t tmp = i->second;
+ time_SpentInABMCode += tmp.duration;
+
+ dstream<<"chlue-INFO: ABMs for node '" << ContentFeature.name << "' took " << tmp.duration << "us for " << tmp.callcount << " processed nodes." << std::endl;
+ //dstream<<"chlue-INFO: ABMcycle\t" << ABMcycle << "\t" << tmp.duration << "\t" << tmp.callcount << "\t" << ContentFeature.name << std::endl;
+ }
+ time_SpentInABMCode = time_SpentInABMCode / 1000;
+ dstream<<"chlue-INFO: " << time_SpentInABMCode << "ms of " << time_OverallABMduration << "ms (" << time_SpentInABMCode*100/time_OverallABMduration << "%) were spend in ABM code" << std::endl;
+ }
+
/*
Step script environment (run global on_step())
*/
