medfall

A super great game engine
Log | Files | Refs

profiler.cc (3508B)


      1 #include <stdio.h>
      2 
      3 #include "intrinsics.h"
      4 #include "profiler.h"
      5 #include "stats.h"
      6 #include "str.h"
      7 #include "strlcpy.h"
      8 #include "strlcat.h"
      9 #include "ggformat.h"
     10 #include "log.h"
     11 #include "platform_rdtsc.h"
     12 
     13 struct Timer {
     14 	const char * name;
     15 	const char * file;
     16 	int line;
     17 	Stats stats;
     18 };
     19 
     20 struct StackTimer {
     21 	u32 timer_idx;
     22 	u64 pushed_at;
     23 };
     24 
     25 struct LogEntry {
     26 	str< 256 > message;
     27 	u64 clocks;
     28 	u32 first_child;
     29 	u32 prev_sibling;
     30 };
     31 
     32 #define MAX_TIMERS 4096
     33 #define TIMER_STACK_SIZE 256
     34 #define TIMER_LOG_SIZE 1024
     35 
     36 static Timer all_timers[ MAX_TIMERS ];
     37 static u32 num_timers = 0;
     38 
     39 static StackTimer timer_stack[ TIMER_STACK_SIZE ];
     40 static u32 timer_stack_top = 0;
     41 
     42 static LogEntry logs[ TIMER_LOG_SIZE ];
     43 static u32 last_at_depth[ TIMER_LOG_SIZE ];
     44 static u32 num_log_entries = 1;
     45 
     46 u32 profiler_new_timer( const char * name, const char * file, int line ) {
     47 	ASSERT( num_timers < MAX_TIMERS );
     48 
     49 	all_timers[ num_timers ].name = name;
     50 	all_timers[ num_timers ].file = file;
     51 	all_timers[ num_timers ].line = line;
     52 
     53 	u32 ret = num_timers;
     54 	num_timers++;
     55 	return ret;
     56 }
     57 
     58 void profiler_push( u32 timer_idx ) {
     59 	ASSERT( timer_stack_top < TIMER_STACK_SIZE );
     60 
     61 	timer_stack[ timer_stack_top ].timer_idx = timer_idx;
     62 	timer_stack[ timer_stack_top ].pushed_at = rdtsc();
     63 	timer_stack_top++;
     64 }
     65 
     66 static FILE * log_file = NULL;
     67 void profiler_init() {
     68 	const str< 256 > log_path( "{}/profiler.log", logger_get_logs_dir() );
     69 	log_file = fopen( log_path.c_str(), "w" );
     70 }
     71 
     72 void profiler_term() {
     73 	fclose( log_file );
     74 }
     75 
     76 static void write_node( u32 idx, u64 frame_clocks ) {
     77 	const LogEntry & entry = logs[ idx ];
     78 	if( entry.prev_sibling != 0 ) {
     79 		write_node( entry.prev_sibling, frame_clocks );
     80 	}
     81 
     82 	ggprint_to_file( log_file, "{} ({.2}%)\n", entry.message.c_str(), entry.clocks * 100.0 / frame_clocks );
     83 
     84 	if( entry.first_child != 0 ) {
     85 		write_node( entry.first_child, frame_clocks );
     86 	}
     87 }
     88 
     89 static void write_frame( u64 frame_clocks ) {
     90 	write_node( num_log_entries - 1, frame_clocks );
     91 	ggprint_to_file( log_file, "\n" );
     92 	fflush( log_file );
     93 }
     94 
     95 void profiler_pop( const char * name ) {
     96 	ASSERT( timer_stack_top > 0 );
     97 
     98 	u64 now = rdtsc();
     99 
    100 	timer_stack_top--;
    101 	u32 idx = timer_stack[ timer_stack_top ].timer_idx;
    102 	u64 clocks = now - timer_stack[ timer_stack_top ].pushed_at;
    103 
    104 	Timer * timer = &all_timers[ idx ];
    105 	stats_record( &timer->stats, double( clocks ) );
    106 
    107 	if( name == NULL ) {
    108 		name = timer->name;
    109 	}
    110 
    111 	str< 512 > spaces;
    112 	for( u32 i = 0; i < timer_stack_top; i++ ) {
    113 		spaces += "  ";
    114 	}
    115 
    116 	ASSERT( num_log_entries < TIMER_LOG_SIZE );
    117 	LogEntry * entry = &logs[ num_log_entries ];
    118 	entry->message.sprintf( "{}{} ({}:{}) - {.3} Kclocks", spaces, name, timer->file, timer->line, clocks / 1024 );
    119 	entry->clocks = clocks;
    120 	entry->first_child = last_at_depth[ timer_stack_top + 1 ];
    121 	entry->prev_sibling = last_at_depth[ timer_stack_top ];
    122 
    123 	last_at_depth[ timer_stack_top ] = num_log_entries;
    124 	last_at_depth[ timer_stack_top + 1 ] = 0;
    125 
    126 	num_log_entries++;
    127 
    128 	if( timer_stack_top == 0 ) {
    129 		write_frame( clocks );
    130 		num_log_entries = 1;
    131 		memset( last_at_depth, 0, sizeof( last_at_depth ) );
    132 	}
    133 }
    134 
    135 void profiler_write_summary() {
    136 	for( u32 i = 0; i < num_timers; i++ ) {
    137 		Timer * timer = &all_timers[ i ];
    138 		ggprint_to_file( log_file, "{} ({}:{}): {}\n", timer->name, timer->file, timer->line, timer->stats );
    139 	}
    140 }
    141 
    142 ScopedTimer::ScopedTimer( u32 timer_idx, const char * n ) {
    143 	strlcpy( name, n, sizeof( name ) );
    144 	profiler_push( timer_idx );
    145 }
    146 
    147 ScopedTimer::~ScopedTimer() {
    148 	profiler_pop( name );
    149 }