1 // Licensed to the .NET Foundation under one or more agreements.
2 // The .NET Foundation licenses this file to you under the MIT license.
3 // See the LICENSE file in the project root for more information.
5 /*************************************************************************************/
7 /*************************************************************************************/
9 /*************************************************************************************/
11 #include "stdafx.h" // precompiled headers
14 #include "stresslog.h"
16 #define DONOT_DEFINE_ETW_CALLBACK
17 #include "eventtracebase.h"
20 #if !defined(STRESS_LOG_READONLY)
21 HANDLE StressLogChunk::s_LogChunkHeap = NULL;
22 #endif // !STRESS_LOG_READONLY
24 /*********************************************************************************/
25 #if defined(_TARGET_X86_)
27 /* This is like QueryPerformanceCounter but a lot faster. On machines with
28 variable-speed CPUs (for power management), this is not accurate, but may
31 __forceinline __declspec(naked) unsigned __int64 getTimeStamp() {
35 RDTSC // read time stamp counter
41 unsigned __int64 getTimeStamp() {
45 ZeroMemory(&ret, sizeof(LARGE_INTEGER));
47 QueryPerformanceCounter(&ret);
52 #endif // _TARGET_X86_
54 #if defined(_TARGET_X86_) && !defined(FEATURE_PAL)
56 /*********************************************************************************/
57 /* Get the the frequency cooresponding to 'getTimeStamp'. For x86, this is the
58 frequency of the RDTSC instruction, which is just the clock rate of the CPU.
59 This can vary due to power management, so this is at best a rough approximation.
61 unsigned __int64 getTickFrequency()
64 // At startup, the OS calculates the CPU clock frequency and makes it available
65 // at HKEY_LOCAL_MACHINE\HARDWARE\DESCRIPTION\System\CentralProcessor\0
68 unsigned __int64 hz = 0;
71 if (ERROR_SUCCESS == RegOpenKeyExW(
73 W("HARDWARE\\DESCRIPTION\\System\\CentralProcessor\\0"),
80 DWORD cbMhz = (DWORD)sizeof(mhz);
81 if (ERROR_SUCCESS == RegQueryValueExW(
89 _ASSERTE(REG_DWORD == mhzType);
90 _ASSERTE((DWORD)sizeof(mhz) == cbMhz);
92 hz = (unsigned __int64)mhz * 1000000;
101 #else // _TARGET_X86_
104 /*********************************************************************************/
105 /* Get the the frequency cooresponding to 'getTimeStamp'. For non-x86
106 architectures, this is just the performance counter frequency.
108 unsigned __int64 getTickFrequency()
111 ZeroMemory(&ret, sizeof(LARGE_INTEGER));
112 QueryPerformanceFrequency(&ret);
116 #endif // _TARGET_X86_
120 StressLog StressLog::theLog = { 0, 0, 0, 0, 0, 0, TLS_OUT_OF_INDEXES, 0, 0, 0 };
121 const static unsigned __int64 RECYCLE_AGE = 0x40000000L; // after a billion cycles, we can discard old threads
123 /*********************************************************************************/
124 void StressLog::Enter(CRITSEC_COOKIE) {
125 STATIC_CONTRACT_LEAF;
128 ClrEnterCriticalSection(theLog.lock);
132 void StressLog::Leave(CRITSEC_COOKIE) {
133 STATIC_CONTRACT_LEAF;
136 ClrLeaveCriticalSection(theLog.lock);
140 /*********************************************************************************/
141 void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxBytesPerThread,
142 unsigned maxBytesTotal, HMODULE hMod)
144 STATIC_CONTRACT_LEAF;
146 if (theLog.MaxSizePerThread != 0)
148 // guard ourself against multiple initialization. First init wins.
152 _ASSERTE (theLog.TLSslot == (unsigned int)TLS_OUT_OF_INDEXES);
153 theLog.lock = ClrCreateCriticalSection(CrstStressLog,(CrstFlags)(CRST_UNSAFE_ANYMODE|CRST_DEBUGGER_THREAD));
154 // StressLog::Terminate is going to free memory.
155 if (maxBytesPerThread < STRESSLOG_CHUNK_SIZE)
157 maxBytesPerThread = STRESSLOG_CHUNK_SIZE;
159 theLog.MaxSizePerThread = maxBytesPerThread;
161 if (maxBytesTotal < STRESSLOG_CHUNK_SIZE * 256)
163 maxBytesTotal = STRESSLOG_CHUNK_SIZE * 256;
165 theLog.MaxSizeTotal = maxBytesTotal;
166 theLog.totalChunk = 0;
167 theLog.facilitiesToLog = facilities | LF_ALWAYS;
168 theLog.levelToLog = level;
169 theLog.deadCount = 0;
170 theLog.TLSslot = TlsIdx_StressLog;
172 theLog.tickFrequency = getTickFrequency();
174 GetSystemTimeAsFileTime (&theLog.startTime);
175 theLog.startTimeStamp = getTimeStamp();
178 theLog.moduleOffset = (SIZE_T)hMod; // HMODULES are base addresses.
181 HMODULE hModNtdll = GetModuleHandleA("ntdll.dll");
182 theLog.RtlCaptureStackBackTrace = reinterpret_cast<PFNRtlCaptureStackBackTrace>(
183 GetProcAddress(hModNtdll, "RtlCaptureStackBackTrace"));
186 #else // !FEATURE_PAL
187 theLog.moduleOffset = (SIZE_T)PAL_GetSymbolModuleBase((void *)StressLog::Initialize);
188 #endif // !FEATURE_PAL
190 #if !defined (STRESS_LOG_READONLY)
191 StressLogChunk::s_LogChunkHeap = ClrHeapCreate (0, STRESSLOG_CHUNK_SIZE * 128, 0);
192 if (StressLogChunk::s_LogChunkHeap == NULL)
194 StressLogChunk::s_LogChunkHeap = ClrGetProcessHeap ();
196 _ASSERTE (StressLogChunk::s_LogChunkHeap);
197 #endif //!STRESS_LOG_READONLY
200 /*********************************************************************************/
201 void StressLog::Terminate(BOOL fProcessDetach) {
202 STATIC_CONTRACT_NOTHROW;
203 STATIC_CONTRACT_FORBID_FAULT;
205 if (theLog.TLSslot != (unsigned int)TLS_OUT_OF_INDEXES) {
206 theLog.facilitiesToLog = 0;
208 StressLogLockHolder lockh(theLog.lock, FALSE);
209 if (!fProcessDetach) {
210 lockh.Acquire(); lockh.Release(); // The Enter() Leave() forces a memory barrier on weak memory model systems
211 // we want all the other threads to notice that facilitiesToLog is now zero
213 // This is not strictly threadsafe, since there is no way of insuring when all the
214 // threads are out of logMsg. In practice, since they can no longer enter logMsg
215 // and there are no blocking operations in logMsg, simply sleeping will insure
216 // that everyone gets out.
217 ClrSleepEx(2, FALSE);
221 // Free the log memory
222 ThreadStressLog* ptr = theLog.logs;
225 ThreadStressLog* tmp = ptr;
230 theLog.TLSslot = TLS_OUT_OF_INDEXES;
231 if (!fProcessDetach) {
235 #if !defined (STRESS_LOG_READONLY)
236 if (StressLogChunk::s_LogChunkHeap != NULL && StressLogChunk::s_LogChunkHeap != ClrGetProcessHeap ())
238 ClrHeapDestroy (StressLogChunk::s_LogChunkHeap);
240 #endif //!STRESS_LOG_READONLY
243 /*********************************************************************************/
244 /* create a new thread stress log buffer associated with Thread local slot TLSslot, for the Stress log */
246 ThreadStressLog* StressLog::CreateThreadStressLog() {
255 static PVOID callerID = NULL;
257 ThreadStressLog* msgs = (ThreadStressLog*) ClrFlsGetValue(theLog.TLSslot);
263 if (callerID == ClrTeb::GetFiberPtrId())
268 //if we are not allowed to allocate stress log, we should not even try to take the lock
269 if (!StressLogChunk::s_LogChunkHeap || !CanThisThreadCallIntoHost() || IsInCantAllocStressLogRegion ())
274 // if it looks like we won't be allowed to allocate a new chunk, exit early
275 if (theLog.deadCount == 0 && !AllowNewChunk (0))
280 StressLogLockHolder lockh(theLog.lock, FALSE);
294 callerID = ClrTeb::GetFiberPtrId();
300 BOOL noFLSNow = FALSE;
304 // Acquiring the lack can throw an OOM exception the first time its called on a thread. We go
305 // ahead and try to provoke that now, before we've altered the list of available stress logs, and bail if
310 // ClrFlsSetValue can throw an OOM exception the first time its called on a thread for a given slot. We go
311 // ahead and try to provoke that now, before we've altered the list of available stress logs, and bail if
313 ClrFlsSetValue(theLog.TLSslot, NULL);
315 #pragma warning(suppress: 4101)
316 PAL_CPP_CATCH_DERIVED(OutOfMemoryException, obj)
318 // Just leave on any exception. Note: can't goto or return from within EX_CATCH...
323 if (noFLSNow == FALSE && theLog.facilitiesToLog != 0)
324 msgs = CreateThreadStressLogHelper();
329 ThreadStressLog* StressLog::CreateThreadStressLogHelper() {
339 _ASSERTE(theLog.TLSslot != (unsigned int)TLS_OUT_OF_INDEXES); // because facilitiesToLog is != 0
342 BOOL skipInsert = FALSE;
343 ThreadStressLog* msgs = NULL;
345 // See if we can recycle a dead thread
346 if (theLog.deadCount > 0)
348 unsigned __int64 recycleStamp = getTimeStamp() - RECYCLE_AGE;
350 //find out oldest dead ThreadStressLog in case we can't find one within
351 //recycle age but can't create a new chunk
352 ThreadStressLog * oldestDeadMsg = NULL;
358 BOOL hasTimeStamp = msgs->curPtr != (StressMsg *)msgs->chunkListTail->EndPtr();
359 if (hasTimeStamp && msgs->curPtr->timeStamp < recycleStamp)
362 InterlockedDecrement(&theLog.deadCount);
368 oldestDeadMsg = msgs;
370 else if (hasTimeStamp && oldestDeadMsg->curPtr->timeStamp > msgs->curPtr->timeStamp)
372 oldestDeadMsg = msgs;
379 //if the total stress log size limit is already passed and we can't add new chunk,
380 //always reuse the oldest dead msg
381 if (!AllowNewChunk (0) && !msgs)
383 msgs = oldestDeadMsg;
385 InterlockedDecrement(&theLog.deadCount);
390 FAULT_NOT_FATAL(); // We don't mind if we can't allocate here, we'll try again later.
391 if (IsInCantAllocStressLogRegion ())
396 msgs = new (nothrow) ThreadStressLog;
398 if (msgs == 0 ||!msgs->IsValid ())
408 // We know this isn't going to throw an exception now because the call to ClrFlsSetValue above succeeded for
411 CONTRACT_VIOLATION(ThrowsViolation);
412 ClrFlsSetValue(theLog.TLSslot, msgs);
417 ThreadStressLog* walk = theLog.logs;
420 _ASSERTE (walk != msgs);
424 // Put it into the stress log
425 msgs->next = theLog.logs;
434 /*********************************************************************************/
436 void StressLog::ThreadDetach(ThreadStressLog *msgs) {
437 STATIC_CONTRACT_NOTHROW;
438 STATIC_CONTRACT_FORBID_FAULT;
439 STATIC_CONTRACT_CANNOT_TAKE_LOCK;
441 #ifndef DACCESS_COMPILE
447 _ASSERTE(theLog.TLSslot != (unsigned int)TLS_OUT_OF_INDEXES); // because facilitiesToLog is != 0
448 // We are deleting a fiber. The thread is running a different fiber now.
449 // We should write this message to the StressLog for deleted fiber.
450 msgs->LogMsg (LF_STARTUP, 0, "******* DllMain THREAD_DETACH called Thread dying *******\n");
454 InterlockedIncrement(&theLog.deadCount);
457 BOOL StressLog::AllowNewChunk (LONG numChunksInCurThread)
459 _ASSERTE (numChunksInCurThread <= theLog.totalChunk);
460 DWORD perThreadLimit = theLog.MaxSizePerThread;
462 #ifndef DACCESS_COMPILE
463 if (numChunksInCurThread == 0 && IsSuspendEEThread())
466 if (IsGCSpecialThread())
468 perThreadLimit *= GC_STRESSLOG_MULTIPLY;
472 if ((DWORD)numChunksInCurThread * STRESSLOG_CHUNK_SIZE >= perThreadLimit)
477 return (DWORD)theLog.totalChunk * STRESSLOG_CHUNK_SIZE < theLog.MaxSizeTotal;
480 BOOL StressLog::ReserveStressLogChunks (unsigned chunksToReserve)
482 ThreadStressLog* msgs = (ThreadStressLog*) ClrFlsGetValue(theLog.TLSslot);
486 msgs = CreateThreadStressLog();
492 if (chunksToReserve == 0)
494 chunksToReserve = (theLog.MaxSizePerThread + STRESSLOG_CHUNK_SIZE - 1) / STRESSLOG_CHUNK_SIZE;
497 LONG numTries = (LONG)chunksToReserve - msgs->chunkListLength;
498 for (LONG i = 0; i < numTries; i++)
500 msgs->GrowChunkList ();
503 return msgs->chunkListLength >= (LONG)chunksToReserve;
506 void (*FSwitchToSOTolerant)();
507 void (*FSwitchToSOIntolerant)();
508 void TrackSO(BOOL tolerance)
512 if (FSwitchToSOTolerant)
514 FSwitchToSOTolerant();
519 if (FSwitchToSOIntolerant)
521 FSwitchToSOIntolerant();
526 /*********************************************************************************/
527 /* fetch a buffer that can be used to write a stress message, it is thread safe */
528 void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, va_list Args)
530 STATIC_CONTRACT_NOTHROW;
531 STATIC_CONTRACT_FORBID_FAULT;
533 // Asserts in this function cause infinite loops in the asserting mechanism.
534 // Just use debug breaks instead.
536 #ifndef DACCESS_COMPILE
538 // _ASSERTE ( cArgs >= 0 && cArgs <= 7 );
539 if (cArgs < 0 || cArgs > 7) DebugBreak();
542 size_t offs = ((size_t)format - StressLog::theLog.moduleOffset);
544 // _ASSERTE ( offs < StressMsg::maxOffset );
545 if (offs >= StressMsg::maxOffset)
548 DebugBreak(); // in lieu of the above _ASSERTE
551 // Set it to this string instead.
554 (size_t)"<BUG: StressLog format string beyond maxOffset>";
556 0; // a 0 offset is ignored by StressLog::Dump
557 #endif // _DEBUG else
560 // Get next available slot
561 StressMsg* msg = AdvanceWrite(cArgs);
563 msg->timeStamp = getTimeStamp();
564 msg->facility = facility;
565 msg->formatOffset = offs;
566 msg->numberOfArgs = cArgs;
568 for ( int i = 0; i < cArgs; ++i )
570 void* data = va_arg(Args, void*);
575 if (!IsValid () || threadId != GetCurrentThreadId ())
578 #endif //DACCESS_COMPILE
581 FORCEINLINE BOOL StressLog::InlinedStressLogOn(unsigned facility, unsigned level)
583 STATIC_CONTRACT_LEAF;
584 STATIC_CONTRACT_SUPPORTS_DAC;
586 #if defined(DACCESS_COMPILE)
589 return ((theLog.facilitiesToLog & facility) && (level <= theLog.levelToLog));
593 BOOL StressLog::StressLogOn(unsigned facility, unsigned level)
595 STATIC_CONTRACT_LEAF;
596 STATIC_CONTRACT_SUPPORTS_DAC;
598 return InlinedStressLogOn(facility, level);
601 FORCEINLINE BOOL StressLog::InlinedETWLogOn(unsigned facility, unsigned level)
603 STATIC_CONTRACT_LEAF;
604 STATIC_CONTRACT_SUPPORTS_DAC;
609 BOOL StressLog::ETWLogOn(unsigned facility, unsigned level)
611 STATIC_CONTRACT_LEAF;
612 STATIC_CONTRACT_SUPPORTS_DAC;
614 return InlinedETWLogOn(facility, level);
617 #if !defined(DACCESS_COMPILE)
618 BOOL StressLog::LogOn(unsigned facility, unsigned level)
620 STATIC_CONTRACT_LEAF;
621 STATIC_CONTRACT_SUPPORTS_DAC;
623 return InlinedStressLogOn(facility, level) || InlinedETWLogOn(facility, level);
628 void StressLog::LogMsg (unsigned level, unsigned facility, int cArgs, const char* format, ... )
630 STATIC_CONTRACT_SUPPORTS_DAC;
631 #ifndef DACCESS_COMPILE
632 STATIC_CONTRACT_NOTHROW;
633 STATIC_CONTRACT_GC_NOTRIGGER;
634 STATIC_CONTRACT_FORBID_FAULT;
635 STATIC_CONTRACT_SUPPORTS_DAC;
637 // Any stresslog LogMsg could theoretically create a new stress log and thus
638 // enter a critical section. But we don't want these to cause violations in
639 // CANNOT_TAKE_LOCK callers, since the callers would otherwise be fine in runs that don't
640 // set the stress log config parameter.
641 CONTRACT_VIOLATION(TakesLockViolation);
643 _ASSERTE ( cArgs >= 0 && cArgs <= 7 );
647 if(InlinedStressLogOn(facility, level))
649 ThreadStressLog* msgs = (ThreadStressLog*) ClrFlsGetValue(theLog.TLSslot);
652 msgs = CreateThreadStressLog();
657 va_start(Args, format);
658 msgs->LogMsg (facility, cArgs, format, Args);
662 // Stress Log ETW feature available only on the desktop versions of the runtime
663 #endif //!DACCESS_COMPILE
668 void StressLog::LogCallStack(const char *const callTag){
669 if (theLog.RtlCaptureStackBackTrace)
671 size_t CallStackTrace[MAX_CALL_STACK_TRACE];
673 USHORT stackTraceCount = theLog.RtlCaptureStackBackTrace (2, MAX_CALL_STACK_TRACE, (PVOID *)CallStackTrace, &hash);
674 if (stackTraceCount > MAX_CALL_STACK_TRACE)
675 stackTraceCount = MAX_CALL_STACK_TRACE;
676 LogMsgOL("Start of %s stack \n", callTag);
678 for (;i < stackTraceCount; i++)
680 LogMsgOL("(%s stack)%pK\n", callTag, CallStackTrace[i]);
682 LogMsgOL("End of %s stack\n", callTag);