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

This commit is contained in:
Perttu Ahola 2011-10-16 22:39:35 +03:00
parent b8f2dcea4d
commit 2419d0029a
5 changed files with 66 additions and 24 deletions

@ -21,6 +21,7 @@ with this program; if not, write to the Free Software Foundation, Inc.,
#include "collision.h" #include "collision.h"
#include "environment.h" #include "environment.h"
#include "settings.h" #include "settings.h"
#include "profiler.h"
core::map<u16, ServerActiveObject::Factory> ServerActiveObject::m_types; 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) void ItemSAO::step(float dtime, bool send_recommended)
{ {
ScopeProfiler sp2(g_profiler, "ItemSAO::step avg", SPT_AVG);
assert(m_env); assert(m_env);
const float interval = 0.2; 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) void RatSAO::step(float dtime, bool send_recommended)
{ {
ScopeProfiler sp2(g_profiler, "RatSAO::step avg", SPT_AVG);
assert(m_env); assert(m_env);
if(m_is_active == false) 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) void Oerkki1SAO::step(float dtime, bool send_recommended)
{ {
ScopeProfiler sp2(g_profiler, "Oerkki1SAO::step avg", SPT_AVG);
assert(m_env); assert(m_env);
if(m_is_active == false) 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) void FireflySAO::step(float dtime, bool send_recommended)
{ {
ScopeProfiler sp2(g_profiler, "FireflySAO::step avg", SPT_AVG);
assert(m_env); assert(m_env);
if(m_is_active == false) 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) void MobV2SAO::step(float dtime, bool send_recommended)
{ {
ScopeProfiler sp2(g_profiler, "MobV2SAO::step avg", SPT_AVG);
assert(m_env); assert(m_env);
Map *map = &m_env->getMap(); Map *map = &m_env->getMap();

@ -684,7 +684,7 @@ void ServerEnvironment::step(float dtime)
Handle players 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(); for(core::list<Player*>::Iterator i = m_players.begin();
i != m_players.end(); i++) i != m_players.end(); i++)
{ {
@ -726,7 +726,7 @@ void ServerEnvironment::step(float dtime)
*/ */
if(m_active_blocks_management_interval.step(dtime, 2.0)) 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 Get player block positions
*/ */
@ -803,7 +803,7 @@ void ServerEnvironment::step(float dtime)
*/ */
if(m_active_blocks_nodemetadata_interval.step(dtime, 1.0)) 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; float dtime = 1.0;
@ -842,7 +842,7 @@ void ServerEnvironment::step(float dtime)
if(m_active_blocks_test_interval.step(dtime, 10.0)) 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; //float dtime = 10.0;
for(core::map<v3s16, bool>::Iterator for(core::map<v3s16, bool>::Iterator
@ -1045,9 +1045,11 @@ void ServerEnvironment::step(float dtime)
Step active objects 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"); //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 // This helps the objects to send data at the same time
bool send_recommended = false; bool send_recommended = false;
m_send_recommended_timer += dtime; m_send_recommended_timer += dtime;
@ -1086,7 +1088,7 @@ void ServerEnvironment::step(float dtime)
*/ */
if(m_object_management_interval.step(dtime, 0.5)) 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) Remove objects that satisfy (m_removed && m_known_by_count==0)
*/ */

@ -1070,7 +1070,7 @@ void the_game(
object_hit_delay_timer -= dtime; object_hit_delay_timer -= dtime;
g_profiler->add("Elapsed time", dtime * 1000); g_profiler->add("Elapsed time", dtime);
/* /*
Log frametime for visualization Log frametime for visualization

@ -41,28 +41,48 @@ public:
void add(const std::string &name, float value) void add(const std::string &name, float value)
{ {
JMutexAutoLock lock(m_mutex); 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); 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); i.getNode()->setValue(0);
} }
m_avgcounts.clear();
} }
void print(std::ostream &o) void print(std::ostream &o)
@ -85,6 +106,12 @@ public:
i.atEnd() == false; i++) i.atEnd() == false; i++)
{ {
std::string name = i.getNode()->getKey(); 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<<": "; o<<" "<<name<<": ";
s32 clampsize = 40; s32 clampsize = 40;
s32 space = clampsize - name.size(); s32 space = clampsize - name.size();
@ -95,7 +122,7 @@ public:
else else
o<<" "; o<<" ";
} }
o<<i.getNode()->getValue(); o<<(i.getNode()->getValue() / avgcount);
o<<std::endl; o<<std::endl;
} }
} }
@ -103,11 +130,12 @@ public:
private: private:
JMutex m_mutex; JMutex m_mutex;
core::map<std::string, float> m_data; core::map<std::string, float> m_data;
core::map<std::string, int> m_avgcounts;
}; };
enum ScopeProfilerType{ enum ScopeProfilerType{
SPT_ADD, SPT_ADD,
SPT_LOWPASS SPT_AVG
}; };
class ScopeProfiler class ScopeProfiler
@ -138,14 +166,15 @@ public:
{ {
if(m_timer) 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){ if(m_profiler){
switch(m_type){ switch(m_type){
case SPT_ADD: case SPT_ADD:
m_profiler->add(m_name, duration); m_profiler->add(m_name, duration);
break; break;
case SPT_LOWPASS: case SPT_AVG:
m_profiler->lowpass(m_name, duration, 20.0); m_profiler->avg(m_name, duration);
break; break;
} }
} }

@ -1214,7 +1214,7 @@ void Server::AsyncRunStep()
JMutexAutoLock lock(m_env_mutex); JMutexAutoLock lock(m_env_mutex);
// Step environment // Step environment
ScopeProfiler sp(g_profiler, "SEnv step"); 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); m_env.step(dtime);
} }