#include "PerfTimer.h" #include "BFApp.h" #pragma warning(disable:4996) #ifdef _DEBUG #define PERF_WANTS_THREAD_CHECK #endif USING_NS_BF; PerfManager* Beefy::gPerfManager = NULL; PerfEntry::PerfEntry() { mCount = 0; mTimeTotal = 0; mCurTimingStart = 0; mChild = NULL; } void PerfEntry::DbgPrint(const StringImpl& name, int level, std::map& uniqueTimingMap) { String text; uint64 childrenTime = 0; /*PerfEntryMap::iterator itr = mChildren.begin(); while (itr != mChildren.end()) { PerfEntry* child = &itr->second; childrenTime += child->mTimeTotal; ++itr; }*/ for (auto& kv : mChildren) { PerfEntry* child = kv.mValue; childrenTime += child->mTimeTotal; } for (int i = 0; i <= level; i++) text += " "; String prefix = text; text += name; while (text.length() < 80) text += ' '; int selfTime = (int)(mTimeTotal - childrenTime); if (uniqueTimingMap.find(name) == uniqueTimingMap.end()) uniqueTimingMap[name] = selfTime; else uniqueTimingMap[name] += selfTime; text += StrFormat("%4d\t%6.1f\t%6.1f\n", mCount, mTimeTotal / 1000.0f, (int) (selfTime) / 1000.0f); /*for (int i = 0; i < (int) mLog.size(); i++) { PerfLogEntry* logEntry = &mLog[i]; text += prefix + StrFormat("@%d: %s\n", logEntry->mTick, logEntry->mString.c_str()); }*/ OutputDebugStrF(text.c_str()); for (auto& kv : mChildren) { PerfEntry* child = kv.mValue; child->DbgPrint(kv.mKey, level + 1, uniqueTimingMap); } } void PerfManager::Clear() { mLogEntries.ClearFast(); mAlloc.Clear(); mFrames.clear(); mCurStackIdx = 0; mOverhead = 0; } PerfManager::PerfManager() { mRecording = false; mCurStackIdx = 0; mOwningThreadId = 0; mOverhead = 0; mAlloc.mDisableDebugTracing = true; } void PerfManager::NextFrame() { if (!mRecording) return; BF_ASSERT(mCurStackIdx <= 1); while (mCurStackIdx > 0) ZoneEnd(true); auto logEntryFrameStart = mAlloc.Alloc(); logEntryFrameStart->mType = PerfLogEntryType_FrameStart; logEntryFrameStart->mTimingStart = BFGetTickCountMicroFast(); mLogEntries.PushBack(logEntryFrameStart); mCurStackIdx++; } void PerfManager::ZoneStart(const char* name) { if (!mRecording) return; #ifdef PERF_WANTS_THREAD_CHECK BF_ASSERT(mOwningThreadId == BfpThread_GetCurrentId()); #endif uint64 callTimerStart = BFGetTickCountMicroFast(); mCurStackIdx++; int nameLen = (int)strlen(name); auto logEntryStart = mAlloc.Alloc(nameLen + 1); char* namePtr = (char*)(logEntryStart + 1); strcpy(namePtr, name); logEntryStart->mType = PerfLogEntryType_Start; logEntryStart->mName = namePtr; mLogEntries.PushBack(logEntryStart); logEntryStart->mTimingStart = BFGetTickCountMicroFast();; mOverhead += logEntryStart->mTimingStart - callTimerStart; /* if (mCurStackIdx == 0) GetCurFrame(); PerfEntry* curParent = mCurStack[mCurStackIdx - 1]; PerfEntry* entry = NULL; if (curParent->mChild != NULL) { if (curParent->mChild->mName == name) entry = curParent->mChild; } if (entry == NULL) { PerfEntryMap::iterator itr = curParent->mChildren.find(name); if (itr != curParent->mChildren.end()) { entry = &itr->second; } else { itr = curParent->mChildren.insert(PerfEntryMap::value_type(name, PerfEntry())).first; entry = &itr->second; entry->mName = name; } curParent->mChild = entry; } entry->mCount++; entry->mCurTimingStart = BFGetTickCountMicroFast(); mCurStack[mCurStackIdx++] = entry; mOverhead += entry->mCurTimingStart - callTimerStart;*/ } void PerfManager::ZoneEnd(bool allowFrameEnd) { if (!mRecording) return; if ((mCurStackIdx <= 1) && (!allowFrameEnd)) return; auto logEntryEnd = mAlloc.Alloc(); logEntryEnd->mType = PerfLogEntryType_End; logEntryEnd->mTimingEnd = BFGetTickCountMicroFast(); mLogEntries.PushBack(logEntryEnd); mCurStackIdx--; /*PerfEntry* entry = mCurStack[mCurStackIdx - 1]; mCurStackIdx--; entry->mTimeTotal += BFGetTickCountMicroFast() - entry->mCurTimingStart;*/ } void PerfManager::Message(const StringImpl& theString) { if (!mRecording) return; //TODO: Implement /*if (mCurStackIdx == 0) GetCurFrame(); PerfEntry* entry = mCurStack[mCurStackIdx - 1]; PerfLogEntry logEntry; logEntry.mTick = BFTickCount(); logEntry.mString = theString; entry->mLog.push_back(logEntry);*/ } void PerfManager::StartRecording() { #ifdef PERF_WANTS_THREAD_CHECK mOwningThreadId = BfpThread_GetCurrentId(); #endif mRecording = true; Clear(); NextFrame(); } void PerfManager::StopRecording(bool dbgPrint) { if (!mRecording) return; #ifdef PERF_WANTS_THREAD_CHECK BF_ASSERT(mOwningThreadId == ::BfpThread_GetCurrentId()); #endif mRecording = false; auto logEntryStopRecording = mAlloc.Alloc(); logEntryStopRecording->mType = PerfLogEntryType_StopRecording; logEntryStopRecording->mTimingEnd = BFGetTickCountMicroFast(); mLogEntries.PushBack(logEntryStopRecording); if (dbgPrint) DbgPrint(); /*if (mFrames.size() > 0) { PerfFrame* frame = &mFrames.back(); frame->mTimeTotal = BFGetTickCountMicroFast() - frame->mCurTimingStart; }*/ } bool PerfManager::IsRecording() { return mRecording; } void PerfManager::DbgPrint() { #ifdef PERF_WANTS_THREAD_CHECK BF_ASSERT(mOwningThreadId == ::BfpThread_GetCurrentId()); #endif if (mFrames.empty()) { mCurStackIdx = 0; PerfFrame* curFrame = NULL; for (auto logEntry : mLogEntries) { if (logEntry->mType == PerfLogEntryType_FrameStart) { PerfLogEntry_FrameStart* frameStartEntry = (PerfLogEntry_FrameStart*)logEntry; if (mFrames.size() > 0) { PerfFrame* frame = &mFrames.back(); frame->mTimeTotal = frameStartEntry->mTimingStart - frame->mCurTimingStart; } mFrames.push_back(PerfFrame()); PerfFrame* frame = &mFrames.back(); frame->mCurTimingStart = frameStartEntry->mTimingStart; #ifndef BF_NO_BFAPP if (gBFApp != NULL) frame->mAppFrameNum = gBFApp->mUpdateCnt; else frame->mAppFrameNum = 0; #else frame->mAppFrameNum = 0; #endif frame->mCount = 1; mCurStack[mCurStackIdx++] = frame; } else if (logEntry->mType == PerfLogEntryType_Start) { PerfLogEntry_Start* entryStart = (PerfLogEntry_Start*)logEntry; PerfEntry* curParent = mCurStack[mCurStackIdx - 1]; PerfEntry* entry = NULL; if (curParent->mChild != NULL) { if (curParent->mChild->mName == entryStart->mName) entry = curParent->mChild; } if (entry == NULL) { /*PerfEntryMap::iterator itr = curParent->mChildren.find(entryStart->mName); if (itr != curParent->mChildren.end()) { entry = &itr->second; } else { itr = curParent->mChildren.insert(PerfEntryMap::value_type(entryStart->mName, PerfEntry())).first; entry = &itr->second; entry->mName = entryStart->mName; }*/ PerfEntry** entryPtr = NULL; if (curParent->mChildren.TryAdd(entryStart->mName, NULL, &entryPtr)) { entry = mAlloc.Alloc(); *entryPtr = entry; entry->mName = entryStart->mName; } else { entry = *entryPtr; } curParent->mChild = entry; } entry->mCount++; entry->mCurTimingStart = entryStart->mTimingStart; mCurStack[mCurStackIdx++] = entry; } else if (logEntry->mType == PerfLogEntryType_End) { PerfLogEntry_End* entryEnd = (PerfLogEntry_End*)logEntry; PerfEntry* entry = mCurStack[mCurStackIdx - 1]; mCurStackIdx--; entry->mTimeTotal += entryEnd->mTimingEnd - entry->mCurTimingStart; } else if (logEntry->mType == PerfLogEntryType_StopRecording) { PerfLogEntry_StopRecording* stopRecordingEntry = (PerfLogEntry_StopRecording*)logEntry; if (mFrames.size() > 0) { PerfFrame* frame = &mFrames.back(); frame->mTimeTotal = stopRecordingEntry->mTimingEnd - frame->mCurTimingStart; } } } } std::map uniqueTimingMap; OutputDebugStrF("PerfManager_Results____________________________________________________________Calls___MSTotal__MSSelf\n"); PerfFrameList::iterator frameItr = mFrames.begin(); while (frameItr != mFrames.end()) { PerfFrame* frame = &(*frameItr); frame->DbgPrint(StrFormat("Frame %d", frame->mAppFrameNum), 0, uniqueTimingMap); ++frameItr; } OutputDebugStr("\nPerfManager_Combined_Results____________________________________________________________________MSSelf\n"); typedef std::multimap SortedMap; SortedMap sortedMap; for (auto& entry : uniqueTimingMap) { sortedMap.insert(SortedMap::value_type(-entry.second, entry.first)); } for (auto& entry : sortedMap) { String text = entry.second; for (int i = (int)text.length(); i < 96; i++) text += " "; text += StrFormat("%6.1f\n", -entry.first / 1000.0f); OutputDebugStr(text.c_str()); } { String text = "PerfTimer Timing Overhead"; for (int i = (int) text.length(); i < 96; i++) text += " "; text += StrFormat("%6.1f\n", mOverhead / 1000.0f); OutputDebugStr(text.c_str()); } } AutoPerf::AutoPerf(const char* name, PerfManager* perfManager) { if ((perfManager == NULL) || (!perfManager->mRecording)) { mPerfManager = NULL; mStartStackIdx = 0; return; } mPerfManager = perfManager; mPerfManager->ZoneStart(name); mStartStackIdx = mPerfManager->mCurStackIdx - 1; } void AutoPerf::Leave() { if (mStartStackIdx <= 0) return; BF_ASSERT(mPerfManager->mCurStackIdx <= mStartStackIdx + 1); if (mPerfManager->mCurStackIdx > mStartStackIdx) mPerfManager->ZoneEnd(); mStartStackIdx = -1; } AutoPerf::~AutoPerf() { Leave(); } ////////////////////////////////////////////////////////////////////////// AutoPerfRecordAndPrint::AutoPerfRecordAndPrint(PerfManager* perfManager) { mPerfManager = perfManager; mDidStart = !perfManager->mRecording; if (mDidStart) perfManager->StartRecording(); } AutoPerfRecordAndPrint::~AutoPerfRecordAndPrint() { if (mDidStart) mPerfManager->StopRecording(true); } ////////////////////////////////////////////////////////////////////////// AutoDbgTime::AutoDbgTime(const StringImpl& name) { mName = name; mStartTick = BFTickCount(); } AutoDbgTime::~AutoDbgTime() { int totalTime = BFTickCount() - mStartTick; OutputDebugStrF("%s: %d\n", mName.c_str(), totalTime); } /// #ifdef BFSYSLIB_DYNAMIC BF_EXPORT void BF_CALLTYPE PerfTimer_ZoneStart(const char* name) { gPerfManager->ZoneStart(name); } BF_EXPORT void BF_CALLTYPE PerfTimer_ZoneEnd() { gPerfManager->ZoneEnd(); } BF_EXPORT void BF_CALLTYPE PerfTimer_Message(const char* theString) { gPerfManager->Message(theString); } BF_EXPORT int BF_CALLTYPE PerfTimer_IsRecording() { return gPerfManager->IsRecording() ? 1 : 0; } BF_EXPORT void BF_CALLTYPE PerfTimer_StartRecording() { gPerfManager->StartRecording(); } BF_EXPORT void BF_CALLTYPE PerfTimer_StopRecording() { gPerfManager->StopRecording(); } BF_EXPORT void BF_CALLTYPE PerfTimer_DbgPrint() { gPerfManager->DbgPrint(); } #endif