/* $Id: perfview.cpp,v 1.5 2001-11-21 16:02:14 phaller Exp $ */ /* * Project Odin Software License can be found in LICENSE.TXT * * Win32 performance measurement and self-profiling API functions * * Copyright 2001 Patrick Haller */ /**************************************************************************** * includes ****************************************************************************/ #include "perfview.h" #ifndef PROFILE // insert "nullified" dummies here to save space in the executable image void PerfView_Initialize(void) {} void PerfView_RegisterCall(char* pszCallerName, char* pszFunctionName, unsigned long int nTicks) {} void PerfView_DumpProfile(FILE *file) {} void PerfView_Write() {} #else #include #include #include // imported from the kernel loader (initterm) extern char kernel32Path[]; typedef struct tagFUNCTION { char* pszFunctionName; unsigned long int nCalled; unsigned long int nTotalTicks; unsigned long int nMinimumTicks; unsigned long int nMaximumTicks; } PERFVIEW_FUNCTION, *PPERFVIEW_FUNCTION; // the map keeps track of all called methods and functions static CHashtableLookup* pProfileMap = new CHashtableLookup(1021); static BOOL flagLock = FALSE; static unsigned long int tsCompensation = 0; // measure the measurement overhead itself void PerfView_Initialize(void) { #define CALIBRATION_RUNS 100 LARGE_INTEGER liStart; LARGE_INTEGER liEnd; unsigned long ulElapsed; // initialize this tsCompensation = 0; for (int i = 0; i < CALIBRATION_RUNS; i++) { QueryPerformanceCounter(&liStart); QueryPerformanceCounter(&liEnd); if (liStart.LowPart > liEnd.LowPart) ulElapsed = 0xFFFFFFFF - liStart.LowPart + liEnd.LowPart; else ulElapsed = liEnd.LowPart - liStart.LowPart; // save the determined amount of elapsed ticks // as compensatory factor tsCompensation += ulElapsed; } // now calculate back to real value tsCompensation /= CALIBRATION_RUNS; } // register a call to a function void _Optlink PerfView_RegisterCall(char* pszCallerName, char* pszFunctionName, unsigned long int nTicks) { // don't record call if currently locked if (flagLock) return; // subtract the measurement overhead factor. // Note: this should rather be done where the times are taken, // however this would spread the code just too far. if (tsCompensation < nTicks) nTicks -= tsCompensation; else nTicks = 0; // check if that particular function is registered already PPERFVIEW_FUNCTION p = (PPERFVIEW_FUNCTION)pProfileMap->getElement(pszFunctionName); if (NULL == p) { // new function call p = (PPERFVIEW_FUNCTION)malloc( sizeof( PERFVIEW_FUNCTION ) ); p->pszFunctionName = strdup( pszFunctionName ); p->nCalled = 0; p->nTotalTicks = 0; p->nMinimumTicks = 0xffffffff; p->nMaximumTicks = 0; // add to the hashtable pProfileMap->addElement(pszFunctionName, p); } // update statistical data p->nCalled++; p->nTotalTicks += nTicks; if (nTicks < p->nMinimumTicks) p->nMinimumTicks = nTicks; if (nTicks > p->nMaximumTicks) p->nMaximumTicks = nTicks; // add call-path tracing if (NULL != pszCallerName) { // build path name char szBuf[256]; strcpy(szBuf, pszCallerName); strcat(szBuf, "->"); strcat(szBuf, pszFunctionName); // check if that particular callpath is registered already PPERFVIEW_FUNCTION p2 = (PPERFVIEW_FUNCTION)pProfileMap->getElement(szBuf); if (NULL == p2) { // new function call p2 = (PPERFVIEW_FUNCTION)malloc( sizeof( PERFVIEW_FUNCTION ) ); p2->pszFunctionName = strdup( szBuf ); p2->nCalled = 0; p2->nTotalTicks = 0; p2->nMinimumTicks = 0xffffffff; p2->nMaximumTicks = 0; // add to the hashtable pProfileMap->addElement(p2->pszFunctionName, p2); } // update statistical data p2->nCalled++; p2->nTotalTicks += nTicks; if (nTicks < p2->nMinimumTicks) p2->nMinimumTicks = nTicks; if (nTicks > p2->nMaximumTicks) p2->nMaximumTicks = nTicks; } } int _Optlink sortHashtableEntries0(const void *arg1,const void *arg2) { PHASHTABLEENTRY pHTE1 = (PHASHTABLEENTRY)arg1; PHASHTABLEENTRY pHTE2 = (PHASHTABLEENTRY)arg2; PPERFVIEW_FUNCTION p1 = (PPERFVIEW_FUNCTION)pHTE1->pObject; PPERFVIEW_FUNCTION p2 = (PPERFVIEW_FUNCTION)pHTE2->pObject; return strcmp(p1->pszFunctionName, p2->pszFunctionName); } int _Optlink sortHashtableEntries1(const void *arg1,const void *arg2) { PHASHTABLEENTRY pHTE1 = (PHASHTABLEENTRY)arg1; PHASHTABLEENTRY pHTE2 = (PHASHTABLEENTRY)arg2; PPERFVIEW_FUNCTION p1 = (PPERFVIEW_FUNCTION)pHTE1->pObject; PPERFVIEW_FUNCTION p2 = (PPERFVIEW_FUNCTION)pHTE2->pObject; // return strcmp(pHTE1->pszName, pHTE2->pszName); return p1->nTotalTicks - p2->nTotalTicks; } int _Optlink sortHashtableEntries2(const void *arg1,const void *arg2) { PHASHTABLEENTRY pHTE1 = (PHASHTABLEENTRY)arg1; PHASHTABLEENTRY pHTE2 = (PHASHTABLEENTRY)arg2; PPERFVIEW_FUNCTION p1 = (PPERFVIEW_FUNCTION)pHTE1->pObject; PPERFVIEW_FUNCTION p2 = (PPERFVIEW_FUNCTION)pHTE2->pObject; return p1->nCalled - p2->nCalled; } int _Optlink sortHashtableEntries3(const void *arg1,const void *arg2) { PHASHTABLEENTRY pHTE1 = (PHASHTABLEENTRY)arg1; PHASHTABLEENTRY pHTE2 = (PHASHTABLEENTRY)arg2; PPERFVIEW_FUNCTION p1 = (PPERFVIEW_FUNCTION)pHTE1->pObject; PPERFVIEW_FUNCTION p2 = (PPERFVIEW_FUNCTION)pHTE2->pObject; unsigned long int iAvg1 = p1->nTotalTicks / p1->nCalled; unsigned long int iAvg2 = p2->nTotalTicks / p2->nCalled; return iAvg1 - iAvg2; } // dump the collected profile to the specified file void _Optlink PerfView_DumpProfile(FILE *file) { flagLock = TRUE; // lock recording int iEntries = pProfileMap->getNumberOfElements(); // get a list of all entries of the hashtable PHASHTABLEENTRY arrEntries = (PHASHTABLEENTRY)malloc( iEntries * sizeof(HASHTABLEENTRY) ); iEntries = pProfileMap->getElementMap(arrEntries); fprintf(file, "ODIN Performance Analysis\n" "%d entries available, compensated measure overhead is %d ticks.\n\n", iEntries, tsCompensation); // sort the list by function name qsort(arrEntries, iEntries, sizeof( HASHTABLEENTRY ), sortHashtableEntries0); // write to file fprintf(file, "Sorted by function name\n" "Ticks ---- Called --- Average -- Minimum -- Maximum -- Function -----------\n"); for(int i = 0; i < iEntries; i++) { PPERFVIEW_FUNCTION p = (PPERFVIEW_FUNCTION)arrEntries[i].pObject; fprintf(file, "%10d %10d %10d %10d %10d %s\n", p->nTotalTicks, p->nCalled, p->nTotalTicks / p->nCalled, p->nMinimumTicks, p->nMaximumTicks, p->pszFunctionName); } // sort the list by nTotalTicks qsort(arrEntries, iEntries, sizeof( HASHTABLEENTRY ), sortHashtableEntries1); // write to file fprintf(file, "\nSorted by total call time\n" "Ticks ---- Called --- Average -- Function ---------------------------------\n"); for(i = 0; i < iEntries; i++) { PPERFVIEW_FUNCTION p = (PPERFVIEW_FUNCTION)arrEntries[i].pObject; fprintf(file, "%10d %10d %10d %s\n", p->nTotalTicks, p->nCalled, p->nTotalTicks / p->nCalled, p->pszFunctionName); } // sort the list by nCalled qsort(arrEntries, iEntries, sizeof( HASHTABLEENTRY ), sortHashtableEntries2); // write to file fprintf(file, "\nSorted by total calls\n" "Called --- Ticks ---- Average -- Function ---------------------------------\n"); for(i = 0; i < iEntries; i++) { PPERFVIEW_FUNCTION p = (PPERFVIEW_FUNCTION)arrEntries[i].pObject; fprintf(file, "%10d %10d %10d %s\n", p->nCalled, p->nTotalTicks, p->nTotalTicks / p->nCalled, p->pszFunctionName); } // sort the list by average call time qsort(arrEntries, iEntries, sizeof( HASHTABLEENTRY ), sortHashtableEntries3); // write to file fprintf(file, "\nSorted by average call time\n" "Average -- Calls ---- Ticks ---- Function ---------------------------------\n"); for(i = 0; i < iEntries; i++) { PPERFVIEW_FUNCTION p = (PPERFVIEW_FUNCTION)arrEntries[i].pObject; fprintf(file, "%10d %10d %10d %s\n", p->nTotalTicks / p->nCalled, p->nCalled, p->nTotalTicks, p->pszFunctionName); } flagLock = FALSE; // lock recording } //use a different logfile #define PRIVATE_LOGGING #include void PerfView_Write() { FILE* _privateLogFile; char szFilename[260]; sprintf(szFilename, "perf_%d.log", getpid()); _privateLogFile = fopen(szFilename, "w"); if(_privateLogFile == NULL) { sprintf(szFilename, "%sperf_%d.log", kernel32Path, getpid()); _privateLogFile = fopen(szFilename, "w"); } dprintfGlobal(("PE PERFFILE : %s", szFilename)); // dump the gathered data PerfView_DumpProfile(_privateLogFile); if(_privateLogFile) { fclose(_privateLogFile); _privateLogFile = NULL; } } #endif /* PROFILE */