Dprintf optimization (#47046)

This is support for putting the stress log into a memory mapped file and piping the dprintf calls in the GC codebase to the stress log.

It's much faster than the dprintf implementation we used before and doesn't take a lock for each dprintf call - only when it needs to get a new buffer. It also works for clrgc.dll, which accounts for some complications, because now calls can come from either coreclr.dll or clrgc.dll.

There is logic inside src/coreclr/util/StressLog.cpp to switch to the memory mapped file when the new environment variable COMPLUS_StressLogFilename is set. Here's a set of environment variables I've used:

COMPLUS_StressLogFilename=GCPerfSimStresslog.log
COMPLUS_gcServer=1
COMPLUS_LogLevel=9
COMPlus_StressLog=1
COMPlus_StressLogSize=10000000
COMPlus_TotalStressLogSize=1000000000

So this creates a max of 64 GB of stress log.

There is an analyzer tool to go with this under src/coreclr/tools/StressLogAnalyzer that is also part of this checkin. The tool is expected to become more sophisticated over time. The tool is itself multithreaded and uses a plugin dll for the actual analysis which makes it possible to change the plugin, rebuild and re-run the analysis on the in-memory log datastructure without reloading the log file.

The stresslog mechanism had a limit of 7 arguments so far, which seemed too small, so I've increased that to 12 currently. It can easily be increased up to 63, which is the limit in the format. The higher number of arguments is only supported when putting the stress log into a file, it is not yet supported when building the stress log in memory the traditional way. 

Supporting it would call for changes in SOS that I haven't done yet. However, stress logs containing no calls of more than 7 arguments would be dumped correctly by the current SOS - SOS would crash though with stress logs containing calls with more arguments. To catch this early, the logic in StressLog.cpp does a debug break when a call with more than 7 arguments is attempted without the memory-mapped file.

Note that for the purposes of GC logging, the logging level specified in the dprintf call is also persisted in the stress log. This makes it possible to selectively dump messages from specific subsystems.

1 files changed, 265 insertions, 34 deletions

diff --git a/src/coreclr/utilcode/stresslog.cpp b/src/coreclr/utilcode/stresslog.cpp
index 108080455d7..2b81551eb38 100644
--- a/src/coreclr/utilcode/stresslog.cpp
+++ b/src/coreclr/utilcode/stresslog.cpp
@@ -21,6 +21,7 @@
 HANDLE StressLogChunk::s_LogChunkHeap = NULL;
 #endif
 thread_local ThreadStressLog* StressLog::t_pCurrentThreadLog;
+thread_local bool t_triedToCreateThreadStressLog;
 #endif // !STRESS_LOG_READONLY
 
 /*********************************************************************************/
@@ -140,8 +141,8 @@ void StressLog::Leave(CRITSEC_COOKIE) {
 }
 
 /*********************************************************************************/
-void StressLog::Initialize(unsigned facilities,  unsigned level, unsigned maxBytesPerThread,
-            unsigned maxBytesTotal, void* moduleBase)
+void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxBytesPerThread,
+    ULONGLONG maxBytesTotal, void* moduleBase, LPWSTR logFilename)
 {
     STATIC_CONTRACT_LEAF;
 
@@ -151,7 +152,7 @@ void StressLog::Initialize(unsigned facilities,  unsigned level, unsigned maxByt
         return;
     }
 
-    theLog.lock = ClrCreateCriticalSection(CrstStressLog,(CrstFlags)(CRST_UNSAFE_ANYMODE|CRST_DEBUGGER_THREAD|CRST_TAKEN_DURING_SHUTDOWN));
+    theLog.lock = ClrCreateCriticalSection(CrstStressLog, (CrstFlags)(CRST_UNSAFE_ANYMODE | CRST_DEBUGGER_THREAD | CRST_TAKEN_DURING_SHUTDOWN));
     // StressLog::Terminate is going to free memory.
     if (maxBytesPerThread < STRESSLOG_CHUNK_SIZE)
     {
@@ -163,7 +164,7 @@ void StressLog::Initialize(unsigned facilities,  unsigned level, unsigned maxByt
     {
         maxBytesTotal = STRESSLOG_CHUNK_SIZE * 256;
     }
-    theLog.MaxSizeTotal = maxBytesTotal;
+    theLog.MaxSizeTotal = (unsigned)min(maxBytesTotal, 0xffffffff);;
     theLog.totalChunk = 0;
     theLog.facilitiesToLog = facilities | LF_ALWAYS;
     theLog.levelToLog = level;
@@ -171,7 +172,7 @@ void StressLog::Initialize(unsigned facilities,  unsigned level, unsigned maxByt
 
     theLog.tickFrequency = getTickFrequency();
 
-    GetSystemTimeAsFileTime (&theLog.startTime);
+    GetSystemTimeAsFileTime(&theLog.startTime);
     theLog.startTimeStamp = getTimeStamp();
     theLog.moduleOffset = (SIZE_T)moduleBase;
 
@@ -179,18 +180,113 @@ void StressLog::Initialize(unsigned facilities,  unsigned level, unsigned maxByt
 #ifdef _DEBUG
     HMODULE hModNtdll = GetModuleHandleA("ntdll.dll");
     theLog.RtlCaptureStackBackTrace = reinterpret_cast<PFNRtlCaptureStackBackTrace>(
-            GetProcAddress(hModNtdll, "RtlCaptureStackBackTrace"));
+        GetProcAddress(hModNtdll, "RtlCaptureStackBackTrace"));
 #endif // _DEBUG
 #endif // !HOST_UNIX
 
 #if !defined (STRESS_LOG_READONLY) && defined(HOST_WINDOWS)
-    StressLogChunk::s_LogChunkHeap = HeapCreate (0, STRESSLOG_CHUNK_SIZE * 128, 0);
-    if (StressLogChunk::s_LogChunkHeap == NULL)
+    if (logFilename == nullptr)
     {
-        StressLogChunk::s_LogChunkHeap = GetProcessHeap ();
+        StressLogChunk::s_LogChunkHeap = HeapCreate(0, STRESSLOG_CHUNK_SIZE * 128, 0);
+        if (StressLogChunk::s_LogChunkHeap == NULL)
+        {
+            StressLogChunk::s_LogChunkHeap = GetProcessHeap();
+        }
+        _ASSERTE(StressLogChunk::s_LogChunkHeap);
     }
-    _ASSERTE (StressLogChunk::s_LogChunkHeap);
 #endif //!STRESS_LOG_READONLY
+
+#ifdef MEMORY_MAPPED_STRESSLOG
+    if (logFilename != nullptr)
+    {
+        if (maxBytesTotal < sizeof(StressLogHeader))
+        {
+            return;
+        }
+        HandleHolder hFile = WszCreateFile(logFilename,
+            GENERIC_READ | GENERIC_WRITE,
+            FILE_SHARE_READ,
+            NULL,                 // default security descriptor
+            CREATE_ALWAYS,
+            FILE_ATTRIBUTE_NORMAL,
+            NULL);
+
+        if (hFile == INVALID_HANDLE_VALUE)
+        {
+            return;
+        }
+
+        size_t fileSize = maxBytesTotal;
+        HandleHolder hMap = WszCreateFileMapping(hFile, NULL, PAGE_READWRITE, (DWORD)(fileSize >> 32), (DWORD)fileSize, NULL);
+        if (hMap == NULL)
+        {
+            return;
+        }
+
+        theLog.hMapView = MapViewOfFileEx(hMap, FILE_MAP_ALL_ACCESS, 0, 0, fileSize, (void*)0x400000000000);
+        if (theLog.hMapView == NULL)
+        {
+            return;
+        }
+
+        StressLogHeader* hdr = (StressLogHeader*)(uint8_t*)(void*)theLog.hMapView;
+        hdr->headerSize = sizeof(StressLogHeader);
+        hdr->magic = 'STRL';
+        hdr->version = 0x00010001;
+        hdr->memoryBase = (uint8_t*)hdr;
+        hdr->memoryCur = hdr->memoryBase + sizeof(StressLogHeader);
+        hdr->memoryLimit = hdr->memoryBase + fileSize;
+        hdr->logs = nullptr;
+        hdr->tickFrequency = theLog.tickFrequency;
+        hdr->startTimeStamp = theLog.startTimeStamp;
+        theLog.stressLogHeader = hdr;
+
+        // copy coreclr image - just for the string literals
+        AddModule((uint8_t*)moduleBase);
+    }
+#endif
+}
+
+void StressLog::AddModule(uint8_t* moduleBase)
+{
+#ifdef MEMORY_MAPPED_STRESSLOG
+    int moduleIndex = 0;
+    StressLogHeader* hdr = theLog.stressLogHeader;
+    if (hdr == nullptr)
+    {
+        // nothing to do for the non-memory mapped stress log
+        return;
+    }
+    size_t cumSize = 0;
+    while (moduleIndex < MAX_MODULES && hdr->modules[moduleIndex].baseAddress != nullptr)
+    {
+        if (hdr->modules[moduleIndex].baseAddress == moduleBase)
+            return;
+        cumSize += hdr->modules[moduleIndex].size;
+        moduleIndex++;
+    }
+    if (moduleIndex >= MAX_MODULES)
+    {
+        DebugBreak();
+        return;
+    }
+    hdr->modules[moduleIndex].baseAddress = moduleBase;
+    uint8_t* addr = moduleBase;
+    while (true)
+    {
+        MEMORY_BASIC_INFORMATION mbi;
+        size_t size = VirtualQuery(addr, &mbi, sizeof(mbi));
+        if (size == 0)
+            break;
+        // copy the region containing string literals to the memory mapped file
+        if (mbi.AllocationBase != moduleBase)
+            break;
+        ptrdiff_t offs = (uint8_t*)mbi.BaseAddress - (uint8_t*)mbi.AllocationBase + cumSize;
+        memcpy(&hdr->moduleImage[offs], mbi.BaseAddress, mbi.RegionSize);
+        addr += mbi.RegionSize;
+        hdr->modules[moduleIndex].size = (size_t)(addr - (uint8_t*)moduleBase);
+    }
+#endif //MEMORY_MAPPED_STRESSLOG
 }
 
 /*********************************************************************************/
@@ -259,7 +355,7 @@ ThreadStressLog* StressLog::CreateThreadStressLog() {
         return NULL;
     }
 
-#ifdef HOST_WINDOWS
+#if defined(HOST_WINDOWS) && !defined(MEMORY_MAPPED_STRESSLOG)
     if (!StressLogChunk::s_LogChunkHeap)
     {
         return NULL;
@@ -397,9 +493,28 @@ ThreadStressLog* StressLog::CreateThreadStressLogHelper() {
         {
             delete msgs;
             msgs = 0;
+#ifdef MEMORY_MAPPED_STRESSLOG
+            if (!t_triedToCreateThreadStressLog && theLog.stressLogHeader != nullptr)
+            {
+                theLog.stressLogHeader->threadsWithNoLog++;
+                t_triedToCreateThreadStressLog = true;
+            }
+#endif //MEMORY_MAPPED_STRESSLOG
             goto LEAVE;
         }
     }
+    else
+    {
+        // recycle old thread msg
+        msgs->threadId = GetCurrentThreadId();
+        StressLogChunk* slc = msgs->chunkListHead;
+        while (true)
+        {
+            if (slc == msgs->chunkListTail)
+                break;
+            slc = slc->next;
+        }
+    }
 
     msgs->Activate ();
 
@@ -417,6 +532,10 @@ ThreadStressLog* StressLog::CreateThreadStressLogHelper() {
         // Put it into the stress log
         msgs->next = theLog.logs;
         theLog.logs = msgs;
+#ifdef MEMORY_MAPPED_STRESSLOG
+        if (theLog.stressLogHeader != nullptr)
+        theLog.stressLogHeader->logs = msgs;
+#endif // MEMORY_MAPPED_STRESSLOG
     }
 
 LEAVE:
@@ -470,7 +589,7 @@ BOOL StressLog::AllowNewChunk (LONG numChunksInCurThread)
         return FALSE;
     }
 
-    return (DWORD)theLog.totalChunk * STRESSLOG_CHUNK_SIZE < theLog.MaxSizeTotal;
+    return theLog.MaxSizeTotal == 0xffffffff || (DWORD)theLog.totalChunk * STRESSLOG_CHUNK_SIZE < theLog.MaxSizeTotal;
 }
 
 BOOL StressLog::ReserveStressLogChunks (unsigned chunksToReserve)
@@ -521,45 +640,75 @@ void TrackSO(BOOL tolerance)
 
 /*********************************************************************************/
 /* fetch a buffer that can be used to write a stress message, it is thread safe */
-void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, va_list Args)
+FORCEINLINE void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, va_list Args)
 {
     STATIC_CONTRACT_NOTHROW;
     STATIC_CONTRACT_FORBID_FAULT;
 
-	// Asserts in this function cause infinite loops in the asserting mechanism.
-	// Just use debug breaks instead.
+    // Asserts in this function cause infinite loops in the asserting mechanism.
+    // Just use debug breaks instead.
 
 #ifndef DACCESS_COMPILE
 #ifdef _DEBUG
-    // _ASSERTE ( cArgs >= 0 && cArgs <= 7 );
-	if (cArgs < 0 || cArgs > 7) DebugBreak();
+    // _ASSERTE ( cArgs >= 0 && cArgs <= 63 );
+    if (cArgs < 0 || cArgs > 63) DebugBreak();
 #endif //
 
-    size_t offs = ((size_t)format - StressLog::theLog.moduleOffset);
+    size_t offs = 0;
+#ifdef MEMORY_MAPPED_STRESSLOG
+    StressLog::StressLogHeader* hdr = StressLog::theLog.stressLogHeader;
+    if (hdr != nullptr)
+    {
+        int moduleIndex = 0;
+        size_t cumSize = 0;
+        offs = 0;
+        while (moduleIndex < StressLog::MAX_MODULES)
+        {
+            offs = (uint8_t*)format - hdr->modules[moduleIndex].baseAddress;
+            if (offs < hdr->modules[moduleIndex].size)
+            {
+                offs += cumSize;
+                break;
+            }
+            cumSize += hdr->modules[moduleIndex].size;
+            moduleIndex++;
+        }
+    }
+    else
+#endif // MEMORY_MAPPED_STRESSLOG
+    {
+#ifdef _DEBUG
+        // currently SOS stress log only supports a maximum of 7 arguments
+        if (cArgs > 7)
+            DebugBreak();
+#endif //_DEBUG
+        offs = ((size_t)format - StressLog::theLog.moduleOffset);
+    }
 
     // _ASSERTE ( offs < StressMsg::maxOffset );
-	if (offs >= StressMsg::maxOffset)
-	{
+    if (offs >= StressMsg::maxOffset)
+    {
 #ifdef _DEBUG
-		DebugBreak(); // in lieu of the above _ASSERTE
+        DebugBreak(); // in lieu of the above _ASSERTE
 #endif // _DEBUG
 
-		// Set it to this string instead.
-		offs =
+        // Set it to this string instead.
+        offs =
 #ifdef _DEBUG
-			(size_t)"<BUG: StressLog format string beyond maxOffset>";
+            (size_t)"<BUG: StressLog format string beyond maxOffset>";
 #else // _DEBUG
-			0; // a 0 offset is ignored by StressLog::Dump
+            0; // a 0 offset is ignored by StressLog::Dump
 #endif // _DEBUG else
-	}
+    }
 
     // Get next available slot
     StressMsg* msg = AdvanceWrite(cArgs);
 
     msg->timeStamp = getTimeStamp();
     msg->facility = facility;
-	msg->formatOffset = offs;
-	msg->numberOfArgs = cArgs;
+    msg->formatOffset = offs;
+    msg->numberOfArgs = cArgs & 0x7;
+    msg->numberOfArgsX = cArgs >> 3;
 
     for ( int i = 0; i < cArgs; ++i )
     {
@@ -567,6 +716,9 @@ void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, v
         msg->args[i] = data;
     }
 
+    // only store curPtr once the msg is complete
+    curPtr = msg;
+
 #ifdef _DEBUG
     if (!IsValid () || threadId != GetCurrentThreadId ())
         DebugBreak();
@@ -574,6 +726,14 @@ void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, v
 #endif //DACCESS_COMPILE
 }
 
+void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, ...)
+{
+    va_list Args;
+    va_start(Args, format);
+    LogMsg(facility, cArgs, format, Args);
+    va_end(Args);
+}
+
 FORCEINLINE BOOL StressLog::InlinedStressLogOn(unsigned facility, unsigned level)
 {
     STATIC_CONTRACT_LEAF;
@@ -621,7 +781,7 @@ BOOL StressLog::LogOn(unsigned facility, unsigned level)
 #endif
 
 /* static */
-void StressLog::LogMsg (unsigned level, unsigned facility, int cArgs, const char* format, ... )
+void StressLog::LogMsg(unsigned level, unsigned facility, int cArgs, const char* format, ...)
 {
     STATIC_CONTRACT_SUPPORTS_DAC;
 #ifndef DACCESS_COMPILE
@@ -636,26 +796,65 @@ void StressLog::LogMsg (unsigned level, unsigned facility, int cArgs, const char
     // set the stress log config parameter.
     CONTRACT_VIOLATION(TakesLockViolation);
 
-    _ASSERTE ( cArgs >= 0 && cArgs <= 7 );
+    _ASSERTE(cArgs >= 0 && cArgs <= 63);
 
     va_list Args;
 
-    if(InlinedStressLogOn(facility, level))
+    if (InlinedStressLogOn(facility, level))
     {
         ThreadStressLog* msgs = t_pCurrentThreadLog;
 
-        if (msgs == 0) {
+        if (msgs == 0)
+        {
             msgs = CreateThreadStressLog();
 
             if (msgs == 0)
                 return;
         }
         va_start(Args, format);
-        msgs->LogMsg (facility, cArgs, format, Args);
+        msgs->LogMsg(facility, cArgs, format, Args);
         va_end(Args);
     }
 
-// Stress Log ETW feature available only on the desktop versions of the runtime
+    // Stress Log ETW feature available only on the desktop versions of the runtime
+#endif //!DACCESS_COMPILE
+}
+
+/* static */
+void StressLog::LogMsg(unsigned level, unsigned facility, const StressLogMsg &msg)
+{
+    STATIC_CONTRACT_SUPPORTS_DAC;
+#ifndef DACCESS_COMPILE
+    STATIC_CONTRACT_NOTHROW;
+    STATIC_CONTRACT_GC_NOTRIGGER;
+    STATIC_CONTRACT_FORBID_FAULT;
+    STATIC_CONTRACT_SUPPORTS_DAC;
+
+    // Any stresslog LogMsg could theoretically create a new stress log and thus
+    // enter a critical section.  But we don't want these to cause violations in
+    // CANNOT_TAKE_LOCK callers, since the callers would otherwise be fine in runs that don't
+    // set the stress log config parameter.
+    CONTRACT_VIOLATION(TakesLockViolation);
+
+    _ASSERTE(msg.m_cArgs >= 0 && msg.m_cArgs <= 63);
+
+    if (InlinedStressLogOn(facility, level))
+    {
+#ifdef HOST_WINDOWS // On Linux, this cast: (va_list)msg.m_args gives a compile error
+       ThreadStressLog* msgs = t_pCurrentThreadLog;
+
+        if (msgs == 0)
+        {
+            msgs = CreateThreadStressLog();
+
+            if (msgs == 0)
+                return;
+        }
+        msgs->LogMsg(facility, msg.m_cArgs, msg.m_format, (va_list)msg.m_args);
+#endif //HOST_WINDOWS
+    }
+
+    // Stress Log ETW feature available only on the desktop versions of the runtime
 #endif //!DACCESS_COMPILE
 }
 
@@ -680,5 +879,37 @@ void  StressLog::LogCallStack(const char *const callTag){
 }
 #endif //_DEBUG
 
+#ifdef MEMORY_MAPPED_STRESSLOG
+void* StressLog::AllocMemoryMapped(size_t n)
+{
+    if ((ptrdiff_t)n > 0)
+    {
+        StressLogHeader* hdr = theLog.stressLogHeader;
+        assert(hdr != nullptr);
+        uint8_t* newMemValue = (uint8_t*)InterlockedAdd64((LONG64*)&hdr->memoryCur, n);
+        if (newMemValue < hdr->memoryLimit)
+        {
+            return newMemValue - n;
+        }
+        // when we run out, we just can't allocate anymore
+        hdr->memoryCur = hdr->memoryLimit;
+    }
+    return nullptr;
+}
+
+void* __cdecl ThreadStressLog::operator new(size_t n, const NoThrow&) NOEXCEPT
+{
+    if (StressLogChunk::s_LogChunkHeap != NULL)
+    {
+        //no need to zero memory because we could handle garbage contents
+        return HeapAlloc(StressLogChunk::s_LogChunkHeap, 0, n);
+    }
+    else
+    {
+        return StressLog::AllocMemoryMapped(n);
+    }
+}
+#endif //MEMORY_MAPPED_STRESSLOG
+
 #endif // STRESS_LOG