path: root/src/ToolBox/SOS/Strike/stressLogDump.cpp

// 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;
}