diff options
Diffstat (limited to 'src/ToolBox/SOS/Strike/stressLogDump.cpp')
| -rw-r--r-- | src/ToolBox/SOS/Strike/stressLogDump.cpp | 549 |
1 files changed, 549 insertions, 0 deletions
diff --git a/src/ToolBox/SOS/Strike/stressLogDump.cpp b/src/ToolBox/SOS/Strike/stressLogDump.cpp new file mode 100644 index 0000000000..f277f92434 --- /dev/null +++ b/src/ToolBox/SOS/Strike/stressLogDump.cpp @@ -0,0 +1,549 @@ +// Licensed to the .NET Foundation under one or more agreements. +// The .NET Foundation licenses this file to you under the MIT license. +// See the LICENSE file in the project root for more information. + +// ==++== +// + +// +// ==--== + +#include "strike.h" +#include "util.h" +#include <stdio.h> +#include <ctype.h> + +#ifndef STRESS_LOG +#define STRESS_LOG +#endif // STRESS_LOG +#define STRESS_LOG_READONLY +#include "stresslog.h" + + +void GcHistClear(); +void GcHistAddLog(LPCSTR msg, StressMsg* stressMsg); + + +/*********************************************************************************/ +static const WCHAR* getTime(const FILETIME* time, __out_ecount (buffLen) WCHAR* buff, int buffLen) +{ + SYSTEMTIME systemTime; + static const WCHAR badTime[] = W("BAD TIME"); + + if (!FileTimeToSystemTime(time, &systemTime)) + return badTime; + +#ifdef FEATURE_PAL + int length = _snwprintf(buff, buffLen, W("%02d:%02d:%02d"), systemTime.wHour, systemTime.wMinute, systemTime.wSecond); + if (length <= 0) + return badTime; +#else // FEATURE_PAL + static const WCHAR format[] = W("HH:mm:ss"); + + SYSTEMTIME localTime; + SystemTimeToTzSpecificLocalTime(NULL, &systemTime, &localTime); + + // we want a non null buff for the following + int ret = GetTimeFormatW(LOCALE_USER_DEFAULT, 0, &localTime, format, buff, buffLen); + if (ret == 0) + return badTime; +#endif // FEATURE_PAL else + + return buff; +} + +/*********************************************************************************/ +static inline __int64& toInt64(FILETIME& t) +{ + return *((__int64 *) &t); +} + +/*********************************************************************************/ +ThreadStressLog* ThreadStressLog::FindLatestThreadLog() const +{ + const ThreadStressLog* latestLog = 0; + for (const ThreadStressLog* ptr = this; ptr != NULL; ptr = ptr->next) + { + if (ptr->readPtr != NULL) + if (latestLog == 0 || ptr->readPtr->timeStamp > latestLog->readPtr->timeStamp) + latestLog = ptr; + } + return const_cast<ThreadStressLog*>(latestLog); +} + +const char *getFacilityName(DWORD_PTR lf) +{ + struct FacilityName_t { size_t lf; const char* lfName; }; + #define DEFINE_LOG_FACILITY(logname, value) {logname, #logname}, + static FacilityName_t facilities[] = + { + #include <loglf.h> + { LF_ALWAYS, "LF_ALWAYS" } + }; + static char buff[1024] = "`"; + if ( lf == LF_ALL ) + { + return "`ALL`"; + } + else + { + buff[1] = '\0'; + for ( int i = 0; i < 32; ++i ) + { + if ( lf & 0x1 ) + { + strcat_s ( buff, _countof(buff), &(facilities[i].lfName[3]) ); + strcat_s ( buff, _countof(buff), "`" ); + } + lf >>= 1; + } + return buff; + } +} + +/***********************************************************************************/ +/* recognize special pretty printing instructions in the format string */ +/* Note that this function might have side effect such that args array value might */ +/* be altered if format string contains %s */ +// TODO: This function assumes the pointer size of the target equals the pointer size of the host +// TODO: replace uses of void* with appropriate TADDR or CLRDATA_ADDRESS +void formatOutput(struct IDebugDataSpaces* memCallBack, ___in FILE* file, __inout __inout_z char* format, unsigned threadId, double timeStamp, DWORD_PTR facility, ___in void** args) +{ + fprintf(file, "%4x %13.9f : ", threadId, timeStamp); + fprintf(file, "%-20s ", getFacilityName ( facility )); + + CQuickBytes fullname; + char* ptr = format; + void** argsPtr = args; + const SIZE_T capacity_buff = 2048; + LPWSTR buff = (LPWSTR)alloca(capacity_buff * sizeof(WCHAR)); + static char formatCopy[256]; + + int iArgCount = 0; + + strcpy_s(formatCopy, _countof(formatCopy), format); + for(;;) + { + char c = *ptr++; + if (c == 0) + break; + if (c == '{') // Reverse the '{' 's because the log is displayed backwards + ptr[-1] = '}'; + else if (c == '}') + ptr[-1] = '{'; + else if (c == '%') + { + argsPtr++; // This format will consume one of the args + if (*ptr == '%') + { + ptr++; // skip the whole %% + --argsPtr; // except for a %% + } + else if (*ptr == 'p') + { // It is a %p + ptr++; + if (isalpha(*ptr)) + { // It is a special %p formatter + // Print the string up to that point + c = *ptr; + *ptr = 0; // Terminate the string temporarily + fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6]); + *ptr = c; // Put it back + + // move the argument pointers past the part the was printed + format = ptr + 1; + args = argsPtr; + iArgCount = -1; + DWORD_PTR arg = DWORD_PTR(argsPtr[-1]); + + switch (c) + { + case 'M': // format as a method Desc + if (g_bDacBroken) + { + fprintf(file," (MethodDesc: %p)",arg); + } + else + { + if (!IsMethodDesc(arg)) + { + if (arg != 0) + fprintf(file, " (BAD Method)"); + } + else + { + DacpMethodDescData MethodDescData; + MethodDescData.Request(g_sos,(CLRDATA_ADDRESS)arg); + + static WCHAR wszNameBuffer[1024]; // should be large enough + if (g_sos->GetMethodDescName(arg, 1024, wszNameBuffer, NULL) != S_OK) + { + wcscpy_s(wszNameBuffer, _countof(wszNameBuffer), W("UNKNOWN METHODDESC")); + } + + wcscpy_s(buff, capacity_buff, wszNameBuffer); + fprintf(file, " (%S)", wszNameBuffer); + } + } + break; + + // fall through + case 'T': // format as a MethodTable + if (g_bDacBroken) + { + fprintf(file, "(MethodTable: %p)",arg); + } + else + { + if (arg & 3) + { + arg &= ~3; // GC steals the lower bits for its own use during GC. + fprintf(file, " Low Bit(s) Set"); + } + if (!IsMethodTable(arg)) + { + fprintf(file, " (BAD MethodTable)"); + } + else + { + NameForMT_s (arg, g_mdName, mdNameLen); + fprintf(file, " (%S)", g_mdName); + } + } + break; + + case 'V': + { // format as a C vtable pointer + char Symbol[1024]; + ULONG64 Displacement; + HRESULT hr = g_ExtSymbols->GetNameByOffset(TO_CDADDR(arg), Symbol, 1024, NULL, &Displacement); + if (SUCCEEDED(hr) && Symbol[0] != '\0' && Displacement == 0) + fprintf(file, " (%s)", Symbol); + else + fprintf(file, " (Unknown VTable)"); + } + break; + case 'K': + { // format a frame in stack trace + char Symbol[1024]; + ULONG64 Displacement; + HRESULT hr = g_ExtSymbols->GetNameByOffset (TO_CDADDR(arg), Symbol, 1024, NULL, &Displacement); + if (SUCCEEDED (hr) && Symbol[0] != '\0') + { + fprintf (file, " (%s", Symbol); + if (Displacement) + { + fprintf (file, "+%#x", Displacement); + } + fprintf (file, ")"); + } + else + fprintf (file, " (Unknown function)"); + } + break; + default: + format = ptr; // Just print the character. + } + } + } + else if (*ptr == 's' || (*ptr == 'h' && *(ptr+1) == 's' && ++ptr)) + { + HRESULT hr; + + // need to _alloca, instead of declaring a local buffer + // since we may have more than one %s in the format + ULONG cbStrBuf = 256; + char* strBuf = (char *)_alloca(cbStrBuf); + + hr = memCallBack->ReadVirtual(TO_CDADDR((char* )args[iArgCount]), strBuf, cbStrBuf, 0); + if (hr != S_OK) + { + strcpy_s(strBuf, cbStrBuf, "(#Could not read address of string#)"); + } + + args[iArgCount] = strBuf; + } + else if (*ptr == 'S' || (*ptr == 'l' && *(ptr+1) == 's' && ++ptr)) + { + HRESULT hr; + + // need to _alloca, instead of declaring a local buffer + // since we may have more than one %s in the format + ULONG cbWstrBuf = 256 * sizeof(WCHAR); + WCHAR* wstrBuf = (WCHAR *)_alloca(cbWstrBuf); + + hr = memCallBack->ReadVirtual(TO_CDADDR((char* )args[iArgCount]), wstrBuf, cbWstrBuf, 0); + if (hr != S_OK) + { + wcscpy_s(wstrBuf, cbWstrBuf/sizeof(WCHAR), W("(#Could not read address of string#)")); + } + + args[iArgCount] = wstrBuf; + } + iArgCount++; + } + } + // Print anything after the last special format instruction. + fprintf(file, format, args[0], args[1], args[2], args[3], args[4], args[5], args[6]); + fprintf(file, "\n"); +} + +void __cdecl +vDoOut(BOOL bToConsole, FILE* file, PCSTR Format, ...) +{ + va_list Args; + + va_start(Args, Format); + + if (bToConsole) + { + g_ExtControl->OutputVaList(DEBUG_OUTPUT_NORMAL, Format, Args); + } + else + { + vfprintf(file, Format, Args); + } + + va_end(Args); +} + + +/*********************************************************************************/ +HRESULT StressLog::Dump(ULONG64 outProcLog, const char* fileName, struct IDebugDataSpaces* memCallBack) +{ + ULONG64 g_hThisInst; + BOOL bDoGcHist = (fileName == NULL); + FILE* file = NULL; + + // Fetch the circular buffer bookeeping data + StressLog inProcLog; + HRESULT hr = memCallBack->ReadVirtual(UL64_TO_CDA(outProcLog), &inProcLog, sizeof(StressLog), 0); + if (hr != S_OK) + { + return hr; + } + if (inProcLog.logs.Load() == NULL || inProcLog.moduleOffset == 0) + { + ExtOut ( "----- No thread logs in the image: The stress log was probably not initialized correctly. -----\n"); + return S_FALSE; + } + + g_hThisInst = (ULONG64) inProcLog.moduleOffset; + + if (bDoGcHist) + { + GcHistClear(); + } + else + { + ExtOut("Writing to file: %s\n", fileName); + ExtOut("Stress log in module 0x%p\n", SOS_PTR(g_hThisInst)); + ExtOut("Stress log address = 0x%p\n", SOS_PTR(outProcLog)); + } + // Fetch the circular buffers for each thread into the 'logs' list + ThreadStressLog* logs = 0; + + CLRDATA_ADDRESS outProcPtr = TO_CDADDR(inProcLog.logs.Load()); + ThreadStressLog* inProcPtr; + ThreadStressLog** logsPtr = &logs; + int threadCtr = 0; + unsigned __int64 lastTimeStamp = 0;// timestamp of last log entry + + while(outProcPtr != 0) { + inProcPtr = new ThreadStressLog; + hr = memCallBack->ReadVirtual(outProcPtr, inProcPtr, sizeof (*inProcPtr), 0); + if (hr != S_OK || inProcPtr->chunkListHead == NULL) + { + delete inProcPtr; + goto FREE_MEM; + } + + CLRDATA_ADDRESS outProcListHead = TO_CDADDR(inProcPtr->chunkListHead); + CLRDATA_ADDRESS outProcChunkPtr = outProcListHead; + StressLogChunk ** chunksPtr = &inProcPtr->chunkListHead; + StressLogChunk * inProcPrevChunkPtr = NULL; + BOOL curPtrInitialized = FALSE; + do + { + StressLogChunk * inProcChunkPtr = new StressLogChunk; + hr = memCallBack->ReadVirtual (outProcChunkPtr, inProcChunkPtr, sizeof (*inProcChunkPtr), NULL); + if (hr != S_OK || !inProcChunkPtr->IsValid ()) + { + if (hr != S_OK) + ExtOut ("ReadVirtual failed with code hr = %x.\n", hr ); + else + ExtOut ("Invalid stress log chunk: %p", SOS_PTR(outProcChunkPtr)); + + // Now cleanup + delete inProcChunkPtr; + // if this is the first time through, inProcPtr->chunkListHead may still contain + // the out-of-process value for the chunk pointer. NULL it to avoid AVs + if (TO_CDADDR(inProcPtr->chunkListHead) == outProcListHead) + inProcPtr->chunkListHead = NULL; + delete inProcPtr; + goto FREE_MEM; + } + + if (!curPtrInitialized && outProcChunkPtr == TO_CDADDR(inProcPtr->curWriteChunk)) + { + inProcPtr->curPtr = (StressMsg *)((BYTE *)inProcChunkPtr + ((BYTE *)inProcPtr->curPtr - (BYTE *)inProcPtr->curWriteChunk)); + inProcPtr->curWriteChunk = inProcChunkPtr; + curPtrInitialized = TRUE; + } + + outProcChunkPtr = TO_CDADDR(inProcChunkPtr->next); + *chunksPtr = inProcChunkPtr; + chunksPtr = &inProcChunkPtr->next; + inProcChunkPtr->prev = inProcPrevChunkPtr; + inProcPrevChunkPtr = inProcChunkPtr; + + if (outProcChunkPtr == outProcListHead) + { + inProcChunkPtr->next = inProcPtr->chunkListHead; + inProcPtr->chunkListHead->prev = inProcChunkPtr; + inProcPtr->chunkListTail = inProcChunkPtr; + } + } while (outProcChunkPtr != outProcListHead); + + if (!curPtrInitialized) + { + delete inProcPtr; + goto FREE_MEM; + } + + // TODO: fix on 64 bit + inProcPtr->Activate (); + if (inProcPtr->readPtr->timeStamp > lastTimeStamp) + { + lastTimeStamp = inProcPtr->readPtr->timeStamp; + } + + outProcPtr = TO_CDADDR(inProcPtr->next); + *logsPtr = inProcPtr; + logsPtr = &inProcPtr->next; + threadCtr++; + } + + if (!bDoGcHist && ((file = fopen(fileName, "w")) == NULL)) + { + hr = GetLastError(); + goto FREE_MEM; + } + hr = S_FALSE; // return false if there are no message to print to the log + + vDoOut(bDoGcHist, file, "STRESS LOG:\n" + " facilitiesToLog = 0x%x\n" + " levelToLog = %d\n" + " MaxLogSizePerThread = 0x%x (%d)\n" + " MaxTotalLogSize = 0x%x (%d)\n" + " CurrentTotalLogChunk = %d\n" + " ThreadsWithLogs = %d\n", + inProcLog.facilitiesToLog, inProcLog.levelToLog, inProcLog.MaxSizePerThread, inProcLog.MaxSizePerThread, + inProcLog.MaxSizeTotal, inProcLog.MaxSizeTotal, inProcLog.totalChunk.Load(), threadCtr); + + FILETIME endTime; + double totalSecs; + totalSecs = ((double) (lastTimeStamp - inProcLog.startTimeStamp)) / inProcLog.tickFrequency; + toInt64(endTime) = toInt64(inProcLog.startTime) + ((__int64) (totalSecs * 1.0E7)); + + WCHAR timeBuff[64]; + vDoOut(bDoGcHist, file, " Clock frequency = %5.3f GHz\n", inProcLog.tickFrequency / 1.0E9); + vDoOut(bDoGcHist, file, " Start time %S\n", getTime(&inProcLog.startTime, timeBuff, 64)); + vDoOut(bDoGcHist, file, " Last message time %S\n", getTime(&endTime, timeBuff, 64)); + vDoOut(bDoGcHist, file, " Total elapsed time %5.3f sec\n", totalSecs); + + if (!bDoGcHist) + { + fprintf(file, "\nTHREAD TIMESTAMP FACILITY MESSAGE\n"); + fprintf(file, " ID (sec from start)\n"); + fprintf(file, "--------------------------------------------------------------------------------------\n"); + } + char format[257]; + format[256] = format[0] = 0; + void** args; + unsigned msgCtr; + msgCtr = 0; + for (;;) + { + ThreadStressLog* latestLog = logs->FindLatestThreadLog(); + + if (IsInterrupt()) + { + vDoOut(bDoGcHist, file, "----- Interrupted by user -----\n"); + break; + } + + if (latestLog == 0) + { + break; + } + + StressMsg* latestMsg = latestLog->readPtr; + if (latestMsg->formatOffset != 0 && !latestLog->CompletedDump()) + { + TADDR taFmt = (latestMsg->formatOffset) + TO_TADDR(g_hThisInst); + hr = memCallBack->ReadVirtual(TO_CDADDR(taFmt), format, 256, 0); + if (hr != S_OK) + strcpy_s(format, _countof(format), "Could not read address of format string"); + + double deltaTime = ((double) (latestMsg->timeStamp - inProcLog.startTimeStamp)) / inProcLog.tickFrequency; + if (bDoGcHist) + { + if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0) + { + latestLog->threadId = (unsigned)(size_t)latestMsg->args[0]; + } + GcHistAddLog(format, latestMsg); + } + else + { + if (strcmp(format, ThreadStressLog::TaskSwitchMsg()) == 0) + { + fprintf (file, "Task was switched from %x\n", (unsigned)(size_t)latestMsg->args[0]); + latestLog->threadId = (unsigned)(size_t)latestMsg->args[0]; + } + else + { + args = latestMsg->args; + formatOutput(memCallBack, file, format, latestLog->threadId, deltaTime, latestMsg->facility, args); + } + } + msgCtr++; + } + + latestLog->readPtr = latestLog->AdvanceRead(); + if (latestLog->CompletedDump()) + { + latestLog->readPtr = NULL; + if (!bDoGcHist) + { + fprintf(file, "------------ Last message from thread %x -----------\n", latestLog->threadId); + } + } + + if (msgCtr % 64 == 0) + { + ExtOut("."); // to indicate progress + if (msgCtr % (64*64) == 0) + ExtOut("\n"); + } + } + ExtOut("\n"); + + vDoOut(bDoGcHist, file, "---------------------------- %d total entries ------------------------------------\n", msgCtr); + if (!bDoGcHist) + { + fclose(file); + } + +FREE_MEM: + // clean up the 'logs' list + while (logs) { + ThreadStressLog* temp = logs; + logs = logs->next; + delete temp; + } + + return hr; +} + |