Improve debug profiler usage for investigating CPU usage of server
authorPerttu Ahola <celeron55@gmail.com>
Sun, 16 Oct 2011 18:16:44 +0000 (21:16 +0300)
committerPerttu Ahola <celeron55@gmail.com>
Sun, 16 Oct 2011 18:16:44 +0000 (21:16 +0300)
src/environment.cpp
src/game.cpp
src/profiler.h
src/server.cpp

index 267dd66afb6cb0db95621273c00471e87f43a6ca..99dc6d62be495172ff12400e954e2e09f786fcc9 100644 (file)
@@ -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)
                */
index c415db1e31f593ee11bc93e1c8130bdf9343cfa1..276857f80612945bc58198d578531d921c2238ce 100644 (file)
@@ -1070,6 +1070,8 @@ void the_game(
 
                object_hit_delay_timer -= dtime;
 
+               g_profiler->add("Elapsed time", dtime * 1000);
+
                /*
                        Log frametime for visualization
                */
index a30e34a7c77dd06558d7efa40bf755d61f0b043f..8eaf18df5effb290e88ec49d2a37758d94e82121 100644 (file)
@@ -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
index 3e1034f50e78ab0d49de7969453d84632df6c119..ed0c97c29145559390e6c7ea348dafd36fd3e5a1 100644 (file)
@@ -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);