Update the timer to properly handle recursion and deep call stacks

haversine_02/include/profiler/timer.h

@@ -27,9 +27,10 @@ typedef struct sample profiler_sample_t;
 
 struct sample {
   const char *title;
+  u64 first_start;
   u64 start;
-  u64 duration;
+  u64 exclusive_time;
-  u64 children_duration;
+  u64 children_time;
   u64 hit_count;
   profiler_sample_t *parent;
 };

haversine_02/src/profiler/timer.c

@@ -1,5 +1,6 @@
 #include "profiler/timer.h"
 #include "aliases.h"
+#include <stdbool.h>
 #include <stdio.h>
 #include <string.h>
 #include <time.h>
@@ -105,21 +106,17 @@ void profile_end() {
       continue;
     }
 
-    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,
+           (unsigned long long)sample->exclusive_time, percentage_char_count,
-           percentage_precision, (f64)duration / total * 100.0);
+           percentage_precision, (f64)(sample->exclusive_time) / total * 100.0);
 
-    if (sample->children_duration > 0) {
+    if (sample->children_time > 0) {
       printf(", w/ children: %*.*f %%", percentage_char_count,
-             percentage_precision, (f64)sample->duration / total * 100.0);
+             percentage_precision,
+             (f64)(sample->exclusive_time + sample->children_time) / total *
+                 100.0);
     }
 
     printf(")\n");
@@ -135,9 +132,10 @@ void sample_start(u64 id, const char *title) {
 
   if (!(sample->title) || strcmp(title, sample->title) != 0) {
     sample->title = title;
+    sample->first_start = 0;
     sample->start = 0;
-    sample->duration = 0;
+    sample->exclusive_time = 0;
-    sample->children_duration = 0;
+    sample->children_time = 0;
     sample->hit_count = 0;
     sample->parent = NULL;
 
@@ -149,9 +147,20 @@ void sample_start(u64 id, const char *title) {
   }
 
   sample->start = read_cpu_timer();
+
+  if (sample->hit_count == 0) {
+    sample->first_start = sample->start;
+  }
+
   ++(sample->hit_count);
 
-  if (sample != profiler.active) {
+  if (profiler.active) {
+    u64 duration = sample->start - (profiler.active->start);
+
+    profiler.active->exclusive_time += duration;
+  }
+
+  if (!(profiler.active) || sample != profiler.active) {
     // This handles recursive functions by changing the parent only when a
     // function isn't calling itself
     sample->parent = profiler.active;
@@ -169,16 +178,24 @@ void sample_end(u64 id) {
 
   u64 duration = read_cpu_timer() - sample->start;
 
-  if (!(sample->parent) || sample != sample->parent) {
+  sample->exclusive_time += duration;
-    // 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) {
+  u64 now = read_cpu_timer();
-    // This handles recursive functions by adding to the children_duration only
+
-    // when a function isn't calling itself
+  // Reset the start time at the end of the sample to handle recursion
-    sample->parent->children_duration += duration;
+  sample->start = now;
+
+  profiler_sample_t *parent = sample->parent;
+
+  if (parent) {
+    sample->parent->start = now;
+
+    // Add sample duration to all parents. This handles deep call stacks
+    while (parent) {
+      parent->children_time += duration;
+
+      parent = parent->parent;
+    }
   }
 
   profiler.active = sample->parent;