From 6b9a7ab8a55c50bb36ac1b21fb917e512ab56689 Mon Sep 17 00:00:00 2001 From: Abdelrahman Said Date: Sun, 9 Jul 2023 22:13:06 +0100 Subject: [PATCH] Update the timer code to support profiling loops and recursive functions --- haversine_02/include/profiler/timer.h | 25 ++++--- haversine_02/src/profiler/timer.c | 101 ++++++++++++++++++++------ 2 files changed, 94 insertions(+), 32 deletions(-) diff --git a/haversine_02/include/profiler/timer.h b/haversine_02/include/profiler/timer.h index 6531cea..6a4cef0 100644 --- a/haversine_02/include/profiler/timer.h +++ b/haversine_02/include/profiler/timer.h @@ -8,12 +8,12 @@ #endif // !MAX_PROFILE_SAMPLES #ifdef ENABLE_PROFILING -#define PROFILE_START profile_start() +#define PROFILE_START(COUNT) profile_start(COUNT) #define PROFILE_END profile_end() -#define SAMPLE_START(ID, TITLE) profiler_sample_t ID = sample_start(TITLE) -#define SAMPLE_END(ID) sample_end(&ID) +#define SAMPLE_START(ID, TITLE) sample_start(ID, TITLE) +#define SAMPLE_END(ID) sample_end(ID) #else -#define PROFILE_START +#define PROFILE_START(COUNT) #define PROFILE_END #define SAMPLE_START(ID, TITLE) #define SAMPLE_END(ID) @@ -23,11 +23,16 @@ extern "C" { #endif -typedef struct { +typedef struct sample profiler_sample_t; + +struct sample { const char *title; u64 start; - u64 end; -} profiler_sample_t; + u64 duration; + u64 children_duration; + u64 hit_count; + profiler_sample_t *parent; +}; u64 get_os_frequency(); @@ -40,11 +45,11 @@ u64 read_cpu_timer(void); // CPU frequency in hz/sec u64 get_cpu_freq(u64 milliseconds); -void profile_start(); +void profile_start(u64 count); void profile_end(); -profiler_sample_t sample_start(const char *title); -void sample_end(profiler_sample_t *sample); +void sample_start(u64 id, const char *title); +void sample_end(u64 id); #ifdef __cplusplus } diff --git a/haversine_02/src/profiler/timer.c b/haversine_02/src/profiler/timer.c index 2a1006f..af26a0f 100644 --- a/haversine_02/src/profiler/timer.c +++ b/haversine_02/src/profiler/timer.c @@ -13,6 +13,7 @@ typedef struct { u64 start; u64 end; u64 max_title_length; + profiler_sample_t *active; } profiler_t; INTERNAL profiler_t profiler = {0}; @@ -58,10 +59,11 @@ u64 get_cpu_freq(u64 milliseconds) { return cpu_freq; } -void profile_start() { +void profile_start(u64 count) { profiler.cpu_freq = get_cpu_freq(500); profiler.start = read_cpu_timer(); profiler.max_title_length = 0; + profiler.size = count; } void profile_end() { @@ -71,11 +73,16 @@ void profile_end() { profiler.end = read_cpu_timer(); - u64 total = profiler.end - profiler.start; + u64 total = 0; + + if (profiler.end >= profiler.start) { + total = profiler.end - profiler.start; + } u16 time_precision = 16; u16 time_char_count = 20; u16 duration_char_count = 22; + u16 hits_char_count = 10; u16 percentage_precision = 8; u16 percentage_char_count = 12; @@ -94,35 +101,85 @@ void profile_end() { for (u64 i = 0; i < profiler.size; ++i) { sample = &(profiler.samples[i]); - u64 duration = sample->end - sample->start; + if (sample->hit_count == 0) { + continue; + } - printf("%*s: %*lld (%*.*f %%)\n", (i32)profiler.max_title_length, - sample->title, duration_char_count, (unsigned long long)duration, - percentage_char_count, percentage_precision, - (f64)duration / total * 100.0); + u64 duration = 0; + + if (sample->duration >= sample->children_duration) { + duration = sample->duration - sample->children_duration; + } + + printf("%*s (hits: %*lld): %*lld (%*.*f %%", (i32)profiler.max_title_length, + sample->title, hits_char_count, + (unsigned long long)sample->hit_count, duration_char_count, + (unsigned long long)duration, percentage_char_count, + percentage_precision, (f64)duration / total * 100.0); + + if (sample->children_duration > 0) { + printf(", w/ children: %*.*f %%", percentage_char_count, + percentage_precision, (f64)sample->duration / total * 100.0); + } + + printf(")\n"); } } -profiler_sample_t sample_start(const char *title) { - return (profiler_sample_t){ - .title = title, - .start = read_cpu_timer(), - .end = 0, - }; -} - -void sample_end(profiler_sample_t *sample) { - if (profiler.size == MAX_PROFILE_SAMPLES) { +void sample_start(u64 id, const char *title) { + if (id >= MAX_PROFILE_SAMPLES) { return; } - u64 length = strlen(sample->title); + profiler_sample_t *sample = &(profiler.samples[id]); - if (length > profiler.max_title_length) { - profiler.max_title_length = length; + if (!(sample->title) || strcmp(title, sample->title) != 0) { + sample->title = title; + sample->start = 0; + sample->duration = 0; + sample->children_duration = 0; + sample->hit_count = 0; + sample->parent = NULL; + + u64 length = strlen(sample->title); + + if (length > profiler.max_title_length) { + profiler.max_title_length = length; + } } - sample->end = read_cpu_timer(); + sample->start = read_cpu_timer(); + ++(sample->hit_count); - profiler.samples[(profiler.size)++] = *sample; + if (sample != profiler.active) { + // This handles recursive functions by changing the parent only when a + // function isn't calling itself + sample->parent = profiler.active; + } + + profiler.active = sample; +} + +void sample_end(u64 id) { + if (id >= MAX_PROFILE_SAMPLES) { + return; + } + + profiler_sample_t *sample = &(profiler.samples[id]); + + u64 duration = read_cpu_timer() - sample->start; + + if (!(sample->parent) || sample != sample->parent) { + // This handles recursive functions by adding to the duration only when a + // function isn't calling itself + sample->duration += duration; + } + + if (sample->parent && sample != sample->parent) { + // This handles recursive functions by adding to the children_duration only + // when a function isn't calling itself + sample->parent->children_duration += duration; + } + + profiler.active = sample->parent; }