project64/Source/Project64-rsp/Profiling.cpp

#include <stdio.h>
#include <windows.h>

#include <shellapi.h>

#include "profiling.h"
#pragma warning(disable : 4786)
#include <Common/File.h>
#include <Common/Log.h>
#include <Common/StdString.h>
#include <map>
#include <vector>

class CProfiling
{
    typedef std::map<DWORD, __int64> PROFILE_ENRTIES;
    typedef PROFILE_ENRTIES::iterator PROFILE_ENRTY;
    typedef PROFILE_ENRTIES::value_type PROFILE_VALUE;
    typedef struct
    {
        SPECIAL_TIMERS Timer;
        char * Name;
    } TIMER_NAME;

    DWORD m_CurrentTimerAddr, CurrentDisplayCount;
    DWORD m_StartTimeHi, m_StartTimeLo; // The current timer start time
    PROFILE_ENRTIES m_Entries;

public:
    CProfiling()
    {
        m_CurrentTimerAddr = Timer_None;
    }

    // Recording timing against current timer, returns the address of the timer stopped
    DWORD StartTimer(DWORD Address)
    {
        DWORD OldTimerAddr = StopTimer();
        m_CurrentTimerAddr = Address;

#if defined(_M_IX86) && defined(_MSC_VER)
        DWORD HiValue, LoValue;
        _asm {
			pushad
			rdtsc
			mov HiValue, edx
			mov LoValue, eax
			popad
        }
        m_StartTimeHi = HiValue;
        m_StartTimeLo = LoValue;
#else
        DebugBreak();
#endif
        return OldTimerAddr;
    }
    DWORD StopTimer(void)
    {
        if (m_CurrentTimerAddr == Timer_None)
        {
            return m_CurrentTimerAddr;
        }

#if defined(_M_IX86) && defined(_MSC_VER)
        DWORD HiValue, LoValue;
        _asm {
			pushad
			rdtsc
			mov HiValue, edx
			mov LoValue, eax
			popad
        }

        __int64 StopTime = ((unsigned __int64)HiValue << 32) + (unsigned __int64)LoValue;
        __int64 StartTime = ((unsigned __int64)m_StartTimeHi << 32) + (unsigned __int64)m_StartTimeLo;
        __int64 TimeTaken = StopTime - StartTime;

        PROFILE_ENRTY Entry = m_Entries.find(m_CurrentTimerAddr);
        if (Entry != m_Entries.end())
        {
            Entry->second += TimeTaken;
        }
        else
        {
            m_Entries.insert(PROFILE_ENRTIES::value_type(m_CurrentTimerAddr, TimeTaken));
        }
#else
        DebugBreak();
#endif

        DWORD OldTimerAddr = m_CurrentTimerAddr;
        m_CurrentTimerAddr = Timer_None;
        return OldTimerAddr;
    }

    // Reset all the counters back to 0
    void ResetCounters(void)
    {
        m_Entries.clear();
    }

    // Generate a log file with the current results, this will also reset the counters
    void GenerateLog(void)
    {
        stdstr LogFileName;
        {
            CLog Log;
            Log.Open("RSP Profiling.txt");
            LogFileName = Log.FileName();

            // Get the total time
            __int64 TotalTime = 0;
            for (PROFILE_ENRTY itemTime = m_Entries.begin(); itemTime != m_Entries.end(); itemTime++)
            {
                TotalTime += itemTime->second;
            }

            // Create a sortable list of items
            std::vector<PROFILE_VALUE *> ItemList;
            for (PROFILE_ENRTY Entry = m_Entries.begin(); Entry != m_Entries.end(); Entry++)
            {
                ItemList.push_back(&(*Entry));
            }

            // Sort the list with a basic bubble sort
            if (ItemList.size() > 0)
            {
                for (size_t OuterPass = 0; OuterPass < (ItemList.size() - 1); OuterPass++)
                {
                    for (size_t InnerPass = 0; InnerPass < (ItemList.size() - 1); InnerPass++)
                    {
                        if (ItemList[InnerPass]->second < ItemList[InnerPass + 1]->second)
                        {
                            PROFILE_VALUE * TempPtr = ItemList[InnerPass];
                            ItemList[InnerPass] = ItemList[InnerPass + 1];
                            ItemList[InnerPass + 1] = TempPtr;
                        }
                    }
                }
            }

            TIMER_NAME TimerNames[] = {
                {Timer_Compiling, "RSP: Compiling"},
                {Timer_RSP_Running, "RSP: Running"},
                {Timer_R4300_Running, "R4300i: Running"},
                {Timer_RDP_Running, "RDP: Running"},
            };

            for (size_t count = 0; count < ItemList.size(); count++)
            {
                char Buffer[255];
                float CpuUsage = (float)(((double)ItemList[count]->second / (double)TotalTime) * 100);

                if (CpuUsage <= 0.2)
                {
                    continue;
                }
                sprintf(Buffer, "Function 0x%08X", ItemList[count]->first);
                for (int NameID = 0; NameID < (sizeof(TimerNames) / sizeof(TIMER_NAME)); NameID++)
                {
                    if (ItemList[count]->first == (DWORD)TimerNames[NameID].Timer)
                    {
                        strcpy(Buffer, TimerNames[NameID].Name);
                        break;
                    }
                }
                Log.LogF("%s\t%2.2f", Buffer, CpuUsage);
            }
        }

        ShellExecuteA(NULL, "open", LogFileName.c_str(), NULL, NULL, SW_SHOW);
        ResetCounters();
    }
};

CProfiling & GetProfiler(void)
{
    static CProfiling Profile;
    return Profile;
}

void ResetTimerList(void)
{
    GetProfiler().ResetCounters();
}

DWORD StartTimer(DWORD Address)
{
    return GetProfiler().StartTimer(Address);
}

void StopTimer(void)
{
    GetProfiler().StopTimer();
}

void GenerateTimerResults(void)
{
    GetProfiler().GenerateLog();
}

#ifdef todelete
#include <stdio.h>
#include <windows.h>

typedef struct
{
    char Label[100];
    __int64 TimeTotal;
} TIME_STAMP_ENTRY;

DWORD StartTimeHi, StartTimeLo, StopTimeHi, StopTimeLo, TSE_Count, TSE_Max;
TIME_STAMP_ENTRY * TS_Entries = NULL;
char LastLabel[100];

void ResetTimerList(void)
{
    if (TS_Entries)
    {
        free(TS_Entries);
    }
    TS_Entries = NULL;
    TSE_Count = 0;
    TSE_Max = 0;
}

void StartTimer(char * Label)
{
    strcpy(LastLabel, Label);
    _asm {
		pushad
		rdtsc
		mov StartTimeHi, edx
		mov StartTimeLo, eax
		popad
    }
}

void StopTimer(void)
{
    _asm {
		pushad
		rdtsc
		mov StopTimeHi, edx
		mov StopTimeLo, eax
		popad
    }
    if (strlen(LastLabel) == 0)
    {
        return;
    }
    {
        DWORD count;

        for (count = 0; count < TSE_Count; count++)
        {
            if (strcmp(LastLabel, TS_Entries[count].Label) == 0)
            {
                __int64 Time = ((unsigned __int64)StopTimeHi << 32) + (unsigned __int64)StopTimeLo;
                Time -= ((unsigned __int64)StartTimeHi << 32) + (unsigned __int64)StartTimeLo;
                TS_Entries[count].TimeTotal += Time;
                return;
            }
        }
    }
    if (TSE_Count == 0)
    {
        TS_Entries = (TIME_STAMP_ENTRY *)malloc(sizeof(TIME_STAMP_ENTRY) * 100);
        if (TS_Entries == NULL)
        {
            MessageBox(NULL, "TIME_STAMP_ENTRY == NULL ??", "ERROR", MB_OK | MB_ICONERROR | MB_SETFOREGROUND);
        }
        TSE_Max = 100;
    }
    else if (TSE_Count == TSE_Max)
    {
        TSE_Max += 100;
        TS_Entries = (TIME_STAMP_ENTRY *)realloc(TS_Entries, sizeof(TIME_STAMP_ENTRY) * TSE_Max);
        if (TS_Entries == NULL)
        {
            MessageBox(NULL, "TIME_STAMP_ENTRY == NULL ??", "ERROR", MB_OK | MB_ICONERROR | MB_SETFOREGROUND);
        }
    }
    strcpy(TS_Entries[TSE_Count].Label, LastLabel);
    TS_Entries[TSE_Count].TimeTotal = ((unsigned __int64)StopTimeHi << 32) + (unsigned __int64)StopTimeLo;
    TS_Entries[TSE_Count].TimeTotal -= ((unsigned __int64)StartTimeHi << 32) + (unsigned __int64)StartTimeLo;
    TSE_Count += 1;
}

void GenerateTimerResults(void)
{
    char buffer[_MAX_PATH], drive[_MAX_DRIVE], dir[_MAX_DIR];
    char fname[_MAX_FNAME], ext[_MAX_EXT], LogFileName[_MAX_PATH];
    DWORD dwWritten, count, count2;
    HANDLE hLogFile = NULL;
    __int64 TotalTime;

    StopTimer();

    GetModuleFileName(NULL, buffer, sizeof(buffer));
    _splitpath(buffer, drive, dir, fname, ext);
    _makepath(LogFileName, drive, dir, "RSP Profiling", "log");

    hLogFile = CreateFile(LogFileName, GENERIC_WRITE, FILE_SHARE_READ | FILE_SHARE_WRITE, NULL,
                          CREATE_ALWAYS, FILE_ATTRIBUTE_NORMAL | FILE_FLAG_SEQUENTIAL_SCAN, NULL);
    SetFilePointer(hLogFile, 0, NULL, FILE_BEGIN);

    for (count = 0; count < TSE_Count; count++)
    {
        for (count2 = 0; count2 < (TSE_Count - 1); count2++)
        {
            if (TS_Entries[count2].TimeTotal < TS_Entries[count2 + 1].TimeTotal)
            {
                TIME_STAMP_ENTRY Temp;
                memcpy(&Temp, &TS_Entries[count2], sizeof(TIME_STAMP_ENTRY));
                memcpy(&TS_Entries[count2], &TS_Entries[count2 + 1], sizeof(TIME_STAMP_ENTRY));
                memcpy(&TS_Entries[count2 + 1], &Temp, sizeof(TIME_STAMP_ENTRY));
            }
        }
    }
    TotalTime = 0;
    for (count = 0; count < TSE_Count; count++)
    {
        TotalTime += TS_Entries[count].TimeTotal;
    }
    for (count = 0; count < (TSE_Count < 50 ? TSE_Count : 50); count++)
    {
        sprintf(buffer, "%s - %0.2f%c\r\n",
                TS_Entries[count].Label,
                (((double)TS_Entries[count].TimeTotal / (double)TotalTime) * 100), '%');
        WriteFile(hLogFile, buffer, strlen(buffer), &dwWritten, NULL);
    }
    CloseHandle(hLogFile);
    ResetTimerList();
}

#endif