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 }