diff --git a/Client/core/CCore.cpp b/Client/core/CCore.cpp index 6876424fb0..1aa66bedb3 100644 --- a/Client/core/CCore.cpp +++ b/Client/core/CCore.cpp @@ -1315,25 +1315,32 @@ bool CCore::IsWindowMinimized() void CCore::DoPreFramePulse() { + CLOCK_SET_SECTION("CCore::DoPreFramePulse"); + CLOCK1("Total"); + TIMING_CHECKPOINT("+CorePreFrame"); if constexpr (bFreezeWatchdogEnabledInCurrentBuild) UpdateWatchdogHeartbeat(); - m_pKeyBinds->DoPreFramePulse(); + CLOCK_CALL1(m_pKeyBinds->DoPreFramePulse();); // Notify the mod manager - m_pModManager->DoPulsePreFrame(); + CLOCK_CALL1(m_pModManager->DoPulsePreFrame();); - m_pLocalGUI->DoPulse(); + CLOCK_CALL1(m_pLocalGUI->DoPulse();); CCrashDumpWriter::UpdateCounters(); TIMING_CHECKPOINT("-CorePreFrame"); + UNCLOCK1("Total"); } void CCore::DoPostFramePulse() { + CLOCK_SET_SECTION("CCore::DoPostFramePulse"); + CLOCK1("Total"); + TIMING_CHECKPOINT("+CorePostFrame1"); if (m_bQuitOnPulse) Quit(); @@ -1441,19 +1448,19 @@ void CCore::DoPostFramePulse() m_bLastFocused = true; } - GetJoystickManager()->DoPulse(); // Note: This may indirectly call CMessageLoopHook::ProcessMessage - m_pKeyBinds->DoPostFramePulse(); + CLOCK_CALL1(GetJoystickManager()->DoPulse();); // Note: This may indirectly call CMessageLoopHook::ProcessMessage + CLOCK_CALL1(m_pKeyBinds->DoPostFramePulse();); if (m_pWebCore) - m_pWebCore->DoPulse(); + CLOCK_CALL1(m_pWebCore->DoPulse();); // Notify the mod manager and the connect manager TIMING_CHECKPOINT("-CorePostFrame1"); - m_pModManager->DoPulsePostFrame(); + CLOCK_CALL1(m_pModManager->DoPulsePostFrame();); TIMING_CHECKPOINT("+CorePostFrame2"); - GetMemStats()->Draw(); - GetGraphStats()->Draw(); - m_pConnectManager->DoPulse(); + CLOCK_CALL1(GetMemStats()->Draw();); + CLOCK_CALL1(GetGraphStats()->Draw();); + CLOCK_CALL1(m_pConnectManager->DoPulse();); // Update Discord Rich Presence status if (const long long ticks = GetTickCount64_(); ticks > m_timeDiscordAppLastUpdate + TIME_DISCORD_UPDATE_RICH_PRESENCE_RATE) @@ -1470,6 +1477,7 @@ void CCore::DoPostFramePulse() } TIMING_CHECKPOINT("-CorePostFrame2"); + UNCLOCK1("Total"); } // Called after MOD is unloaded diff --git a/Client/core/CModManager.cpp b/Client/core/CModManager.cpp index 858b5ea86e..ae483caeb0 100644 --- a/Client/core/CModManager.cpp +++ b/Client/core/CModManager.cpp @@ -56,28 +56,39 @@ bool CModManager::TriggerCommand(const char* commandName, size_t commandNameLeng void CModManager::DoPulsePreFrame() { + CLOCK_SET_SECTION("CModManager::DoPulsePreFrame"); + CLOCK1("Total"); + TIMING_GRAPH("+DoPulsePreFrame"); - CCore::GetSingleton().GetFPSLimiter()->OnFrameStart(); // Prepare FPS limiting for this frame + CLOCK_CALL1(CCore::GetSingleton().GetFPSLimiter()->OnFrameStart();); // Prepare FPS limiting for this frame if (m_client) { - m_client->PreFrameExecutionHandler(); + CLOCK_CALL1(m_client->PreFrameExecutionHandler();); } TIMING_GRAPH("-DoPulsePreFrame"); + UNCLOCK1("Total"); } void CModManager::DoPulsePreHUDRender(bool bDidUnminimize, bool bDidRecreateRenderTargets) { + CLOCK_SET_SECTION("CModManager::DoPulsePreHUDRender"); + CLOCK1("Total"); + TIMING_GRAPH("+DoPulsePreHUDRender"); if (m_client) { - m_client->PreHUDRenderExecutionHandler(bDidUnminimize, bDidRecreateRenderTargets); + CLOCK_CALL1(m_client->PreHUDRenderExecutionHandler(bDidUnminimize, bDidRecreateRenderTargets);); } TIMING_GRAPH("-DoPulsePreHUDRender"); + UNCLOCK1("Total"); } void CModManager::DoPulsePostFrame() { + CLOCK_SET_SECTION("CModManager::DoPulsePostFrame"); + CLOCK1("Total"); + auto handleStateChange = [&]() { if (m_state == State::PendingStart) @@ -88,26 +99,27 @@ void CModManager::DoPulsePostFrame() TIMING_GRAPH("+DoPulsePostFrame"); - handleStateChange(); // Handle state changes before pulse + CLOCK_CALL1(handleStateChange();); // Handle state changes before pulse if (m_client) { - m_client->PostFrameExecutionHandler(); + CLOCK_CALL1(m_client->PostFrameExecutionHandler();); } else { - CCore::GetSingleton().GetNetwork()->DoPulse(); + CLOCK_CALL1(CCore::GetSingleton().GetNetwork()->DoPulse();); } - CCore::GetSingleton().DoReliablePulse(); // Do reliable pulse + CLOCK_CALL1(CCore::GetSingleton().DoReliablePulse();); // Do reliable pulse - handleStateChange(); // Handle state changes after pulse + CLOCK_CALL1(handleStateChange();); // Handle state changes after pulse // TODO: ENSURE "CModManager::DoPulsePostFrame" IS THE LAST THING BEFORE THE FRAME ENDS - CCore::GetSingleton().GetFPSLimiter()->OnFrameEnd(); // Apply FPS limiting + CLOCK_CALL1(CCore::GetSingleton().GetFPSLimiter()->OnFrameEnd();); // Apply FPS limiting TIMING_GRAPH("-DoPulsePostFrame"); TIMING_GRAPH(""); + UNCLOCK1("Total"); } bool CModManager::Load(const char* arguments) diff --git a/Client/mods/deathmatch/CClient.cpp b/Client/mods/deathmatch/CClient.cpp index 44ff7e9cf6..14bf3cf8cc 100644 --- a/Client/mods/deathmatch/CClient.cpp +++ b/Client/mods/deathmatch/CClient.cpp @@ -202,36 +202,52 @@ void CClient::ClientShutdown() void CClient::PreFrameExecutionHandler() { + CLOCK_SET_SECTION("CClient::PreFrameExecutionHandler"); + CLOCK1("Total"); + // If the client modification is loaded, pulse it if (g_pClientGame) { - g_pClientGame->DoPulsePreFrame(); + CLOCK_CALL1(g_pClientGame->DoPulsePreFrame();); } + UNCLOCK1("Total"); } void CClient::PreHUDRenderExecutionHandler(bool bDidUnminimize, bool bDidRecreateRenderTargets) { + CLOCK_SET_SECTION("CClient::PreHUDRenderExecutionHandler"); + CLOCK1("Total"); + if (g_pClientGame) { - g_pClientGame->DoPulsePreHUDRender(bDidUnminimize, bDidRecreateRenderTargets); + CLOCK_CALL1(g_pClientGame->DoPulsePreHUDRender(bDidUnminimize, bDidRecreateRenderTargets);); } + UNCLOCK1("Total"); } void CClient::PostFrameExecutionHandler() { + CLOCK_SET_SECTION("CClient::PostFrameExecutionHandler"); + CLOCK1("Total"); + // If the client modification is loaded, pulse it if (g_pClientGame) { - g_pClientGame->DoPulsePostFrame(); + CLOCK_CALL1(g_pClientGame->DoPulsePostFrame();); } + UNCLOCK1("Total"); } void CClient::IdleHandler() { + CLOCK_SET_SECTION("CClient::IdleHandler"); + CLOCK1("Total"); + if (g_pClientGame) { - g_pClientGame->IdleHandler(); + CLOCK_CALL1(g_pClientGame->IdleHandler();); } + UNCLOCK1("Total"); } bool CClient::WebsiteRequestResultHandler(const std::unordered_set& newPages) diff --git a/Client/mods/deathmatch/logic/CClientPerfStatManager.cpp b/Client/mods/deathmatch/logic/CClientPerfStatManager.cpp index cb32891a0f..0df9aba86a 100644 --- a/Client/mods/deathmatch/logic/CClientPerfStatManager.cpp +++ b/Client/mods/deathmatch/logic/CClientPerfStatManager.cpp @@ -11,6 +11,309 @@ #include "StdInc.h" +namespace +{ + struct SClientTimingRow + { + SString strName; + uint uiFrameCalls; + float fFrameMs; + float fFramePeakMs; + uint uiWindowCalls; + float fWindowMs; + float fWindowPercent; + }; + + bool RowMatchesFilter(const SString& strName, const SString& strFilter) + { + return strFilter.empty() || strName.find(strFilter) != SString::npos; + } + + bool CompareRowsByUsage(const SClientTimingRow& left, const SClientTimingRow& right) + { + if (left.fWindowMs != right.fWindowMs) + return left.fWindowMs > right.fWindowMs; + if (left.fFrameMs != right.fFrameMs) + return left.fFrameMs > right.fFrameMs; + return left.strName < right.strName; + } + + int GetTopCount(const std::map& optionMap) + { + for (std::map::const_iterator it = optionMap.begin(); it != optionMap.end(); ++it) + { + const SString& strOption = it->first; + if (strOption.empty() || strOption[0] < '0' || strOption[0] > '9') + continue; + + int iTopCount = atoi(strOption); + if (iTopCount > 0) + return iTopCount; + } + return 0; + } + + void AddResultRow(CClientPerfStatResult* pResult, const SClientTimingRow& row) + { + SString* pOut = pResult->AddRow(); + int c = 0; + pOut[c++] = row.strName; + pOut[c++] = SString("%u", row.uiFrameCalls); + pOut[c++] = SString("%2.1f ms", row.fFrameMs); + pOut[c++] = SString("%2.1f ms", row.fFramePeakMs); + pOut[c++] = SString("%u", row.uiWindowCalls); + pOut[c++] = SString("%2.1f ms", row.fWindowMs); + pOut[c++] = SString("%2.0f%%", row.fWindowPercent); + } +} + +/////////////////////////////////////////////////////////////// +// +// CClientPerfStatTimingImpl +// +// +// +/////////////////////////////////////////////////////////////// +class CClientPerfStatTimingImpl : public CClientPerfStatTiming +{ +public: + ZERO_ON_NEW + CClientPerfStatTimingImpl(); + virtual ~CClientPerfStatTimingImpl(); + + // CClientPerfStatModule + virtual const SString& GetCategoryName(); + virtual void DoPulse(); + virtual void GetStats(CClientPerfStatResult* pOutResult, const std::map& optionMap, const SString& strFilter); + + // CClientPerfStatTimingImpl + void SetActive(bool bActive); + + SString m_strCategoryName; + CStatResults m_StatResults; + CElapsedTime m_TimeSinceLastViewed; + bool m_bIsActive; +}; + +static CClientPerfStatTimingImpl* g_pClientPerfStatTimingImp = NULL; + +CClientPerfStatTiming* CClientPerfStatTiming::GetSingleton() +{ + if (!g_pClientPerfStatTimingImp) + g_pClientPerfStatTimingImp = new CClientPerfStatTimingImpl(); + return g_pClientPerfStatTimingImp; +} + +CClientPerfStatTimingImpl::CClientPerfStatTimingImpl() +{ + m_strCategoryName = "Client timing"; +} + +CClientPerfStatTimingImpl::~CClientPerfStatTimingImpl() +{ +} + +const SString& CClientPerfStatTimingImpl::GetCategoryName() +{ + return m_strCategoryName; +} + +void CClientPerfStatTimingImpl::DoPulse() +{ + if (m_bIsActive && m_TimeSinceLastViewed.Get() > 15000) + SetActive(false); + + if (m_bIsActive) + m_StatResults.FrameEnd(); +} + +void CClientPerfStatTimingImpl::SetActive(bool bActive) +{ + if (bActive == m_bIsActive) + return; + + m_bIsActive = bActive; + g_StatEvents.SetEnabled(m_bIsActive); +} + +void CClientPerfStatTimingImpl::GetStats(CClientPerfStatResult* pResult, const std::map& optionMap, const SString& strFilter) +{ + m_TimeSinceLastViewed.Reset(); + SetActive(true); + + const bool bHelp = MapContains(optionMap, "h"); + bool bFlat = MapContains(optionMap, "flat") || MapContains(optionMap, "s"); + bool bSort = MapContains(optionMap, "s"); + const int iTopCount = GetTopCount(optionMap); + + if (iTopCount > 0) + { + bFlat = true; + bSort = true; + } + + if (bHelp) + { + pResult->AddColumn("Client timings help"); + pResult->AddRow()[0] = "Option h - This help"; + pResult->AddRow()[0] = "Option s - Flat/sorted output by 2 sec cpu"; + pResult->AddRow()[0] = "Option flat - Flat output without sorting"; + pResult->AddRow()[0] = "Option - Top N rows (implies sorted flat output)"; + pResult->AddRow()[0] = "Use filter to match section::item names"; + pResult->AddRow()[0] = "Rows named (unaccounted) = Total minus known child timings"; + return; + } + + pResult->AddColumn("Section/item"); + pResult->AddColumn("Last frame.calls"); + pResult->AddColumn("Last frame.cpu"); + pResult->AddColumn("Last frame.cpu peak"); + pResult->AddColumn("2 sec.calls"); + pResult->AddColumn("2 sec.cpu"); + pResult->AddColumn("2 sec.cpu %"); + + const SStatResultCollection& collection = m_StatResults.m_CollectionCombo; + + if (bFlat) + { + std::vector rows; + for (std::map::const_iterator itSection = collection.begin(); itSection != collection.end(); ++itSection) + { + const SString& sectionName = itSection->first; + const SStatResultSection& section = itSection->second; + + for (std::map::const_iterator itItem = section.begin(); itItem != section.end(); ++itItem) + { + const SString& itemName = itItem->first; + const SStatResultItem& item = itItem->second; + + SClientTimingRow row; + row.strName = sectionName + "::" + itemName; + row.uiFrameCalls = item.iCounter; + row.fFrameMs = item.fMs; + row.fFramePeakMs = item.fMsMax; + row.uiWindowCalls = item.iCounterTotal; + row.fWindowMs = item.fMsTotal; + row.fWindowPercent = item.fMsTotalPercent; + + if (RowMatchesFilter(row.strName, strFilter)) + rows.push_back(row); + } + } + + if (bSort) + std::sort(rows.begin(), rows.end(), CompareRowsByUsage); + + if (iTopCount > 0 && rows.size() > static_cast(iTopCount)) + rows.resize(iTopCount); + + for (uint i = 0; i < rows.size(); ++i) + AddResultRow(pResult, rows[i]); + + return; + } + + for (std::map::const_iterator itSection = collection.begin(); itSection != collection.end(); ++itSection) + { + const SString& sectionName = itSection->first; + const SStatResultSection& section = itSection->second; + const bool bSectionMatches = RowMatchesFilter(sectionName, strFilter); + + SClientTimingRow sectionRow; + sectionRow.strName = sectionName; + sectionRow.uiFrameCalls = 0; + sectionRow.fFrameMs = 0; + sectionRow.fFramePeakMs = 0; + sectionRow.uiWindowCalls = 0; + sectionRow.fWindowMs = 0; + sectionRow.fWindowPercent = 0; + + std::vector childRows; + + for (std::map::const_iterator itItem = section.begin(); itItem != section.end(); ++itItem) + { + const SString& itemName = itItem->first; + const SStatResultItem& item = itItem->second; + const SString fullItemName = sectionName + "::" + itemName; + if (!bSectionMatches && !RowMatchesFilter(fullItemName, strFilter)) + continue; + + // Don't roll ".Total" into section aggregates to avoid double counting. + // If present, sectionRow will be set to ".Total" values below. + if (itemName != "Total") + { + sectionRow.uiFrameCalls += item.iCounter; + sectionRow.fFrameMs += item.fMs; + sectionRow.fFramePeakMs = std::max(sectionRow.fFramePeakMs, item.fMsMax); + sectionRow.uiWindowCalls += item.iCounterTotal; + sectionRow.fWindowMs += item.fMsTotal; + sectionRow.fWindowPercent += item.fMsTotalPercent; + } + + SClientTimingRow itemRow; + itemRow.strName = SStringX(".") + itemName; + itemRow.uiFrameCalls = item.iCounter; + itemRow.fFrameMs = item.fMs; + itemRow.fFramePeakMs = item.fMsMax; + itemRow.uiWindowCalls = item.iCounterTotal; + itemRow.fWindowMs = item.fMsTotal; + itemRow.fWindowPercent = item.fMsTotalPercent; + childRows.push_back(itemRow); + } + + // Derive section overhead from .Total minus known child timings + const SClientTimingRow* pTotalRow = NULL; + float fKnownFrameMs = 0; + float fKnownWindowMs = 0; + float fKnownWindowPercent = 0; + int iKnownFrameCalls = 0; + int iKnownWindowCalls = 0; + for (uint i = 0; i < childRows.size(); ++i) + { + const SClientTimingRow& row = childRows[i]; + if (row.strName == ".Total") + pTotalRow = &row; + else + { + fKnownFrameMs += row.fFrameMs; + fKnownWindowMs += row.fWindowMs; + fKnownWindowPercent += row.fWindowPercent; + iKnownFrameCalls += row.uiFrameCalls; + iKnownWindowCalls += row.uiWindowCalls; + } + } + + if (pTotalRow) + { + sectionRow.uiFrameCalls = pTotalRow->uiFrameCalls; + sectionRow.fFrameMs = pTotalRow->fFrameMs; + sectionRow.fFramePeakMs = pTotalRow->fFramePeakMs; + sectionRow.uiWindowCalls = pTotalRow->uiWindowCalls; + sectionRow.fWindowMs = pTotalRow->fWindowMs; + sectionRow.fWindowPercent = pTotalRow->fWindowPercent; + + SClientTimingRow unaccountedRow; + unaccountedRow.strName = ".(unaccounted)"; + unaccountedRow.uiFrameCalls = std::max(0, static_cast(pTotalRow->uiFrameCalls) - iKnownFrameCalls); + unaccountedRow.fFrameMs = std::max(0.0f, pTotalRow->fFrameMs - fKnownFrameMs); + unaccountedRow.fFramePeakMs = pTotalRow->fFramePeakMs; + unaccountedRow.uiWindowCalls = std::max(0, static_cast(pTotalRow->uiWindowCalls) - iKnownWindowCalls); + unaccountedRow.fWindowMs = std::max(0.0f, pTotalRow->fWindowMs - fKnownWindowMs); + unaccountedRow.fWindowPercent = std::max(0.0f, pTotalRow->fWindowPercent - fKnownWindowPercent); + + if (unaccountedRow.fFrameMs > 0 || unaccountedRow.fWindowMs > 0) + childRows.push_back(unaccountedRow); + } + + if (childRows.empty()) + continue; + + AddResultRow(pResult, sectionRow); + for (uint i = 0; i < childRows.size(); ++i) + AddResultRow(pResult, childRows[i]); + } +} + /////////////////////////////////////////////////////////////// // // CClientPerfStatManagerImpl @@ -62,6 +365,7 @@ CClientPerfStatManager* CClientPerfStatManager::GetSingleton() /////////////////////////////////////////////////////////////// CClientPerfStatManagerImpl::CClientPerfStatManagerImpl() { + AddModule(CClientPerfStatTiming::GetSingleton()); AddModule(CClientPerfStatLuaTiming::GetSingleton()); AddModule(CClientPerfStatLuaMemory::GetSingleton()); AddModule(CClientPerfStatLibMemory::GetSingleton()); diff --git a/Client/mods/deathmatch/logic/CClientPerfStatModule.h b/Client/mods/deathmatch/logic/CClientPerfStatModule.h index db2c2ea513..1ba8a3b051 100644 --- a/Client/mods/deathmatch/logic/CClientPerfStatModule.h +++ b/Client/mods/deathmatch/logic/CClientPerfStatModule.h @@ -153,3 +153,16 @@ class CClientPerfStatPacketUsage : public CClientPerfStatModule static CClientPerfStatPacketUsage* GetSingleton(); }; +// +// CClientPerfStatTiming +// +class CClientPerfStatTiming : public CClientPerfStatModule +{ +public: + // CClientPerfStatModule + virtual const SString& GetCategoryName() = 0; + virtual void DoPulse() = 0; + virtual void GetStats(CClientPerfStatResult* pOutResult, const std::map& optionMap, const SString& strFilter) = 0; + + static CClientPerfStatTiming* GetSingleton(); +};