Doc speed_meter timers and misc. low-ish level stuff (#1364)

* Misc docs (somewhat lower level)

* Run formatter

* Simplify comment

* `a = a +` -> `a +=` with pad removal

Co-authored-by: Roman971 <32455037+Roman971@users.noreply.github.com>

* `isPreNMIStateRunning` -> `inPreNMIState`

* line breaks

Co-authored-by: Roman971 <32455037+Roman971@users.noreply.github.com>
Co-authored-by: fig02 <fig02srl@gmail.com>

6 files changed, 135 insertions, 75 deletions

diff --git a/src/code/audioMgr.c b/src/code/audioMgr.c
index 840b25490..f3701acc2 100644
--- a/src/code/audioMgr.c
+++ b/src/code/audioMgr.c
@@ -27,14 +27,15 @@ void AudioMgr_HandleRetrace(AudioMgr* audioMgr) {
         Sched_Notify(audioMgr->sched);
     }
 
-    D_8016A550 = osGetTime();
+    gAudioThreadUpdateTimeStart = osGetTime();
     if (SREG(20) >= 2) {
         rspTask = NULL;
     } else {
         rspTask = func_800E4FE0();
     }
-    D_8016A558 += osGetTime() - D_8016A550;
-    D_8016A550 = 0;
+    gAudioThreadUpdateTimeAcc += osGetTime() - gAudioThreadUpdateTimeStart;
+    gAudioThreadUpdateTimeStart = 0;
+
     if (audioMgr->rspTask != NULL) {
         osRecvMesg(&audioMgr->taskQueue, NULL, OS_MESG_BLOCK);
         func_800C3C80(audioMgr);
diff --git a/src/code/graph.c b/src/code/graph.c
index c7bd56756..ac0ffbdfe 100644
--- a/src/code/graph.c
+++ b/src/code/graph.c
@@ -4,8 +4,16 @@
 #define GFXPOOL_HEAD_MAGIC 0x1234
 #define GFXPOOL_TAIL_MAGIC 0x5678
 
-OSTime sGraphUpdateTime;
-OSTime sGraphSetTaskTime;
+/**
+ * The time at which the previous `Graph_Update` ended.
+ */
+OSTime sGraphPrevUpdateEndTime;
+
+/**
+ * The time at which the previous graphics task was scheduled to run.
+ */
+OSTime sGraphPrevTaskTimeStart;
+
 FaultClient sGraphFaultClient;
 CfbInfo sGraphCfbInfos[3];
 FaultClient sGraphUcodeFaultClient;
@@ -144,18 +152,18 @@ void Graph_Destroy(GraphicsContext* gfxCtx) {
 }
 
 void Graph_TaskSet00(GraphicsContext* gfxCtx) {
-    static Gfx* D_8012D260 = NULL;
+    static Gfx* sPrevTaskWorkBuffer = NULL;
     static s32 sGraphCfbInfoIdx = 0;
 
-    OSTime time;
+    OSTime timeNow;
     OSTimer timer;
     OSMesg msg;
     OSTask_t* task = &gfxCtx->task.list.t;
     OSScTask* scTask = &gfxCtx->task;
     CfbInfo* cfb;
-    s32 pad1;
 
-    D_8016A528 = osGetTime() - sGraphSetTaskTime - D_8016A558;
+    gGfxTaskSentToNextReadyMinusAudioThreadUpdateTime =
+        osGetTime() - sGraphPrevTaskTimeStart - gAudioThreadUpdateTimeAcc;
 
     osSetTimer(&timer, OS_USEC_TO_CYCLES(3000000), 0, &gfxCtx->queue, (OSMesg)666);
 
@@ -166,36 +174,41 @@ void Graph_TaskSet00(GraphicsContext* gfxCtx) {
         osSyncPrintf(VT_FGCOL(RED));
         osSyncPrintf("RCPが帰ってきませんでした。"); // "RCP did not return."
         osSyncPrintf(VT_RST);
+
         LogUtils_LogHexDump((void*)&HW_REG(SP_MEM_ADDR_REG, u32), 0x20);
         LogUtils_LogHexDump((void*)&DPC_START_REG, 0x20);
         LogUtils_LogHexDump(gGfxSPTaskYieldBuffer, sizeof(gGfxSPTaskYieldBuffer));
 
         SREG(6) = -1;
-        if (D_8012D260 != NULL) {
+        if (sPrevTaskWorkBuffer != NULL) {
             HREG(80) = 7;
             HREG(81) = 1;
             HREG(83) = 2;
-            D_8012D260 = D_8012D260;
-            Graph_DisassembleUCode(D_8012D260);
+            sPrevTaskWorkBuffer = sPrevTaskWorkBuffer;
+            Graph_DisassembleUCode(sPrevTaskWorkBuffer);
         }
         Fault_AddHungupAndCrashImpl("RCP is HUNG UP!!", "Oh! MY GOD!!");
     }
 
     osRecvMesg(&gfxCtx->queue, &msg, OS_MESG_NOBLOCK);
 
-    D_8012D260 = gfxCtx->workBuffer;
+    sPrevTaskWorkBuffer = gfxCtx->workBuffer;
     if (gfxCtx->callback != NULL) {
         gfxCtx->callback(gfxCtx, gfxCtx->callbackParam);
     }
 
-    time = osGetTime();
-    if (D_8016A550 != 0) {
-        D_8016A558 = (D_8016A558 + time) - D_8016A550;
-        D_8016A550 = time;
+    timeNow = osGetTime();
+    if (gAudioThreadUpdateTimeStart != 0) {
+        // The audio thread update is running
+        // Add the time already spent to the accumulator and leave the rest for the next cycle
+
+        gAudioThreadUpdateTimeAcc += timeNow - gAudioThreadUpdateTimeStart;
+        gAudioThreadUpdateTimeStart = timeNow;
     }
-    D_8016A520 = D_8016A558;
-    D_8016A558 = 0;
-    sGraphSetTaskTime = osGetTime();
+    gAudioThreadUpdateTimeTotalPerGfxTask = gAudioThreadUpdateTimeAcc;
+    gAudioThreadUpdateTimeAcc = 0;
+
+    sGraphPrevTaskTimeStart = osGetTime();
 
     task->type = M_GFXTASK;
     task->flags = OS_SC_DRAM_DLIST;
@@ -242,7 +255,7 @@ void Graph_TaskSet00(GraphicsContext* gfxCtx) {
     cfb->updateRate = R_UPDATE_RATE;
 
     scTask->framebuffer = cfb;
-    sGraphCfbInfoIdx = sGraphCfbInfoIdx % ARRAY_COUNT(sGraphCfbInfos);
+    sGraphCfbInfoIdx %= ARRAY_COUNT(sGraphCfbInfos);
 
     if (1) {}
 
@@ -255,7 +268,7 @@ void Graph_TaskSet00(GraphicsContext* gfxCtx) {
 void Graph_Update(GraphicsContext* gfxCtx, GameState* gameState) {
     u32 problem;
 
-    gameState->unk_A0 = 0;
+    gameState->inPreNMIState = false;
     Graph_InitTHGA(gfxCtx);
 
     OPEN_DISPS(gfxCtx, "../graph.c", 966);
@@ -366,20 +379,20 @@ void Graph_Update(GraphicsContext* gfxCtx, GameState* gameState) {
     func_800F3054();
 
     {
-        OSTime time = osGetTime();
+        OSTime timeNow = osGetTime();
         s32 pad[4];
 
-        D_8016A538 = gRSPGFXTotalTime;
-        D_8016A530 = gRSPAudioTotalTime;
-        D_8016A540 = gRDPTotalTime;
-        gRSPGFXTotalTime = 0;
-        gRSPAudioTotalTime = 0;
-        gRDPTotalTime = 0;
+        gRSPGfxTimeTotal = gRSPGfxTimeAcc;
+        gRSPAudioTimeTotal = gRSPAudioTimeAcc;
+        gRDPTimeTotal = gRDPTimeAcc;
+        gRSPGfxTimeAcc = 0;
+        gRSPAudioTimeAcc = 0;
+        gRDPTimeAcc = 0;
 
-        if (sGraphUpdateTime != 0) {
-            D_8016A548 = time - sGraphUpdateTime;
+        if (sGraphPrevUpdateEndTime != 0) {
+            gGraphUpdatePeriod = timeNow - sGraphPrevUpdateEndTime;
         }
-        sGraphUpdateTime = time;
+        sGraphPrevUpdateEndTime = timeNow;
     }
 
     if (gIsCtrlr2Valid && CHECK_BTN_ALL(gameState->input[0].press.button, BTN_Z) &&
@@ -389,7 +402,7 @@ void Graph_Update(GraphicsContext* gfxCtx, GameState* gameState) {
         gameState->running = false;
     }
 
-    if (gIsCtrlr2Valid && PreNmiBuff_IsResetting(gAppNmiBufferPtr) && !gameState->unk_A0) {
+    if (gIsCtrlr2Valid && PreNmiBuff_IsResetting(gAppNmiBufferPtr) && !gameState->inPreNMIState) {
         // "To reset mode"
         osSyncPrintf(VT_COL(YELLOW, BLACK) "PRE-NMIによりリセットモードに移行します\n" VT_RST);
         SET_NEXT_GAMESTATE(gameState, PreNMI_Init, PreNMIState);
@@ -419,12 +432,13 @@ void Graph_ThreadEntry(void* arg0) {
 
         gameState = SystemArena_MallocDebug(size, "../graph.c", 1196);
 
-        if (!gameState) {
+        if (gameState == NULL) {
             osSyncPrintf("確保失敗\n"); // "Failure to secure"
 
             sprintf(faultMsg, "CLASS SIZE= %d bytes", size);
             Fault_AddHungupAndCrashImpl("GAME CLASS MALLOC FAILED", faultMsg);
         }
+
         GameState_Init(gameState, ovl->init, &gfxCtx);
 
         while (GameState_IsRunning(gameState)) {
diff --git a/src/code/sched.c b/src/code/sched.c
index 99ce8099f..343d0eeb8 100644
--- a/src/code/sched.c
+++ b/src/code/sched.c
@@ -47,10 +47,10 @@
 
 vs32 sLogScheduler = false;
 
-OSTime sRSPGFXStartTime;
-OSTime sRSPAudioStartTime;
-OSTime sRSPOtherStartTime;
-OSTime sRDPStartTime;
+OSTime sRSPGfxTimeStart;
+OSTime sRSPAudioTimeStart;
+OSTime sRSPOtherTimeStart;
+OSTime sRDPTimeStart;
 
 /**
  * Set the current framebuffer to the swapbuffer pointed to by the provided cfb
@@ -120,20 +120,20 @@ void Sched_HandlePreNMI(Scheduler* sc) {
         if (sc->curRSPTask->framebuffer == NULL) {
             // audio and jpeg tasks end up in here
             LOG_TIME("(((u64)(now - audio_rsp_start_time)*(1000000LL/15625LL))/((62500000LL*3/4)/15625LL))",
-                     OS_CYCLES_TO_USEC(now - sRSPAudioStartTime), "../sched.c", 421);
-        } else if (OS_CYCLES_TO_USEC(now - sRSPGFXStartTime) > 1000000 ||
-                   OS_CYCLES_TO_USEC(now - sRDPStartTime) > 1000000) {
+                     OS_CYCLES_TO_USEC(now - sRSPAudioTimeStart), "../sched.c", 421);
+        } else if (OS_CYCLES_TO_USEC(now - sRSPGfxTimeStart) > 1000000 ||
+                   OS_CYCLES_TO_USEC(now - sRDPTimeStart) > 1000000) {
             // More than 1 second since the RSP or RDP tasks began, halt the RSP and RDP
             RcpUtils_Reset();
             // Manually send RSP/RDP done messages to the scheduler interrupt queue if appropriate
             if (sc->curRSPTask != NULL) {
                 LOG_TIME("(((u64)(now - graph_rsp_start_time)*(1000000LL/15625LL))/((62500000LL*3/4)/15625LL))",
-                         OS_CYCLES_TO_USEC(now - sRSPGFXStartTime), "../sched.c", 427);
+                         OS_CYCLES_TO_USEC(now - sRSPGfxTimeStart), "../sched.c", 427);
                 osSendMesg(&sc->interruptQueue, (OSMesg)RSP_DONE_MSG, OS_MESG_NOBLOCK);
             }
             if (sc->curRDPTask != NULL) {
                 LOG_TIME("(((u64)(now - rdp_start_time)*(1000000LL/15625LL))/((62500000LL*3/4)/15625LL))",
-                         OS_CYCLES_TO_USEC(now - sRDPStartTime), "../sched.c", 431);
+                         OS_CYCLES_TO_USEC(now - sRDPTimeStart), "../sched.c", 431);
                 osSendMesg(&sc->interruptQueue, (OSMesg)RDP_DONE_MSG, OS_MESG_NOBLOCK);
             }
         }
@@ -390,11 +390,11 @@ void Sched_RunTask(Scheduler* sc, OSScTask* spTask, OSScTask* dpTask) {
 
         // Begin profiling timers
         if (spTask->list.t.type == M_AUDTASK) {
-            sRSPAudioStartTime = osGetTime();
+            sRSPAudioTimeStart = osGetTime();
         } else if (spTask->list.t.type == M_GFXTASK) {
-            sRSPGFXStartTime = osGetTime();
+            sRSPGfxTimeStart = osGetTime();
         } else {
-            sRSPOtherStartTime = osGetTime();
+            sRSPOtherTimeStart = osGetTime();
         }
 
         // Run RSP
@@ -412,7 +412,7 @@ void Sched_RunTask(Scheduler* sc, OSScTask* spTask, OSScTask* dpTask) {
         // If the task also uses the RDP, set current running RDP task
         if (spTask == dpTask && sc->curRDPTask == NULL) {
             sc->curRDPTask = dpTask;
-            sRDPStartTime = sRSPGFXStartTime;
+            sRDPTimeStart = sRSPGfxTimeStart;
         }
     }
 }
@@ -508,11 +508,11 @@ void Sched_HandleRSPDone(Scheduler* sc) {
 
     // Task profiling
     if (sc->curRSPTask->list.t.type == M_AUDTASK) {
-        gRSPAudioTotalTime += osGetTime() - sRSPAudioStartTime;
+        gRSPAudioTimeAcc += osGetTime() - sRSPAudioTimeStart;
     } else if (sc->curRSPTask->list.t.type == M_GFXTASK) {
-        gRSPGFXTotalTime += osGetTime() - sRSPGFXStartTime;
+        gRSPGfxTimeAcc += osGetTime() - sRSPGfxTimeStart;
     } else {
-        gRSPOtherTotalTime += osGetTime() - sRSPOtherStartTime;
+        gRSPOtherTimeAcc += osGetTime() - sRSPOtherTimeStart;
     }
 
     // Clear current RSP task
@@ -564,7 +564,7 @@ void Sched_HandleRDPDone(Scheduler* sc) {
     s32 state;
 
     // Task profiling
-    gRDPTotalTime = osGetTime() - sRDPStartTime;
+    gRDPTimeAcc = osGetTime() - sRDPTimeStart;
 
     // Sanity check
     ASSERT(sc->curRDPTask != NULL, "sc->curRDPTask", "../sched.c", 878);
diff --git a/src/code/speed_meter.c b/src/code/speed_meter.c
index f37a22788..84e7cb52e 100644
--- a/src/code/speed_meter.c
+++ b/src/code/speed_meter.c
@@ -1,25 +1,70 @@
 #include "global.h"
 #include "vt.h"
 
-volatile OSTime D_8016A520;
-volatile OSTime D_8016A528;
-volatile OSTime D_8016A530;
-volatile OSTime D_8016A538;
-volatile OSTime D_8016A540;
-volatile OSTime D_8016A548;
-volatile OSTime D_8016A550;
-volatile OSTime D_8016A558;
-volatile OSTime gRSPAudioTotalTime;
-volatile OSTime gRSPGFXTotalTime;
-volatile OSTime gRSPOtherTotalTime;
+/**
+ * How much time the audio update on the audio thread (`func_800E4FE0`) took in total, between scheduling the last two
+ * graphics tasks.
+ */
+volatile OSTime gAudioThreadUpdateTimeTotalPerGfxTask;
+
+/**
+ * How much time elapsed between scheduling the previous graphics task and the current one being ready (the previous
+ * task not necessarily being finished yet), without the amount of time spent on the audio update in the audio thread.
+ */
+volatile OSTime gGfxTaskSentToNextReadyMinusAudioThreadUpdateTime;
+
+/**
+ * How much time the RSP ran audio tasks for over the course of `gGraphUpdatePeriod`.
+ */
+volatile OSTime gRSPAudioTimeTotal;
+
+/**
+ * How much time the RSP ran graphics tasks for over the course of `gGraphUpdatePeriod`.
+ * Typically the RSP runs 1 graphics task per `Graph_Update` cycle, but may run 0 (see `Graph_Update`).
+ */
+volatile OSTime gRSPGfxTimeTotal;
+
+/**
+ * How much time the RDP ran for over the course of `gGraphUpdatePeriod`.
+ */
+volatile OSTime gRDPTimeTotal;
+
+/**
+ * How much time elapsed between the last two `Graph_Update` ending.
+ * This is expected to be at least the duration of a single frame, since it includes the time spent waiting on the
+ * graphics task to be done.
+ */
+volatile OSTime gGraphUpdatePeriod;
+
+/**
+ * The time at which the audio thread audio update started.
+ */
+volatile OSTime gAudioThreadUpdateTimeStart;
+
+// Accumulator for `gAudioThreadUpdateTimeStart`
+volatile OSTime gAudioThreadUpdateTimeAcc;
+
+// Accumulator for `gRSPAudioTimeTotal`
+volatile OSTime gRSPAudioTimeAcc;
+
+// Accumulator for `gRSPGfxTimeTotal`.
+volatile OSTime gRSPGfxTimeAcc;
+
+volatile OSTime gRSPOtherTimeAcc;
 volatile OSTime D_8016A578;
-volatile OSTime gRDPTotalTime;
+
+// Accumulator for `gRDPTimeTotal`
+volatile OSTime gRDPTimeAcc;
+
 SpeedMeterTimeEntry* sSpeedMeterTimeEntryPtr;
 
 SpeedMeterTimeEntry sSpeedMeterTimeEntryArray[] = {
-    { &D_8016A520, 0, 0, GPACK_RGBA5551(255, 0, 0, 1) }, { &D_8016A528, 0, 2, GPACK_RGBA5551(255, 255, 0, 1) },
-    { &D_8016A530, 0, 4, GPACK_RGBA5551(0, 0, 255, 1) }, { &D_8016A538, 0, 6, GPACK_RGBA5551(255, 128, 128, 1) },
-    { &D_8016A540, 0, 8, GPACK_RGBA5551(0, 255, 0, 1) }, { &D_8016A548, 0, 10, GPACK_RGBA5551(255, 0, 255, 1) },
+    { &gAudioThreadUpdateTimeTotalPerGfxTask, 0, 0, GPACK_RGBA5551(255, 0, 0, 1) },
+    { &gGfxTaskSentToNextReadyMinusAudioThreadUpdateTime, 0, 2, GPACK_RGBA5551(255, 255, 0, 1) },
+    { &gRSPAudioTimeTotal, 0, 4, GPACK_RGBA5551(0, 0, 255, 1) },
+    { &gRSPGfxTimeTotal, 0, 6, GPACK_RGBA5551(255, 128, 128, 1) },
+    { &gRDPTimeTotal, 0, 8, GPACK_RGBA5551(0, 255, 0, 1) },
+    { &gGraphUpdatePeriod, 0, 10, GPACK_RGBA5551(255, 0, 255, 1) },
 };
 
 #define gDrawRect(gfx, color, ulx, uly, lrx, lry)      \
@@ -44,7 +89,7 @@ void SpeedMeter_Destroy(SpeedMeter* this) {
 void SpeedMeter_DrawTimeEntries(SpeedMeter* this, GraphicsContext* gfxCtx) {
     s32 pad[2];
     u32 baseX = 32;
-    s32 temp;
+    s32 width;
     s32 i;
     s32 uly;
     s32 lry;
@@ -64,8 +109,8 @@ void SpeedMeter_DrawTimeEntries(SpeedMeter* this, GraphicsContext* gfxCtx) {
 
     sSpeedMeterTimeEntryPtr = &sSpeedMeterTimeEntryArray[0];
     for (i = 0; i < ARRAY_COUNT(sSpeedMeterTimeEntryArray); i++) {
-        temp = ((f64)*sSpeedMeterTimeEntryPtr->time / gIrqMgrRetraceTime) * 64.0;
-        sSpeedMeterTimeEntryPtr->x = temp + baseX;
+        width = ((f64)*sSpeedMeterTimeEntryPtr->time / gIrqMgrRetraceTime) * 64.0;
+        sSpeedMeterTimeEntryPtr->x = baseX + width;
         sSpeedMeterTimeEntryPtr++;
     }
 
@@ -151,11 +196,11 @@ void SpeedMeter_DrawAllocEntry(SpeedMeterAllocEntry* this, GraphicsContext* gfxC
 }
 
 void SpeedMeter_DrawAllocEntries(SpeedMeter* meter, GraphicsContext* gfxCtx, GameState* state) {
-    s32 pad[2];
+    s32 pad1[2];
     u32 ulx = 30;
     u32 lrx = 290;
     SpeedMeterAllocEntry entry;
-    u32 temp;
+    u32 pad2;
     s32 y;
     TwoHeadGfxArena* thga;
     u32 zeldaFreeMax;
@@ -166,7 +211,7 @@ void SpeedMeter_DrawAllocEntries(SpeedMeter* meter, GraphicsContext* gfxCtx, Gam
     s32 sysAlloc;
 
     y = 212;
-    if (SREG(0) > 2) {
+    if (R_ENABLE_ARENA_DBG > 2) {
         if (ZeldaArena_IsInitialized()) {
             ZeldaArena_GetSizes(&zeldaFreeMax, &zeldaFree, &zeldaAlloc);
             SpeedMeter_InitAllocEntry(&entry, zeldaFree + zeldaAlloc, zeldaAlloc, GPACK_RGBA5551(0, 0, 255, 1),
@@ -177,7 +222,7 @@ void SpeedMeter_DrawAllocEntries(SpeedMeter* meter, GraphicsContext* gfxCtx, Gam
         }
     }
 
-    if (SREG(0) > 1) {
+    if (R_ENABLE_ARENA_DBG > 1) {
         SystemArena_GetSizes((u32*)&sysFreeMax, (u32*)&sysFree, (u32*)&sysAlloc);
         SpeedMeter_InitAllocEntry(&entry, sysFree + sysAlloc - state->tha.size, sysAlloc - state->tha.size,
                                   GPACK_RGBA5551(0, 0, 255, 1), GPACK_RGBA5551(255, 128, 128, 1), ulx, lrx, y, y);
diff --git a/src/code/z_kankyo.c b/src/code/z_kankyo.c
index d52f8db99..1b6ce5b4c 100644
--- a/src/code/z_kankyo.c
+++ b/src/code/z_kankyo.c
@@ -949,7 +949,7 @@ void Environment_Update(PlayState* play, EnvironmentContext* envCtx, LightContex
             gSaveContext.nightFlag = 0;
         }
 
-        if (SREG(0) != 0 || CREG(2) != 0) {
+        if (R_ENABLE_ARENA_DBG != 0 || CREG(2) != 0) {
             Gfx* displayList;
             Gfx* prevDisplayList;
 
diff --git a/src/code/z_prenmi.c b/src/code/z_prenmi.c
index 82c72a944..b893cb349 100644
--- a/src/code/z_prenmi.c
+++ b/src/code/z_prenmi.c
@@ -47,7 +47,7 @@ void PreNMI_Main(GameState* thisx) {
     PreNMI_Update(this);
     PreNMI_Draw(this);
 
-    this->state.unk_A0 = 1;
+    this->state.inPreNMIState = true;
 }
 
 void PreNMI_Destroy(GameState* thisx) {