Update the timer code to support profiling loops and recursive functions

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_START(ID, TITLE) sample_start(ID, TITLE)
-#define SAMPLE_END(ID) sample_end(&ID)
+#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;
+  u64 duration;
-} profiler_sample_t;
+  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_start(u64 id, const char *title);
-void sample_end(profiler_sample_t *sample);
+void sample_end(u64 id);
 
 #ifdef __cplusplus
 }

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,
+    u64 duration = 0;
-           sample->title, duration_char_count, (unsigned long long)duration,
+
-           percentage_char_count, percentage_precision,
+    if (sample->duration >= sample->children_duration) {
-           (f64)duration / total * 100.0);
+      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) {
+void sample_start(u64 id, const char *title) {
-  return (profiler_sample_t){
+  if (id >= MAX_PROFILE_SAMPLES) {
-      .title = title,
-      .start = read_cpu_timer(),
-      .end = 0,
-  };
-}
-
-void sample_end(profiler_sample_t *sample) {
-  if (profiler.size == MAX_PROFILE_SAMPLES) {
     return;
   }
 
-  u64 length = strlen(sample->title);
+  profiler_sample_t *sample = &(profiler.samples[id]);
 
-  if (length > profiler.max_title_length) {
+  if (!(sample->title) || strcmp(title, sample->title) != 0) {
-    profiler.max_title_length = length;
+    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;
 }