In _DEBUG, dump call stack when a contention lasts more than a thresh…

…old (1 second)
criteo-forks · Dec 3, 2018 · 7394345 · 7394345
1 parent 15797bb
commit 7394345
Show file tree

Hide file tree

Showing 2 changed files with 79 additions and 0 deletions.
diff --git a/src/vm/debughelp.cpp b/src/vm/debughelp.cpp
@@ -1249,5 +1249,35 @@ void LogStackTrace()
 }
 #endif
 
+const wchar_t* SEPARATOR = W("~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~~\n");
+void PrintStackTracewithHeader(wchar_t* wszHeader, bool sendToStdOut)
+{
+    CONTRACTL
+    {
+        DISABLED(NOTHROW);
+        DISABLED(GC_TRIGGERS);
+    }
+    CONTRACTL_END;
+
+
+    int toStdOut = 0;
+    if (sendToStdOut)
+    {
+        // traces will be sent to StdOut only
+        toStdOut = 1;
+        PrintToStdOutW(wszHeader);
+        PrintToStdOutW(SEPARATOR);
+    }
+    else
+    {
+        // traces will be sent to OutputDebugString only
+        WszOutputDebugString(wszHeader);
+        WszOutputDebugString(SEPARATOR);
+    }
+
+    PrintCallbackData cbd = { toStdOut, 0 };
+    GetThread()->StackWalkFrames(PrintStackTraceCallback, &cbd, ALLOW_ASYNC_STACK_WALK, 0);
+}
+
 #endif // #ifndef DACCESS_COMPILE
 #endif //_DEBUG
diff --git a/src/vm/syncblk.cpp b/src/vm/syncblk.cpp
@@ -3035,10 +3035,46 @@ inline void LogContention()
     }
 #endif
 }
+
+void PrintStackTracewithHeader(wchar_t* wszHeader, bool sendToStdOut);
+inline void LogContentionWithCallStack(double duration, DWORD threadID)
+{
+    WRAPPER_NO_CONTRACT;
+
+    const int nLen = 64;
+    wchar_t* pBuffer = (wchar_t*)alloca(nLen * sizeof(wchar_t));
+    pBuffer[0] = W('\0');
+    pBuffer[nLen - 1] = W('\0');
+    _snwprintf_s(pBuffer, nLen - 1, _TRUNCATE, W("Contention duration for thread #%u = %.2fs\n"), threadID, duration);
+
+    BOOL sendToStdOut = TRUE;
+    PrintStackTracewithHeader(pBuffer, sendToStdOut);
+}
 #else
 #define LogContention()
+inline void LogContentionWithCallStack(double duration, DWORD threadID)
+{
+    WRAPPER_NO_CONTRACT;
+}
 #endif
 
+
+inline double GetDurationInSeconds(FILETIME& start, FILETIME& end)
+{
+    ULARGE_INTEGER uliStart;
+    uliStart.HighPart = start.dwHighDateTime;
+    uliStart.LowPart = start.dwLowDateTime;
+
+    ULARGE_INTEGER uliEnd;
+    uliEnd.HighPart = end.dwHighDateTime;
+    uliEnd.LowPart = end.dwLowDateTime;
+
+    double durationInSeconds = ((double)((uliEnd.QuadPart - uliStart.QuadPart))) / 10000.0;
+    return durationInSeconds / 1000.0;
+}
+
+// TODO: read this value from an environment variable instead of this 1 seconds hardcoded value
+const double CLR_CONTENTION_DURATION_THRESHOLD = 1.0;
 BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
 {
     STATIC_CONTRACT_THROWS;
@@ -3058,6 +3094,10 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
 
     COUNTER_ONLY(GetPerfCounters().m_LocksAndThreads.cContention++);
 
+    // measure contention duration if more than the threshold
+    FILETIME startTime;
+    GetSystemTimeAsFileTime(&startTime);
+
     // Fire a contention start event for a managed contention
     FireEtwContentionStart_V1(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId());
 
@@ -3190,6 +3230,15 @@ BOOL AwareLock::EnterEpilogHelper(Thread* pCurThread, INT32 timeOut)
     GCPROTECT_END();
     DecrementTransientPrecious();
 
+    // dump call stack of the current thread if contention last too long
+    FILETIME endTime;
+    GetSystemTimeAsFileTime(&endTime);
+    double durationInSeconds = GetDurationInSeconds(endTime, startTime);
+    if (durationInSeconds >= CLR_CONTENTION_DURATION_THRESHOLD)
+    {
+        LogContentionWithCallStack(durationInSeconds, pCurThread->m_ThreadId);
+    }
+
     // Fire a contention end event for a managed contention
     FireEtwContentionStop(ETW::ContentionLog::ContentionStructs::ManagedContention, GetClrInstanceId());