diff --git a/src/twn_loop.c b/src/twn_loop.c index a812167..f3b1849 100644 --- a/src/twn_loop.c +++ b/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 */ diff --git a/src/twn_util.c b/src/twn_util.c index 5d77e46..91a48e8 100644 --- a/src/twn_util.c +++ b/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; - sample_count = p->value.sample_count; - worst_tick = p->value.worst_tick; + p->value.tick_start = counter; + p->value.active = true; + } else { + shput(profiles, profile, ((struct Profile) { + .tick_start = counter, + .active = true, + })); } - - shput(profiles, profile, ((struct Profile) { - .tick_start = SDL_GetPerformanceCounter(), - .tick_accum = tick_accum, - .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 / - (double)profiles[i].value.sample_count / - (double)(SDL_GetPerformanceFrequency()), - (double)profiles[i].value.worst_tick / (double)(SDL_GetPerformanceFrequency()), + format_profile_time((double)profiles[i].value.tick_accum / (double)profiles[i].value.sample_count), + format_profile_time((double)profiles[i].value.worst_tick), profiles[i].value.sample_count); } }