From 66ef2cd08fe275af81125a1d04bc2f8e9c0b4ac2 Mon Sep 17 00:00:00 2001 From: Magnus Auvinen Date: Sun, 16 Dec 2007 15:33:44 +0000 Subject: added performance timers --- src/engine/e_engine.c | 73 ++++++++++++++++++++++++++++++++ src/engine/e_interface.h | 19 +++++++++ src/engine/server/es_server.c | 98 +++++++++++++++++++++++++++++++++++-------- src/game/server/gs_server.cpp | 49 +++++++++++++++++----- 4 files changed, 211 insertions(+), 28 deletions(-) (limited to 'src') diff --git a/src/engine/e_engine.c b/src/engine/e_engine.c index 998621e8..c3851380 100644 --- a/src/engine/e_engine.c +++ b/src/engine/e_engine.c @@ -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); +} diff --git a/src/engine/e_interface.h b/src/engine/e_interface.h index 67f8c78c..9d251443 100644 --- a/src/engine/e_interface.h +++ b/src/engine/e_interface.h @@ -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; diff --git a/src/engine/server/es_server.c b/src/engine/server/es_server.c index ac22f62b..c8bdebc0 100644 --- a/src/engine/server/es_server.c +++ b/src/engine/server/es_server.c @@ -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, diff --git a/src/game/server/gs_server.cpp b/src/game/server/gs_server.cpp index f6bc7cb6..a34766f3 100644 --- a/src/game/server/gs_server.cpp +++ b/src/game/server/gs_server.cpp @@ -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 -- cgit 1.4.1