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//
7
8//
9// ==--==
10
11#include "strike.h"
12#include "util.h"
13#include <stdio.h>
14#include <ctype.h>
15
16#ifndef STRESS_LOG
17#define STRESS_LOG
18#endif // STRESS_LOG
19#define STRESS_LOG_READONLY
20#include "stresslog.h"
21
22
23void GcHistClear();
24void GcHistAddLog(LPCSTR msg, StressMsg* stressMsg);
25
26
27/*********************************************************************************/
28static const WCHAR* getTime(const FILETIME* time, __out_ecount (buffLen) WCHAR* buff, int buffLen)
29{
30 SYSTEMTIME systemTime;
31 static const WCHAR badTime[] = W("BAD TIME");
32
33 if (!FileTimeToSystemTime(time, &systemTime))
34 return badTime;
35
36#ifdef FEATURE_PAL
37 int length = _snwprintf_s(buff, buffLen, _TRUNCATE, W("%02d:%02d:%02d"), systemTime.wHour, systemTime.wMinute, systemTime.wSecond);
38 if (length <= 0)
39 return badTime;
40#else // FEATURE_PAL
41 static const WCHAR format[] = W("HH:mm:ss");
42
43 SYSTEMTIME localTime;
44 SystemTimeToTzSpecificLocalTime(NULL, &systemTime, &localTime);
45
46 // we want a non null buff for the following
47 int ret = GetTimeFormatW(LOCALE_USER_DEFAULT, 0, &localTime, format, buff, buffLen);
48 if (ret == 0)
49 return badTime;
50#endif // FEATURE_PAL else
51
52 return buff;
53}
54
55/*********************************************************************************/
56static inline __int64& toInt64(FILETIME& t)
57{
58 return *((__int64 *) &t);
59}
60
61/*********************************************************************************/
62ThreadStressLog* ThreadStressLog::FindLatestThreadLog() const
63{
64 const ThreadStressLog* latestLog = 0;
65 for (const ThreadStressLog* ptr = this; ptr != NULL; ptr = ptr->next)
66 {
67 if (ptr->readPtr != NULL)
68 if (latestLog == 0 || ptr->readPtr->timeStamp > latestLog->readPtr->timeStamp)
69 latestLog = ptr;
70 }
71 return const_cast<ThreadStressLog*>(latestLog);
72}
73
74const char *getFacilityName(DWORD_PTR lf)
75{
76 struct FacilityName_t { size_t lf; const char* lfName; };
77 #define DEFINE_LOG_FACILITY(logname, value) {logname, #logname},
78 static FacilityName_t facilities[] =
79 {
80 #include <loglf.h>
81 { LF_ALWAYS, "LF_ALWAYS" }
82 };
83 static char buff[1024] = "`";
84 if ( lf == LF_ALL )
85 {
86 return "`ALL`";
87 }
88 else
89 {
90 buff[1] = '\0';
91 for ( int i = 0; i < 32; ++i )
92 {
93 if ( lf & 0x1 )
94 {
95 strcat_s ( buff, _countof(buff), &(facilities[i].lfName[3]) );
96 strcat_s ( buff, _countof(buff), "`" );
97 }
98 lf >>= 1;
99 }
100 return buff;
101 }
102}
103
104/***********************************************************************************/
105/* recognize special pretty printing instructions in the format string */
106/* Note that this function might have side effect such that args array value might */
107/* be altered if format string contains %s */
108// TODO: This function assumes the pointer size of the target equals the pointer size of the host
109// TODO: replace uses of void* with appropriate TADDR or CLRDATA_ADDRESS
110void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, unsigned threadId, double timeStamp, DWORD_PTR facility, ___in void** args)
111{
112 fprintf(file, "%4x %13.9f : ", threadId, timeStamp);
113 fprintf(file, "%-20s ", getFacilityName ( facility ));
114
115 CQuickBytes fullname;
116 char* ptr = format;
117 void** argsPtr = args;
118 const SIZE_T capacity_buff = 2048;
119 LPWSTR buff = (LPWSTR)alloca(capacity_buff * sizeof(WCHAR));
120 static char formatCopy[256];
121
122 int iArgCount = 0;
123
124 strcpy_s(formatCopy, _countof(formatCopy), format);
125 for(;;)
126 {
127 char c = *ptr++;
128 if (c == 0)
129 break;
130 if (c == '{') // Reverse the '{' 's because the log is displayed backwards
131 ptr[-1] = '}';
132 else if (c == '}')
133 ptr[-1] = '{';
134 else if (c == '%')
135 {
136 argsPtr++; // This format will consume one of the args
137 if (*ptr == '%')
138 {
139 ptr++; // skip the whole %%
140 --argsPtr; // except for a %%
141 }
142 else if (*ptr == 'p')
143 { // It is a %p
144 ptr++;
145 if (isalpha(*ptr))
146 { // It is a special %p formatter
147 // Print the string up to that point
148 c = *ptr;
149 *ptr = 0; // Terminate the string temporarily
150 fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6]);
151 *ptr = c; // Put it back
152
153 // move the argument pointers past the part the was printed
154 format = ptr + 1;
155 args = argsPtr;
156 iArgCount = -1;
157 DWORD_PTR arg = DWORD_PTR(argsPtr[-1]);
158
159 switch (c)
160 {
161 case 'M': // format as a method Desc
162 if (g_bDacBroken)
163 {
164 fprintf(file," (MethodDesc: %p)",arg);
165 }
166 else
167 {
168 if (!IsMethodDesc(arg))
169 {
170 if (arg != 0)
171 fprintf(file, " (BAD Method)");
172 }
173 else
174 {
175 DacpMethodDescData MethodDescData;
176 MethodDescData.Request(g_sos,(CLRDATA_ADDRESS)arg);
177
178 static WCHAR wszNameBuffer[1024]; // should be large enough
179 if (g_sos->GetMethodDescName(arg, 1024, wszNameBuffer, NULL) != S_OK)
180 {
181 wcscpy_s(wszNameBuffer, _countof(wszNameBuffer), W("UNKNOWN METHODDESC"));
182 }
183
184 wcscpy_s(buff, capacity_buff, wszNameBuffer);
185 fprintf(file, " (%S)", wszNameBuffer);
186 }
187 }
188 break;
189
190 // fall through
191 case 'T': // format as a MethodTable
192 if (g_bDacBroken)
193 {
194 fprintf(file, "(MethodTable: %p)",arg);
195 }
196 else
197 {
198 if (arg & 3)
199 {
200 arg &= ~3; // GC steals the lower bits for its own use during GC.
201 fprintf(file, " Low Bit(s) Set");
202 }
203 if (!IsMethodTable(arg))
204 {
205 fprintf(file, " (BAD MethodTable)");
206 }
207 else
208 {
209 NameForMT_s (arg, g_mdName, mdNameLen);
210 fprintf(file, " (%S)", g_mdName);
211 }
212 }
213 break;
214
215 case 'V':
216 { // format as a C vtable pointer
217 char Symbol[1024];
218 ULONG64 Displacement;
219 HRESULT hr = g_ExtSymbols->GetNameByOffset(TO_CDADDR(arg), Symbol, 1024, NULL, &Displacement);
220 if (SUCCEEDED(hr) && Symbol[0] != '\0' && Displacement == 0)
221 fprintf(file, " (%s)", Symbol);
222 else
223 fprintf(file, " (Unknown VTable)");
224 }
225 break;
226 case 'K':
227 { // format a frame in stack trace
228 char Symbol[1024];
229 ULONG64 Displacement;
230 HRESULT hr = g_ExtSymbols->GetNameByOffset (TO_CDADDR(arg), Symbol, 1024, NULL, &Displacement);
231 if (SUCCEEDED (hr) && Symbol[0] != '\0')
232 {
233 fprintf (file, " (%s", Symbol);
234 if (Displacement)
235 {
236 fprintf (file, "+%#x", Displacement);
237 }
238 fprintf (file, ")");
239 }
240 else
241 fprintf (file, " (Unknown function)");
242 }
243 break;
244 default:
245 format = ptr; // Just print the character.
246 }
247 }
248 }
249 else if (*ptr == 's' || (*ptr == 'h' && *(ptr+1) == 's' && ++ptr))
250 {
251 HRESULT hr;
252
253 // need to _alloca, instead of declaring a local buffer
254 // since we may have more than one %s in the format
255 ULONG cbStrBuf = 256;
256 char* strBuf = (char *)_alloca(cbStrBuf);
257
258 hr = memCallBack->ReadVirtual(TO_CDADDR((char* )args[iArgCount]), strBuf, cbStrBuf, 0);
259 if (hr != S_OK)
260 {
261 strcpy_s(strBuf, cbStrBuf, "(#Could not read address of string#)");
262 }
263
264 args[iArgCount] = strBuf;
265 }
266 else if (*ptr == 'S' || (*ptr == 'l' && *(ptr+1) == 's' && ++ptr))
267 {
268 HRESULT hr;
269
270 // need to _alloca, instead of declaring a local buffer
271 // since we may have more than one %s in the format
272 ULONG cbWstrBuf = 256 * sizeof(WCHAR);
273 WCHAR* wstrBuf = (WCHAR *)_alloca(cbWstrBuf);
274
275 hr = memCallBack->ReadVirtual(TO_CDADDR((char* )args[iArgCount]), wstrBuf, cbWstrBuf, 0);
276 if (hr != S_OK)
277 {
278 wcscpy_s(wstrBuf, cbWstrBuf/sizeof(WCHAR), W("(#Could not read address of string#)"));
279 }
280
281 args[iArgCount] = wstrBuf;
282 }
283 iArgCount++;
284 }
285 }
286 // Print anything after the last special format instruction.
287 fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6]);
288 fprintf(file, "\n");
289}
290
291void __cdecl
292vDoOut(BOOL bToConsole, FILE* file, PCSTR Format, ...)
293{
294 va_list Args;
295
296 va_start(Args, Format);
297
298 if (bToConsole)
299 {
300 g_ExtControl->OutputVaList(DEBUG_OUTPUT_NORMAL, Format, Args);
301 }
302 else
303 {
304 vfprintf(file, Format, Args);
305 }
306
307 va_end(Args);
308}
309
310
311/*********************************************************************************/
312HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugDataSpaces* memCallBack)
313{
314 ULONG64 g_hThisInst;
315 BOOL bDoGcHist = (fileName == NULL);
316 FILE* file = NULL;
317
318 // Fetch the circular buffer bookkeeping data
319 StressLog inProcLog;
320 HRESULT hr = memCallBack->ReadVirtual(UL64_TO_CDA(outProcLog), &inProcLog, sizeof(StressLog), 0);
321 if (hr != S_OK)
322 {
323 return hr;
324 }
325 if (inProcLog.logs.Load() == NULL || inProcLog.moduleOffset == 0)
326 {
327 ExtOut ( "----- No thread logs in the image: The stress log was probably not initialized correctly. -----\n");
328 return S_FALSE;
329 }
330
331 g_hThisInst = (ULONG64) inProcLog.moduleOffset;
332
333 if (bDoGcHist)
334 {
335 GcHistClear();
336 }
337 else
338 {
339 ExtOut("Writing to file: %s\n", fileName);
340 ExtOut("Stress log in module 0x%p\n", SOS_PTR(g_hThisInst));
341 ExtOut("Stress log address = 0x%p\n", SOS_PTR(outProcLog));
342 }
343 // Fetch the circular buffers for each thread into the 'logs' list
344 ThreadStressLog* logs = 0;
345
346 CLRDATA_ADDRESS outProcPtr = TO_CDADDR(inProcLog.logs.Load());
347 ThreadStressLog* inProcPtr;
348 ThreadStressLog** logsPtr = &logs;
349 int threadCtr = 0;
350 unsigned __int64 lastTimeStamp = 0;// timestamp of last log entry
351
352 while(outProcPtr != 0) {
353 inProcPtr = new ThreadStressLog;
354 hr = memCallBack->ReadVirtual(outProcPtr, inProcPtr, sizeof (*inProcPtr), 0);
355 if (hr != S_OK || inProcPtr->chunkListHead == NULL)
356 {
357 delete inProcPtr;
358 goto FREE_MEM;
359 }
360
361 CLRDATA_ADDRESS outProcListHead = TO_CDADDR(inProcPtr->chunkListHead);
362 CLRDATA_ADDRESS outProcChunkPtr = outProcListHead;
363 StressLogChunk ** chunksPtr = &inProcPtr->chunkListHead;
364 StressLogChunk * inProcPrevChunkPtr = NULL;
365 BOOL curPtrInitialized = FALSE;
366 do
367 {
368 StressLogChunk * inProcChunkPtr = new StressLogChunk;
369 hr = memCallBack->ReadVirtual (outProcChunkPtr, inProcChunkPtr, sizeof (*inProcChunkPtr), NULL);
370 if (hr != S_OK || !inProcChunkPtr->IsValid ())
371 {
372 if (hr != S_OK)
373 ExtOut ("ReadVirtual failed with code hr = %x.\n", hr );
374 else
375 ExtOut ("Invalid stress log chunk: %p", SOS_PTR(outProcChunkPtr));
376
377 // Now cleanup
378 delete inProcChunkPtr;
379 // if this is the first time through, inProcPtr->chunkListHead may still contain
380 // the out-of-process value for the chunk pointer. NULL it to avoid AVs
381 if (TO_CDADDR(inProcPtr->chunkListHead) == outProcListHead)
382 inProcPtr->chunkListHead = NULL;
383 delete inProcPtr;
384 goto FREE_MEM;
385 }
386
387 if (!curPtrInitialized && outProcChunkPtr == TO_CDADDR(inProcPtr->curWriteChunk))
388 {
389 inProcPtr->curPtr = (StressMsg *)((BYTE *)inProcChunkPtr + ((BYTE *)inProcPtr->curPtr - (BYTE *)inProcPtr->curWriteChunk));
390 inProcPtr->curWriteChunk = inProcChunkPtr;
391 curPtrInitialized = TRUE;
392 }
393
394 outProcChunkPtr = TO_CDADDR(inProcChunkPtr->next);
395 *chunksPtr = inProcChunkPtr;
396 chunksPtr = &inProcChunkPtr->next;
397 inProcChunkPtr->prev = inProcPrevChunkPtr;
398 inProcPrevChunkPtr = inProcChunkPtr;
399
400 if (outProcChunkPtr == outProcListHead)
401 {
402 inProcChunkPtr->next = inProcPtr->chunkListHead;
403 inProcPtr->chunkListHead->prev = inProcChunkPtr;
404 inProcPtr->chunkListTail = inProcChunkPtr;
405 }
406 } while (outProcChunkPtr != outProcListHead);
407
408 if (!curPtrInitialized)
409 {
410 delete inProcPtr;
411 goto FREE_MEM;
412 }
413
414 // TODO: fix on 64 bit
415 inProcPtr->Activate ();
416 if (inProcPtr->readPtr->timeStamp > lastTimeStamp)
417 {
418 lastTimeStamp = inProcPtr->readPtr->timeStamp;
419 }
420
421 outProcPtr = TO_CDADDR(inProcPtr->next);
422 *logsPtr = inProcPtr;
423 logsPtr = &inProcPtr->next;
424 threadCtr++;
425 }
426
427 if (!bDoGcHist && ((file = fopen(fileName, "w")) == NULL))
428 {
429 hr = GetLastError();
430 goto FREE_MEM;
431 }
432 hr = S_FALSE; // return false if there are no message to print to the log
433
434 vDoOut(bDoGcHist, file, "STRESS LOG:\n"
435 " facilitiesToLog = 0x%x\n"
436 " levelToLog = %d\n"
437 " MaxLogSizePerThread = 0x%x (%d)\n"
438 " MaxTotalLogSize = 0x%x (%d)\n"
439 " CurrentTotalLogChunk = %d\n"
440 " ThreadsWithLogs = %d\n",
441 inProcLog.facilitiesToLog, inProcLog.levelToLog, inProcLog.MaxSizePerThread, inProcLog.MaxSizePerThread,
442 inProcLog.MaxSizeTotal, inProcLog.MaxSizeTotal, inProcLog.totalChunk.Load(), threadCtr);
443
444 FILETIME endTime;
445 double totalSecs;
446 totalSecs = ((double) (lastTimeStamp - inProcLog.startTimeStamp)) / inProcLog.tickFrequency;
447 toInt64(endTime) = toInt64(inProcLog.startTime) + ((__int64) (totalSecs * 1.0E7));
448
449 WCHAR timeBuff[64];
450 vDoOut(bDoGcHist, file, " Clock frequency = %5.3f GHz\n", inProcLog.tickFrequency / 1.0E9);
451 vDoOut(bDoGcHist, file, " Start time %S\n", getTime(&inProcLog.startTime, timeBuff, 64));
452 vDoOut(bDoGcHist, file, " Last message time %S\n", getTime(&endTime, timeBuff, 64));
453 vDoOut(bDoGcHist, file, " Total elapsed time %5.3f sec\n", totalSecs);
454
455 if (!bDoGcHist)
456 {
457 fprintf(file, "\nTHREAD TIMESTAMP FACILITY MESSAGE\n");
458 fprintf(file, " ID (sec from start)\n");
459 fprintf(file, "--------------------------------------------------------------------------------------\n");
460 }
461 char format[257];
462 format[256] = format[0] = 0;
463 void** args;
464 unsigned msgCtr;
465 msgCtr = 0;
466 for (;;)
467 {
468 ThreadStressLog* latestLog = logs->FindLatestThreadLog();
469
470 if (IsInterrupt())
471 {
472 vDoOut(bDoGcHist, file, "----- Interrupted by user -----\n");
473 break;
474 }
475
476 if (latestLog == 0)
477 {
478 break;
479 }
480
481 StressMsg* latestMsg = latestLog->readPtr;
482 if (latestMsg->formatOffset != 0 && !latestLog->CompletedDump())
483 {
484 TADDR taFmt = (latestMsg->formatOffset) + TO_TADDR(g_hThisInst);
485 hr = memCallBack->ReadVirtual(TO_CDADDR(taFmt), format, 256, 0);
486 if (hr != S_OK)
487 strcpy_s(format, _countof(format), "Could not read address of format string");
488
489 double deltaTime = ((double) (latestMsg->timeStamp - inProcLog.startTimeStamp)) / inProcLog.tickFrequency;
490 if (bDoGcHist)
491 {
492 if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0)
493 {
494 latestLog->threadId = (unsigned)(size_t)latestMsg->args[0];
495 }
496 GcHistAddLog(format, latestMsg);
497 }
498 else
499 {
500 if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0)
501 {
502 fprintf (file, "Task was switched from %x\n", (unsigned)(size_t)latestMsg->args[0]);
503 latestLog->threadId = (unsigned)(size_t)latestMsg->args[0];
504 }
505 else
506 {
507 args = latestMsg->args;
508 formatOutput(memCallBack, file, format, (unsigned)latestLog->threadId, deltaTime, latestMsg->facility, args);
509 }
510 }
511 msgCtr++;
512 }
513
514 latestLog->readPtr = latestLog->AdvanceRead();
515 if (latestLog->CompletedDump())
516 {
517 latestLog->readPtr = NULL;
518 if (!bDoGcHist)
519 {
520 fprintf(file, "------------ Last message from thread %x -----------\n", latestLog->threadId);
521 }
522 }
523
524 if (msgCtr % 64 == 0)
525 {
526 ExtOut("."); // to indicate progress
527 if (msgCtr % (64*64) == 0)
528 ExtOut("\n");
529 }
530 }
531 ExtOut("\n");
532
533 vDoOut(bDoGcHist, file, "---------------------------- %d total entries ------------------------------------\n", msgCtr);
534 if (!bDoGcHist)
535 {
536 fclose(file);
537 }
538
539FREE_MEM:
540 // clean up the 'logs' list
541 while (logs) {
542 ThreadStressLog* temp = logs;
543 logs = logs->next;
544 delete temp;
545 }
546
547 return hr;
548}
549
550