added performance timers

This commit is contained in:
Magnus Auvinen 2007-12-16 15:33:44 +00:00
parent 7b6ed7861a
commit 66ef2cd08f
4 changed files with 211 additions and 28 deletions

View file

@ -69,3 +69,76 @@ void engine_writeconfig()
char buf[1024];
config_save(engine_savepath("default.cfg", buf, sizeof(buf)));
}
static int perf_tick = 1;
static PERFORMACE_INFO *current = 0;
void perf_init()
{
}
void perf_next()
{
perf_tick++;
current = 0;
}
void perf_start(PERFORMACE_INFO *info)
{
if(info->tick != perf_tick)
{
info->parent = current;
info->first_child = 0;
info->next_child = 0;
if(info->parent)
{
info->next_child = info->parent->first_child;
info->parent->first_child = info;
}
info->tick = perf_tick;
info->biggest = 0;
info->total = 0;
}
current = info;
current->start = time_get();
}
void perf_end()
{
int64 delta = time_get()-current->start;
current->total += delta;
if(delta > current->biggest)
current->biggest = delta;
current = current->parent;
}
static void perf_dump_imp(PERFORMACE_INFO *info, int indent)
{
char buf[512] = {0};
int64 freq = time_freq();
int i;
for(i = 0; i < indent; i++)
buf[i] = ' ';
sprintf(&buf[indent], "%-20s %8.2f %8.2f", info->name, info->total*1000/(float)freq, info->biggest*1000/(float)freq);
dbg_msg("perf", "%s", buf);
info = info->first_child;
while(info)
{
perf_dump_imp(info, indent+2);
info = info->next_child;
}
}
void perf_dump(PERFORMACE_INFO *top)
{
perf_dump_imp(top, 0);
}

View file

@ -11,6 +11,7 @@ extern "C" {
*/
#include "e_keys.h"
#include "e_system.h"
enum
{
@ -88,6 +89,24 @@ typedef struct
int player_scores[16];
} SERVER_INFO;
typedef struct PERFORMACE_INFO_t
{
const char *name;
struct PERFORMACE_INFO_t *parent;
struct PERFORMACE_INFO_t *first_child;
struct PERFORMACE_INFO_t *next_child;
int tick;
int64 start;
int64 total;
int64 biggest;
} PERFORMACE_INFO;
void perf_init();
void perf_next();
void perf_start(PERFORMACE_INFO *info);
void perf_end();
void perf_dump();
struct rect
{
float x, y, w, h;

View file

@ -276,7 +276,13 @@ int server_send_msg(int client_id)
static void server_do_snap()
{
int i, k;
mods_presnap();
{
static PERFORMACE_INFO scope = {"presnap", 0};
perf_start(&scope);
mods_presnap();
perf_end();
}
for(i = 0; i < MAX_CLIENTS; i++)
{
@ -294,9 +300,17 @@ static void server_do_snap()
int input_predtick = -1;
int64 timeleft = 0;
int deltasize;
static PERFORMACE_INFO scope = {"build", 0};
perf_start(&scope);
snapbuild_init(&builder);
mods_snap(i);
{
static PERFORMACE_INFO scope = {"modsnap", 0};
perf_start(&scope);
mods_snap(i);
perf_end();
}
/* finish snapshot */
snapshot_size = snapbuild_finish(&builder, data);
@ -330,17 +344,48 @@ static void server_do_snap()
}
/* create delta */
deltasize = snapshot_create_delta(deltashot, (SNAPSHOT*)data, deltadata);
{
static PERFORMACE_INFO scope = {"delta", 0};
perf_start(&scope);
deltasize = snapshot_create_delta(deltashot, (SNAPSHOT*)data, deltadata);
perf_end();
}
if(deltasize)
{
/* compress it */
unsigned char intdata[MAX_SNAPSHOT_SIZE];
int intsize = intpack_compress(deltadata, deltasize, intdata);
int snapshot_size = zerobit_compress(intdata, intsize, compdata);
int intsize;
int snapshot_size;
const int max_size = MAX_SNAPSHOT_PACKSIZE;
int numpackets = (snapshot_size+max_size-1)/max_size;
int numpackets;
int n, left;
{
static PERFORMACE_INFO scope = {"compress", 0};
perf_start(&scope);
{
static PERFORMACE_INFO scope = {"int", 0};
perf_start(&scope);
intsize = intpack_compress(deltadata, deltasize, intdata);
perf_end();
}
{
static PERFORMACE_INFO scope = {"zero", 0};
perf_start(&scope);
snapshot_size = zerobit_compress(intdata, intsize, compdata);
perf_end();
}
perf_end();
}
numpackets = (snapshot_size+max_size-1)/max_size;
for(n = 0, left = snapshot_size; left; n++)
{
@ -380,6 +425,8 @@ static void server_do_snap()
msg_pack_end();
server_send_msg(i);
}
perf_end();
}
}
@ -755,7 +802,11 @@ static int server_run()
while(1)
{
static PERFORMACE_INFO rootscope = {"root", 0};
int64 t = time_get();
perf_start(&rootscope);
/* load new map TODO: don't poll this */
if(strcmp(config.sv_map, current_map) != 0 || config.sv_map_reload)
{
@ -797,7 +848,11 @@ static int server_run()
/* apply new input */
{
static PERFORMACE_INFO scope = {"input", 0};
int c, i;
perf_start(&scope);
for(c = 0; c < MAX_CLIENTS; c++)
{
if(clients[c].state == SRVCLIENT_STATE_EMPTY)
@ -811,18 +866,16 @@ static int server_run()
}
}
}
perf_end();
}
/* progress game */
{
int64 start = time_get();
int64 delta;
static PERFORMACE_INFO scope = {"tick", 0};
perf_start(&scope);
mods_tick();
delta = time_get()-start;
simulationtime += delta;
if(config.debug && delta > time_freq()/10)
dbg_msg("server", "hitch warning! %.2f ms", delta/(float)time_freq()*1000);
perf_end();
}
/* snap game */
@ -831,9 +884,10 @@ static int server_run()
(config.sv_bandwidth_mode == 2 && (current_tick%3) == 0 ))
/* if(current_tick&1) */
{
int64 start = time_get();
static PERFORMACE_INFO scope = {"snap", 0};
perf_start(&scope);
server_do_snap();
snaptime += time_get()-start;
perf_end();
}
}
@ -847,10 +901,13 @@ static int server_run()
}
{
int64 start = time_get();
static PERFORMACE_INFO scope = {"net", 0};
perf_start(&scope);
server_pump_network();
networktime += time_get()-start;
perf_end();
}
perf_end();
if(reporttime < time_get())
{
@ -859,12 +916,17 @@ static int server_run()
static NETSTATS prev_stats;
NETSTATS stats;
netserver_stats(net, &stats);
perf_next();
perf_dump(&rootscope);
/*
dbg_msg("server", "sim=%.02fms snap=%.02fms net=%.02fms tot=%.02fms load=%.02f%%",
(simulationtime/reportinterval)/(double)time_freq()*1000,
(snaptime/reportinterval)/(double)time_freq()*1000,
(networktime/reportinterval)/(double)time_freq()*1000,
(totaltime/reportinterval)/(double)time_freq()*1000,
(totaltime)/reportinterval/(double)time_freq()*100.0f);
(totaltime)/reportinterval/(double)time_freq()*100.0f);*/
dbg_msg("server", "send=%8d recv=%8d",
(stats.send_bytes - prev_stats.send_bytes)/reportinterval,

View file

@ -249,26 +249,54 @@ void game_world::tick()
if(!paused)
{
static PERFORMACE_INFO scopes[OBJTYPE_FLAG+1] =
{
{"null", 0},
{"game", 0},
{"player_info", 0},
{"player_character", 0},
{"projectile", 0},
{"powerup", 0},
{"flag", 0}
};
static PERFORMACE_INFO scopes_def[OBJTYPE_FLAG+1] =
{
{"null", 0},
{"game", 0},
{"player_info", 0},
{"player_character", 0},
{"projectile", 0},
{"powerup", 0},
{"flag", 0}
};
static PERFORMACE_INFO tick_scope = {"tick", 0};
perf_start(&tick_scope);
// update all objects
for(entity *ent = first_entity; ent; ent = ent->next_entity)
{
int64 start = time_get();
if(ent->objtype >= 0 && ent->objtype < OBJTYPE_FLAG)
perf_start(&scopes[ent->objtype]);
ent->tick();
int64 delta = time_get()-start;
if(config.debug && delta > time_freq()/10)
dbg_msg("world", "entity tick hitch warning! %.2f ms objtype=%d", delta/(float)time_freq()*1000, ent->objtype);
if(ent->objtype >= 0 && ent->objtype < OBJTYPE_FLAG)
perf_end();
}
perf_end();
static PERFORMACE_INFO deftick_scope = {"tick_defered", 0};
perf_start(&deftick_scope);
for(entity *ent = first_entity; ent; ent = ent->next_entity)
{
int64 start = time_get();
if(ent->objtype >= 0 && ent->objtype < OBJTYPE_FLAG)
perf_start(&scopes_def[ent->objtype]);
ent->tick_defered();
int64 delta = time_get()-start;
if(config.debug && delta > time_freq()/10)
dbg_msg("world", "entity defered tick hitch warning! %.2f ms objtype=%d", delta/(float)time_freq()*1000, ent->objtype);
if(ent->objtype >= 0 && ent->objtype < OBJTYPE_FLAG)
perf_end();
}
perf_end();
}
remove_entities();
@ -1637,6 +1665,7 @@ void mods_tick()
{
// clear all events
events.clear();
world->tick();
if(world->paused) // make sure that the game object always updates