added performance timers

4 files changed, 211 insertions, 28 deletions

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