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.
4
5/*************************************************************************************/
6/* StressLog.cpp */
7/*************************************************************************************/
8
9/*************************************************************************************/
10
11#include "stdafx.h" // precompiled headers
12
13#include "switches.h"
14#include "stresslog.h"
15#include "clrhost.h"
16#define DONOT_DEFINE_ETW_CALLBACK
17#include "eventtracebase.h"
18#include "ex.h"
19
20 #if !defined(STRESS_LOG_READONLY)
21HANDLE StressLogChunk::s_LogChunkHeap = NULL;
22#endif // !STRESS_LOG_READONLY
23
24/*********************************************************************************/
25#if defined(_TARGET_X86_)
26
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
29 be good enough.
30*/
31__forceinline __declspec(naked) unsigned __int64 getTimeStamp() {
32 STATIC_CONTRACT_LEAF;
33
34 __asm {
35 RDTSC // read time stamp counter
36 ret
37 };
38}
39
40#else // _TARGET_X86_
41unsigned __int64 getTimeStamp() {
42 STATIC_CONTRACT_LEAF;
43
44 LARGE_INTEGER ret;
45 ZeroMemory(&ret, sizeof(LARGE_INTEGER));
46
47 QueryPerformanceCounter(&ret);
48
49 return ret.QuadPart;
50}
51
52#endif // _TARGET_X86_
53
54#if defined(_TARGET_X86_) && !defined(FEATURE_PAL)
55
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.
60*/
61unsigned __int64 getTickFrequency()
62{
63 //
64 // At startup, the OS calculates the CPU clock frequency and makes it available
65 // at HKEY_LOCAL_MACHINE\HARDWARE\DESCRIPTION\System\CentralProcessor\0
66 //
67
68 unsigned __int64 hz = 0;
69
70 HKEY hKey;
71 if (ERROR_SUCCESS == RegOpenKeyExW(
72 HKEY_LOCAL_MACHINE,
73 W("HARDWARE\\DESCRIPTION\\System\\CentralProcessor\\0"),
74 0,
75 KEY_QUERY_VALUE,
76 &hKey))
77 {
78 DWORD mhz;
79 DWORD mhzType;
80 DWORD cbMhz = (DWORD)sizeof(mhz);
81 if (ERROR_SUCCESS == RegQueryValueExW(
82 hKey,
83 W("~MHz"),
84 NULL,
85 &mhzType,
86 (LPBYTE)&mhz,
87 &cbMhz))
88 {
89 _ASSERTE(REG_DWORD == mhzType);
90 _ASSERTE((DWORD)sizeof(mhz) == cbMhz);
91
92 hz = (unsigned __int64)mhz * 1000000;
93 }
94
95 RegCloseKey(hKey);
96 }
97
98 return hz;
99}
100
101#else // _TARGET_X86_
102
103
104/*********************************************************************************/
105/* Get the the frequency cooresponding to 'getTimeStamp'. For non-x86
106 architectures, this is just the performance counter frequency.
107*/
108unsigned __int64 getTickFrequency()
109{
110 LARGE_INTEGER ret;
111 ZeroMemory(&ret, sizeof(LARGE_INTEGER));
112 QueryPerformanceFrequency(&ret);
113 return ret.QuadPart;
114}
115
116#endif // _TARGET_X86_
117
118#ifdef STRESS_LOG
119
120StressLog StressLog::theLog = { 0, 0, 0, 0, 0, 0, TLS_OUT_OF_INDEXES, 0, 0, 0 };
121const static unsigned __int64 RECYCLE_AGE = 0x40000000L; // after a billion cycles, we can discard old threads
122
123/*********************************************************************************/
124void StressLog::Enter(CRITSEC_COOKIE) {
125 STATIC_CONTRACT_LEAF;
126
127 IncCantAllocCount();
128 ClrEnterCriticalSection(theLog.lock);
129 DecCantAllocCount();
130}
131
132void StressLog::Leave(CRITSEC_COOKIE) {
133 STATIC_CONTRACT_LEAF;
134
135 IncCantAllocCount();
136 ClrLeaveCriticalSection(theLog.lock);
137 DecCantAllocCount();
138}
139
140/*********************************************************************************/
141void StressLog::Initialize(unsigned facilities, unsigned level, unsigned maxBytesPerThread,
142 unsigned maxBytesTotal, HMODULE hMod)
143{
144 STATIC_CONTRACT_LEAF;
145
146 if (theLog.MaxSizePerThread != 0)
147 {
148 // guard ourself against multiple initialization. First init wins.
149 return;
150 }
151
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)
156 {
157 maxBytesPerThread = STRESSLOG_CHUNK_SIZE;
158 }
159 theLog.MaxSizePerThread = maxBytesPerThread;
160
161 if (maxBytesTotal < STRESSLOG_CHUNK_SIZE * 256)
162 {
163 maxBytesTotal = STRESSLOG_CHUNK_SIZE * 256;
164 }
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;
171
172 theLog.tickFrequency = getTickFrequency();
173
174 GetSystemTimeAsFileTime (&theLog.startTime);
175 theLog.startTimeStamp = getTimeStamp();
176
177#ifndef FEATURE_PAL
178 theLog.moduleOffset = (SIZE_T)hMod; // HMODULES are base addresses.
179
180#ifdef _DEBUG
181 HMODULE hModNtdll = GetModuleHandleA("ntdll.dll");
182 theLog.RtlCaptureStackBackTrace = reinterpret_cast<PFNRtlCaptureStackBackTrace>(
183 GetProcAddress(hModNtdll, "RtlCaptureStackBackTrace"));
184#endif // _DEBUG
185
186#else // !FEATURE_PAL
187 theLog.moduleOffset = (SIZE_T)PAL_GetSymbolModuleBase((void *)StressLog::Initialize);
188#endif // !FEATURE_PAL
189
190#if !defined (STRESS_LOG_READONLY)
191 StressLogChunk::s_LogChunkHeap = ClrHeapCreate (0, STRESSLOG_CHUNK_SIZE * 128, 0);
192 if (StressLogChunk::s_LogChunkHeap == NULL)
193 {
194 StressLogChunk::s_LogChunkHeap = ClrGetProcessHeap ();
195 }
196 _ASSERTE (StressLogChunk::s_LogChunkHeap);
197#endif //!STRESS_LOG_READONLY
198}
199
200/*********************************************************************************/
201void StressLog::Terminate(BOOL fProcessDetach) {
202 STATIC_CONTRACT_NOTHROW;
203 STATIC_CONTRACT_FORBID_FAULT;
204
205 if (theLog.TLSslot != (unsigned int)TLS_OUT_OF_INDEXES) {
206 theLog.facilitiesToLog = 0;
207
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
212
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);
218 lockh.Acquire();
219 }
220
221 // Free the log memory
222 ThreadStressLog* ptr = theLog.logs;
223 theLog.logs = 0;
224 while(ptr != 0) {
225 ThreadStressLog* tmp = ptr;
226 ptr = ptr->next;
227 delete tmp;
228 }
229
230 theLog.TLSslot = TLS_OUT_OF_INDEXES;
231 if (!fProcessDetach) {
232 lockh.Release();
233 }
234 }
235#if !defined (STRESS_LOG_READONLY)
236 if (StressLogChunk::s_LogChunkHeap != NULL && StressLogChunk::s_LogChunkHeap != ClrGetProcessHeap ())
237 {
238 ClrHeapDestroy (StressLogChunk::s_LogChunkHeap);
239 }
240#endif //!STRESS_LOG_READONLY
241}
242
243/*********************************************************************************/
244/* create a new thread stress log buffer associated with Thread local slot TLSslot, for the Stress log */
245
246ThreadStressLog* StressLog::CreateThreadStressLog() {
247 CONTRACTL
248 {
249 NOTHROW;
250 GC_NOTRIGGER;
251 FORBID_FAULT;
252 SO_TOLERANT;
253 }
254 CONTRACTL_END;
255
256 static PVOID callerID = NULL;
257
258 ThreadStressLog* msgs = (ThreadStressLog*) ClrFlsGetValue(theLog.TLSslot);
259 if (msgs != NULL)
260 {
261 return msgs;
262 }
263
264 if (callerID == ClrTeb::GetFiberPtrId())
265 {
266 return NULL;
267 }
268
269 //if we are not allowed to allocate stress log, we should not even try to take the lock
270 if (!StressLogChunk::s_LogChunkHeap || !CanThisThreadCallIntoHost() || IsInCantAllocStressLogRegion ())
271 {
272 return NULL;
273 }
274
275 // if it looks like we won't be allowed to allocate a new chunk, exit early
276 if (theLog.deadCount == 0 && !AllowNewChunk (0))
277 {
278 return NULL;
279 }
280
281 BEGIN_SO_INTOLERANT_CODE_NO_THROW_CHECK_THREAD(return NULL);
282 StressLogLockHolder lockh(theLog.lock, FALSE);
283
284 class NestedCaller
285 {
286 public:
287 NestedCaller()
288 {
289 }
290 ~NestedCaller()
291 {
292 callerID = NULL;
293 }
294 void Mark()
295 {
296 callerID = ClrTeb::GetFiberPtrId();
297 }
298 };
299
300 NestedCaller nested;
301
302 BOOL noFLSNow = FALSE;
303
304 PAL_CPP_TRY
305 {
306 // Acquiring the lack can throw an OOM exception the first time its called on a thread. We go
307 // ahead and try to provoke that now, before we've altered the list of available stress logs, and bail if
308 // we fail.
309 lockh.Acquire();
310 nested.Mark();
311
312 // ClrFlsSetValue can throw an OOM exception the first time its called on a thread for a given slot. We go
313 // ahead and try to provoke that now, before we've altered the list of available stress logs, and bail if
314 // we fail.
315 ClrFlsSetValue(theLog.TLSslot, NULL);
316 }
317#pragma warning(suppress: 4101)
318 PAL_CPP_CATCH_DERIVED(OutOfMemoryException, obj)
319 {
320 // Just leave on any exception. Note: can't goto or return from within EX_CATCH...
321 noFLSNow = TRUE;
322 }
323 PAL_CPP_ENDTRY;
324
325 if (noFLSNow == FALSE && theLog.facilitiesToLog != 0)
326 msgs = CreateThreadStressLogHelper();
327
328 END_SO_INTOLERANT_CODE;
329
330 return msgs;
331}
332
333ThreadStressLog* StressLog::CreateThreadStressLogHelper() {
334 CONTRACTL
335 {
336 NOTHROW;
337 GC_NOTRIGGER;
338 FORBID_FAULT;
339 SO_INTOLERANT;
340 CANNOT_TAKE_LOCK;
341 }
342 CONTRACTL_END;
343
344 _ASSERTE(theLog.TLSslot != (unsigned int)TLS_OUT_OF_INDEXES); // because facilitiesToLog is != 0
345
346
347 BOOL skipInsert = FALSE;
348 ThreadStressLog* msgs = NULL;
349
350 // See if we can recycle a dead thread
351 if (theLog.deadCount > 0)
352 {
353 unsigned __int64 recycleStamp = getTimeStamp() - RECYCLE_AGE;
354 msgs = theLog.logs;
355 //find out oldest dead ThreadStressLog in case we can't find one within
356 //recycle age but can't create a new chunk
357 ThreadStressLog * oldestDeadMsg = NULL;
358
359 while(msgs != 0)
360 {
361 if (msgs->isDead)
362 {
363 BOOL hasTimeStamp = msgs->curPtr != (StressMsg *)msgs->chunkListTail->EndPtr();
364 if (hasTimeStamp && msgs->curPtr->timeStamp < recycleStamp)
365 {
366 skipInsert = TRUE;
367 InterlockedDecrement(&theLog.deadCount);
368 break;
369 }
370
371 if (!oldestDeadMsg)
372 {
373 oldestDeadMsg = msgs;
374 }
375 else if (hasTimeStamp && oldestDeadMsg->curPtr->timeStamp > msgs->curPtr->timeStamp)
376 {
377 oldestDeadMsg = msgs;
378 }
379 }
380
381 msgs = msgs->next;
382 }
383
384 //if the total stress log size limit is already passed and we can't add new chunk,
385 //always reuse the oldest dead msg
386 if (!AllowNewChunk (0) && !msgs)
387 {
388 msgs = oldestDeadMsg;
389 skipInsert = TRUE;
390 InterlockedDecrement(&theLog.deadCount);
391 }
392 }
393
394 if (msgs == 0) {
395 FAULT_NOT_FATAL(); // We don't mind if we can't allocate here, we'll try again later.
396 if (IsInCantAllocStressLogRegion ())
397 {
398 goto LEAVE;
399 }
400
401 msgs = new (nothrow) ThreadStressLog;
402
403 if (msgs == 0 ||!msgs->IsValid ())
404 {
405 delete msgs;
406 msgs = 0;
407 goto LEAVE;
408 }
409 }
410
411 msgs->Activate ();
412
413 // We know this isn't going to throw an exception now because the call to ClrFlsSetValue above succeeded for
414 // this thread.
415 {
416 CONTRACT_VIOLATION(ThrowsViolation);
417 ClrFlsSetValue(theLog.TLSslot, msgs);
418 }
419
420 if (!skipInsert) {
421#ifdef _DEBUG
422 ThreadStressLog* walk = theLog.logs;
423 while (walk)
424 {
425 _ASSERTE (walk != msgs);
426 walk = walk->next;
427 }
428#endif
429 // Put it into the stress log
430 msgs->next = theLog.logs;
431 theLog.logs = msgs;
432 }
433
434LEAVE:
435 ;
436 return msgs;
437}
438
439/*********************************************************************************/
440/* static */
441void StressLog::ThreadDetach(ThreadStressLog *msgs) {
442 STATIC_CONTRACT_NOTHROW;
443 STATIC_CONTRACT_FORBID_FAULT;
444 STATIC_CONTRACT_CANNOT_TAKE_LOCK;
445
446#ifndef DACCESS_COMPILE
447 if (msgs == 0)
448 {
449 return;
450 }
451
452 _ASSERTE(theLog.TLSslot != (unsigned int)TLS_OUT_OF_INDEXES); // because facilitiesToLog is != 0
453 // We are deleting a fiber. The thread is running a different fiber now.
454 // We should write this message to the StressLog for deleted fiber.
455 msgs->LogMsg (LF_STARTUP, 0, "******* DllMain THREAD_DETACH called Thread dying *******\n");
456#endif
457
458 msgs->isDead = TRUE;
459 InterlockedIncrement(&theLog.deadCount);
460}
461
462BOOL StressLog::AllowNewChunk (LONG numChunksInCurThread)
463{
464 _ASSERTE (numChunksInCurThread <= theLog.totalChunk);
465 DWORD perThreadLimit = theLog.MaxSizePerThread;
466
467#ifndef DACCESS_COMPILE
468 if (numChunksInCurThread == 0 && IsSuspendEEThread())
469 return TRUE;
470
471 if (IsGCSpecialThread())
472 {
473 perThreadLimit *= GC_STRESSLOG_MULTIPLY;
474 }
475#endif
476
477 if ((DWORD)numChunksInCurThread * STRESSLOG_CHUNK_SIZE >= perThreadLimit)
478 {
479 return FALSE;
480 }
481
482 return (DWORD)theLog.totalChunk * STRESSLOG_CHUNK_SIZE < theLog.MaxSizeTotal;
483}
484
485BOOL StressLog::ReserveStressLogChunks (unsigned chunksToReserve)
486{
487 ThreadStressLog* msgs = (ThreadStressLog*) ClrFlsGetValue(theLog.TLSslot);
488
489 if (msgs == 0)
490 {
491 msgs = CreateThreadStressLog();
492
493 if (msgs == 0)
494 return FALSE;
495 }
496
497 if (chunksToReserve == 0)
498 {
499 chunksToReserve = (theLog.MaxSizePerThread + STRESSLOG_CHUNK_SIZE - 1) / STRESSLOG_CHUNK_SIZE;
500 }
501
502 LONG numTries = (LONG)chunksToReserve - msgs->chunkListLength;
503 for (LONG i = 0; i < numTries; i++)
504 {
505 msgs->GrowChunkList ();
506 }
507
508 return msgs->chunkListLength >= (LONG)chunksToReserve;
509}
510
511void (*FSwitchToSOTolerant)();
512void (*FSwitchToSOIntolerant)();
513void TrackSO(BOOL tolerance)
514{
515 if (tolerance)
516 {
517 if (FSwitchToSOTolerant)
518 {
519 FSwitchToSOTolerant();
520 }
521 }
522 else
523 {
524 if (FSwitchToSOIntolerant)
525 {
526 FSwitchToSOIntolerant();
527 }
528 }
529}
530
531/*********************************************************************************/
532/* fetch a buffer that can be used to write a stress message, it is thread safe */
533void ThreadStressLog::LogMsg(unsigned facility, int cArgs, const char* format, va_list Args)
534{
535 STATIC_CONTRACT_NOTHROW;
536 STATIC_CONTRACT_FORBID_FAULT;
537 STATIC_CONTRACT_SO_TOLERANT;
538
539 // Asserts in this function cause infinite loops in the asserting mechanism.
540 // Just use debug breaks instead.
541
542#ifndef DACCESS_COMPILE
543#ifdef _DEBUG
544 // _ASSERTE ( cArgs >= 0 && cArgs <= 7 );
545 if (cArgs < 0 || cArgs > 7) DebugBreak();
546#endif //
547
548 size_t offs = ((size_t)format - StressLog::theLog.moduleOffset);
549
550 // _ASSERTE ( offs < StressMsg::maxOffset );
551 if (offs >= StressMsg::maxOffset)
552 {
553#ifdef _DEBUG
554 DebugBreak(); // in lieu of the above _ASSERTE
555#endif // _DEBUG
556
557 // Set it to this string instead.
558 offs =
559#ifdef _DEBUG
560 (size_t)"<BUG: StressLog format string beyond maxOffset>";
561#else // _DEBUG
562 0; // a 0 offset is ignored by StressLog::Dump
563#endif // _DEBUG else
564 }
565
566 // Get next available slot
567 StressMsg* msg = AdvanceWrite(cArgs);
568
569 msg->timeStamp = getTimeStamp();
570 msg->facility = facility;
571 msg->formatOffset = offs;
572 msg->numberOfArgs = cArgs;
573
574 for ( int i = 0; i < cArgs; ++i )
575 {
576 void* data = va_arg(Args, void*);
577 msg->args[i] = data;
578 }
579
580#ifdef _DEBUG
581 if (!IsValid () || threadId != GetCurrentThreadId ())
582 DebugBreak();
583#endif // _DEBUG
584#endif //DACCESS_COMPILE
585}
586
587FORCEINLINE BOOL StressLog::InlinedStressLogOn(unsigned facility, unsigned level)
588{
589 STATIC_CONTRACT_LEAF;
590 STATIC_CONTRACT_SUPPORTS_DAC;
591
592#if defined(DACCESS_COMPILE)
593 return FALSE;
594#else
595 return ((theLog.facilitiesToLog & facility) && (level <= theLog.levelToLog));
596#endif
597}
598
599BOOL StressLog::StressLogOn(unsigned facility, unsigned level)
600{
601 STATIC_CONTRACT_LEAF;
602 STATIC_CONTRACT_SUPPORTS_DAC;
603
604 return InlinedStressLogOn(facility, level);
605}
606
607FORCEINLINE BOOL StressLog::InlinedETWLogOn(unsigned facility, unsigned level)
608{
609 STATIC_CONTRACT_LEAF;
610 STATIC_CONTRACT_SUPPORTS_DAC;
611
612 return FALSE;
613}
614
615BOOL StressLog::ETWLogOn(unsigned facility, unsigned level)
616{
617 STATIC_CONTRACT_LEAF;
618 STATIC_CONTRACT_SUPPORTS_DAC;
619
620 return InlinedETWLogOn(facility, level);
621}
622
623#if !defined(DACCESS_COMPILE)
624BOOL StressLog::LogOn(unsigned facility, unsigned level)
625{
626 STATIC_CONTRACT_LEAF;
627 STATIC_CONTRACT_SUPPORTS_DAC;
628
629 return InlinedStressLogOn(facility, level) || InlinedETWLogOn(facility, level);
630}
631#endif
632
633/* static */
634void StressLog::LogMsg (unsigned level, unsigned facility, int cArgs, const char* format, ... )
635{
636 STATIC_CONTRACT_SUPPORTS_DAC;
637#ifndef DACCESS_COMPILE
638 STATIC_CONTRACT_NOTHROW;
639 STATIC_CONTRACT_GC_NOTRIGGER;
640 STATIC_CONTRACT_FORBID_FAULT;
641 STATIC_CONTRACT_SO_TOLERANT;
642 STATIC_CONTRACT_SUPPORTS_DAC;
643
644 // Any stresslog LogMsg could theoretically create a new stress log and thus
645 // enter a critical section. But we don't want these to cause violations in
646 // CANNOT_TAKE_LOCK callers, since the callers would otherwise be fine in runs that don't
647 // set the stress log config parameter.
648 CONTRACT_VIOLATION(TakesLockViolation);
649
650 _ASSERTE ( cArgs >= 0 && cArgs <= 7 );
651
652 va_list Args;
653
654 if(InlinedStressLogOn(facility, level))
655 {
656 ThreadStressLog* msgs = (ThreadStressLog*) ClrFlsGetValue(theLog.TLSslot);
657
658 if (msgs == 0) {
659 msgs = CreateThreadStressLog();
660
661 if (msgs == 0)
662 return;
663 }
664 va_start(Args, format);
665 msgs->LogMsg (facility, cArgs, format, Args);
666 va_end(Args);
667 }
668
669// Stress Log ETW feature available only on the desktop versions of the runtime
670#endif //!DACCESS_COMPILE
671}
672
673#ifdef _DEBUG
674/* static */
675void StressLog::LogCallStack(const char *const callTag){
676 if (theLog.RtlCaptureStackBackTrace)
677 {
678 size_t CallStackTrace[MAX_CALL_STACK_TRACE];
679 ULONG hash;
680 USHORT stackTraceCount = theLog.RtlCaptureStackBackTrace (2, MAX_CALL_STACK_TRACE, (PVOID *)CallStackTrace, &hash);
681 if (stackTraceCount > MAX_CALL_STACK_TRACE)
682 stackTraceCount = MAX_CALL_STACK_TRACE;
683 LogMsgOL("Start of %s stack \n", callTag);
684 USHORT i = 0;
685 for (;i < stackTraceCount; i++)
686 {
687 LogMsgOL("(%s stack)%pK\n", callTag, CallStackTrace[i]);
688 }
689 LogMsgOL("End of %s stack\n", callTag);
690 }
691}
692#endif //_DEBUG
693
694#endif // STRESS_LOG
695
696