Add option to display puppyprint debug values as cycles

2026-01-21 10:17:19 -08:00 · 2021-09-26 12:33:02 -07:00
parent 499fc33d7e
commit f0e4dd964b
5 changed files with 71 additions and 38 deletions
--- a/include/config.h
+++ b/include/config.h
@@ -190,6 +190,8 @@
 // Include Puppyprint, a display library for text and large images. Also includes a custom, enhanced performance profiler.
 //#define PUPPYPRINT
 #define PUPPYPRINT_DEBUG 0
+// Use cycles instead of microseconds
+//#define PUPPYPRINT_DEBUG_CYCLES
 // Visual debug enables some collision visuals. Tapping Right on the dpad will cycle between visual hitboxes, visual surfaces, both, and neither.
 // If puppyprint is enabled, then this can be cycled only while the screen is active.
 //#define VISUAL_DEBUG
--- a/src/audio/heap.c
+++ b/src/audio/heap.c
@@ -1493,7 +1493,11 @@ void audio_reset_session(void) {
    }
 #endif
 #if PUPPYPRINT_DEBUG
+#ifdef PUPPYPRINT_DEBUG_CYCLES
+    append_puppyprint_log("Audio Initialised in %dc.", (s32)(osGetTime() - first));
+#else
    append_puppyprint_log("Audio Initialised in %dus.", (s32)OS_CYCLES_TO_USEC(osGetTime() - first));
+#endif
 #endif
    sAudioFirstBoot = 1;
 }
--- a/src/game/hud.c
+++ b/src/game/hud.c
@@ -35,8 +35,7 @@ u8 curFrameTimeIndex = 0;
 #include "PR/os_convert.h"

 // Call once per frame
-f32 calculate_and_update_fps()
-{
+f32 calculate_and_update_fps() {
    OSTime newTime = osGetTime();
    OSTime oldTime = frameTimes[curFrameTimeIndex];
    frameTimes[curFrameTimeIndex] = newTime;
@@ -45,12 +44,10 @@ f32 calculate_and_update_fps()
    if (curFrameTimeIndex >= FRAMETIME_COUNT)
        curFrameTimeIndex = 0;

-
    return ((f32)FRAMETIME_COUNT * 1000000.0f) / (s32)OS_CYCLES_TO_USEC(newTime - oldTime);
 }

-void print_fps(s32 x, s32 y)
-{
+void print_fps(s32 x, s32 y) {
    f32 fps = calculate_and_update_fps();
    char text[14];

--- a/src/game/level_update.c
+++ b/src/game/level_update.c
@@ -1252,7 +1252,11 @@ s32 init_level(void) {
 #endif

 #if PUPPYPRINT_DEBUG
+#ifdef PUPPYPRINT_DEBUG_CYCLES
+    append_puppyprint_log("Level loaded in %dc", (s32)(osGetTime() - first));
+#else
    append_puppyprint_log("Level loaded in %dus", (s32)(OS_CYCLES_TO_USEC(osGetTime() - first)));
+#endif
 #endif
    return TRUE;
 }
--- a/src/game/puppyprint.c
+++ b/src/game/puppyprint.c
@@ -139,8 +139,7 @@ void puppyprint_calculate_ram_usage(void)
                        audioPool[6] + audioPool[7] + audioPool[8] + audioPool[9] + audioPool[10] + audioPool[11];
 }

-void puppyprint_profiler_finished(void)
-{
+void puppyprint_profiler_finished(void) {
    s32 i = 0;
    benchMark[NUM_BENCH_ITERATIONS] = 0;
    benchMark[NUM_BENCH_ITERATIONS+1] = 0;
@@ -158,37 +157,37 @@ void puppyprint_profiler_finished(void)

 //RGB colour lookup table for colouring all the funny ram prints.
 u8 colourChart[33][3] = {
-    {255, 0, 0},
-    {0, 0, 255},
-    {0, 255, 0},
-    {255, 255, 0},
-    {255, 0, 255},
-    {255, 127, 0},
-    {0, 255, 255},
-    {51, 255, 51},
-    {255, 153, 153},
-    {204, 0, 102},
-    {0, 153, 153},
-    {153, 255, 153},
-    {0, 0, 128},
-    {128, 0, 128},
-    {218, 165, 32},
-    {107, 142, 35},
-    {188, 143, 143},
-    {210, 105, 30},
-    {154, 205, 50},
-    {165, 42, 42},
-    {255, 105, 180},
-    {139, 69, 19},
-    {250, 240, 230},
-    {95, 158, 160},
-    {60, 179, 113},
-    {255, 69, 0},
-    {128, 0, 0},
-    {216, 191, 216},
-    {244, 164, 96},
-    {176, 196, 222},
-    {255, 255, 255}};
+    { 255,   0,   0 },
+    {   0,   0, 255 },
+    {   0, 255,   0 },
+    { 255, 255,   0 },
+    { 255,   0, 255 },
+    { 255, 127,   0 },
+    {   0, 255, 255 },
+    {  51, 255,  51 },
+    { 255, 153, 153 },
+    { 204,   0, 102 },
+    {   0, 153, 153 },
+    { 153, 255, 153 },
+    {   0,   0, 128 },
+    { 128,   0, 128 },
+    { 218, 165,  32 },
+    { 107, 142,  35 },
+    { 188, 143, 143 },
+    { 210, 105,  30 },
+    { 154, 205,  50 },
+    { 165,  42,  42 },
+    { 255, 105, 180 },
+    { 139,  69,  19 },
+    { 250, 240, 230 },
+    {  95, 158, 160 },
+    {  60, 179, 113 },
+    { 255,  69,   0 },
+    { 128,   0,   0 },
+    { 216, 191, 216 },
+    { 244, 164,  96 },
+    { 176, 196, 222 },
+    { 255, 255, 255 }};

 //Change this to alter the width of the bar at the bottom.
 #define BAR_LENGTH 200
@@ -366,8 +365,13 @@ void puppyprint_render_profiler(void)
    s32 perfPercentage[5];
    s32 graphPos;
    s32 prevGraph;
+#ifdef PUPPYPRINT_DEBUG_CYCLES
+    OSTime cpuCount = (cpuTime+audioTime[NUM_PERF_ITERATIONS]+dmaAudioTime[NUM_PERF_ITERATIONS]+faultTime[NUM_PERF_ITERATIONS]
+                               +taskTime[NUM_PERF_ITERATIONS]-profilerTime[NUM_PERF_ITERATIONS]-profilerTime2[NUM_PERF_ITERATIONS]);
+#else
    OSTime cpuCount = OS_CYCLES_TO_USEC(cpuTime+audioTime[NUM_PERF_ITERATIONS]+dmaAudioTime[NUM_PERF_ITERATIONS]+faultTime[NUM_PERF_ITERATIONS]
                                        +taskTime[NUM_PERF_ITERATIONS]-profilerTime[NUM_PERF_ITERATIONS]-profilerTime2[NUM_PERF_ITERATIONS]);
+#endif
    OSTime first = osGetTime();
    char textBytes[80];

@@ -383,7 +387,11 @@ void puppyprint_render_profiler(void)
    if (!ramViewer && !benchViewer && !logViewer)
    {
        print_fps(16,40);
+#ifdef PUPPYPRINT_DEBUG_CYCLES
+        sprintf(textBytes, "CPU: %dc (%d_)#RSP: %dc (%d_)#RDP: %dc (%d_)", (s32)cpuCount, (s32)(cpuCount/333), (s32)(rspTime), (s32)(rspTime)/333, (s32)(rdpTime), (s32)(rdpTime)/333);
+#else
        sprintf(textBytes, "CPU: %dus (%d_)#RSP: %dus (%d_)#RDP: %dus (%d_)", (s32)cpuCount, (s32)(cpuCount/333), (s32)OS_CYCLES_TO_USEC(rspTime), (s32)OS_CYCLES_TO_USEC(rspTime)/333, (s32)OS_CYCLES_TO_USEC(rdpTime), (s32)OS_CYCLES_TO_USEC(rdpTime)/333);
+#endif
        print_small_text(16, 52, textBytes, PRINT_TEXT_ALIGN_LEFT, PRINT_ALL);

        sprintf(textBytes, "OBJ: %d/%d", gObjectCounter, OBJECT_POOL_CAPACITY);
@@ -406,8 +414,13 @@ void puppyprint_render_profiler(void)
        {
            benchmarkTimer--;
            prepare_blank_box();
+#ifdef PUPPYPRINT_DEBUG_CYCLES
+            //sprintf(textBytes, "Benchmark: %dus#High: %dc", (s32)(benchMark[NUM_BENCH_ITERATIONS]), (s32)(benchMark[NUM_BENCH_ITERATIONS+1]));
+            sprintf(textBytes, "Done in %0.000f seconds#Benchmark: %dc#High: %dc", (f32)(benchmarkProgramTimer)*0.000001f, (s32)(benchMark[NUM_BENCH_ITERATIONS]), (s32)(benchMark[NUM_BENCH_ITERATIONS+1]));
+#else
            //sprintf(textBytes, "Benchmark: %dus#High: %dus", (s32)OS_CYCLES_TO_USEC(benchMark[NUM_BENCH_ITERATIONS]), (s32)OS_CYCLES_TO_USEC(benchMark[NUM_BENCH_ITERATIONS+1]));
            sprintf(textBytes, "Done in %0.000f seconds#Benchmark: %dus#High: %dus", (f32)(benchmarkProgramTimer)*0.000001f, (s32)OS_CYCLES_TO_USEC(benchMark[NUM_BENCH_ITERATIONS]), (s32)OS_CYCLES_TO_USEC(benchMark[NUM_BENCH_ITERATIONS+1]));
+#endif
            render_blank_box(160-(get_text_width(textBytes)/2)-4, 158, 160+(get_text_width(textBytes)/2)+4, 196, 0, 0, 0, 255);
            print_set_envcolour(255, 255, 255, 255);
            print_small_text(160, 160, textBytes, PRINT_TEXT_ALIGN_CENTRE, PRINT_ALL);
@@ -422,6 +435,18 @@ void puppyprint_render_profiler(void)
        perfPercentage[4] = MAX((dmaTime[NUM_PERF_ITERATIONS]/ADDTIMES), 1);
        #undef ADDTIMES

+#ifdef PUPPYPRINT_DEBUG_CYCLES
+        sprintf(textBytes, "Collision: <COL_99505099>%dc", (s32)(collisionTime[NUM_PERF_ITERATIONS]));
+        print_small_text(304, 40, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
+        sprintf(textBytes, "Graph: <COL_50509999>%dc", (s32)(graphTime[NUM_PERF_ITERATIONS]));
+        print_small_text(304, 52, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
+        sprintf(textBytes, "Behaviour: <COL_50995099>%dc", (s32)(behaviourTime[NUM_PERF_ITERATIONS]));
+        print_small_text(304, 64, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
+        sprintf(textBytes, "Audio: <COL_99995099>%dc", (s32)(audioTime[NUM_PERF_ITERATIONS]));
+        print_small_text(304, 76, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
+        sprintf(textBytes, "DMA: <COL_99509999>%dc", (s32)(dmaTime[NUM_PERF_ITERATIONS]));
+        print_small_text(304, 88, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
+#else
        sprintf(textBytes, "Collision: <COL_99505099>%dus", (s32)OS_CYCLES_TO_USEC(collisionTime[NUM_PERF_ITERATIONS]));
        print_small_text(304, 40, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
        sprintf(textBytes, "Graph: <COL_50509999>%dus", (s32)OS_CYCLES_TO_USEC(graphTime[NUM_PERF_ITERATIONS]));
@@ -432,6 +457,7 @@ void puppyprint_render_profiler(void)
        print_small_text(304, 76, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
        sprintf(textBytes, "DMA: <COL_99509999>%dus", (s32)OS_CYCLES_TO_USEC(dmaTime[NUM_PERF_ITERATIONS]));
        print_small_text(304, 88, textBytes, PRINT_TEXT_ALIGN_RIGHT, PRINT_ALL);
+#endif

        //Render CPU breakdown bar.
        prepare_blank_box();