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 |
|
---|