diff --git a/cmake/targets/psp.cmake b/cmake/targets/psp.cmake index ea0c8076..68f5fec5 100644 --- a/cmake/targets/psp.cmake +++ b/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 diff --git a/src/dusk/CMakeLists.txt b/src/dusk/CMakeLists.txt index b1b7a22c..a801be9a 100644 --- a/src/dusk/CMakeLists.txt +++ b/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) diff --git a/src/dusk/engine/engine.c b/src/dusk/engine/engine.c index 0ab81ad3..fa640248 100644 --- a/src/dusk/engine/engine.c +++ b/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(); } diff --git a/src/dusk/perf/CMakeLists.txt b/src/dusk/perf/CMakeLists.txt new file mode 100644 index 00000000..bc198e9e --- /dev/null +++ b/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 +) diff --git a/src/dusk/perf/perf.c b/src/dusk/perf/perf.c new file mode 100644 index 00000000..1b83095f --- /dev/null +++ b/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 +#elif defined(DUSK_PSP) + #include +#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 + ); +} diff --git a/src/dusk/perf/perf.h b/src/dusk/perf/perf.h new file mode 100644 index 00000000..82619a2f --- /dev/null +++ b/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() diff --git a/src/dusk/perf/perfitem.h b/src/dusk/perf/perfitem.h new file mode 100644 index 00000000..c9975758 --- /dev/null +++ b/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; \ No newline at end of file diff --git a/src/dusk/rpg/overworld/map.c b/src/dusk/rpg/overworld/map.c index c22dfc8d..78252261 100644 --- a/src/dusk/rpg/overworld/map.c +++ b/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( diff --git a/src/dusk/rpg/overworld/map.h b/src/dusk/rpg/overworld/map.h index d2eecc97..93b70057 100644 --- a/src/dusk/rpg/overworld/map.h +++ b/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; diff --git a/src/duskpsp/log/log.c b/src/duskpsp/log/log.c index 040f0be7..3d8b0d1c 100644 --- a/src/duskpsp/log/log.c +++ b/src/duskpsp/log/log.c @@ -17,14 +17,17 @@ void logDebug(const char_t *message, ...) { vprintf(message, copy); va_end(copy); - // print to file - FILE *file = fopen("ms0:/PSP/GAME/Dusk/debug.log", "a"); - if(file) { - va_copy(copy, args); - vfprintf(file, message, copy); - va_end(copy); - fclose(file); - } + #ifdef DUSK_PSP_LOG_FILE + // print to file - fopen+fclose every call is real, measured Memory + // Stick I/O cost (this is why the flag exists - see psp.cmake). + FILE *file = fopen("ms0:/PSP/GAME/Dusk/debug.log", "a"); + if(file) { + va_copy(copy, args); + 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 - FILE *file = fopen("ms0:/PSP/GAME/Dusk/error.log", "a"); - if(file) { - va_copy(copy, args); - vfprintf(file, message, copy); - va_end(copy); - fclose(file); - } + #ifdef DUSK_PSP_LOG_FILE + // print to file - fopen+fclose every call is real, measured Memory + // Stick I/O cost (this is why the flag exists - see psp.cmake). + FILE *file = fopen("ms0:/PSP/GAME/Dusk/error.log", "a"); + if(file) { + va_copy(copy, args); + vfprintf(file, message, copy); + va_end(copy); + fclose(file); + } + #endif va_end(args); } \ No newline at end of file