From 13a4043118197d062ff28de11bc3201a8b5981a8 Mon Sep 17 00:00:00 2001 From: tomcw Date: Sat, 23 May 2020 16:23:06 +0100 Subject: [PATCH] Added a new PerfMarker class: used to instrument emulation sub-systems and log timings (#788) To enable this uncomment the #define LOG_PERF_TIMINGS in AppleWin.h. --- source/Applewin.cpp | 51 +++++++++++++++++++++++++++++++++++++++++ source/Applewin.h | 24 +++++++++++++++++++ source/CPU.cpp | 5 ++++ source/Mockingboard.cpp | 13 ++++++++++- source/NTSC.cpp | 5 ++++ source/Speaker.cpp | 5 ++++ 6 files changed, 102 insertions(+), 1 deletion(-) diff --git a/source/Applewin.cpp b/source/Applewin.cpp index 932e775e..39d2b079 100644 --- a/source/Applewin.cpp +++ b/source/Applewin.cpp @@ -123,11 +123,51 @@ CSpeech g_Speech; //=========================================================================== +#ifdef LOG_PERF_TIMINGS +static UINT64 g_timeTotal = 0; +UINT64 g_timeCpu = 0; +UINT64 g_timeVideo = 0; // part of timeCpu +UINT64 g_timeMB_Timer = 0; // part of timeCpu +UINT64 g_timeMB_NoTimer = 0; +UINT64 g_timeSpeaker = 0; +static UINT64 g_timeVideoRefresh = 0; + +void LogPerfTimings(void) +{ + if (g_timeTotal) + { + UINT64 cpu = g_timeCpu - g_timeVideo - g_timeMB_Timer; + UINT64 video = g_timeVideo + g_timeVideoRefresh; + UINT64 spkr = g_timeSpeaker; + UINT64 mb = g_timeMB_Timer + g_timeMB_NoTimer; + UINT64 audio = spkr + mb; + UINT64 other = g_timeTotal - g_timeCpu - g_timeSpeaker - g_timeMB_NoTimer - g_timeVideoRefresh; + + LogOutput("Perf breakdown:\n"); + LogOutput(". CPU %% = %2f.2\n", (double)cpu / (double)g_timeTotal * 100.0); + LogOutput(". Video %% = %2f.2\n", (double)video / (double)g_timeTotal * 100.0); + LogOutput("... NTSC %% = %2f.2\n", (double)g_timeVideo / (double)g_timeTotal * 100.0); + LogOutput("... refresh %% = %2f.2\n", (double)g_timeVideoRefresh / (double)g_timeTotal * 100.0); + LogOutput(". Audio %% = %2f.2\n", (double)audio / (double)g_timeTotal * 100.0); + LogOutput("... Speaker %% = %2f.2\n", (double)spkr / (double)g_timeTotal * 100.0); + LogOutput("... MB %% = %2f.2\n", (double)mb / (double)g_timeTotal * 100.0); + LogOutput(". Other %% = %2f.2\n", (double)other / (double)g_timeTotal * 100.0); + LogOutput(". TOTAL %% = %2f.2\n", (double)(cpu+video+audio+other) / (double)g_timeTotal * 100.0); + } +} +#endif + +//=========================================================================== + static DWORD dwLogKeyReadTickStart; static bool bLogKeyReadDone = false; void LogFileTimeUntilFirstKeyReadReset(void) { +#ifdef LOG_PERF_TIMINGS + LogPerfTimings(); +#endif + if (!g_fh) return; @@ -234,6 +274,10 @@ static bool g_uModeStepping_LastGetKey_ScrollLock = false; static void ContinueExecution(void) { +#ifdef LOG_PERF_TIMINGS + PerfMarker* pPerfMarkerTotal = new PerfMarker(g_timeTotal); +#endif + _ASSERT(g_nAppMode == MODE_RUNNING || g_nAppMode == MODE_STEPPING); const double fUsecPerSec = 1.e6; @@ -352,6 +396,9 @@ static void ContinueExecution(void) const UINT dwClksPerFrame = NTSC_GetCyclesPerFrame(); if (g_dwCyclesThisFrame >= dwClksPerFrame && !VideoGetVblBarEx(g_dwCyclesThisFrame)) { +#ifdef LOG_PERF_TIMINGS + PerfMarker perfMarkerVideoRefresh(g_timeVideoRefresh); +#endif g_dwCyclesThisFrame -= dwClksPerFrame; if (g_bFullSpeed) @@ -360,6 +407,10 @@ static void ContinueExecution(void) VideoRefreshScreen(); // Just copy the output of our Apple framebuffer to the system Back Buffer } +#ifdef LOG_PERF_TIMINGS + delete pPerfMarkerTotal; // Explicitly call dtor *before* SysClk_WaitTimer() +#endif + if ((g_nAppMode == MODE_RUNNING && !g_bFullSpeed) || bModeStepping_WaitTimer) { SysClk_WaitTimer(); diff --git a/source/Applewin.h b/source/Applewin.h index 36a12974..49c446f1 100644 --- a/source/Applewin.h +++ b/source/Applewin.h @@ -63,3 +63,27 @@ extern CSpeech g_Speech; #endif extern __interface IPropertySheet& sg_PropertySheet; + +// + +//#define LOG_PERF_TIMINGS +#ifdef LOG_PERF_TIMINGS +class PerfMarker +{ +public: + PerfMarker(UINT64& globalCounter) + : counter(globalCounter) + { + QueryPerformanceCounter(&timeStart); + } + ~PerfMarker() + { + QueryPerformanceCounter(&timeEnd); + counter += (UINT64)timeEnd.QuadPart - (UINT64)timeStart.QuadPart; + } +private: + UINT64& counter; + LARGE_INTEGER timeStart; + LARGE_INTEGER timeEnd; +}; +#endif diff --git a/source/CPU.cpp b/source/CPU.cpp index 1c5efb0e..d546a981 100644 --- a/source/CPU.cpp +++ b/source/CPU.cpp @@ -564,6 +564,11 @@ ULONG CpuGetCyclesThisVideoFrame(const ULONG nExecutedCycles) DWORD CpuExecute(const DWORD uCycles, const bool bVideoUpdate) { +#ifdef LOG_PERF_TIMINGS + extern UINT64 g_timeCpu; + PerfMarker perfMarker(g_timeCpu); +#endif + g_nCyclesExecuted = 0; #ifdef _DEBUG diff --git a/source/Mockingboard.cpp b/source/Mockingboard.cpp index 90911373..b71e42d9 100644 --- a/source/Mockingboard.cpp +++ b/source/Mockingboard.cpp @@ -814,7 +814,7 @@ static UINT64 g_uLastMBUpdateCycle = 0; // Called by: // . MB_UpdateCycles() - when g_nMBTimerDevice == {0,1,2,3} // . MB_PeriodicUpdate() - when g_nMBTimerDevice == kTIMERDEVICE_INVALID -static void MB_Update(void) +static void MB_UpdateInt(void) { if (!MockingboardVoice.bActive) return; @@ -1021,6 +1021,17 @@ static void MB_Update(void) #endif } +static void MB_Update(void) +{ +#ifdef LOG_PERF_TIMINGS + extern UINT64 g_timeMB_NoTimer; + extern UINT64 g_timeMB_Timer; + PerfMarker perfMarker(g_nMBTimerDevice == kTIMERDEVICE_INVALID ? g_timeMB_NoTimer : g_timeMB_Timer); +#endif + + MB_UpdateInt(); +} + //----------------------------------------------------------------------------- // Called by SSI263Thread(), MB_LoadSnapshot & Phasor_LoadSnapshot diff --git a/source/NTSC.cpp b/source/NTSC.cpp index fb5e077a..12507f97 100644 --- a/source/NTSC.cpp +++ b/source/NTSC.cpp @@ -2091,6 +2091,11 @@ static void VideoUpdateCycles( int cyclesLeftToUpdate ) //=========================================================================== void NTSC_VideoUpdateCycles( UINT cycles6502 ) { +#ifdef LOG_PERF_TIMINGS + extern UINT64 g_timeVideo; + PerfMarker perfMarker(g_timeVideo); +#endif + _ASSERT(cycles6502 && cycles6502 < g_videoScanner6502Cycles); // Use NTSC_VideoRedrawWholeScreen() instead if (g_bDelayVideoMode) diff --git a/source/Speaker.cpp b/source/Speaker.cpp index 247bdd56..6802e35a 100644 --- a/source/Speaker.cpp +++ b/source/Speaker.cpp @@ -415,6 +415,11 @@ BYTE __stdcall SpkrToggle (WORD, WORD, BYTE, BYTE, ULONG nExecutedCycles) // Called by ContinueExecution() void SpkrUpdate (DWORD totalcycles) { +#ifdef LOG_PERF_TIMINGS + extern UINT64 g_timeSpeaker; + PerfMarker perfMarker(g_timeSpeaker); +#endif + if(!g_bSpkrToggleFlag) { if(!g_nSpkrQuietCycleCount)