Some more profiler stuff to get the hang on what really uses CPU

5 files changed, 66 insertions, 24 deletions

diff --git a/src/content_sao.cpp b/src/content_sao.cpp
index 1968b7b6a..9569b6586 100644
--- a/src/content_sao.cpp
+++ b/src/content_sao.cpp
@@ -21,6 +21,7 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 #include "collision.h"
 #include "environment.h"
 #include "settings.h"
+#include "profiler.h"
 
 core::map<u16, ServerActiveObject::Factory> ServerActiveObject::m_types;
 
@@ -137,6 +138,8 @@ ServerActiveObject* ItemSAO::create(ServerEnvironment *env, u16 id, v3f pos,
 
 void ItemSAO::step(float dtime, bool send_recommended)
 {
+	ScopeProfiler sp2(g_profiler, "ItemSAO::step avg", SPT_AVG);
+
 	assert(m_env);
 
 	const float interval = 0.2;
@@ -291,6 +294,8 @@ ServerActiveObject* RatSAO::create(ServerEnvironment *env, u16 id, v3f pos,
 
 void RatSAO::step(float dtime, bool send_recommended)
 {
+	ScopeProfiler sp2(g_profiler, "RatSAO::step avg", SPT_AVG);
+
 	assert(m_env);
 
 	if(m_is_active == false)
@@ -480,6 +485,8 @@ ServerActiveObject* Oerkki1SAO::create(ServerEnvironment *env, u16 id, v3f pos,
 
 void Oerkki1SAO::step(float dtime, bool send_recommended)
 {
+	ScopeProfiler sp2(g_profiler, "Oerkki1SAO::step avg", SPT_AVG);
+
 	assert(m_env);
 
 	if(m_is_active == false)
@@ -752,6 +759,8 @@ ServerActiveObject* FireflySAO::create(ServerEnvironment *env, u16 id, v3f pos,
 
 void FireflySAO::step(float dtime, bool send_recommended)
 {
+	ScopeProfiler sp2(g_profiler, "FireflySAO::step avg", SPT_AVG);
+
 	assert(m_env);
 
 	if(m_is_active == false)
@@ -1065,6 +1074,8 @@ static void explodeSquare(Map *map, v3s16 p0, v3s16 size)
 
 void MobV2SAO::step(float dtime, bool send_recommended)
 {
+	ScopeProfiler sp2(g_profiler, "MobV2SAO::step avg", SPT_AVG);
+
 	assert(m_env);
 	Map *map = &m_env->getMap();
 
diff --git a/src/environment.cpp b/src/environment.cpp
index 99dc6d62b..47743bfc7 100644
--- a/src/environment.cpp
+++ b/src/environment.cpp
@@ -684,7 +684,7 @@ void ServerEnvironment::step(float dtime)
 		Handle players
 	*/
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: handle players avg", SPT_LOWPASS);
+		ScopeProfiler sp(g_profiler, "SEnv: handle players avg", SPT_AVG);
 		for(core::list<Player*>::Iterator i = m_players.begin();
 				i != m_players.end(); i++)
 		{
@@ -726,7 +726,7 @@ void ServerEnvironment::step(float dtime)
 	*/
 	if(m_active_blocks_management_interval.step(dtime, 2.0))
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: manage act. block list avg", SPT_LOWPASS);
+		ScopeProfiler sp(g_profiler, "SEnv: manage act. block list avg /2s", SPT_AVG);
 		/*
 			Get player block positions
 		*/
@@ -803,7 +803,7 @@ void ServerEnvironment::step(float dtime)
 	*/
 	if(m_active_blocks_nodemetadata_interval.step(dtime, 1.0))
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: mess in act. blocks avg", SPT_LOWPASS);
+		ScopeProfiler sp(g_profiler, "SEnv: mess in act. blocks avg /1s", SPT_AVG);
 		
 		float dtime = 1.0;
 
@@ -842,7 +842,7 @@ void ServerEnvironment::step(float dtime)
 	
 	if(m_active_blocks_test_interval.step(dtime, 10.0))
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: modify in blocks avg", SPT_LOWPASS);
+		ScopeProfiler sp(g_profiler, "SEnv: modify in blocks avg /10s", SPT_AVG);
 		//float dtime = 10.0;
 		
 		for(core::map<v3s16, bool>::Iterator
@@ -1045,8 +1045,10 @@ void ServerEnvironment::step(float dtime)
 		Step active objects
 	*/
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: step act. objs avg", SPT_LOWPASS);
+		ScopeProfiler sp(g_profiler, "SEnv: step act. objs avg", SPT_AVG);
 		//TimeTaker timer("Step active objects");
+
+		g_profiler->avg("SEnv: num of objects", m_active_objects.size());
 		
 		// This helps the objects to send data at the same time
 		bool send_recommended = false;
@@ -1086,7 +1088,7 @@ void ServerEnvironment::step(float dtime)
 	*/
 	if(m_object_management_interval.step(dtime, 0.5))
 	{
-		ScopeProfiler sp(g_profiler, "SEnv: remove removed objs avg", SPT_LOWPASS);
+		ScopeProfiler sp(g_profiler, "SEnv: remove removed objs avg /.5s", SPT_AVG);
 		/*
 			Remove objects that satisfy (m_removed && m_known_by_count==0)
 		*/
diff --git a/src/game.cpp b/src/game.cpp
index 276857f80..e666e084d 100644
--- a/src/game.cpp
+++ b/src/game.cpp
@@ -1070,7 +1070,7 @@ void the_game(
 
 		object_hit_delay_timer -= dtime;
 
-		g_profiler->add("Elapsed time", dtime * 1000);
+		g_profiler->add("Elapsed time", dtime);
 
 		/*
 			Log frametime for visualization
diff --git a/src/profiler.h b/src/profiler.h
index 8eaf18df5..129118ef6 100644
--- a/src/profiler.h
+++ b/src/profiler.h
@@ -41,28 +41,48 @@ public:
 	void add(const std::string &name, float value)
 	{
 		JMutexAutoLock lock(m_mutex);
-		core::map<std::string, float>::Node *n = m_data.find(name);
-		if(n == NULL)
 		{
-			m_data[name] = value;
+			/* No average shall have been used; mark add used as -2 */
+			core::map<std::string, int>::Node *n = m_avgcounts.find(name);
+			if(n == NULL)
+				m_avgcounts[name] = -2;
+			else{
+				if(n->getValue() == -1)
+					n->setValue(-2);
+				assert(n->getValue() == -2);
+			}
 		}
-		else
 		{
-			n->setValue(n->getValue() + value);
+			core::map<std::string, float>::Node *n = m_data.find(name);
+			if(n == NULL)
+				m_data[name] = value;
+			else
+				n->setValue(n->getValue() + value);
 		}
 	}
 
-	void lowpass(const std::string &name, float value, float factor)
+	void avg(const std::string &name, float value)
 	{
 		JMutexAutoLock lock(m_mutex);
-		core::map<std::string, float>::Node *n = m_data.find(name);
-		if(n == NULL)
 		{
-			m_data[name] = value;
+			core::map<std::string, int>::Node *n = m_avgcounts.find(name);
+			if(n == NULL)
+				m_avgcounts[name] = 1;
+			else{
+				/* No add shall have been used */
+				assert(n->getValue() != -2);
+				if(n->getValue() <= 0)
+					n->setValue(1);
+				else
+					n->setValue(n->getValue() + 1);
+			}
 		}
-		else
 		{
-			n->setValue(n->getValue() * (1.0 - 1.0/factor) + value / factor);
+			core::map<std::string, float>::Node *n = m_data.find(name);
+			if(n == NULL)
+				m_data[name] = value;
+			else
+				n->setValue(n->getValue() + value);
 		}
 	}
 
@@ -75,6 +95,7 @@ public:
 		{
 			i.getNode()->setValue(0);
 		}
+		m_avgcounts.clear();
 	}
 
 	void print(std::ostream &o)
@@ -85,6 +106,12 @@ public:
 				i.atEnd() == false; i++)
 		{
 			std::string name = i.getNode()->getKey();
+			int avgcount = 1;
+			core::map<std::string, int>::Node *n = m_avgcounts.find(name);
+			if(n){
+				if(n->getValue() >= 1)
+					avgcount = n->getValue();
+			}
 			o<<"  "<<name<<": ";
 			s32 clampsize = 40;
 			s32 space = clampsize - name.size();
@@ -95,7 +122,7 @@ public:
 				else
 					o<<" ";
 			}
-			o<<i.getNode()->getValue();
+			o<<(i.getNode()->getValue() / avgcount);
 			o<<std::endl;
 		}
 	}
@@ -103,11 +130,12 @@ public:
 private:
 	JMutex m_mutex;
 	core::map<std::string, float> m_data;
+	core::map<std::string, int> m_avgcounts;
 };
 
 enum ScopeProfilerType{
 	SPT_ADD,
-	SPT_LOWPASS
+	SPT_AVG
 };
 
 class ScopeProfiler
@@ -138,14 +166,15 @@ public:
 	{
 		if(m_timer)
 		{
-			u32 duration = m_timer->stop(true);
+			float duration_ms = m_timer->stop(true);
+			float duration = duration_ms / 1000.0;
 			if(m_profiler){
 				switch(m_type){
 				case SPT_ADD:
 					m_profiler->add(m_name, duration);
 					break;
-				case SPT_LOWPASS:
-					m_profiler->lowpass(m_name, duration, 20.0);
+				case SPT_AVG:
+					m_profiler->avg(m_name, duration);
 					break;
 				}
 			}
diff --git a/src/server.cpp b/src/server.cpp
index ed0c97c29..14c019d52 100644
--- a/src/server.cpp
+++ b/src/server.cpp
@@ -1214,7 +1214,7 @@ void Server::AsyncRunStep()
 		JMutexAutoLock lock(m_env_mutex);
 		// Step environment
 		ScopeProfiler sp(g_profiler, "SEnv step");
-		ScopeProfiler sp2(g_profiler, "SEnv step avg", SPT_LOWPASS);
+		ScopeProfiler sp2(g_profiler, "SEnv step avg", SPT_AVG);
 		m_env.step(dtime);
 	}