feat(server): log tick diagnostics periodically

example/server/main.c

@@ -1,6 +1,7 @@
 #include "clock.h"
 #include "skele.h"
 #include <stk/stk.h>
+#include <stk/stk_log.h>
 
 static uint8_t running = 1;
 
@@ -10,6 +11,7 @@ int main(int argc, char *argv[])
 {
 	uint64_t tick_start;
 	uint64_t elapsed;
+	uint64_t log_start;
 
 	skele_clock_init(on_signal);
 
@@ -21,6 +23,8 @@ int main(int argc, char *argv[])
 		return 1;
 	}
 
+	log_start = skele_time_ns();
+
 	while (running) {
 		tick_start = skele_time_ns();
 
@@ -28,8 +32,21 @@ int main(int argc, char *argv[])
 		skele_tick();
 
 		elapsed = skele_time_ns() - tick_start;
-		if (elapsed < skele_tick_ns)
+		if (elapsed < skele_tick_ns) {
+			skele_clock_idle_begin();
 			skele_sleep_ns(skele_tick_ns - elapsed);
+			skele_clock_idle_end();
+		}
+
+		if (skele_time_ns() - log_start >= 1000000000ULL) {
+			stk_log(STK_LOG_INFO,
+				"tps=%.1f work=%.2fms idle=%.2fms total=%.2fms budget=%.2fms",
+				skele_tps, skele_tick_work_time_ns / 1e6,
+				skele_tick_idle_time_ns / 1e6,
+				skele_tick_total_time_ns / 1e6,
+				skele_tick_ns / 1e6);
+			log_start = skele_time_ns();
+		}
 	}
 
 	skele_stk_teardown();

include/clock.h

@@ -8,8 +8,9 @@ extern "C" {
 #endif
 
 extern float skele_tps;
-extern uint64_t skele_tick_time_ns;
+extern uint64_t skele_tick_work_time_ns;
-extern uint64_t skele_tick_idle_ns;
+extern uint64_t skele_tick_idle_time_ns;
+extern uint64_t skele_tick_total_time_ns;
 
 void     skele_clock_init(void (*on_signal)(void));
 uint64_t skele_time_ns(void);

include/fps.h

@@ -8,10 +8,12 @@ extern "C" {
 #endif
 
 extern float skele_fps;
-extern float skele_frame_time_ms;
+extern float skele_frame_work_time_ms;
+extern float skele_frame_render_time_ms;
 extern float skele_frame_budget_ms;
 
 void skele_fps_init(void);
+void skele_fps_work_mark(void);
 void skele_fps_frame_mark(void);
 
 #ifdef __cplusplus

src/fps.c

@@ -2,12 +2,14 @@
 #include "clock.h"
 
 float skele_fps = 0.0f;
-float skele_frame_time_ms = 0.0f;
+float skele_frame_render_time_ms = 0.0f;
 float skele_frame_budget_ms = 0.0f;
+float skele_frame_work_time_ms = 0.0f;
 
 static uint64_t win_start = 0;
 static uint64_t last_frame_ns = 0;
 static uint64_t frame_ns_accum = 0;
+static uint64_t work_ns_accum = 0;
 static uint32_t frame_count = 0;
 
 void skele_fps_init(void)
@@ -15,9 +17,16 @@ void skele_fps_init(void)
 	win_start = skele_time_ns();
 	last_frame_ns = win_start;
 	frame_ns_accum = 0;
+	work_ns_accum = 0;
 	frame_count = 0;
 	skele_fps = 0.0f;
-	skele_frame_time_ms = 0.0f;
+	skele_frame_render_time_ms = 0.0f;
+	skele_frame_work_time_ms = 0.0f;
+}
+
+void skele_fps_work_mark(void)
+{
+	work_ns_accum += skele_time_ns() - last_frame_ns;
 }
 
 void skele_fps_frame_mark(void)
@@ -31,11 +40,14 @@ void skele_fps_frame_mark(void)
 	if (now - win_start >= 1000000000ULL) {
 		double elapsed_s = (double)(now - win_start) / 1e9;
 		skele_fps = (float)(frame_count / elapsed_s);
-		skele_frame_time_ms =
+		skele_frame_render_time_ms =
 			(float)((frame_ns_accum / (double)frame_count) / 1e6);
+		skele_frame_work_time_ms =
+			(float)((work_ns_accum / (double)frame_count) / 1e6);
 
 		win_start = now;
 		frame_ns_accum = 0;
+		work_ns_accum = 0;
 		frame_count = 0;
 	}
 }

src/platform/client/video/gl.c

@@ -244,6 +244,7 @@ void skele_video_shutdown(void)
 
 void skele_video_present(void)
 {
+	skele_fps_work_mark();
 	present_fn();
 	skele_fps_frame_mark();
 }

src/platform/client/video/sdl.c

@@ -289,6 +289,7 @@ void skele_video_blit(uint8_t *pixels)
 
 void skele_video_present(void)
 {
+	skele_fps_work_mark();
 	present_fn();
 	skele_fps_frame_mark();
 }

src/skele.c

@@ -6,8 +6,9 @@
 uint64_t skele_tick_ns = 1000000000ULL / SKELE_DEFAULT_TICK_RATE;
 
 float skele_tps = 0.0f;
-uint64_t skele_tick_time_ns = 0;
+uint64_t skele_tick_work_time_ns = 0;
-uint64_t skele_tick_idle_ns = 0;
+uint64_t skele_tick_idle_time_ns = 0;
+uint64_t skele_tick_total_time_ns = 0;
 
 static uint8_t stk_initialized = 0;
 
@@ -30,8 +31,9 @@ uint8_t skele_init(void)
 	tick_idle_accum = 0;
 	tick_count = 0;
 	skele_tps = 0.0f;
-	skele_tick_time_ns = 0;
+	skele_tick_work_time_ns = 0;
-	skele_tick_idle_ns = 0;
+	skele_tick_idle_time_ns = 0;
+	skele_tick_total_time_ns = 0;
 	return SKELE_INIT_SUCCESS;
 }
 
@@ -55,8 +57,10 @@ void skele_clock_tick_end(void)
 	if (now - tick_win_start >= 1000000000ULL) {
 		double elapsed_s = (now - tick_win_start) / 1e9;
 		skele_tps = tick_count / elapsed_s;
-		skele_tick_time_ns = tick_ns_accum / tick_count;
+		skele_tick_work_time_ns = tick_ns_accum / tick_count;
-		skele_tick_idle_ns = tick_idle_accum / tick_count;
+		skele_tick_idle_time_ns = tick_idle_accum / tick_count;
+		skele_tick_total_time_ns =
+			skele_tick_work_time_ns + skele_tick_idle_time_ns;
 
 		tick_win_start = now;
 		tick_ns_accum = 0;