Improve debug profiler usage for investigating CPU usage of server

4 files changed, 97 insertions, 72 deletions

diff --git a/src/environment.cpp b/src/environment.cpp
index 267dd66af..99dc6d62b 100644
--- a/src/environment.cpp
+++ b/src/environment.cpp
@@ -28,6 +28,7 @@ with this program; if not, write to the Free Software Foundation, Inc.,
 #include "mapgen.h"
 #include "settings.h"
 #include "log.h"
+#include "profiler.h"
 
 #define PP(x) "("<<(x).X<<","<<(x).Y<<","<<(x).Z<<")"
 
@@ -682,38 +683,41 @@ void ServerEnvironment::step(float dtime)
 	/*
 		Handle players
 	*/
-	for(core::list<Player*>::Iterator i = m_players.begin();
-			i != m_players.end(); i++)
 	{
-		Player *player = *i;
-		
-		// Ignore disconnected players
-		if(player->peer_id == 0)
-			continue;
-
-		v3f playerpos = player->getPosition();
-		
-		// Move
-		player->move(dtime, *m_map, 100*BS);
-		
-		/*
-			Add footsteps to grass
-		*/
-		if(footprints)
+		ScopeProfiler sp(g_profiler, "SEnv: handle players avg", SPT_LOWPASS);
+		for(core::list<Player*>::Iterator i = m_players.begin();
+				i != m_players.end(); i++)
 		{
-			// Get node that is at BS/4 under player
-			v3s16 bottompos = floatToInt(playerpos + v3f(0,-BS/4,0), BS);
-			try{
-				MapNode n = m_map->getNode(bottompos);
-				if(n.getContent() == CONTENT_GRASS)
+			Player *player = *i;
+			
+			// Ignore disconnected players
+			if(player->peer_id == 0)
+				continue;
+
+			v3f playerpos = player->getPosition();
+			
+			// Move
+			player->move(dtime, *m_map, 100*BS);
+			
+			/*
+				Add footsteps to grass
+			*/
+			if(footprints)
+			{
+				// Get node that is at BS/4 under player
+				v3s16 bottompos = floatToInt(playerpos + v3f(0,-BS/4,0), BS);
+				try{
+					MapNode n = m_map->getNode(bottompos);
+					if(n.getContent() == CONTENT_GRASS)
+					{
+						n.setContent(CONTENT_GRASS_FOOTSTEPS);
+						m_map->setNode(bottompos, n);
+					}
+				}
+				catch(InvalidPositionException &e)
 				{
-					n.setContent(CONTENT_GRASS_FOOTSTEPS);
-					m_map->setNode(bottompos, n);
 				}
 			}
-			catch(InvalidPositionException &e)
-			{
-			}
 		}
 	}
 
@@ -722,6 +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);
 		/*
 			Get player block positions
 		*/
@@ -798,6 +803,8 @@ 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);
+		
 		float dtime = 1.0;
 
 		for(core::map<v3s16, bool>::Iterator
@@ -832,8 +839,10 @@ 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);
 		//float dtime = 10.0;
 		
 		for(core::map<v3s16, bool>::Iterator
@@ -1036,6 +1045,7 @@ void ServerEnvironment::step(float dtime)
 		Step active objects
 	*/
 	{
+		ScopeProfiler sp(g_profiler, "SEnv: step act. objs avg", SPT_LOWPASS);
 		//TimeTaker timer("Step active objects");
 		
 		// This helps the objects to send data at the same time
@@ -1076,6 +1086,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);
 		/*
 			Remove objects that satisfy (m_removed && m_known_by_count==0)
 		*/
diff --git a/src/game.cpp b/src/game.cpp
index c415db1e3..276857f80 100644
--- a/src/game.cpp
+++ b/src/game.cpp
@@ -1070,6 +1070,8 @@ void the_game(
 
 		object_hit_delay_timer -= dtime;
 
+		g_profiler->add("Elapsed time", dtime * 1000);
+
 		/*
 			Log frametime for visualization
 		*/
diff --git a/src/profiler.h b/src/profiler.h
index a30e34a7c..8eaf18df5 100644
--- a/src/profiler.h
+++ b/src/profiler.h
@@ -38,24 +38,38 @@ public:
 		m_mutex.Init();
 	}
 
-	void add(const std::string &name, u32 duration)
+	void add(const std::string &name, float value)
 	{
 		JMutexAutoLock lock(m_mutex);
-		core::map<std::string, u32>::Node *n = m_data.find(name);
+		core::map<std::string, float>::Node *n = m_data.find(name);
 		if(n == NULL)
 		{
-			m_data[name] = duration;
+			m_data[name] = value;
 		}
 		else
 		{
-			n->setValue(n->getValue()+duration);
+			n->setValue(n->getValue() + value);
+		}
+	}
+
+	void lowpass(const std::string &name, float value, float factor)
+	{
+		JMutexAutoLock lock(m_mutex);
+		core::map<std::string, float>::Node *n = m_data.find(name);
+		if(n == NULL)
+		{
+			m_data[name] = value;
+		}
+		else
+		{
+			n->setValue(n->getValue() * (1.0 - 1.0/factor) + value / factor);
 		}
 	}
 
 	void clear()
 	{
 		JMutexAutoLock lock(m_mutex);
-		for(core::map<std::string, u32>::Iterator
+		for(core::map<std::string, float>::Iterator
 				i = m_data.getIterator();
 				i.atEnd() == false; i++)
 		{
@@ -66,14 +80,14 @@ public:
 	void print(std::ostream &o)
 	{
 		JMutexAutoLock lock(m_mutex);
-		for(core::map<std::string, u32>::Iterator
+		for(core::map<std::string, float>::Iterator
 				i = m_data.getIterator();
 				i.atEnd() == false; i++)
 		{
 			std::string name = i.getNode()->getKey();
-			o<<name<<": ";
+			o<<"  "<<name<<": ";
 			s32 clampsize = 40;
-			s32 space = clampsize-name.size();
+			s32 space = clampsize - name.size();
 			for(s32 j=0; j<space; j++)
 			{
 				if(j%2 == 0 && j < space - 1)
@@ -88,25 +102,34 @@ public:
 
 private:
 	JMutex m_mutex;
-	core::map<std::string, u32> m_data;
+	core::map<std::string, float> m_data;
+};
+
+enum ScopeProfilerType{
+	SPT_ADD,
+	SPT_LOWPASS
 };
 
 class ScopeProfiler
 {
 public:
-	ScopeProfiler(Profiler *profiler, const std::string &name):
+	ScopeProfiler(Profiler *profiler, const std::string &name,
+			enum ScopeProfilerType type = SPT_ADD):
 		m_profiler(profiler),
 		m_name(name),
-		m_timer(NULL)
+		m_timer(NULL),
+		m_type(type)
 	{
 		if(m_profiler)
 			m_timer = new TimeTaker(m_name.c_str());
 	}
 	// name is copied
-	ScopeProfiler(Profiler *profiler, const char *name):
+	ScopeProfiler(Profiler *profiler, const char *name,
+			enum ScopeProfilerType type = SPT_ADD):
 		m_profiler(profiler),
 		m_name(name),
-		m_timer(NULL)
+		m_timer(NULL),
+		m_type(type)
 	{
 		if(m_profiler)
 			m_timer = new TimeTaker(m_name.c_str());
@@ -116,8 +139,16 @@ public:
 		if(m_timer)
 		{
 			u32 duration = m_timer->stop(true);
-			if(m_profiler)
-				m_profiler->add(m_name, duration);
+			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);
+					break;
+				}
+			}
 			delete m_timer;
 		}
 	}
@@ -125,6 +156,7 @@ private:
 	Profiler *m_profiler;
 	std::string m_name;
 	TimeTaker *m_timer;
+	enum ScopeProfilerType m_type;
 };
 
 #endif
diff --git a/src/server.cpp b/src/server.cpp
index 3e1034f50..ed0c97c29 100644
--- a/src/server.cpp
+++ b/src/server.cpp
@@ -842,31 +842,9 @@ void RemoteClient::SendObjectData(
 	}
 	
 	/*
-		Get and write object data
+		Get and write object data (dummy, for compatibility)
 	*/
 
-	/*
-		Get nearby blocks.
-		
-		For making players to be able to build to their nearby
-		environment (building is not possible on blocks that are not
-		in memory):
-		- Set blocks changed
-		- Add blocks to emerge queue if they are not found
-
-		SUGGESTION: These could be ignored from the backside of the player
-	*/
-
-	Player *player = server->m_env.getPlayer(peer_id);
-
-	assert(player);
-
-	v3f playerpos = player->getPosition();
-	v3f playerspeed = player->getSpeed();
-
-	v3s16 center_nodepos = floatToInt(playerpos, BS);
-	v3s16 center = getNodeBlockPos(center_nodepos);
-
 	// Write block count
 	writeU16(buf, 0);
 	os.write((char*)buf, 2);
@@ -1143,6 +1121,8 @@ void Server::AsyncRunStep()
 {
 	DSTACK(__FUNCTION_NAME);
 	
+	g_profiler->add("Server::AsyncRunStep (num)", 1);
+	
 	float dtime;
 	{
 		JMutexAutoLock lock1(m_step_dtime_mutex);
@@ -1150,14 +1130,15 @@ void Server::AsyncRunStep()
 	}
 	
 	{
-		ScopeProfiler sp(g_profiler, "Server: selecting and sending "
-				"blocks to clients");
+		ScopeProfiler sp(g_profiler, "Server: sel and send blocks to clients");
 		// Send blocks to clients
 		SendBlocks(dtime);
 	}
 	
 	if(dtime < 0.001)
 		return;
+	
+	g_profiler->add("Server::AsyncRunStep with dtime (num)", 1);
 
 	//infostream<<"Server steps "<<dtime<<std::endl;
 	//infostream<<"Server::AsyncRunStep(): dtime="<<dtime<<std::endl;
@@ -1184,7 +1165,6 @@ void Server::AsyncRunStep()
 	{
 		// This has to be called so that the client list gets synced
 		// with the peer list of the connection
-		ScopeProfiler sp(g_profiler, "Server: peer change handling");
 		handlePeerChanges();
 	}
 
@@ -1233,7 +1213,8 @@ void Server::AsyncRunStep()
 	{
 		JMutexAutoLock lock(m_env_mutex);
 		// Step environment
-		ScopeProfiler sp(g_profiler, "Server: environment step");
+		ScopeProfiler sp(g_profiler, "SEnv step");
+		ScopeProfiler sp2(g_profiler, "SEnv step avg", SPT_LOWPASS);
 		m_env.step(dtime);
 	}
 		
@@ -1340,7 +1321,7 @@ void Server::AsyncRunStep()
 		JMutexAutoLock envlock(m_env_mutex);
 		JMutexAutoLock conlock(m_con_mutex);
 
-		ScopeProfiler sp(g_profiler, "Server: checking added and deleted objects");
+		ScopeProfiler sp(g_profiler, "Server: checking added and deleted objs");
 
 		// Radius inside which objects are active
 		s16 radius = g_settings->getS16("active_object_send_range_blocks");
@@ -1720,7 +1701,6 @@ void Server::AsyncRunStep()
 
 	/*
 		Send object positions
-		TODO: Get rid of MapBlockObjects
 	*/
 	{
 		float &counter = m_objectdata_timer;
@@ -1730,7 +1710,7 @@ void Server::AsyncRunStep()
 			JMutexAutoLock lock1(m_env_mutex);
 			JMutexAutoLock lock2(m_con_mutex);
 
-			ScopeProfiler sp(g_profiler, "Server: sending mbo positions");
+			ScopeProfiler sp(g_profiler, "Server: sending player positions");
 
 			SendObjectData(counter);