Enable StressLogAnalyzer to read stress logs from old coreclr running with a new...
authorJeremy Koritzinsky <jekoritz@microsoft.com>
Fri, 14 Jul 2023 14:08:56 +0000 (07:08 -0700)
committerGitHub <noreply@github.com>
Fri, 14 Jul 2023 14:08:56 +0000 (07:08 -0700)
src/coreclr/inc/stresslog.h
src/coreclr/tools/StressLogAnalyzer/StressLogDump.cpp
src/coreclr/tools/StressLogAnalyzer/StressLogPlugin.cpp
src/coreclr/tools/StressLogAnalyzer/StressMsgReader.h [new file with mode: 0644]
src/coreclr/utilcode/stresslog.cpp

index 7315177..cdc4b58 100644 (file)
@@ -372,7 +372,9 @@ public:
     {
         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
index 61fa9c4..f3be8b8 100644 (file)
@@ -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<ThreadStressLog*>(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;
index 65e5edc..d4ec558 100644 (file)
@@ -40,6 +40,7 @@ bool IsInCantAllocStressLogRegion()
 
 #include <stddef.h>
 #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 (file)
index 0000000..2d5bfe7
--- /dev/null
@@ -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 <stdint.h>
+
+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;
+    }
+};
index c1f59b2..c55c5af 100644 (file)
@@ -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;