Add a perf timing/stack module and start using it to diagnose PSP hitching

New src/dusk/perf module: a simple push/pop tick-stack (perfPush/perfPop/
perfReport) for measuring how long a labeled span of code takes, wired
into engine.c's init/dispose. perfGetTick() is a placeholder - real time
on DUSK_LINUX (clock_gettime) and DUSK_PSP (sceKernelGetSystemTimeWide),
0 elsewhere until a proper cross-platform answer is settled on.

Used it this session to chase a reported PSP hitch when crossing a chunk
boundary. Confirmed mapPositionSet itself (unload/load sweeps, chunk
order rebuild, entity chunkIndex recompute) is consistently under ~3ms -
not the cause. Along the way, found and fixed a real, unrelated bug:
logDebug()/logError() on PSP did a fopen+write+fclose to the Memory
Stick on every single call, which was massively inflating any perf
measurement that logged from inside another measurement (the actual
source of the ~29-128ms numbers first seen). That's now gated behind a
new DUSK_PSP_LOG_FILE CMake option (default off).

Also, as a real test based on this session's findings:
- MAP_CHUNK_LOAD_CONCURRENCY dropped from 2 to 1 (8 and 4 both crashed/
  were untested further on real PSP hardware; 1 is confirmed safe).
- MAP_CHUNK_LOAD_DELAY_TEST: an intentionally exaggerated (now 50ms)
  artificial delay between starting successive chunk loads, gated in
  mapChunkLoadNext/mapUpdate, to observe the effect on framerate.

All perf instrumentation call sites added during this investigation
(assetChunkLoaderSync, assetMeshLoaderSync, mapPositionSet, the map area
callback invocation, engine.c's frame boundary) were removed again once
they'd served their purpose - only the reusable perf module itself and
the two real fixes above remain.

Co-Authored-By: Claude Sonnet 5 <[email protected]>

cmake/targets/psp.cmake

@@ -60,6 +60,19 @@ target_compile_definitions(${DUSK_BINARY_TARGET_NAME} PUBLIC
   DUSK_DISPLAY_OVERSCAN=6
 )
 
+# logDebug()/logError() additionally write every call to a file on the
+# Memory Stick (ms0:/PSP/GAME/Dusk/*.log) - a real, measured source of
+# per-call hitching (fopen+write+fclose every log line), not just a
+# theoretical cost. Default off so a normal build doesn't pay it; opt in
+# with -DDUSK_PSP_LOG_FILE=ON when the log file itself is actually needed
+# (e.g. no way to see stdout on real hardware).
+set(DUSK_PSP_LOG_FILE OFF CACHE BOOL "Also write PSP debug/error logs to ms0:/PSP/GAME/Dusk/*.log (slow - Memory Stick I/O per call).")
+if(DUSK_PSP_LOG_FILE)
+  target_compile_definitions(${DUSK_BINARY_TARGET_NAME} PUBLIC
+    DUSK_PSP_LOG_FILE
+  )
+endif()
+
 if(NOT CMAKE_BUILD_TYPE STREQUAL "Debug")
   target_compile_definitions(${DUSK_BINARY_TARGET_NAME} PUBLIC
     DUSK_ASSERTIONS_FAKED

src/dusk/CMakeLists.txt

@@ -74,6 +74,7 @@ add_subdirectory(engine)
 add_subdirectory(error)
 add_subdirectory(input)
 add_subdirectory(locale)
+add_subdirectory(perf)
 add_subdirectory(rpg)
 add_subdirectory(scene)
 add_subdirectory(system)

src/dusk/engine/engine.c

@@ -7,6 +7,7 @@
 
 #include "engine.h"
 #include "util/memory.h"
+#include "perf/perf.h"
 #include "time/time.h"
 #include "input/input.h"
 #include "locale/localemanager.h"
@@ -36,6 +37,7 @@ errorret_t engineInit(const int32_t argc, const char_t **argv) {
   ENGINE.version = DUSK_VERSION;
 
   // Init systems. Order is important.
+  perfInit();
   timeInit();
   consoleInit();
   errorChain(systemInit());
@@ -104,6 +106,7 @@ errorret_t engineDispose(void) {
   errorChain(displayDispose());
   errorChain(saveDispose());
   errorChain(assetDispose());
+  perfDispose();
 
   errorOk();
 }

src/dusk/perf/CMakeLists.txt

@@ -0,0 +1,10 @@
+# Copyright (c) 2026 Dominic Masters
+#
+# This software is released under the MIT License.
+# https://opensource.org/licenses/MIT
+
+# Sources
+target_sources(${DUSK_LIBRARY_TARGET_NAME}
+  PUBLIC
+    perf.c
+)

src/dusk/perf/perf.c

@@ -0,0 +1,88 @@
+/**
+ * Copyright (c) 2026 Dominic Masters
+ *
+ * This software is released under the MIT License.
+ * https://opensource.org/licenses/MIT
+ */
+
+#include "perf.h"
+#include "assert/assert.h"
+#include "util/memory.h"
+#include "console/console.h"
+
+#if defined(DUSK_LINUX)
+  #include <time.h>
+#elif defined(DUSK_PSP)
+  #include <pspthreadman.h>
+#endif
+
+perf_t PERF;
+
+void perfInit(void) {
+  assertIsMainThread("Must be called from the main thread.");
+  memoryZero(&PERF, sizeof(perf_t));
+}
+
+void perfDispose(void) {
+  assertIsMainThread("Must be called from the main thread.");
+}
+
+uint64_t perfGetTick(void) {
+  assertIsMainThread("Must be called from the main thread.");
+
+  #if defined(DUSK_LINUX)
+    // TEST - CLOCK_MONOTONIC via clock_gettime(), Linux desktop only for
+    // now. Not a cross-platform answer yet (see perfGetTick's doc
+    // comment in perf.h) - just something real to look at while that
+    // gets settled. Returns nanoseconds since some unspecified starting
+    // point, so only differences between two calls are meaningful.
+    struct timespec ts;
+    clock_gettime(CLOCK_MONOTONIC, &ts);
+    return (uint64_t)ts.tv_sec * 1000000000ull + (uint64_t)ts.tv_nsec;
+  #elif defined(DUSK_PSP)
+    // TEST - sceKernelGetSystemTimeWide(), microseconds since boot at
+    // ~1us resolution (the standard PSP homebrew idiom for elapsed-time
+    // measurement - psprtc.h's sceRtcGetCurrentTick is for wall-clock
+    // date/time instead, already used by timepsp.c for that purpose).
+    // Scaled to nanoseconds to match every other platform's tick unit.
+    return (uint64_t)sceKernelGetSystemTimeWide() * 1000ull;
+  #else
+    return 0;
+  #endif
+}
+
+void perfPushItem(
+  const char_t *label, const char_t *file, const int32_t line
+) {
+  assertIsMainThread("Must be called from the main thread.");
+  assertNotNull(label, "Perf item label cannot be NULL.");
+  assertNotNull(file, "Perf item file cannot be NULL.");
+  assertTrue(PERF.stackSize < PERF_STACK_SIZE, "Perf stack overflow.");
+
+  PERF.stack[PERF.stackSize++] = (perfitem_t){
+    .label = label,
+    .file = file,
+    .line = line,
+    .tick = perfGetTick()
+  };
+}
+
+void perfPopItem(void) {
+  assertIsMainThread("Must be called from the main thread.");
+  assertTrue(PERF.stackSize > 0, "Perf stack underflow.");
+  PERF.stackSize--;
+}
+
+void perfReport(void) {
+  assertIsMainThread("Must be called from the main thread.");
+
+  if(PERF.stackSize == 0) return;
+
+  const perfitem_t *item = &PERF.stack[PERF.stackSize - 1];
+  uint64_t elapsedNs = perfGetTick() - item->tick;
+  double_t elapsedMs = (double_t)elapsedNs / 1000000.0;
+  consolePrint(
+    "perf: %s (%s:%d, %.4fms)",
+    item->label, item->file, item->line, elapsedMs
+  );
+}

src/dusk/perf/perf.h

@@ -0,0 +1,89 @@
+/**
+ * Copyright (c) 2026 Dominic Masters
+ *
+ * This software is released under the MIT License.
+ * https://opensource.org/licenses/MIT
+ */
+
+#pragma once
+#include "perfitem.h"
+
+#define PERF_STACK_SIZE 256
+
+typedef struct {
+  perfitem_t stack[PERF_STACK_SIZE];
+  uint32_t stackSize;
+} perf_t;
+
+extern perf_t PERF;
+
+/**
+ * Initializes the perf system.
+ */
+void perfInit(void);
+
+/**
+ * Disposes/cleans up the perf system. Currently a no-op - here so
+ * engine.c has a symmetric call to make once this needs real cleanup.
+ */
+void perfDispose(void);
+
+/**
+ * Returns a tick value representing "now", for measuring the duration
+ * between a perfPush/perfPushItem and its matching perfPopItem. Always
+ * nanoseconds since some unspecified starting point, on every platform
+ * that implements it, so perfReport's ms conversion stays correct
+ * everywhere without per-platform special-casing.
+ *
+ * PLACEHOLDER - currently only reads a real value on DUSK_LINUX desktop
+ * builds (via clock_gettime(CLOCK_MONOTONIC)) and DUSK_PSP (via
+ * sceKernelGetSystemTimeWide(), scaled from microseconds), as a test;
+ * every other platform still gets a meaningless 0. A common,
+ * cross-platform way of reading CPU cycles/time hasn't been settled on
+ * yet - don't treat results as comparable across platforms until this is
+ * replaced with a real per-platform implementation. Only the difference
+ * between two calls is meaningful, never the raw value itself.
+ *
+ * @return A tick value, in nanoseconds. 0 on unimplemented platforms.
+ */
+uint64_t perfGetTick(void);
+
+/**
+ * Pushes a new item onto the perf stack, capturing the current tick (see
+ * perfGetTick) as its start time. Prefer the perfPush() macro, which
+ * supplies file/line automatically.
+ *
+ * @param label Short caller-supplied memo of what this item represents
+ *   (e.g. "frame start") - stored by pointer, not copied, so pass a
+ *   string literal or something that otherwise outlives the push.
+ * @param file Source file the push originated from (e.g. __FILE__).
+ * @param line Source line the push originated from (e.g. __LINE__).
+ */
+void perfPushItem(
+  const char_t *label, const char_t *file, const int32_t line
+);
+
+/**
+ * Pops the most recently pushed perf item off the stack.
+ */
+void perfPopItem(void);
+
+/**
+ * Reports on the item currently at the top of the perf stack (the most
+ * recently pushed one still awaiting its perfPopItem), if any.
+ */
+void perfReport(void);
+
+/**
+ * Pushes a new perf item onto the stack, tagged with the call site this
+ * macro is expanded at.
+ *
+ * @param label Short memo of what this item represents (e.g. "frame
+ *   start") - see perfPushItem.
+ */
+#define perfPush(label) perfPushItem(label, __FILE__, __LINE__)
+
+/**
+ * Pops the most recently pushed perf item off the stack.
+ */
+#define perfPop() perfPopItem()

src/dusk/perf/perfitem.h

@@ -0,0 +1,16 @@
+/**
+ * Copyright (c) 2026 Dominic Masters
+ * 
+ * This software is released under the MIT License.
+ * https://opensource.org/licenses/MIT
+ */
+
+#pragma once
+#include "dusk.h"
+
+typedef struct {
+  const char_t *label;
+  int32_t line;
+  const char_t *file;
+  uint64_t tick;
+} perfitem_t;

src/dusk/rpg/overworld/map.c

@@ -16,6 +16,7 @@
 #include "rpg/entity/item/entityitem.h"
 #include "rpg/overworld/maparea.h"
 #include "save/save.h"
+#include "time/time.h"
 
 map_t MAP;
 
@@ -144,6 +145,15 @@ errorret_t mapPositionSet(const chunkpos_t newPos) {
 }
 
 errorret_t mapUpdate() {
+  // TEST ONLY - see MAP_CHUNK_LOAD_DELAY_TEST.
+  if(MAP.chunkLoadCooldown > 0.0f) {
+    MAP.chunkLoadCooldown -= TIME.delta;
+    if(MAP.chunkLoadCooldown <= 0.0f) {
+      MAP.chunkLoadCooldown = 0.0f;
+      mapChunkLoadNext();
+    }
+  }
+
   errorOk();
 }
 
@@ -251,6 +261,11 @@ errorret_t mapChunkLoad(chunk_t *chunk) {
 }
 
 void mapChunkLoadNext() {
+  // TEST ONLY - see MAP_CHUNK_LOAD_DELAY_TEST. Skip starting anything new
+  // until the cooldown set by the last load we started has expired;
+  // mapUpdate() ticks it down and retries this once it hits zero.
+  if(MAP.chunkLoadCooldown > 0.0f) return;
+
   for(uint32_t slot = 0; slot < MAP_CHUNK_LOAD_CONCURRENCY; slot++) {
     if(MAP.loadingChunks[slot] != NULL) continue;
     if(MAP.loadQueueCount == 0) return;
@@ -261,6 +276,7 @@ void mapChunkLoadNext() {
     }
     MAP.loadQueueCount--;
     MAP.loadingChunks[slot] = chunk;
+    MAP.chunkLoadCooldown = MAP_CHUNK_LOAD_DELAY_TEST;
 
     char_t name[MAP_FILE_PATH_MAX];
     stringFormat(

src/dusk/rpg/overworld/map.h

@@ -20,6 +20,11 @@
 // onError) at the same time - everything past this waits in loadQueue.
 #define MAP_CHUNK_LOAD_CONCURRENCY 1
 
+// TEST ONLY - deliberately exaggerated delay (seconds) enforced between
+// starting one chunk load and starting the next, to observe its effect on
+// framerate. See MAP.chunkLoadCooldown / mapChunkLoadNext.
+#define MAP_CHUNK_LOAD_DELAY_TEST 0.05f
+
 typedef struct map_s {
   // Name of the currently loaded map, or an empty string if none is
   // loaded (see mapIsLoaded).
@@ -32,6 +37,10 @@ typedef struct map_s {
   chunk_t *loadQueue[MAP_CHUNK_COUNT];
   uint32_t loadQueueCount;
   chunk_t *loadingChunks[MAP_CHUNK_LOAD_CONCURRENCY];
+
+  // TEST ONLY - seconds remaining before mapChunkLoadNext is allowed to
+  // start another chunk load. See MAP_CHUNK_LOAD_DELAY_TEST.
+  float_t chunkLoadCooldown;
 } map_t;
 
 extern map_t MAP;

src/duskpsp/log/log.c

@@ -17,14 +17,17 @@ void logDebug(const char_t *message, ...) {
   vprintf(message, copy);
   va_end(copy);
 
-  // print to file
+  #ifdef DUSK_PSP_LOG_FILE
-  FILE *file = fopen("ms0:/PSP/GAME/Dusk/debug.log", "a");
+    // print to file - fopen+fclose every call is real, measured Memory
-  if(file) {
+    // Stick I/O cost (this is why the flag exists - see psp.cmake).
-      va_copy(copy, args);
+    FILE *file = fopen("ms0:/PSP/GAME/Dusk/debug.log", "a");
-      vfprintf(file, message, copy);
+    if(file) {
-      va_end(copy);
+        va_copy(copy, args);
-      fclose(file);
+        vfprintf(file, message, copy);
-  }
+        va_end(copy);
+        fclose(file);
+    }
+  #endif
 
   va_end(args);
 }
@@ -39,14 +42,17 @@ void logError(const char_t *message, ...) {
   vfprintf(stderr, message, copy);
   va_end(copy);
 
-  // print to file
+  #ifdef DUSK_PSP_LOG_FILE
-  FILE *file = fopen("ms0:/PSP/GAME/Dusk/error.log", "a");
+    // print to file - fopen+fclose every call is real, measured Memory
-  if(file) {
+    // Stick I/O cost (this is why the flag exists - see psp.cmake).
-      va_copy(copy, args);
+    FILE *file = fopen("ms0:/PSP/GAME/Dusk/error.log", "a");
-      vfprintf(file, message, copy);
+    if(file) {
-      va_end(copy);
+        va_copy(copy, args);
-      fclose(file);
+        vfprintf(file, message, copy);
-  }
+        va_end(copy);
+        fclose(file);
+    }
+  #endif
 
   va_end(args);
 }