twn_util.c: show profiles in milliseconds when appropriate, don't include time taken for profile internals

src/twn_loop.c

@@ -214,7 +214,11 @@ static void main_loop(void) {
         if (ctx.window_size_has_changed)
             update_viewport();
         input_state_update(&ctx.input);
+
+        profile_start("game tick");
         game_object_tick();
+        profile_end("game tick");
+
         input_state_update_postframe(&ctx.input);
 
         /* TODO: make it works when ctx.ticks_per_second != 60 */

src/twn_util.c

@@ -16,6 +16,7 @@ static struct ProfileItem {
         uint64_t tick_accum;
         uint64_t sample_count;
         uint64_t worst_tick;
+        bool active;
     } value;
 } *profiles;
 
@@ -301,41 +302,62 @@ char *expand_asterisk(const char *mask, const char *to) {
 
 
 void profile_start(char profile[const static 1]) {
-    uint64_t tick_accum = 0, sample_count = 0, worst_tick = 0;
+    /* stamp time immediately, so to not have influence of our profile lookup */
+    uint64_t const counter = SDL_GetPerformanceCounter();
 
-    struct ProfileItem const *p = shgetp_null(profiles, profile);
+    struct ProfileItem *p = shgetp_null(profiles, profile);
     if (p) {
-        tick_accum = p->value.tick_accum;
+        p->value.tick_start = counter;
-        sample_count = p->value.sample_count;
+        p->value.active = true;
-        worst_tick = p->value.worst_tick;
+    } else {
-    }
-
         shput(profiles, profile, ((struct Profile) {
-            .tick_start = SDL_GetPerformanceCounter(),
+            .tick_start = counter,
-            .tick_accum = tick_accum,
+            .active = true,
-            .sample_count = sample_count,
-            .worst_tick = worst_tick,
         }));
     }
+}
 
 
 void profile_end(char profile[const static 1]) {
+    /* stamp time immediately, so to not have influence of our profile lookup */
+    uint64_t const counter = SDL_GetPerformanceCounter();
+
     struct ProfileItem *p = shgetp_null(profiles, profile);
-    if (!p) {
+    if (!p || !p->value.active) {
         log_warn("Profile %s wasn't started!", profile);
         return;
     }
 
-    uint64_t took = SDL_GetPerformanceCounter() - p->value.tick_start;
+    uint64_t const took = counter - p->value.tick_start;
 
     p->value.tick_accum += took;
     p->value.sample_count++;
+    p->value.active = false;
 
     if (p->value.worst_tick < took)
         p->value.worst_tick = took;
 }
 
 
+static char const *format_profile_time(double ticks) {
+    static char strings[2][128];
+    static char *current = strings[0];
+
+    double const seconds = (double)ticks / (double)(SDL_GetPerformanceFrequency());
+    /* display in seconds */
+    if (seconds >= 0.1)
+        SDL_snprintf(current, 128, "%fs", seconds);
+    /* display in milliseconds */
+    else
+        SDL_snprintf(current, 128, "%fms", seconds * 1000);
+
+    const char *const result = current;
+    current += 128;
+    if (current >= strings[1]) current = strings[0];
+    return result;
+}
+
+
 void profile_list_stats(void) {
     for (size_t i = 0; i < shlenu(profiles); ++i) {
         if (profiles[i].value.sample_count == 0) {
@@ -343,18 +365,16 @@ void profile_list_stats(void) {
         }
 
         else if (profiles[i].value.sample_count == 1) {
-            log_info("Profile '%s' took: %fs",
+            log_info("Profile '%s' took: %s",
                      profiles[i].key,
-                     (double)profiles[i].value.tick_accum / (double)(SDL_GetPerformanceFrequency()));
+                     format_profile_time((double)profiles[i].value.tick_accum));
         }
 
         else if (profiles[i].value.sample_count > 1) {
-            log_info("Profile '%s' on average took: %fs, worst case: %fs, sample count: %llu",
+            log_info("Profile '%s' on average took: %s, worst case: %s, sample count: %llu",
                      profiles[i].key,
-                     (double)profiles[i].value.tick_accum /
+                     format_profile_time((double)profiles[i].value.tick_accum / (double)profiles[i].value.sample_count),
-                        (double)profiles[i].value.sample_count /
+                     format_profile_time((double)profiles[i].value.worst_tick),
-                        (double)(SDL_GetPerformanceFrequency()),
-                     (double)profiles[i].value.worst_tick / (double)(SDL_GetPerformanceFrequency()),
                      profiles[i].value.sample_count);
         }
     }