From aeaebd84067e28e36e61a46b39696e6edccdef65 Mon Sep 17 00:00:00 2001 From: Jeremy Koritzinsky Date: Thu, 13 Jul 2023 10:30:43 -0700 Subject: [PATCH] Enable StressLogAnalyzer to read stress logs from old coreclr running with a new clrgc. --- src/coreclr/inc/stresslog.h | 4 +- .../tools/StressLogAnalyzer/StressLogDump.cpp | 29 +++---- .../StressLogAnalyzer/StressLogPlugin.cpp | 61 +++++++------- .../tools/StressLogAnalyzer/StressMsgReader.h | 80 +++++++++++++++++++ src/coreclr/utilcode/stresslog.cpp | 2 +- 5 files changed, 131 insertions(+), 45 deletions(-) create mode 100644 src/coreclr/tools/StressLogAnalyzer/StressMsgReader.h diff --git a/src/coreclr/inc/stresslog.h b/src/coreclr/inc/stresslog.h index 73151773e0aea..cdc4b58ab9a4b 100644 --- a/src/coreclr/inc/stresslog.h +++ b/src/coreclr/inc/stresslog.h @@ -372,7 +372,9 @@ class StressLog { { size_t headerSize; // size of this header including size field and moduleImage uint32_t magic; // must be 'STRL' - uint32_t version; // must be 0x00010001 + uint32_t version; // must be >=0x00010001. + // 0x00010001 is the legacy short-offset format. + // 0x00010002 is the large-module-offset format introduced in .NET 8. uint8_t* memoryBase; // base address of the memory mapped file uint8_t* memoryCur; // highest address currently used uint8_t* memoryLimit; // limit that can be used diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp index 61fa9c41b1f30..f3be8b8812218 100644 --- a/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp @@ -22,10 +22,11 @@ class MapViewHolder #endif // STRESS_LOG #define STRESS_LOG_READONLY #include "../../../inc/stresslog.h" +#include "StressMsgReader.h" void GcHistClear(); -void GcHistAddLog(LPCSTR msg, StressMsg* stressMsg); +void GcHistAddLog(LPCSTR msg, StressMsgReader stressMsg); /*********************************************************************************/ @@ -57,7 +58,7 @@ ThreadStressLog* ThreadStressLog::FindLatestThreadLog() const for (const ThreadStressLog* ptr = this; ptr != NULL; ptr = ptr->next) { if (ptr->readPtr != NULL) - if (latestLog == 0 || ptr->readPtr->GetTimeStamp() > latestLog->readPtr->GetTimeStamp()) + if (latestLog == 0 || StressMsgReader(ptr->readPtr).GetTimeStamp() > StressMsgReader(latestLog->readPtr).GetTimeStamp()) latestLog = ptr; } return const_cast(latestLog); @@ -423,9 +424,9 @@ HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugD // TODO: fix on 64 bit inProcPtr->Activate (); - if (inProcPtr->readPtr->GetTimeStamp() > lastTimeStamp) + if (StressMsgReader(inProcPtr->readPtr).GetTimeStamp() > lastTimeStamp) { - lastTimeStamp = inProcPtr->readPtr->GetTimeStamp(); + lastTimeStamp = StressMsgReader(inProcPtr->readPtr).GetTimeStamp(); } outProcPtr = TO_CDADDR(inProcPtr->next); @@ -488,20 +489,20 @@ HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugD break; } - StressMsg* latestMsg = latestLog->readPtr; - if (latestMsg->GetFormatOffset() != 0 && !latestLog->CompletedDump()) + StressMsgReader latestMsg = latestLog->readPtr; + if (latestMsg.GetFormatOffset() != 0 && !latestLog->CompletedDump()) { - TADDR taFmt = (latestMsg->GetFormatOffset()) + TO_TADDR(g_hThisInst); + TADDR taFmt = (latestMsg.GetFormatOffset()) + TO_TADDR(g_hThisInst); hr = memCallBack->ReadVirtual(TO_CDADDR(taFmt), format, 256, 0); if (hr != S_OK) strcpy_s(format, ARRAY_SIZE(format), "Could not read address of format string"); - double deltaTime = ((double) (latestMsg->GetTimeStamp() - inProcLog.startTimeStamp)) / inProcLog.tickFrequency; + double deltaTime = ((double) (latestMsg.GetTimeStamp() - inProcLog.startTimeStamp)) / inProcLog.tickFrequency; if (bDoGcHist) { if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0) { - latestLog->threadId = (unsigned)(size_t)latestMsg->args[0]; + latestLog->threadId = (unsigned)(size_t)latestMsg.GetArgs()[0]; } GcHistAddLog(format, latestMsg); } @@ -509,19 +510,19 @@ HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugD { if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0) { - fprintf (file, "Task was switched from %x\n", (unsigned)(size_t)latestMsg->args[0]); - latestLog->threadId = (unsigned)(size_t)latestMsg->args[0]; + fprintf (file, "Task was switched from %x\n", (unsigned)(size_t)latestMsg.GetArgs()[0]); + latestLog->threadId = (unsigned)(size_t)latestMsg.GetArgs()[0]; } else { - args = latestMsg->args; - formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg->GetFacility(), args); + args = latestMsg.GetArgs(); + formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg.GetFacility(), args); } } msgCtr++; } - latestLog->readPtr = latestLog->AdvanceRead(latestMsg->GetNumberOfArgs()); + latestLog->readPtr = latestLog->AdvanceRead(latestMsg.GetNumberOfArgs()); if (latestLog->CompletedDump()) { latestLog->readPtr = NULL; diff --git a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp index 65e5edc5a3a9c..d4ec55851c711 100644 --- a/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp +++ b/src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp @@ -40,6 +40,7 @@ bool IsInCantAllocStressLogRegion() #include #include "../../../inc/stresslog.h" +#include "StressMsgReader.h" size_t StressLog::writing_base_address; size_t StressLog::reading_base_address; @@ -67,7 +68,7 @@ void GcHistClear() { } -void GcHistAddLog(LPCSTR msg, StressMsg* stressMsg) +void GcHistAddLog(LPCSTR msg, StressMsgReader stressMsg) { } @@ -531,7 +532,7 @@ bool FilterMessage(StressLog::StressLogHeader* hdr, ThreadStressLog* tsl, uint32 struct StressThreadAndMsg { uint64_t threadId; - StressMsg* msg; + StressMsgReader msg; uint64_t msgId; }; @@ -540,9 +541,9 @@ int CmpMsg(const void* p1, const void* p2) const StressThreadAndMsg* msg1 = (const StressThreadAndMsg*)p1; const StressThreadAndMsg* msg2 = (const StressThreadAndMsg*)p2; - if (msg1->msg->GetTimeStamp() < msg2->msg->GetTimeStamp()) + if (msg1->msg.GetTimeStamp() < msg2->msg.GetTimeStamp()) return 1; - if (msg1->msg->GetTimeStamp() > msg2->msg->GetTimeStamp()) + if (msg1->msg.GetTimeStamp() > msg2->msg.GetTimeStamp()) return -11; if (msg1->threadId < msg2->threadId) @@ -564,7 +565,7 @@ struct ThreadStressLogDesc volatile LONG workStarted; volatile LONG workFinished; ThreadStressLog* tsl; - StressMsg* earliestMessage; + StressMsgReader earliestMessage; ThreadStressLogDesc() : workStarted(0), workFinished(0), tsl(nullptr), earliestMessage(nullptr) { @@ -584,7 +585,7 @@ static double s_timeFilterStart = 0; static double s_timeFilterEnd = 0; static const char* s_outputFileName = nullptr; -static StressLog::StressLogHeader* s_hdr; +StressLog::StressLogHeader* s_hdr; static bool s_fPrintFormatStrings; @@ -1056,7 +1057,7 @@ bool ParseOptions(int argc, char* argv[]) return true; } -static void IncludeMessage(uint64_t threadId, StressMsg* msg) +static void IncludeMessage(uint64_t threadId, StressMsgReader msg) { LONGLONG msgCount = InterlockedIncrement64(&s_msgCount) - 1; if (msgCount < MAX_MESSAGE_COUNT) @@ -1089,10 +1090,10 @@ DWORD WINAPI ProcessStresslogWorker(LPVOID) wrappedWriteThreadCount++; } // printf("thread: %zx\n", tsl->threadId); - StressMsg* msg = StressLog::TranslateMemoryMappedPointer(tsl->curPtr); + void* msg = StressLog::TranslateMemoryMappedPointer(tsl->curPtr); StressLogChunk* slc = StressLog::TranslateMemoryMappedPointer(tsl->curWriteChunk); int chunkCount = 0; - StressMsg* prevMsg = nullptr; + void* prevMsg = nullptr; while (true) { // printf("stress log chunk %zx\n", (size_t)slc); @@ -1135,14 +1136,15 @@ DWORD WINAPI ProcessStresslogWorker(LPVOID) { while (p < end && *p == 0) p++; - msg = (StressMsg*)p; + msg = (void*)p; } - StressMsg* endMsg = (StressMsg*)end; + void* endMsg = (void*)end; while (msg < endMsg) { + StressMsgReader msgReader(msg); totalMsgCount++; - char* format = (char*)(hdr->moduleImage + msg->GetFormatOffset()); - double deltaTime = ((double)(msg->GetTimeStamp() - hdr->startTimeStamp)) / hdr->tickFrequency; + char* format = (char*)(hdr->moduleImage + msgReader.GetFormatOffset()); + double deltaTime = ((double)(msgReader.GetTimeStamp() - hdr->startTimeStamp)) / hdr->tickFrequency; bool fIgnoreMessage = false; if (fTimeFilter) { @@ -1156,17 +1158,17 @@ DWORD WINAPI ProcessStresslogWorker(LPVOID) fIgnoreMessage = true; } } - int numberOfArgs = msg->GetNumberOfArgs(); + int numberOfArgs = msgReader.GetNumberOfArgs(); if (!fIgnoreMessage) { - bool fIncludeMessage = s_showAllMessages || FilterMessage(hdr, tsl, msg->GetFacility(), format, deltaTime, numberOfArgs, msg->args); + bool fIncludeMessage = s_showAllMessages || FilterMessage(hdr, tsl, msgReader.GetFacility(), format, deltaTime, numberOfArgs, msgReader.GetArgs()); if (!fIncludeMessage && s_valueFilterCount > 0) { for (int i = 0; i < numberOfArgs; i++) { for (int j = 0; j < s_valueFilterCount; j++) { - if (s_valueFilter[j].start <= (size_t)msg->args[i] && (size_t)msg->args[i] <= s_valueFilter[j].end) + if (s_valueFilter[j].start <= (size_t)msgReader.GetArgs()[i] && (size_t)msgReader.GetArgs()[i] <= s_valueFilter[j].end) { fIncludeMessage = true; break; @@ -1182,7 +1184,7 @@ DWORD WINAPI ProcessStresslogWorker(LPVOID) } } prevMsg = msg; - msg = (StressMsg*)&msg->args[numberOfArgs]; + msg = (StressMsg*)&msgReader.GetArgs()[numberOfArgs]; } if (slc == StressLog::TranslateMemoryMappedPointer(tsl->chunkListTail) && !tsl->writeHasWrapped) break; @@ -1233,16 +1235,16 @@ static void PrintFriendlyNumber(LONGLONG n) printf("%11.9f billion", n / 1000000000.0); } -static void PrintMessage(CorClrData& corClrData, FILE *outputFile, uint64_t threadId, StressMsg* msg) +static void PrintMessage(CorClrData& corClrData, FILE *outputFile, uint64_t threadId, StressMsgReader msg) { void* argBuffer[StressMsg::maxArgCnt]; - char* format = (char*)(s_hdr->moduleImage + msg->GetFormatOffset()); - int numberOfArgs = msg->GetNumberOfArgs(); + char* format = (char*)(s_hdr->moduleImage + msg.GetFormatOffset()); + int numberOfArgs = msg.GetNumberOfArgs(); for (int i = 0; i < numberOfArgs; i++) { - argBuffer[i] = msg->args[i]; + argBuffer[i] = msg.GetArgs()[i]; } - double deltaTime = ((double)(msg->GetTimeStamp() - s_hdr->startTimeStamp)) / s_hdr->tickFrequency; + double deltaTime = ((double)(msg.GetTimeStamp() - s_hdr->startTimeStamp)) / s_hdr->tickFrequency; if (!s_printHexTidForGcThreads) { GcThread gcThread; @@ -1255,7 +1257,7 @@ static void PrintMessage(CorClrData& corClrData, FILE *outputFile, uint64_t thre threadId |= 0x4000000000000000; } } - formatOutput(&corClrData, outputFile, format, threadId, deltaTime, msg->GetFacility(), argBuffer, s_fPrintFormatStrings); + formatOutput(&corClrData, outputFile, format, threadId, deltaTime, msg.GetFacility(), argBuffer, s_fPrintFormatStrings); } int ProcessStressLog(void* baseAddress, int argc, char* argv[]) @@ -1301,7 +1303,8 @@ int ProcessStressLog(void* baseAddress, int argc, char* argv[]) StressLog::StressLogHeader* hdr = (StressLog::StressLogHeader*)baseAddress; if (hdr->headerSize != sizeof(*hdr) || hdr->magic != *(uint32_t*)"LRTS" || - hdr->version != 0x00010001) + (hdr->version != 0x00010001 && + hdr->version != 0x00010002)) { printf("Unrecognized file format\n"); return 1; @@ -1383,8 +1386,8 @@ int ProcessStressLog(void* baseAddress, int argc, char* argv[]) int remMsgCount = 0; for (int msgIndex = 0; msgIndex < s_msgCount; msgIndex++) { - StressMsg* msg = s_threadMsgBuf[msgIndex].msg; - double deltaTime = ((double)(msg->GetTimeStamp() - hdr->startTimeStamp)) / hdr->tickFrequency; + StressMsgReader msg = s_threadMsgBuf[msgIndex].msg; + double deltaTime = ((double)(msg.GetTimeStamp() - hdr->startTimeStamp)) / hdr->tickFrequency; if (startTime <= deltaTime && deltaTime <= endTime) { s_threadMsgBuf[remMsgCount] = s_threadMsgBuf[msgIndex]; @@ -1463,7 +1466,7 @@ int ProcessStressLog(void* baseAddress, int argc, char* argv[]) for (LONGLONG i = 0; i < s_msgCount; i++) { uint64_t threadId = (unsigned)s_threadMsgBuf[i].threadId; - StressMsg* msg = s_threadMsgBuf[i].msg; + StressMsgReader msg = s_threadMsgBuf[i].msg; PrintMessage(corClrData, outputFile, threadId, msg); } @@ -1500,7 +1503,7 @@ int ProcessStressLog(void* baseAddress, int argc, char* argv[]) LONGLONG earliestStartCount = s_msgCount; for (int threadStressLogIndex = 0; threadStressLogIndex < s_threadStressLogCount; threadStressLogIndex++) { - StressMsg* msg = s_threadStressLogDesc[threadStressLogIndex].earliestMessage; + StressMsgReader msg = s_threadStressLogDesc[threadStressLogIndex].earliestMessage; if (msg == nullptr) continue; bool fIncludeMessage = s_printEarliestMessages; @@ -1525,7 +1528,7 @@ int ProcessStressLog(void* baseAddress, int argc, char* argv[]) for (LONGLONG i = earliestStartCount; i < s_msgCount; i++) { uint64_t threadId = (unsigned)s_threadMsgBuf[i].threadId; - StressMsg* msg = s_threadMsgBuf[i].msg; + StressMsgReader msg = s_threadMsgBuf[i].msg; PrintMessage(corClrData, outputFile, threadId, msg); } } diff --git a/src/coreclr/tools/StressLogAnalyzer/StressMsgReader.h b/src/coreclr/tools/StressLogAnalyzer/StressMsgReader.h new file mode 100644 index 0000000000000..2d5bfe70e439b --- /dev/null +++ b/src/coreclr/tools/StressLogAnalyzer/StressMsgReader.h @@ -0,0 +1,80 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. + +#include + +extern StressLog::StressLogHeader* s_hdr; + +// A version-aware reader for memory-mapped stress log messages. +struct StressMsgReader +{ +private: + struct StressMsgSmallOffset + { + uint32_t numberOfArgsLow : 3; // at most 7 arguments here + uint32_t formatOffset : 26; // low bits offset of format string in modules + uint32_t numberOfArgsHigh : 3; // extend number of args in a backward compat way + uint32_t facility; // facility used to log the entry + uint64_t timeStamp; // time when mssg was logged + void* args[0]; // variable number of arguments + }; + + void* m_rawMsg; +public: + StressMsgReader() = default; + + StressMsgReader(void* msg) + :m_rawMsg(msg) + { + } + + uint64_t GetFormatOffset() const + { + if (s_hdr->version == 0x00010001) + { + return ((StressMsgSmallOffset*)m_rawMsg)->formatOffset; + } + return ((StressMsg*)m_rawMsg)->GetFormatOffset(); + } + + uint32_t GetNumberOfArgs() const + { + if (s_hdr->version == 0x00010001) + { + return ((StressMsgSmallOffset*)m_rawMsg)->numberOfArgsHigh << 3 | ((StressMsgSmallOffset*)m_rawMsg)->numberOfArgsLow; + } + return ((StressMsg*)m_rawMsg)->GetNumberOfArgs(); + } + + uint32_t GetFacility() const + { + if (s_hdr->version == 0x00010001) + { + return ((StressMsgSmallOffset*)m_rawMsg)->facility; + } + return ((StressMsg*)m_rawMsg)->GetFacility(); + } + + uint64_t GetTimeStamp() const + { + if (s_hdr->version == 0x00010001) + { + return ((StressMsgSmallOffset*)m_rawMsg)->timeStamp; + } + return ((StressMsg*)m_rawMsg)->GetTimeStamp(); + } + + void** GetArgs() const + { + if (s_hdr->version == 0x00010001) + { + return ((StressMsgSmallOffset*)m_rawMsg)->args; + } + return ((StressMsg*)m_rawMsg)->args; + } + + bool operator==(std::nullptr_t) const + { + return m_rawMsg == nullptr; + } +}; diff --git a/src/coreclr/utilcode/stresslog.cpp b/src/coreclr/utilcode/stresslog.cpp index c1f59b2aa89ee..c55c5afe9249c 100644 --- a/src/coreclr/utilcode/stresslog.cpp +++ b/src/coreclr/utilcode/stresslog.cpp @@ -266,7 +266,7 @@ void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxByte StressLogHeader* hdr = (StressLogHeader*)(uint8_t*)(void*)theLog.hMapView; hdr->headerSize = sizeof(StressLogHeader); hdr->magic = *(uint32_t*)"LRTS"; - hdr->version = 0x00010001; + hdr->version = 0x00010002; hdr->memoryBase = (uint8_t*)hdr; hdr->memoryCur = hdr->memoryBase + sizeof(StressLogHeader); hdr->memoryLimit = hdr->memoryBase + maxBytesTotal;