Puppyprint

bin/segment2.c

@@ -9,6 +9,11 @@
 #include "make_const_nonconst.h"
 
 // SM64 (US/JP/EU/SH) Segment 02
+#ifdef PUPPYPRINT
+ALIGNED8 const Texture small_font[] = {
+#include "textures/segment2/custom_text.i4.inc.c"
+};
+#endif
 
 ALIGNED8 static const Texture texture_hud_char_0[] = {
 #include "textures/segment2/segment2.00000.rgba16.inc.c"

include/config.h

@@ -111,6 +111,8 @@
 #define ALL_SURFACES_HAVE_FORCE
 // Custom debug mode. Press DPAD left to show the debug UI. Press DPAD right to enter the noclip mode.
 //#define CUSTOM_DEBUG
+// Include Puppyprint, a display library for text and large images. Also includes a custom, enhanced performance profiler.
+#define PUPPYPRINT
 
 // BUG/GAME QOL FIXES
 // Fix instant warp offset not working when warping across different areas

src/audio/heap.c

@@ -7,6 +7,7 @@
 #include "seqplayer.h"
 #include "effects.h"
 #include "game/game_init.h"
+#include "game/puppyprint.h"
 
 #define ALIGN16(val) (((val) + 0xF) & ~0xF)
 
@@ -339,6 +340,10 @@ extern s32 D_SH_80315EE8;
 void sound_init_main_pools(s32 sizeForAudioInitPool) {
     sound_alloc_pool_init(&gAudioInitPool, gAudioHeap, sizeForAudioInitPool);
     sound_alloc_pool_init(&gAudioSessionPool, gAudioHeap + sizeForAudioInitPool, gAudioHeapSize - sizeForAudioInitPool);
+    #ifdef PUPPYPRINT
+    audioPool[0] = sizeForAudioInitPool;
+    audioPool[1] = gAudioHeapSize - sizeForAudioInitPool;
+    #endif
 }
 
 #ifdef VERSION_SH
@@ -351,20 +356,32 @@ void session_pools_init(struct PoolSplit *a) {
     gAudioSessionPool.cur = gAudioSessionPool.start;
     sound_alloc_pool_init(&gNotesAndBuffersPool, SOUND_ALLOC_FUNC(&gAudioSessionPool, a->wantSeq), a->wantSeq);
     sound_alloc_pool_init(&gSeqAndBankPool, SOUND_ALLOC_FUNC(&gAudioSessionPool, a->wantCustom), a->wantCustom);
+    #ifdef PUPPYPRINT
+    audioPool[2] = a->wantSeq;
+    audioPool[3] = a->wantCustom;
+    #endif
 }
 
 void seq_and_bank_pool_init(struct PoolSplit2 *a) {
     gSeqAndBankPool.cur = gSeqAndBankPool.start;
     sound_alloc_pool_init(&gPersistentCommonPool, SOUND_ALLOC_FUNC(&gSeqAndBankPool, a->wantPersistent), a->wantPersistent);
     sound_alloc_pool_init(&gTemporaryCommonPool, SOUND_ALLOC_FUNC(&gSeqAndBankPool, a->wantTemporary), a->wantTemporary);
+    #ifdef PUPPYPRINT
+    audioPool[4] = a->wantPersistent;
+    audioPool[5] = a->wantTemporary;
+    #endif
 }
 
 void persistent_pools_init(struct PoolSplit *a) {
     gPersistentCommonPool.cur = gPersistentCommonPool.start;
     sound_alloc_pool_init(&gSeqLoadedPool.persistent.pool, SOUND_ALLOC_FUNC(&gPersistentCommonPool, a->wantSeq), a->wantSeq);
     sound_alloc_pool_init(&gBankLoadedPool.persistent.pool, SOUND_ALLOC_FUNC(&gPersistentCommonPool, a->wantBank), a->wantBank);
-    sound_alloc_pool_init(&gUnusedLoadedPool.persistent.pool, SOUND_ALLOC_FUNC(&gPersistentCommonPool, a->wantUnused),
-                  a->wantUnused);
+    sound_alloc_pool_init(&gUnusedLoadedPool.persistent.pool, SOUND_ALLOC_FUNC(&gPersistentCommonPool, a->wantUnused), a->wantUnused);
+    #ifdef PUPPYPRINT
+    audioPool[6] = a->wantSeq;
+    audioPool[7] = a->wantBank;
+    audioPool[8] = a->wantUnused;
+    #endif
     persistent_pool_clear(&gSeqLoadedPool.persistent);
     persistent_pool_clear(&gBankLoadedPool.persistent);
     persistent_pool_clear(&gUnusedLoadedPool.persistent);
@@ -374,8 +391,12 @@ void temporary_pools_init(struct PoolSplit *a) {
     gTemporaryCommonPool.cur = gTemporaryCommonPool.start;
     sound_alloc_pool_init(&gSeqLoadedPool.temporary.pool, SOUND_ALLOC_FUNC(&gTemporaryCommonPool, a->wantSeq), a->wantSeq);
     sound_alloc_pool_init(&gBankLoadedPool.temporary.pool, SOUND_ALLOC_FUNC(&gTemporaryCommonPool, a->wantBank), a->wantBank);
-    sound_alloc_pool_init(&gUnusedLoadedPool.temporary.pool, SOUND_ALLOC_FUNC(&gTemporaryCommonPool, a->wantUnused),
-                  a->wantUnused);
+    sound_alloc_pool_init(&gUnusedLoadedPool.temporary.pool, SOUND_ALLOC_FUNC(&gTemporaryCommonPool, a->wantUnused), a->wantUnused);
+    #ifdef PUPPYPRINT
+    audioPool[9] = a->wantSeq;
+    audioPool[10] = a->wantBank;
+    audioPool[11] = a->wantUnused;
+    #endif
     temporary_pool_clear(&gSeqLoadedPool.temporary);
     temporary_pool_clear(&gBankLoadedPool.temporary);
     temporary_pool_clear(&gUnusedLoadedPool.temporary);

src/audio/load.c

@@ -7,6 +7,7 @@
 #include "heap.h"
 #include "load.h"
 #include "seqplayer.h"
+#include "game/puppyprint.h"
 
 #define ALIGN16(val) (((val) + 0xF) & ~0xF)
 
@@ -141,8 +142,14 @@ u8 audioString49[] = "BANK LOAD MISS! FOR %d\n";
  * Performs an asynchronus (normal priority) DMA copy
  */
 void audio_dma_copy_async(uintptr_t devAddr, void *vAddr, size_t nbytes, OSMesgQueue *queue, OSIoMesg *mesg) {
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
     osInvalDCache(vAddr, nbytes);
     osPiStartDma(mesg, OS_MESG_PRI_NORMAL, OS_READ, devAddr, vAddr, nbytes, queue);
+    #ifdef PUPPYPRINT
+    dmaAudioTime[perfIteration] += osGetTime()-first;
+    #endif
 }
 
 /**
@@ -150,6 +157,9 @@ void audio_dma_copy_async(uintptr_t devAddr, void *vAddr, size_t nbytes, OSMesgQ
  * to 0x1000 bytes transfer at once.
  */
 void audio_dma_partial_copy_async(uintptr_t *devAddr, u8 **vAddr, ssize_t *remaining, OSMesgQueue *queue, OSIoMesg *mesg) {
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 #if defined(VERSION_EU)
     ssize_t transfer = (*remaining >= 0x1000 ? 0x1000 : *remaining);
 #else
@@ -160,6 +170,9 @@ void audio_dma_partial_copy_async(uintptr_t *devAddr, u8 **vAddr, ssize_t *remai
     osPiStartDma(mesg, OS_MESG_PRI_NORMAL, OS_READ, *devAddr, *vAddr, transfer, queue);
     *devAddr += transfer;
     *vAddr += transfer;
+    #ifdef PUPPYPRINT
+    dmaAudioTime[perfIteration] += osGetTime()-first;
+    #endif
 }
 
 void decrease_sample_dma_ttls() {
@@ -207,6 +220,9 @@ void *dma_sample_data(uintptr_t devAddr, u32 size, s32 arg2, u8 *dmaIndexRef) {
     u32 dmaIndex;
     ssize_t bufferPos;
     UNUSED u32 pad;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     if (arg2 != 0 || *dmaIndexRef >= sSampleDmaListSize1) {
         for (i = sSampleDmaListSize1; i < gSampleDmaNumListItems; i++) {
@@ -232,8 +248,14 @@ void *dma_sample_data(uintptr_t devAddr, u32 size, s32 arg2, u8 *dmaIndexRef) {
                 dma->ttl = 60;
                 *dmaIndexRef = (u8) i;
 #if defined(VERSION_EU)
+                #ifdef PUPPYPRINT
+                dmaAudioTime[perfIteration] += osGetTime()-first;
+                #endif
                 return &dma->buffer[(devAddr - dma->source)];
 #else
+                #ifdef PUPPYPRINT
+                dmaAudioTime[perfIteration] += osGetTime()-first;
+                #endif
                 return (devAddr - dma->source) + dma->buffer;
 #endif
             }
@@ -274,8 +296,14 @@ void *dma_sample_data(uintptr_t devAddr, u32 size, s32 arg2, u8 *dmaIndexRef) {
             }
             dma->ttl = 2;
 #if defined(VERSION_EU)
+            #ifdef PUPPYPRINT
+            dmaAudioTime[perfIteration] += osGetTime()-first;
+            #endif
             return dma->buffer + (devAddr - dma->source);
 #else
+            #ifdef PUPPYPRINT
+            dmaAudioTime[perfIteration] += osGetTime()-first;
+            #endif
             return (devAddr - dma->source) + dma->buffer;
 #endif
         }
@@ -301,12 +329,18 @@ void *dma_sample_data(uintptr_t devAddr, u32 size, s32 arg2, u8 *dmaIndexRef) {
     osPiStartDma(&gCurrAudioFrameDmaIoMesgBufs[gCurrAudioFrameDmaCount++], OS_MESG_PRI_NORMAL,
                      OS_READ, dmaDevAddr, dma->buffer, transfer, &gCurrAudioFrameDmaQueue);
     *dmaIndexRef = dmaIndex;
+    #ifdef PUPPYPRINT
+    dmaAudioTime[perfIteration] += osGetTime()-first;
+    #endif
     return (devAddr - dmaDevAddr) + dma->buffer;
 #else
     gCurrAudioFrameDmaCount++;
     osPiStartDma(&gCurrAudioFrameDmaIoMesgBufs[gCurrAudioFrameDmaCount - 1], OS_MESG_PRI_NORMAL,
                  OS_READ, dmaDevAddr, dma->buffer, transfer, &gCurrAudioFrameDmaQueue);
     *dmaIndexRef = dmaIndex;
+    #ifdef PUPPYPRINT
+    dmaAudioTime[perfIteration] += osGetTime()-first;
+    #endif
     return dma->buffer + (devAddr - dmaDevAddr);
 #endif
 }

src/engine/math_util.h

@@ -31,6 +31,7 @@ extern f32 gCosineTable[];
 
 #define min(a, b) ((a) <= (b) ? (a) : (b))
 #define max(a, b) ((a) > (b) ? (a) : (b))
+#define CLAMP(x, low, high)  (((x) > (high)) ? (high) : (((x) < (low)) ? (low) : (x)))
 
 #define sqr(x) ((x) * (x))
 

src/engine/surface_collision.c

@@ -7,6 +7,7 @@
 #include "game/object_list_processor.h"
 #include "surface_collision.h"
 #include "surface_load.h"
+#include "game/puppyprint.h"
 
 /**************************************************
  *                      WALLS                     *
@@ -187,6 +188,9 @@ s32 find_wall_collisions(struct WallCollisionData *colData) {
     s32 numCollisions = 0;
     s16 x = colData->x;
     s16 z = colData->z;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     colData->numWalls = 0;
 
@@ -213,6 +217,10 @@ s32 find_wall_collisions(struct WallCollisionData *colData) {
     // Increment the debug tracker.
     gNumCalls.wall += 1;
 
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
+
     return numCollisions;
 }
 
@@ -299,6 +307,9 @@ f32 find_ceil(f32 posX, f32 posY, f32 posZ, struct Surface **pceil) {
     f32 height = CELL_HEIGHT_LIMIT;
     f32 dynamicHeight = CELL_HEIGHT_LIMIT;
     s16 x, y, z;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     //! (Parallel Universes) Because position is casted to an s16, reaching higher
     // float locations  can return ceilings despite them not existing there.
@@ -337,6 +348,10 @@ f32 find_ceil(f32 posX, f32 posY, f32 posZ, struct Surface **pceil) {
     // Increment the debug tracker.
     gNumCalls.ceil += 1;
 
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
+
     return height;
 }
 
@@ -562,6 +577,9 @@ f32 unused_find_dynamic_floor(f32 xPos, f32 yPos, f32 zPos, struct Surface **pfl
  */
 f32 find_floor(f32 xPos, f32 yPos, f32 zPos, struct Surface **pfloor) {
     s16 cellZ, cellX;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     struct Surface *floor, *dynamicFloor;
     struct SurfaceNode *surfaceList;
@@ -579,9 +597,15 @@ f32 find_floor(f32 xPos, f32 yPos, f32 zPos, struct Surface **pfloor) {
     *pfloor = NULL;
 
     if (x <= -LEVEL_BOUNDARY_MAX || x >= LEVEL_BOUNDARY_MAX) {
+        #ifdef PUPPYPRINT
+        collisionTime[perfIteration] += osGetTime()-first;
+        #endif
         return height;
     }
     if (z <= -LEVEL_BOUNDARY_MAX || z >= LEVEL_BOUNDARY_MAX) {
+        #ifdef PUPPYPRINT
+        collisionTime[perfIteration] += osGetTime()-first;
+        #endif
         return height;
     }
 
@@ -628,6 +652,10 @@ f32 find_floor(f32 xPos, f32 yPos, f32 zPos, struct Surface **pfloor) {
     // Increment the debug tracker.
     gNumCalls.floor += 1;
 
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
+
     return height;
 }
 
@@ -685,6 +713,9 @@ f32 find_water_level_and_floor(f32 x, f32 z, struct Surface **pfloor) {
     f32 waterLevel = FLOOR_LOWER_LIMIT;
     s16 *p = gEnvironmentRegions;
     struct Surface *floor = NULL;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     if (gCheckingSurfaceCollisionsForCamera) {
         waterLevel = find_water_floor(x, gLakituState.pos[1], z, &floor);
@@ -715,6 +746,10 @@ f32 find_water_level_and_floor(f32 x, f32 z, struct Surface **pfloor) {
         *pfloor = floor;
     }
 
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
+
     return waterLevel;
 }
 
@@ -729,6 +764,9 @@ f32 find_water_level(f32 x, f32 z) {
     f32 waterLevel = FLOOR_LOWER_LIMIT;
     s16 *p = gEnvironmentRegions;
     struct Surface *floor;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     if (gCheckingSurfaceCollisionsForCamera) {
         waterLevel = find_water_floor(x, gLakituState.pos[1], z, &floor);
@@ -757,6 +795,10 @@ f32 find_water_level(f32 x, f32 z) {
         }
     }
 
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
+
     return waterLevel;
 }
 
@@ -771,6 +813,9 @@ f32 find_poison_gas_level(f32 x, f32 z) {
     f32 loX, hiX, loZ, hiZ;
     f32 gasLevel = FLOOR_LOWER_LIMIT;
     s16 *p = gEnvironmentRegions;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     if (p != NULL) {
         numRegions = *p++;
@@ -797,6 +842,10 @@ f32 find_poison_gas_level(f32 x, f32 z) {
         }
     }
 
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
+
     return gasLevel;
 }
 

src/engine/surface_load.c

@@ -14,6 +14,7 @@
 #include "game/mario.h"
 #include "game/object_list_processor.h"
 #include "surface_load.h"
+#include "game/puppyprint.h"
 
 #include "config.h"
 
@@ -617,6 +618,9 @@ void load_area_terrain(s16 index, s16 *data, s8 *surfaceRooms, s16 *macroObjects
     s16 terrainLoadType;
     s16 *vertexData = NULL;
     UNUSED s32 unused;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     // Initialize the data for this.
     gEnvironmentRegions = NULL;
@@ -665,6 +669,9 @@ void load_area_terrain(s16 index, s16 *data, s8 *surfaceRooms, s16 *macroObjects
 
     gNumStaticSurfaceNodes = gSurfaceNodesAllocated;
     gNumStaticSurfaces = gSurfacesAllocated;
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
 }
 
 /**
@@ -796,6 +803,9 @@ void load_object_surfaces(s16 **data, s16 *vertexData) {
 void load_object_collision_model(void) {
     UNUSED s32 unused;
     s16 vertexData[600];
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     s16 *collisionData = gCurrentObject->collisionData;
     f32 marioDist = gCurrentObject->oDistanceToMario;
@@ -830,4 +840,7 @@ void load_object_collision_model(void) {
     } else {
         gCurrentObject->header.gfx.node.flags &= ~GRAPH_RENDER_ACTIVE;
     }
+    #ifdef PUPPYPRINT
+    collisionTime[perfIteration] += osGetTime()-first;
+    #endif
 }

src/game/area.c

@@ -23,6 +23,7 @@
 #include "save_file.h"
 #include "level_table.h"
 #include "dialog_ids.h"
+#include "puppyprint.h"
 
 struct SpawnInfo gPlayerSpawnInfos[1];
 struct GraphNode *gGraphNodePointers[MODEL_ID_COUNT];
@@ -413,6 +414,11 @@ void render_game(void) {
         }
     }
 
+
+    #ifdef PUPPYPRINT
+    puppyprint_render_profiler();
+    #endif
+
     D_8032CE74 = NULL;
     D_8032CE78 = NULL;
 }

src/game/game_init.c

@@ -29,6 +29,7 @@
 #ifdef SRAM
 #include "sram.h"
 #endif
+#include "puppyprint.h"
 #include <prevent_bss_reordering.h>
 
 // First 3 controller slots
@@ -421,6 +422,7 @@ void display_and_vsync(void) {
         gBorderHeight = BORDER_HEIGHT_CONSOLE;
     }
     profiler_log_thread5_time(BEFORE_DISPLAY_LISTS);
+    //gIsConsole = (IO_READ(DPC_PIPEBUSY_REG));
     osRecvMesg(&gGfxVblankQueue, &gMainReceivedMesg, OS_MESG_BLOCK);
     if (gGoddardVblankCallback != NULL) {
         gGoddardVblankCallback();
@@ -709,6 +711,9 @@ void setup_game_memory(void) {
  */
 void thread5_game_loop(UNUSED void *arg) {
     struct LevelCommand *addr;
+    #ifdef PUPPYPRINT
+    OSTime lastTime = 0;
+    #endif
 
     setup_game_memory();
 #if ENABLE_RUMBLE
@@ -742,6 +747,14 @@ void thread5_game_loop(UNUSED void *arg) {
             continue;
         }
         profiler_log_thread5_time(THREAD5_START);
+        #ifdef PUPPYPRINT
+        while (TRUE)
+        {
+            lastTime = osGetTime();
+            collisionTime[perfIteration] = 0;
+            behaviourTime[perfIteration] = 0;
+            dmaTime[perfIteration] = 0;
+        #endif
 
         // If any controllers are plugged in, start read the data for when
         // read_controller_inputs is called later.
@@ -756,6 +769,23 @@ void thread5_game_loop(UNUSED void *arg) {
         select_gfx_pool();
         read_controller_inputs();
         addr = level_script_execute(addr);
+        #ifdef PUPPYPRINT
+        profiler_update(scriptTime, lastTime);
+            if (benchmarkLoop > 0 && benchOption == 0)
+            {
+                benchmarkLoop--;
+                benchMark[benchmarkLoop] = osGetTime() - lastTime;
+                if (benchmarkLoop == 0)
+                {
+                    puppyprint_profiler_finished();
+                    break;
+                }
+            }
+            else
+                break;
+        }
+        puppyprint_profiler_process();
+        #endif
 
         display_and_vsync();
 

src/game/hud.c

@@ -14,6 +14,7 @@
 #include "save_file.h"
 #include "print.h"
 #include "engine/surface_load.h"
+#include "puppyprint.h"
 
 #include "config.h"
 
@@ -53,8 +54,12 @@ void print_fps(s32 x, s32 y)
     char text[14];
 
     sprintf(text, "FPS %2.2f", fps);
-
+    #ifdef PUPPYPRINT
+    print_small_text(x, y, text, PRINT_TEXT_ALIGN_LEFT, PRINT_ALL);
+    #else
     print_text(x, y, text);
+    #endif
+
 }
 
 // ------------ END OF FPS COUNER -----------------
@@ -540,5 +545,8 @@ void render_hud(void) {
             render_debug_mode();
         }
     #endif
+    #ifdef PUPPYPRINT
+    print_set_envcolour(255,255,255,255);
+    #endif
     }
 }

src/game/main.c

@@ -18,6 +18,7 @@
 #include "usb/usb.h"
 #include "usb/debug.h"
 #endif
+#include "puppyprint.h"
 
 // Message IDs
 #define MESG_SP_COMPLETE 100
@@ -188,6 +189,9 @@ void start_gfx_sptask(void) {
     if (gActiveSPTask == NULL && sCurrentDisplaySPTask != NULL
         && sCurrentDisplaySPTask->state == SPTASK_STATE_NOT_STARTED) {
         profiler_log_gfx_time(TASKS_QUEUED);
+        #ifdef PUPPYPRINT
+        rspDelta = osGetTime();
+        #endif
         start_sptask(M_GFXTASK);
     }
 }
@@ -233,6 +237,9 @@ void handle_vblank(void) {
         if (gActiveSPTask == NULL && sCurrentDisplaySPTask != NULL
             && sCurrentDisplaySPTask->state != SPTASK_STATE_FINISHED) {
             profiler_log_gfx_time(TASKS_QUEUED);
+            #ifdef PUPPYPRINT
+            rspDelta = osGetTime();
+            #endif
             start_sptask(M_GFXTASK);
         }
     }
@@ -265,6 +272,9 @@ void handle_sp_complete(void) {
             // The gfx task completed before we had time to interrupt it.
             // Mark it finished, just like below.
             curSPTask->state = SPTASK_STATE_FINISHED;
+            #ifdef PUPPYPRINT
+            profiler_update(rspGenTime, rspDelta);
+            #endif
             profiler_log_gfx_time(RSP_COMPLETE);
         }
 
@@ -295,6 +305,9 @@ void handle_sp_complete(void) {
             // The SP process is done, but there is still a Display Processor notification
             // that needs to arrive before we can consider the task completely finished and
             // null out sCurrentDisplaySPTask. That happens in handle_dp_complete.
+            #ifdef PUPPYPRINT
+            profiler_update(rspGenTime, rspDelta);
+            #endif
             profiler_log_gfx_time(RSP_COMPLETE);
         }
     }

src/game/memory.c

@@ -21,6 +21,7 @@
 #include "usb/usb.h"
 #include "usb/debug.h"
 #endif
+#include "puppyprint.h"
 
 
 // round up to the next multiple
@@ -134,6 +135,9 @@ void main_pool_init(void *start, void *end) {
     sPoolListHeadL->next = NULL;
     sPoolListHeadR->prev = NULL;
     sPoolListHeadR->next = NULL;
+    #ifdef PUPPYPRINT
+    mempool = sPoolFreeSpace;
+    #endif
 }
 
 /**
@@ -256,6 +260,9 @@ u32 main_pool_pop_state(void) {
  */
 void dma_read(u8 *dest, u8 *srcStart, u8 *srcEnd) {
     u32 size = ALIGN16(srcEnd - srcStart);
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     osInvalDCache(dest, size);
     while (size != 0) {
@@ -269,6 +276,9 @@ void dma_read(u8 *dest, u8 *srcStart, u8 *srcEnd) {
         srcStart += copySize;
         size -= copySize;
     }
+    #ifdef PUPPYPRINT
+    dmaTime[perfIteration] += osGetTime()-first;
+    #endif
 }
 
 /**
@@ -293,6 +303,9 @@ static void *dynamic_dma_read(u8 *srcStart, u8 *srcEnd, u32 side) {
  */
 void *load_segment(s32 segment, u8 *srcStart, u8 *srcEnd, u32 side) {
     void *addr = dynamic_dma_read(srcStart, srcEnd, side);
+    #ifdef PUPPYPRINT
+    ramsizeSegment[segment+nameTable-2] = (s32)srcEnd- (s32)srcStart;
+    #endif
 
     if (addr != NULL) {
         set_segment_base_addr(segment, addr);
@@ -374,6 +387,9 @@ void *load_segment_decompress(s32 segment, u8 *srcStart, u8 *srcEnd) {
         }
     } else {
     }
+    #ifdef PUPPYPRINT
+    ramsizeSegment[segment+nameTable-2] = (s32)srcEnd - (s32)srcStart;
+    #endif
     return dest;
 }
 

src/game/object_list_processor.c

@@ -19,6 +19,7 @@
 #include "platform_displacement.h"
 #include "profiler.h"
 #include "spawn_object.h"
+#include "puppyprint.h"
 
 
 /**
@@ -625,6 +626,10 @@ UNUSED static u16 unused_get_elapsed_time(u64 *cycleCounts, s32 index) {
  */
 void update_objects(UNUSED s32 unused) {
     s64 cycleCounts[30];
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    OSTime colTime = collisionTime[perfIteration];
+    #endif
 
     cycleCounts[0] = get_current_clock();
 
@@ -683,4 +688,8 @@ void update_objects(UNUSED s32 unused) {
     }
 
     gPrevFrameObjectCount = gObjectCounter;
+    #ifdef PUPPYPRINT
+    profiler_update(behaviourTime, first);
+    behaviourTime[perfIteration] -= collisionTime[perfIteration]+colTime;
+    #endif
 }

src/game/puppyprint.h

@@ -0,0 +1,72 @@
+#ifndef PUPPYPRINT_H
+#define PUPPYPRINT_H
+
+#ifdef PUPPYPRINT
+
+//This is how many indexes of timers are saved at once. higher creates a smoother average, but naturally uses more RAM. 15's fine.
+#define NUM_PERF_ITERATIONS 15
+#define NUM_BENCH_ITERATIONS 150
+
+#define BENCHMARK_GAME 1
+#define BENCHMARK_AUDIO 2
+#define BENCHMARK_GRAPHICS 3
+
+#define PRINT_TEXT_ALIGN_LEFT 0
+#define PRINT_TEXT_ALIGN_CENTRE 1
+#define PRINT_TEXT_ALIGN_RIGHT 2
+#define PRINT_ALL -1
+
+extern Texture small_font[];
+extern s8 perfIteration;
+extern s16 benchmarkLoop;
+extern s32 benchmarkTimer;
+extern u8 currEnv[4];
+extern s32 ramsizeSegment[33];
+extern s32 audioPool[12];
+extern s8 nameTable;
+extern s32 mempool;
+extern u8 benchOption;
+
+//General
+extern OSTime cpuTime;
+extern OSTime rspTime;
+extern OSTime rdpTime;
+extern OSTime ramTime;
+extern OSTime loadTime;
+extern OSTime rspDelta;
+extern s32 benchMark[NUM_BENCH_ITERATIONS+2];
+
+//CPU
+extern OSTime collisionTime[NUM_PERF_ITERATIONS+1];
+extern OSTime behaviourTime[NUM_PERF_ITERATIONS+1];
+extern OSTime scriptTime[NUM_PERF_ITERATIONS+1];
+extern OSTime graphTime[NUM_PERF_ITERATIONS+1];
+extern OSTime audioTime[NUM_PERF_ITERATIONS+1];
+extern OSTime dmaTime[NUM_PERF_ITERATIONS+1];
+extern OSTime dmaAudioTime[NUM_PERF_ITERATIONS+1];
+//RSP
+extern OSTime rspGenTime[NUM_PERF_ITERATIONS+1];
+//RDP
+extern OSTime bufferTime[NUM_PERF_ITERATIONS+1];
+extern OSTime tmemTime[NUM_PERF_ITERATIONS+1];
+extern OSTime busTime[NUM_PERF_ITERATIONS+1];
+
+extern void profiler_update(OSTime *time, OSTime time2);
+extern void puppyprint_profiler_process(void);
+extern void puppyprint_render_profiler(void);
+extern void puppyprint_profiler_finished(void);
+extern void print_set_envcolour(s32 r, s32 g, s32 b, s32 a);
+extern void prepare_blank_box(void);
+extern void finish_blank_box(void);
+extern void render_blank_box(s16 x1, s16 y1, s16 x2, s16 y2, u8 r, u8 g, u8 b, u8 a);
+extern void print_small_text(s32 x, s32 y, const char *str, s32 align, s32 amount);
+extern void render_multi_image(Texture *image, s32 x, s32 y, s32 width, s32 height, s32 scaleX, s32 scaleY, s32 mode);
+extern s32 get_text_height(const char *str);
+extern s32 get_text_width(const char *str);
+extern void prepare_blank_box(void);
+extern void finish_blank_box(void);
+extern void render_blank_box(s16 x1, s16 y1, s16 x2, s16 y2, u8 r, u8 g, u8 b, u8 a);
+
+#endif
+
+#endif // PUPPYPRINT_H

src/game/rendering_graph_node.c

@@ -12,6 +12,7 @@
 #include "sm64.h"
 #include "game_init.h"
 #include "engine/extended_bounds.h"
+#include "puppyprint.h"
 
 #include "config.h"
 
@@ -1107,6 +1108,9 @@ void geo_process_node_and_siblings(struct GraphNode *firstNode) {
  */
 void geo_process_root(struct GraphNodeRoot *node, Vp *b, Vp *c, s32 clearColor) {
     UNUSED s32 unused;
+    #ifdef PUPPYPRINT
+    OSTime first = osGetTime();
+    #endif
 
     if (node->node.flags & GRAPH_RENDER_ACTIVE) {
         Mtx *initialMatrix;
@@ -1147,4 +1151,7 @@ void geo_process_root(struct GraphNodeRoot *node, Vp *b, Vp *c, s32 clearColor)
         }
         main_pool_free(gDisplayListHeap);
     }
+    #ifdef PUPPYPRINT
+    profiler_update(graphTime, first);
+    #endif
 }

src/game/sound_init.c

@@ -15,6 +15,7 @@
 #include "sm64.h"
 #include "sound_init.h"
 #include "rumble_init.h"
+#include "puppyprint.h"
 
 #define MUSIC_NONE 0xFFFF
 
@@ -335,6 +336,9 @@ void audio_game_loop_tick(void) {
 void thread4_sound(UNUSED void *arg) {
     audio_init();
     sound_init();
+    #ifdef PUPPYPRINT
+    OSTime lastTime;
+    #endif
 
     // Zero-out unused vector
     vec3f_copy(unused80339DC0, gVec3fZero);
@@ -342,18 +346,44 @@ void thread4_sound(UNUSED void *arg) {
     osCreateMesgQueue(&sSoundMesgQueue, sSoundMesgBuf, ARRAY_COUNT(sSoundMesgBuf));
     set_vblank_handler(1, &sSoundVblankHandler, &sSoundMesgQueue, (OSMesg) 512);
 
-    while (TRUE) {
+    while (TRUE)
+    {
         OSMesg msg;
 
         osRecvMesg(&sSoundMesgQueue, &msg, OS_MESG_BLOCK);
-        if (gResetTimer < 25) {
-            struct SPTask *spTask;
-            profiler_log_thread4_time();
-            spTask = create_next_audio_frame_task(); 
-            if (spTask != NULL) {
-                dispatch_audio_sptask(spTask);
+        #ifdef PUPPYPRINT
+        while (TRUE)
+        {
+            lastTime = osGetTime();
+            dmaAudioTime[perfIteration] = 0;
+            #endif
+            if (gResetTimer < 25) {
+                struct SPTask *spTask;
+                profiler_log_thread4_time();
+                spTask = create_next_audio_frame_task();
+                if (spTask != NULL) {
+                    dispatch_audio_sptask(spTask);
+                }
+                profiler_log_thread4_time();
+                #ifdef PUPPYPRINT
+                profiler_update(audioTime, lastTime);
+                audioTime[perfIteration] -= dmaAudioTime[perfIteration];
+                if (benchmarkLoop > 0 && benchOption == 1)
+                {
+                    benchmarkLoop--;
+                    benchMark[benchmarkLoop] = osGetTime() - lastTime;
+                    if (benchmarkLoop == 0)
+                    {
+                        puppyprint_profiler_finished();
+                        break;
+                    }
+                }
+                else
+                    break;
+                #endif
             }
-            profiler_log_thread4_time();
+        #ifdef PUPPYPRINT
         }
+        #endif
     }
 }