| 1 | /* $Id: profiler.cpp,v 1.3 2001-11-22 13:35:42 phaller Exp $ */
|
|---|
| 2 | /*
|
|---|
| 3 | * Project Odin Software License can be found in LICENSE.TXT
|
|---|
| 4 | * Execution Trace Profiler
|
|---|
| 5 | *
|
|---|
| 6 | * Copyright 2001 Patrick Haller <patrick.haller@innotek.de>
|
|---|
| 7 | *
|
|---|
| 8 | */
|
|---|
| 9 |
|
|---|
| 10 |
|
|---|
| 11 | /****************************************************************************
|
|---|
| 12 | * To Do
|
|---|
| 13 | ****************************************************************************
|
|---|
| 14 |
|
|---|
| 15 | - write result in java.prof style
|
|---|
| 16 | - find tool to nicely work on the output files
|
|---|
| 17 | - fix wrong timestamps (use 64-bit arithmetic and recalculate to ms)
|
|---|
| 18 | */
|
|---|
| 19 |
|
|---|
| 20 |
|
|---|
| 21 | /****************************************************************************
|
|---|
| 22 | * includes
|
|---|
| 23 | ****************************************************************************/
|
|---|
| 24 |
|
|---|
| 25 | #define INCL_DOSERRORS
|
|---|
| 26 | #define INCL_DOSPROCESS
|
|---|
| 27 | #include <os2.h>
|
|---|
| 28 |
|
|---|
| 29 | #include <os2sel.h>
|
|---|
| 30 | #include <stdlib.h>
|
|---|
| 31 | #include <string.h>
|
|---|
| 32 | #include <stdio.h>
|
|---|
| 33 | #include <math.h>
|
|---|
| 34 | #include <direct.h>
|
|---|
| 35 | #include <process.h>
|
|---|
| 36 |
|
|---|
| 37 | #include "symfile.h"
|
|---|
| 38 |
|
|---|
| 39 |
|
|---|
| 40 | /****************************************************************************
|
|---|
| 41 | * local class definitions
|
|---|
| 42 | ****************************************************************************/
|
|---|
| 43 |
|
|---|
| 44 |
|
|---|
| 45 | typedef struct
|
|---|
| 46 | {
|
|---|
| 47 | ULONG ulID;
|
|---|
| 48 | void* pObject;
|
|---|
| 49 | } HASHTABLEENTRYID, *PHASHTABLEENTRYID;
|
|---|
| 50 |
|
|---|
| 51 |
|
|---|
| 52 | class CProfilerHashtableLookup : public CHashtableLookup
|
|---|
| 53 | {
|
|---|
| 54 | public:
|
|---|
| 55 | CProfilerHashtableLookup(int iInitialSize);
|
|---|
| 56 | PHASHTABLEENTRYID addElement(ULONG ulID, void *pObject);
|
|---|
| 57 | void* removeElement(ULONG ulID);
|
|---|
| 58 | void* getElement(ULONG ulID);
|
|---|
| 59 | int getElementMap(PHASHTABLEENTRYID pBuffer);
|
|---|
| 60 |
|
|---|
| 61 | protected:
|
|---|
| 62 | void setSize0(int iNewSize);
|
|---|
| 63 | };
|
|---|
| 64 |
|
|---|
| 65 |
|
|---|
| 66 | /****************************************************************************
|
|---|
| 67 | * definitions
|
|---|
| 68 | ****************************************************************************/
|
|---|
| 69 |
|
|---|
| 70 | typedef struct tagThreadProfileEntry
|
|---|
| 71 | {
|
|---|
| 72 | unsigned long EIP; /* currently only 32-bit segments are traced */
|
|---|
| 73 | char* pszModule; /* name of the current module */
|
|---|
| 74 | /* name of the current function or (caller;callee pair) */
|
|---|
| 75 | char* pszFunction;
|
|---|
| 76 | unsigned long ulCalls;
|
|---|
| 77 | unsigned long ulTimeMinimum;
|
|---|
| 78 | unsigned long ulTimeMaximum;
|
|---|
| 79 | unsigned long ulTimeTotal;
|
|---|
| 80 | } PROFILEENTRY, *PPROFILEENTRY;
|
|---|
| 81 |
|
|---|
| 82 |
|
|---|
| 83 | typedef struct tagThreadProfilerDataBlock
|
|---|
| 84 | {
|
|---|
| 85 | unsigned long ulCalldepth; // current call depth
|
|---|
| 86 | unsigned long ret[384]; // last saved return address
|
|---|
| 87 | unsigned long callStack[384]; // call stack (CS:) EIP records
|
|---|
| 88 | unsigned long enterTimeHi[384]; // machine timestamps of function entry
|
|---|
| 89 | unsigned long enterTimeLo[384];
|
|---|
| 90 |
|
|---|
| 91 | // Hashtable to record the PROFILEENTRY records
|
|---|
| 92 | CProfilerHashtableLookup* pHashtable;
|
|---|
| 93 |
|
|---|
| 94 | } PROFILERBLOCK, *PPROFILERBLOCK;
|
|---|
| 95 |
|
|---|
| 96 |
|
|---|
| 97 | /****************************************************************************
|
|---|
| 98 | * module local variables
|
|---|
| 99 | ****************************************************************************/
|
|---|
| 100 |
|
|---|
| 101 | static SymbolFilePool* pSymPool = new SymbolFilePool();
|
|---|
| 102 | static CProfilerHashtableLookup* pProfileMap = new CProfilerHashtableLookup(1021);
|
|---|
| 103 | static PPROFILERBLOCK* ppTLS = 0; /* thread local storage */
|
|---|
| 104 | static BOOL fIsProfilerEnabled = FALSE; /* enable / disable hook*/
|
|---|
| 105 | static CHAR szWorkingDirectory[260] = ".";
|
|---|
| 106 |
|
|---|
| 107 | extern void _System odin_ProfileHook32Bottom();
|
|---|
| 108 | extern void _System _ProfileGetTimestamp(PULONG hi, PULONG lo);
|
|---|
| 109 |
|
|---|
| 110 |
|
|---|
| 111 | /****************************************************************************
|
|---|
| 112 | * local class definitions
|
|---|
| 113 | ****************************************************************************/
|
|---|
| 114 |
|
|---|
| 115 | static inline unsigned long _Optlink hashcodeEIP(int iRing, ULONG eip)
|
|---|
| 116 | {
|
|---|
| 117 | return eip % iRing;
|
|---|
| 118 | }
|
|---|
| 119 |
|
|---|
| 120 |
|
|---|
| 121 | CProfilerHashtableLookup::CProfilerHashtableLookup(int iInitialSize)
|
|---|
| 122 | : CHashtableLookup(iInitialSize)
|
|---|
| 123 | {
|
|---|
| 124 | }
|
|---|
| 125 |
|
|---|
| 126 |
|
|---|
| 127 | PHASHTABLEENTRYID CProfilerHashtableLookup::addElement(ULONG ulID, void *pObject)
|
|---|
| 128 | {
|
|---|
| 129 | // get slot number
|
|---|
| 130 | unsigned long ulHash = hashcodeEIP(iSize, ulID);
|
|---|
| 131 |
|
|---|
| 132 | // create entry
|
|---|
| 133 | PHASHTABLEENTRYID pHTE = (PHASHTABLEENTRYID)malloc(sizeof(HASHTABLEENTRYID));
|
|---|
| 134 | pHTE->ulID = ulID;
|
|---|
| 135 | pHTE->pObject = pObject;
|
|---|
| 136 |
|
|---|
| 137 | // check if slot has a list object already
|
|---|
| 138 | if (parrLists[ulHash] == NULL)
|
|---|
| 139 | parrLists[ulHash] = new CLinearList();
|
|---|
| 140 |
|
|---|
| 141 | parrLists[ulHash]->addLast(pHTE);
|
|---|
| 142 |
|
|---|
| 143 | // count allocated elements
|
|---|
| 144 | iElements++;
|
|---|
| 145 |
|
|---|
| 146 | return pHTE;
|
|---|
| 147 | }
|
|---|
| 148 |
|
|---|
| 149 |
|
|---|
| 150 | void* CProfilerHashtableLookup::removeElement(ULONG ulID)
|
|---|
| 151 | {
|
|---|
| 152 | // get slot number
|
|---|
| 153 | unsigned long ulHash = hashcodeEIP(iSize, ulID);
|
|---|
| 154 |
|
|---|
| 155 | // check if slot is occupied
|
|---|
| 156 | if (parrLists[ulHash] == NULL)
|
|---|
| 157 | // signal not found
|
|---|
| 158 | return NULL;
|
|---|
| 159 |
|
|---|
| 160 | // search the list
|
|---|
| 161 | PLINEARLISTENTRY pLLE = parrLists[ulHash]->getFirst();
|
|---|
| 162 | if (pLLE == NULL)
|
|---|
| 163 | // signal not found
|
|---|
| 164 | return NULL;
|
|---|
| 165 |
|
|---|
| 166 | // iterate over the list
|
|---|
| 167 | while(pLLE)
|
|---|
| 168 | {
|
|---|
| 169 | PHASHTABLEENTRYID pHTE = (PHASHTABLEENTRYID)pLLE->pObject;
|
|---|
| 170 |
|
|---|
| 171 | if (pHTE->ulID == ulID)
|
|---|
| 172 | {
|
|---|
| 173 | // save old object pointer
|
|---|
| 174 | void* pTemp = pHTE->pObject;
|
|---|
| 175 | free(pHTE);
|
|---|
| 176 |
|
|---|
| 177 | // found the correct entry
|
|---|
| 178 | parrLists[ulHash]->removeElement(pLLE);
|
|---|
| 179 |
|
|---|
| 180 | // count allocated elements
|
|---|
| 181 | iElements--;
|
|---|
| 182 |
|
|---|
| 183 | // return old object pointer to signal success
|
|---|
| 184 | return pTemp;
|
|---|
| 185 | }
|
|---|
| 186 |
|
|---|
| 187 | pLLE = pLLE->pNext;
|
|---|
| 188 | }
|
|---|
| 189 |
|
|---|
| 190 | // failed
|
|---|
| 191 | return NULL;
|
|---|
| 192 | }
|
|---|
| 193 |
|
|---|
| 194 |
|
|---|
| 195 | void* CProfilerHashtableLookup::getElement(ULONG ulID)
|
|---|
| 196 | {
|
|---|
| 197 | // get slot number
|
|---|
| 198 | unsigned long ulHash = hashcodeEIP(iSize, ulID);
|
|---|
| 199 |
|
|---|
| 200 | CLinearList *pLL = parrLists[ulHash];
|
|---|
| 201 |
|
|---|
| 202 | // check if slot is occupied
|
|---|
| 203 | if (pLL == NULL)
|
|---|
| 204 | // signal not found
|
|---|
| 205 | return NULL;
|
|---|
| 206 |
|
|---|
| 207 | // search the list
|
|---|
| 208 | PLINEARLISTENTRY pLLE = pLL->getFirst();
|
|---|
| 209 | if (pLLE == NULL)
|
|---|
| 210 | // signal not found
|
|---|
| 211 | return NULL;
|
|---|
| 212 |
|
|---|
| 213 | // iterate over the list
|
|---|
| 214 | while(pLLE)
|
|---|
| 215 | {
|
|---|
| 216 | PHASHTABLEENTRYID pHTE = (PHASHTABLEENTRYID)pLLE->pObject;
|
|---|
| 217 |
|
|---|
| 218 | // quickly compare 1st character for equality
|
|---|
| 219 | // before doing the strcmp call
|
|---|
| 220 | if (pHTE->ulID == ulID)
|
|---|
| 221 | {
|
|---|
| 222 | // return result
|
|---|
| 223 | return pHTE->pObject;
|
|---|
| 224 | }
|
|---|
| 225 |
|
|---|
| 226 | pLLE = pLLE->pNext;
|
|---|
| 227 | }
|
|---|
| 228 |
|
|---|
| 229 | // failed
|
|---|
| 230 | return NULL;
|
|---|
| 231 | }
|
|---|
| 232 |
|
|---|
| 233 |
|
|---|
| 234 | int CProfilerHashtableLookup::getElementMap(PHASHTABLEENTRYID pBuffer)
|
|---|
| 235 | {
|
|---|
| 236 | int iIndex = 0;
|
|---|
| 237 |
|
|---|
| 238 | // iterate over all registered entries and dump them to the buffer
|
|---|
| 239 | // giving the caller direct access to the hashtable internals.
|
|---|
| 240 | for (int i = 0;
|
|---|
| 241 | i < iSize;
|
|---|
| 242 | i++)
|
|---|
| 243 | {
|
|---|
| 244 | // check if slot was occupied
|
|---|
| 245 | if (parrLists[i] != NULL)
|
|---|
| 246 | {
|
|---|
| 247 | // walk along any entry in that linear list
|
|---|
| 248 | PLINEARLISTENTRY pLLE = parrLists[i]->getFirst();
|
|---|
| 249 |
|
|---|
| 250 | while (pLLE)
|
|---|
| 251 | {
|
|---|
| 252 | PHASHTABLEENTRYID pHTE = (PHASHTABLEENTRYID)pLLE->pObject;
|
|---|
| 253 | memcpy(&pBuffer[iIndex], pHTE, sizeof( HASHTABLEENTRYID ) );
|
|---|
| 254 | iIndex++;
|
|---|
| 255 |
|
|---|
| 256 | pLLE = parrLists[i]->getNext(pLLE);
|
|---|
| 257 | }
|
|---|
| 258 | }
|
|---|
| 259 | }
|
|---|
| 260 |
|
|---|
| 261 | // return number of elements copied
|
|---|
| 262 | return iIndex;
|
|---|
| 263 | }
|
|---|
| 264 |
|
|---|
| 265 |
|
|---|
| 266 | void CProfilerHashtableLookup::setSize0(int iNewSize)
|
|---|
| 267 | {
|
|---|
| 268 | // check if rehashing is necessary at all
|
|---|
| 269 | if (iSize == iNewSize)
|
|---|
| 270 | return;
|
|---|
| 271 |
|
|---|
| 272 | // save old array, allocate new array
|
|---|
| 273 | CLinearList** parrNew = new CLinearList* [iNewSize];
|
|---|
| 274 | memset(parrNew,
|
|---|
| 275 | 0,
|
|---|
| 276 | sizeof(CLinearList*) * iNewSize);
|
|---|
| 277 |
|
|---|
| 278 | // convert all the slot lists
|
|---|
| 279 | for (int i = 0;
|
|---|
| 280 | i < iSize;
|
|---|
| 281 | i++)
|
|---|
| 282 | {
|
|---|
| 283 | // check if slot was occupied
|
|---|
| 284 | if (parrLists[i] != NULL)
|
|---|
| 285 | {
|
|---|
| 286 | // iterate over the slot
|
|---|
| 287 | PLINEARLISTENTRY pLLE = parrLists[i]->getFirst();
|
|---|
| 288 | PHASHTABLEENTRYID pHTE;
|
|---|
| 289 | unsigned long ulHash;
|
|---|
| 290 |
|
|---|
| 291 | while(pLLE)
|
|---|
| 292 | {
|
|---|
| 293 | // calculate new hashcode for the entry
|
|---|
| 294 | pHTE = (PHASHTABLEENTRYID)pLLE->pObject;
|
|---|
| 295 | ulHash = hashcodeEIP(iNewSize, pHTE->ulID);
|
|---|
| 296 |
|
|---|
| 297 | // reinsert the pHTE into new slot
|
|---|
| 298 | if (parrNew[ulHash] == NULL)
|
|---|
| 299 | parrNew[ulHash] = new CLinearList();
|
|---|
| 300 |
|
|---|
| 301 | parrNew[ulHash]->addLast( (void*)pHTE );
|
|---|
| 302 |
|
|---|
| 303 | pLLE=pLLE->pNext;
|
|---|
| 304 | }
|
|---|
| 305 |
|
|---|
| 306 | // kill the slot
|
|---|
| 307 | delete parrLists[i];
|
|---|
| 308 | parrLists[i] = NULL;
|
|---|
| 309 | }
|
|---|
| 310 | }
|
|---|
| 311 |
|
|---|
| 312 | // swap the tables
|
|---|
| 313 | iSize = iNewSize;
|
|---|
| 314 | delete [] parrLists;
|
|---|
| 315 |
|
|---|
| 316 | parrLists = parrNew;
|
|---|
| 317 | }
|
|---|
| 318 |
|
|---|
| 319 |
|
|---|
| 320 | /****************************************************************************
|
|---|
| 321 | * implementation
|
|---|
| 322 | ****************************************************************************/
|
|---|
| 323 |
|
|---|
| 324 | static PPROFILERBLOCK inline getProfilerBlock(void)
|
|---|
| 325 | {
|
|---|
| 326 | if ( ( (ULONG)ppTLS != 0) && ( (ULONG)ppTLS != 0xffffffff) )
|
|---|
| 327 | return *ppTLS;
|
|---|
| 328 |
|
|---|
| 329 | // is TLS already available?
|
|---|
| 330 | if (ppTLS == NULL)
|
|---|
| 331 | {
|
|---|
| 332 | // allocate thread local storage
|
|---|
| 333 | USHORT sel = RestoreOS2FS();
|
|---|
| 334 | APIRET rc = DosAllocThreadLocalMemory(1, (PULONG*)&ppTLS);
|
|---|
| 335 | SetFS(sel);
|
|---|
| 336 |
|
|---|
| 337 | if (rc != NO_ERROR)
|
|---|
| 338 | ppTLS = (PPROFILERBLOCK*)0xffffffff; // mark as invalid
|
|---|
| 339 | }
|
|---|
| 340 |
|
|---|
| 341 | if ((ULONG)ppTLS == 0xffffffff)
|
|---|
| 342 | // profiling is not available
|
|---|
| 343 | return NULL;
|
|---|
| 344 |
|
|---|
| 345 | // allocate data structure
|
|---|
| 346 | {
|
|---|
| 347 | USHORT sel = RestoreOS2FS();
|
|---|
| 348 |
|
|---|
| 349 | // Note: must be DosAllocMem because the CRT would automatically close
|
|---|
| 350 | // all heap objects on termination
|
|---|
| 351 | // *ppTLS = (PPROFILERBLOCK)malloc( sizeof(PROFILERBLOCK) );
|
|---|
| 352 | int iSize = 4096 * (1 + sizeof(PROFILERBLOCK) / 4096);
|
|---|
| 353 | APIRET rc = DosAllocMem((PPVOID)ppTLS, iSize, PAG_COMMIT | PAG_READ | PAG_WRITE);
|
|---|
| 354 | SetFS(sel);
|
|---|
| 355 |
|
|---|
| 356 | if (rc == NO_ERROR)
|
|---|
| 357 | {
|
|---|
| 358 | memset(*ppTLS, 0, sizeof(PROFILERBLOCK) );
|
|---|
| 359 |
|
|---|
| 360 | PPROFILERBLOCK pPB = (PPROFILERBLOCK)*ppTLS;
|
|---|
| 361 |
|
|---|
| 362 | // experiment: thread-local profile
|
|---|
| 363 | // pPB->pHashtable = new CProfilerHashtableLookup(1021);
|
|---|
| 364 | pPB->pHashtable = pProfileMap;
|
|---|
| 365 | }
|
|---|
| 366 | }
|
|---|
| 367 |
|
|---|
| 368 | return (PPROFILERBLOCK)*ppTLS;
|
|---|
| 369 | }
|
|---|
| 370 |
|
|---|
| 371 |
|
|---|
| 372 |
|
|---|
| 373 | /***********************************************************************
|
|---|
| 374 | * Name : APIRET QueryModuleFromEIP
|
|---|
| 375 | * Funktion : Determine which module resides at 0:EIP
|
|---|
| 376 | * Parameter :
|
|---|
| 377 | * Variablen :
|
|---|
| 378 | * Ergebnis : Rckgabewert ans Betriebssystem
|
|---|
| 379 | * Bemerkung :
|
|---|
| 380 | *
|
|---|
| 381 | * Autor : Patrick Haller [Samstag, 28.10.1995 14.55.13]
|
|---|
| 382 | ***********************************************************************/
|
|---|
| 383 |
|
|---|
| 384 | APIRET APIENTRY DosQueryModFromEIP (PULONG pulModule,
|
|---|
| 385 | PULONG pulObject,
|
|---|
| 386 | ULONG ulBufferLength,
|
|---|
| 387 | PSZ pszBuffer,
|
|---|
| 388 | PULONG pulOffset,
|
|---|
| 389 | ULONG ulEIP);
|
|---|
| 390 |
|
|---|
| 391 | static void i_ProfileQuerySymbol(ULONG eip_function,
|
|---|
| 392 | char **ppszModule,
|
|---|
| 393 | char **ppszFunction)
|
|---|
| 394 | {
|
|---|
| 395 | APIRET rc; /* API returncode */
|
|---|
| 396 | ULONG ulModule; /* module number */
|
|---|
| 397 | ULONG ulObject; /* object number within the module */
|
|---|
| 398 | CHAR szModule[260]; /* buffer for the module name */
|
|---|
| 399 | ULONG ulOffset; /* offset within the object within the module */
|
|---|
| 400 | ULONG ulSymbolOffset;
|
|---|
| 401 |
|
|---|
| 402 | rc = DosQueryModFromEIP(&ulModule,
|
|---|
| 403 | &ulObject,
|
|---|
| 404 | sizeof(szModule),
|
|---|
| 405 | szModule,
|
|---|
| 406 | &ulOffset,
|
|---|
| 407 | eip_function);
|
|---|
| 408 | if (rc == NO_ERROR)
|
|---|
| 409 | {
|
|---|
| 410 | CHAR szFunction[128];
|
|---|
| 411 | *ppszModule = strdup(szModule);
|
|---|
| 412 |
|
|---|
| 413 | // @@@PH replace by symbol file lookup
|
|---|
| 414 | if (FALSE == pSymPool->getSymbolName(szModule,
|
|---|
| 415 | ulObject,
|
|---|
| 416 | ulOffset,
|
|---|
| 417 | szFunction,
|
|---|
| 418 | sizeof(szFunction),
|
|---|
| 419 | &ulSymbolOffset) )
|
|---|
| 420 | {
|
|---|
| 421 | sprintf(szFunction,
|
|---|
| 422 | "func_#%08xh",
|
|---|
| 423 | eip_function);
|
|---|
| 424 | }
|
|---|
| 425 | *ppszFunction = strdup(szFunction);
|
|---|
| 426 | }
|
|---|
| 427 | else
|
|---|
| 428 | {
|
|---|
| 429 | // neither module name nor function could be determined, so
|
|---|
| 430 | // we can just provide these values here.
|
|---|
| 431 | CHAR szFunction[40];
|
|---|
| 432 | *ppszModule = "<unknown module>";
|
|---|
| 433 | sprintf(szFunction,
|
|---|
| 434 | "func_#%08xh",
|
|---|
| 435 | eip_function);
|
|---|
| 436 | *ppszFunction = strdup(szFunction);
|
|---|
| 437 | }
|
|---|
| 438 | }
|
|---|
| 439 |
|
|---|
| 440 |
|
|---|
| 441 |
|
|---|
| 442 | //
|
|---|
| 443 | // @@@PH
|
|---|
| 444 | // Note: prevent compiler from generating hooks in these functions here!
|
|---|
| 445 | // -> is there any pragma to prevent this?
|
|---|
| 446 | // -> alternative: place it in the makefile accordingly w/ "/Gh-"
|
|---|
| 447 |
|
|---|
| 448 | ULONG _System C_ProfileHook32Enter(ULONG eip_function, ULONG ret, ULONG time_hi, ULONG time_lo)
|
|---|
| 449 | {
|
|---|
| 450 | if (!fIsProfilerEnabled)
|
|---|
| 451 | // tell low level procedure not to replace the return address
|
|---|
| 452 | // so bottom half will never be called
|
|---|
| 453 | return ret;
|
|---|
| 454 |
|
|---|
| 455 | USHORT sel = RestoreOS2FS();
|
|---|
| 456 | // DosEnterCritSec();
|
|---|
| 457 |
|
|---|
| 458 |
|
|---|
| 459 | // "call _ProfileHook32" has 5 bytes, adjust here
|
|---|
| 460 | eip_function -= 5;
|
|---|
| 461 |
|
|---|
| 462 | // 1 - get profiler per-thread-data-block
|
|---|
| 463 | PPROFILERBLOCK pPB = getProfilerBlock();
|
|---|
| 464 | if (NULL == pPB)
|
|---|
| 465 | // tell low level procedure not to replace the return address
|
|---|
| 466 | // so bottom half will never be called
|
|---|
| 467 | return ret;
|
|---|
| 468 |
|
|---|
| 469 | // 2 - save return address and call stack entry
|
|---|
| 470 | int i = pPB->ulCalldepth;
|
|---|
| 471 | pPB->ret[i] = ret;
|
|---|
| 472 | pPB->callStack[i] = eip_function;
|
|---|
| 473 |
|
|---|
| 474 | // 3 - check if the database has an entry with the current EIP
|
|---|
| 475 | // @@@PH need to synchronize access!
|
|---|
| 476 | PPROFILEENTRY pPE = (PPROFILEENTRY) pPB->pHashtable->getElement(eip_function);
|
|---|
| 477 |
|
|---|
| 478 | // 3.1 - if not, create new entry
|
|---|
| 479 | if (NULL == pPE)
|
|---|
| 480 | {
|
|---|
| 481 | pPE = (PPROFILEENTRY)malloc( sizeof(PROFILEENTRY) );
|
|---|
| 482 |
|
|---|
| 483 | i_ProfileQuerySymbol(eip_function,
|
|---|
| 484 | &pPE->pszModule,
|
|---|
| 485 | &pPE->pszFunction);
|
|---|
| 486 |
|
|---|
| 487 | pPE->EIP = eip_function;
|
|---|
| 488 | // pPE->pszModule = NULL; // @@@PH
|
|---|
| 489 | // pPE->pszFunction = NULL; // @@@PH
|
|---|
| 490 | pPE->ulCalls = 0;
|
|---|
| 491 | pPE->ulTimeMaximum = 0;
|
|---|
| 492 | pPE->ulTimeMinimum = 0xffffffff;
|
|---|
| 493 | pPE->ulTimeTotal = 0;
|
|---|
| 494 |
|
|---|
| 495 | // add to the hashtable
|
|---|
| 496 | // @@@PH need to synchronize access!
|
|---|
| 497 | pPB->pHashtable->addElement(eip_function, pPE);
|
|---|
| 498 | }
|
|---|
| 499 |
|
|---|
| 500 | // update available statistical data
|
|---|
| 501 | pPE->ulCalls++;
|
|---|
| 502 |
|
|---|
| 503 | // register call and skip to the next empty slot
|
|---|
| 504 | pPB->ulCalldepth++;
|
|---|
| 505 |
|
|---|
| 506 | // DosExitCritSec();
|
|---|
| 507 | SetFS(sel);
|
|---|
| 508 |
|
|---|
| 509 | // get "compensated" timestamp
|
|---|
| 510 | // -> keep the time between entering the function and
|
|---|
| 511 | // exiting it as low as possible, yet the error will definately
|
|---|
| 512 | // accumulate for the "higher" callers
|
|---|
| 513 | _ProfileGetTimestamp(&pPB->enterTimeHi[i],
|
|---|
| 514 | &pPB->enterTimeLo[i]);
|
|---|
| 515 |
|
|---|
| 516 | // tell low level procedure to replace the return address
|
|---|
| 517 | return (ULONG)&odin_ProfileHook32Bottom;
|
|---|
| 518 | }
|
|---|
| 519 |
|
|---|
| 520 |
|
|---|
| 521 | ULONG _System C_ProfileHook32Exit(ULONG time_hi, ULONG time_lo)
|
|---|
| 522 | {
|
|---|
| 523 | // 1 - get profiler per-thread-data-block
|
|---|
| 524 | PPROFILERBLOCK pPB = getProfilerBlock();
|
|---|
| 525 | if (NULL == pPB)
|
|---|
| 526 | // Oops, we're now in deep trouble! The return address will not be
|
|---|
| 527 | // available, so we're definately gonna crash!
|
|---|
| 528 | return NULL;
|
|---|
| 529 |
|
|---|
| 530 | USHORT sel = RestoreOS2FS();
|
|---|
| 531 | // DosEnterCritSec();
|
|---|
| 532 |
|
|---|
| 533 | // register call exit
|
|---|
| 534 | pPB->ulCalldepth--;
|
|---|
| 535 |
|
|---|
| 536 | // 3.2 - add gathered statistical values to the entry
|
|---|
| 537 | int i = pPB->ulCalldepth;
|
|---|
| 538 | ULONG eip_function = pPB->callStack[i];
|
|---|
| 539 | PPROFILEENTRY pPE = (PPROFILEENTRY) pPB->pHashtable->getElement(eip_function);
|
|---|
| 540 | if (pPE)
|
|---|
| 541 | {
|
|---|
| 542 | ULONG ulDiffHi = time_hi - pPB->enterTimeHi[i];
|
|---|
| 543 | ULONG ulDiffLo = time_lo - pPB->enterTimeLo[i];
|
|---|
| 544 |
|
|---|
| 545 | // test for wrap around
|
|---|
| 546 | if (ulDiffHi)
|
|---|
| 547 | ulDiffLo = ~ulDiffLo;
|
|---|
| 548 |
|
|---|
| 549 | // timestamps are in "cpu cycles"
|
|---|
| 550 | // ULONG ulTime = (ulDiffHi >> 4) | (ulDiffLo << 28);
|
|---|
| 551 | ULONG ulTime = ulDiffLo;
|
|---|
| 552 |
|
|---|
| 553 | if (pPE->ulTimeMinimum > ulTime)
|
|---|
| 554 | pPE->ulTimeMinimum = ulTime;
|
|---|
| 555 |
|
|---|
| 556 | if (pPE->ulTimeMaximum < ulTime)
|
|---|
| 557 | pPE->ulTimeMaximum = ulTime;
|
|---|
| 558 |
|
|---|
| 559 | pPE->ulTimeTotal += ulTime;
|
|---|
| 560 | }
|
|---|
| 561 |
|
|---|
| 562 | // DosExitCritSec();
|
|---|
| 563 | SetFS(sel);
|
|---|
| 564 |
|
|---|
| 565 | // 2 - return saved return address
|
|---|
| 566 | return pPB->ret[pPB->ulCalldepth];
|
|---|
| 567 | }
|
|---|
| 568 |
|
|---|
| 569 |
|
|---|
| 570 | // query if the profiler is enabled
|
|---|
| 571 | BOOL _System ProfilerIsEnabled(void)
|
|---|
| 572 | {
|
|---|
| 573 | return fIsProfilerEnabled;
|
|---|
| 574 | }
|
|---|
| 575 |
|
|---|
| 576 |
|
|---|
| 577 | // enable / disable the profiler hook
|
|---|
| 578 | void _System ProfilerEnable(BOOL fState)
|
|---|
| 579 | {
|
|---|
| 580 | fIsProfilerEnabled = fState;
|
|---|
| 581 | }
|
|---|
| 582 |
|
|---|
| 583 |
|
|---|
| 584 | // initialize the profiler (i. e. working directory)
|
|---|
| 585 | void _System ProfilerInitialize(void)
|
|---|
| 586 | {
|
|---|
| 587 | USHORT sel = RestoreOS2FS();
|
|---|
| 588 |
|
|---|
| 589 | // determine where to write the profile data to
|
|---|
| 590 | // (get the current working directory)
|
|---|
| 591 | getcwd(szWorkingDirectory, sizeof(szWorkingDirectory) );
|
|---|
| 592 |
|
|---|
| 593 | // @@@PH
|
|---|
| 594 | // try to determine the measurement overhead
|
|---|
| 595 | // (difficult due to non-deterministic behaviour
|
|---|
| 596 | // of the hashtable lookups and dynamic symbol loading, etc.)
|
|---|
| 597 | // We'd have to split the hook function into three parts:
|
|---|
| 598 | // - lookup and prepare the call
|
|---|
| 599 | // - enter call
|
|---|
| 600 | // - exit call
|
|---|
| 601 | // This however, still leaves us with wrong timing for the parent functions.
|
|---|
| 602 |
|
|---|
| 603 | SetFS(sel);
|
|---|
| 604 | }
|
|---|
| 605 |
|
|---|
| 606 |
|
|---|
| 607 | // terminate the profiler
|
|---|
| 608 | void _System ProfilerTerminate(void)
|
|---|
| 609 | {
|
|---|
| 610 | USHORT sel = RestoreOS2FS();
|
|---|
| 611 |
|
|---|
| 612 | // disable the profiler
|
|---|
| 613 | ProfilerEnable(FALSE);
|
|---|
| 614 |
|
|---|
| 615 | SetFS(sel);
|
|---|
| 616 | }
|
|---|
| 617 |
|
|---|
| 618 |
|
|---|
| 619 | int _Optlink sortHashtableEntries0(const void *arg1,const void *arg2)
|
|---|
| 620 | {
|
|---|
| 621 | PHASHTABLEENTRYID pHTE1 = (PHASHTABLEENTRYID)arg1;
|
|---|
| 622 | PHASHTABLEENTRYID pHTE2 = (PHASHTABLEENTRYID)arg2;
|
|---|
| 623 |
|
|---|
| 624 | PPROFILEENTRY p1 = (PPROFILEENTRY)pHTE1->pObject;
|
|---|
| 625 | PPROFILEENTRY p2 = (PPROFILEENTRY)pHTE2->pObject;
|
|---|
| 626 |
|
|---|
| 627 | return strcmp(p1->pszFunction, p2->pszFunction);
|
|---|
| 628 | }
|
|---|
| 629 |
|
|---|
| 630 | int _Optlink sortHashtableEntries1(const void *arg1,const void *arg2)
|
|---|
| 631 | {
|
|---|
| 632 | PHASHTABLEENTRYID pHTE1 = (PHASHTABLEENTRYID)arg1;
|
|---|
| 633 | PHASHTABLEENTRYID pHTE2 = (PHASHTABLEENTRYID)arg2;
|
|---|
| 634 |
|
|---|
| 635 | PPROFILEENTRY p1 = (PPROFILEENTRY)pHTE1->pObject;
|
|---|
| 636 | PPROFILEENTRY p2 = (PPROFILEENTRY)pHTE2->pObject;
|
|---|
| 637 |
|
|---|
| 638 | return p1->ulTimeTotal - p2->ulTimeTotal;
|
|---|
| 639 | }
|
|---|
| 640 |
|
|---|
| 641 | int _Optlink sortHashtableEntries2(const void *arg1,const void *arg2)
|
|---|
| 642 | {
|
|---|
| 643 | PHASHTABLEENTRYID pHTE1 = (PHASHTABLEENTRYID)arg1;
|
|---|
| 644 | PHASHTABLEENTRYID pHTE2 = (PHASHTABLEENTRYID)arg2;
|
|---|
| 645 |
|
|---|
| 646 | PPROFILEENTRY p1 = (PPROFILEENTRY)pHTE1->pObject;
|
|---|
| 647 | PPROFILEENTRY p2 = (PPROFILEENTRY)pHTE2->pObject;
|
|---|
| 648 |
|
|---|
| 649 | return p1->ulCalls - p2->ulCalls;
|
|---|
| 650 | }
|
|---|
| 651 |
|
|---|
| 652 | int _Optlink sortHashtableEntries3(const void *arg1,const void *arg2)
|
|---|
| 653 | {
|
|---|
| 654 | PHASHTABLEENTRYID pHTE1 = (PHASHTABLEENTRYID)arg1;
|
|---|
| 655 | PHASHTABLEENTRYID pHTE2 = (PHASHTABLEENTRYID)arg2;
|
|---|
| 656 |
|
|---|
| 657 | PPROFILEENTRY p1 = (PPROFILEENTRY)pHTE1->pObject;
|
|---|
| 658 | PPROFILEENTRY p2 = (PPROFILEENTRY)pHTE2->pObject;
|
|---|
| 659 |
|
|---|
| 660 | unsigned long int iAvg1 = p1->ulTimeTotal / p1->ulCalls;
|
|---|
| 661 | unsigned long int iAvg2 = p2->ulTimeTotal / p2->ulCalls;
|
|---|
| 662 |
|
|---|
| 663 | return iAvg1 - iAvg2;
|
|---|
| 664 | }
|
|---|
| 665 |
|
|---|
| 666 | int _Optlink sortHashtableEntries4(const void *arg1,const void *arg2)
|
|---|
| 667 | {
|
|---|
| 668 | PHASHTABLEENTRYID pHTE1 = (PHASHTABLEENTRYID)arg1;
|
|---|
| 669 | PHASHTABLEENTRYID pHTE2 = (PHASHTABLEENTRYID)arg2;
|
|---|
| 670 |
|
|---|
| 671 | PPROFILEENTRY p1 = (PPROFILEENTRY)pHTE1->pObject;
|
|---|
| 672 | PPROFILEENTRY p2 = (PPROFILEENTRY)pHTE2->pObject;
|
|---|
| 673 |
|
|---|
| 674 | return p1->EIP - p2->EIP;
|
|---|
| 675 | }
|
|---|
| 676 |
|
|---|
| 677 |
|
|---|
| 678 | // dump the collected profile to the specified file
|
|---|
| 679 | void _Optlink Profiler_DumpProfile(FILE *file)
|
|---|
| 680 | {
|
|---|
| 681 | fprintf(file,
|
|---|
| 682 | "ODIN Performance Analysis\n");
|
|---|
| 683 |
|
|---|
| 684 | BOOL flagLock = ProfilerIsEnabled(); // lock recording
|
|---|
| 685 | ProfilerEnable(FALSE);
|
|---|
| 686 |
|
|---|
| 687 | int iEntries = pProfileMap->getNumberOfElements();
|
|---|
| 688 |
|
|---|
| 689 | // get a list of all entries of the hashtable
|
|---|
| 690 | PHASHTABLEENTRYID arrEntries = (PHASHTABLEENTRYID)malloc( iEntries * sizeof(HASHTABLEENTRYID) );
|
|---|
| 691 | iEntries = pProfileMap->getElementMap(arrEntries);
|
|---|
| 692 |
|
|---|
| 693 | fprintf(file,
|
|---|
| 694 | "%d entries available.\n\n",
|
|---|
| 695 | iEntries);
|
|---|
| 696 |
|
|---|
| 697 | // sort the list by function name
|
|---|
| 698 | qsort(arrEntries,
|
|---|
| 699 | iEntries,
|
|---|
| 700 | sizeof( HASHTABLEENTRYID ),
|
|---|
| 701 | sortHashtableEntries0);
|
|---|
| 702 |
|
|---|
| 703 | // write to file
|
|---|
| 704 | fprintf(file,
|
|---|
| 705 | "Sorted by function name\n"
|
|---|
| 706 | "Ticks ---- Called --- Average -- Minimum -- Maximum -- Function -----------\n");
|
|---|
| 707 | for(int i = 0;
|
|---|
| 708 | i < iEntries;
|
|---|
| 709 | i++)
|
|---|
| 710 | {
|
|---|
| 711 | PPROFILEENTRY p = (PPROFILEENTRY)arrEntries[i].pObject;
|
|---|
| 712 | fprintf(file,
|
|---|
| 713 | "%10d %10d %10d %10d %10d %s(%s)\n",
|
|---|
| 714 | p->ulTimeTotal,
|
|---|
| 715 | p->ulCalls,
|
|---|
| 716 | p->ulTimeTotal / p->ulCalls,
|
|---|
| 717 | p->ulTimeMinimum,
|
|---|
| 718 | p->ulTimeMaximum,
|
|---|
| 719 | p->pszFunction,
|
|---|
| 720 | p->pszModule);
|
|---|
| 721 | }
|
|---|
| 722 |
|
|---|
| 723 |
|
|---|
| 724 | // sort the list by ulTimeTotal
|
|---|
| 725 | qsort(arrEntries,
|
|---|
| 726 | iEntries,
|
|---|
| 727 | sizeof( HASHTABLEENTRYID ),
|
|---|
| 728 | sortHashtableEntries1);
|
|---|
| 729 |
|
|---|
| 730 | // write to file
|
|---|
| 731 | fprintf(file,
|
|---|
| 732 | "\nSorted by total call time\n"
|
|---|
| 733 | "Ticks ---- Called --- Average -- Function ---------------------------------\n");
|
|---|
| 734 | for(i = 0;
|
|---|
| 735 | i < iEntries;
|
|---|
| 736 | i++)
|
|---|
| 737 | {
|
|---|
| 738 | PPROFILEENTRY p = (PPROFILEENTRY)arrEntries[i].pObject;
|
|---|
| 739 | fprintf(file,
|
|---|
| 740 | "%10d %10d %10d %s(%s)\n",
|
|---|
| 741 | p->ulTimeTotal,
|
|---|
| 742 | p->ulCalls,
|
|---|
| 743 | p->ulTimeTotal / p->ulCalls,
|
|---|
| 744 | p->pszFunction,
|
|---|
| 745 | p->pszModule);
|
|---|
| 746 | }
|
|---|
| 747 |
|
|---|
| 748 |
|
|---|
| 749 | // sort the list by ulCalls
|
|---|
| 750 | qsort(arrEntries,
|
|---|
| 751 | iEntries,
|
|---|
| 752 | sizeof( HASHTABLEENTRYID ),
|
|---|
| 753 | sortHashtableEntries2);
|
|---|
| 754 |
|
|---|
| 755 | // write to file
|
|---|
| 756 | fprintf(file,
|
|---|
| 757 | "\nSorted by total calls\n"
|
|---|
| 758 | "Called --- Ticks ---- Average -- Function ---------------------------------\n");
|
|---|
| 759 | for(i = 0;
|
|---|
| 760 | i < iEntries;
|
|---|
| 761 | i++)
|
|---|
| 762 | {
|
|---|
| 763 | PPROFILEENTRY p = (PPROFILEENTRY)arrEntries[i].pObject;
|
|---|
| 764 | fprintf(file,
|
|---|
| 765 | "%10d %10d %10d %s(%s)\n",
|
|---|
| 766 | p->ulCalls,
|
|---|
| 767 | p->ulTimeTotal,
|
|---|
| 768 | p->ulTimeTotal / p->ulCalls,
|
|---|
| 769 | p->pszFunction,
|
|---|
| 770 | p->pszModule);
|
|---|
| 771 | }
|
|---|
| 772 |
|
|---|
| 773 |
|
|---|
| 774 | // sort the list by average call time
|
|---|
| 775 | qsort(arrEntries,
|
|---|
| 776 | iEntries,
|
|---|
| 777 | sizeof( HASHTABLEENTRYID ),
|
|---|
| 778 | sortHashtableEntries3);
|
|---|
| 779 |
|
|---|
| 780 | // write to file
|
|---|
| 781 | fprintf(file,
|
|---|
| 782 | "\nSorted by average call time\n"
|
|---|
| 783 | "Average -- Calls ---- Ticks ---- Function ---------------------------------\n");
|
|---|
| 784 | for(i = 0;
|
|---|
| 785 | i < iEntries;
|
|---|
| 786 | i++)
|
|---|
| 787 | {
|
|---|
| 788 | PPROFILEENTRY p = (PPROFILEENTRY)arrEntries[i].pObject;
|
|---|
| 789 | fprintf(file,
|
|---|
| 790 | "%10d %10d %10d %s(%s)\n",
|
|---|
| 791 | p->ulTimeTotal / p->ulCalls,
|
|---|
| 792 | p->ulCalls,
|
|---|
| 793 | p->ulTimeTotal,
|
|---|
| 794 | p->pszFunction,
|
|---|
| 795 | p->pszModule);
|
|---|
| 796 | }
|
|---|
| 797 |
|
|---|
| 798 |
|
|---|
| 799 | // sort the list by address
|
|---|
| 800 | qsort(arrEntries,
|
|---|
| 801 | iEntries,
|
|---|
| 802 | sizeof( HASHTABLEENTRYID ),
|
|---|
| 803 | sortHashtableEntries4);
|
|---|
| 804 |
|
|---|
| 805 |
|
|---|
| 806 | // write to file
|
|---|
| 807 | fprintf(file,
|
|---|
| 808 | "\nFunctions / symbols sorted by address\n"
|
|---|
| 809 | "Address ----- Function / Symbol -------------------------------------------\n");
|
|---|
| 810 | for(i = 0;
|
|---|
| 811 | i < iEntries;
|
|---|
| 812 | i++)
|
|---|
| 813 | {
|
|---|
| 814 | PPROFILEENTRY p = (PPROFILEENTRY)arrEntries[i].pObject;
|
|---|
| 815 | fprintf(file,
|
|---|
| 816 | "#%08xh %-9s %s\n",
|
|---|
| 817 | p->EIP,
|
|---|
| 818 | p->pszModule,
|
|---|
| 819 | p->pszFunction);
|
|---|
| 820 | }
|
|---|
| 821 |
|
|---|
| 822 | // at last print the sym map
|
|---|
| 823 | pSymPool->printSYMs(file);
|
|---|
| 824 |
|
|---|
| 825 | ProfilerEnable(flagLock);
|
|---|
| 826 | }
|
|---|
| 827 |
|
|---|
| 828 |
|
|---|
| 829 | void _System ProfilerWrite()
|
|---|
| 830 | {
|
|---|
| 831 | FILE* _privateLogFile;
|
|---|
| 832 | char szFilename[260];
|
|---|
| 833 | USHORT sel = RestoreOS2FS();
|
|---|
| 834 | int pid = _getpid();
|
|---|
| 835 |
|
|---|
| 836 | sprintf(szFilename, "%s\\%d.prof", szWorkingDirectory, pid);
|
|---|
| 837 | _privateLogFile = fopen(szFilename, "w");
|
|---|
| 838 |
|
|---|
| 839 | if(_privateLogFile == NULL)
|
|---|
| 840 | {
|
|---|
| 841 | DosBeep(500,500);
|
|---|
| 842 | }
|
|---|
| 843 | else
|
|---|
| 844 | {
|
|---|
| 845 | // dump the gathered data
|
|---|
| 846 | Profiler_DumpProfile(_privateLogFile);
|
|---|
| 847 |
|
|---|
| 848 | if(_privateLogFile)
|
|---|
| 849 | {
|
|---|
| 850 | fclose(_privateLogFile);
|
|---|
| 851 | _privateLogFile = NULL;
|
|---|
| 852 | }
|
|---|
| 853 | }
|
|---|
| 854 |
|
|---|
| 855 | SetFS(sel);
|
|---|
| 856 | }
|
|---|
| 857 |
|
|---|