1 /*
2 * Analyze the profile file (cmon.out) written out by the dbug
3 * routines with profiling enabled.
4 *
5 * Copyright June 1987, Binayak Banerjee
6 * All rights reserved.
7 *
8 * This program may be freely distributed under the same terms and
9 * conditions as Fred Fish's Dbug package.
10 *
11 * Compile with -- cc -O -s -o %s analyze.c
12 *
13 * Analyze will read an trace file created by the dbug package
14 * (when run with traceing enabled). It will then produce a
15 * summary on standard output listing the name of each traced
16 * function, the number of times it was called, the percentage
17 * of total calls, the time spent executing the function, the
18 * proportion of the total time and the 'importance'. The last
19 * is a metric which is obtained by multiplying the proportions
20 * of calls and the proportions of time for each function. The
21 * greater the importance, the more likely it is that a speedup
22 * could be obtained by reducing the time taken by that function.
23 *
24 * Note that the timing values that you obtain are only rough
25 * measures. The overhead of the dbug package is included
26 * within. However, there is no need to link in special profiled
27 * libraries and the like.
28 *
29 * CHANGES:
30 *
31 * 2-Mar-89: fnf
32 * Changes to support tracking of stack usage. This required
33 * reordering the fields in the profile log file to make
34 * parsing of different record types easier. Corresponding
35 * changes made in dbug runtime library. Also used this
36 * opportunity to reformat the code more to my liking (my
37 * apologies to Binayak Banerjee for "uglifying" his code).
38 *
39 * 24-Jul-87: fnf
40 * Because I tend to use functions names like
41 * "ExternalFunctionDoingSomething", I've rearranged the
42 * printout to put the function name last in each line, so
43 * long names don't screw up the formatting unless they are
44 * *very* long and wrap around the screen width...
45 *
46 * 24-Jul-87: fnf
47 * Modified to put out table very similar to Unix profiler
48 * by default, but also puts out original verbose table
49 * if invoked with -v flag.
50 */
51
52 #include <my_global.h>
53 #include <m_string.h>
54 #include <my_thread.h>
55
56 static char *my_name;
57 static int verbose;
58
59 /*
60 * Structure of the stack.
61 */
62
63 #define PRO_FILE "dbugmon.out" /* Default output file name */
64 #define STACKSIZ 100 /* Maximum function nesting */
65 #define MAXPROCS 10000 /* Maximum number of function calls */
66
67 # ifdef BSD
68 # include <sysexits.h>
69 # else
70 # define EX_SOFTWARE 1
71 # define EX_DATAERR 1
72 # define EX_USAGE 1
73 # define EX_OSERR 1
74 # define EX_IOERR 1
75 #ifndef EX_OK
76 # define EX_OK 0
77 #endif
78 # endif
79
80 #define __MERF_OO_ "%s: Malloc Failed in %s: %d\n"
81
82 #define MALLOC(Ptr,Num,Typ) do /* Malloc w/error checking & exit */ \
83 if (!(Ptr = (Typ *)malloc((Num)*(sizeof(Typ))))) \
84 {fprintf(stderr,__MERF_OO_,my_name,__FILE__,__LINE__);\
85 exit(EX_OSERR);} while(0)
86
87 #define Malloc(Ptr,Num,Typ) do /* Weaker version of above */\
88 if (!(Ptr = (Typ *)malloc((Num)*(sizeof(Typ))))) \
89 fprintf(stderr,__MERF_OO_,my_name,__FILE__,__LINE__);\
90 while(0)
91
92 #define FILEOPEN(Fp,Fn,Mod) do /* File open with error exit */ \
93 if (!(Fp = fopen(Fn,Mod)))\
94 {fprintf(stderr,"%s: Couldn't open %s\n",my_name,Fn);\
95 exit(EX_IOERR);} while(0)
96
97 #define Fileopen(Fp,Fn,Mod) do /* Weaker version of above */ \
98 if(!(Fp = fopen(Fn,Mod))) \
99 fprintf(stderr,"%s: Couldn't open %s\n",my_name,Fn);\
100 while(0)
101
102
103 struct stack_t {
104 unsigned int pos; /* which function? */
105 unsigned long time; /* Time that this was entered */
106 unsigned long children; /* Time spent in called funcs */
107 };
108
109 static struct stack_t fn_stack[STACKSIZ+1];
110
111 static unsigned int stacktop = 0; /* Lowest stack position is a dummy */
112
113 static unsigned long tot_time = 0;
114 static unsigned long tot_calls = 0;
115 static unsigned long highstack = 0;
116 static unsigned long lowstack = (ulong) ~0;
117
118 /*
119 * top() returns a pointer to the top item on the stack.
120 * (was a function, now a macro)
121 */
122
123 #define top() &fn_stack[stacktop]
124
125 /*
126 * Push - Push the given record on the stack.
127 */
128
push(name_pos,time_entered)129 void push (name_pos, time_entered)
130 unsigned int name_pos;
131 unsigned long time_entered;
132 {
133 struct stack_t *t;
134
135 DBUG_ENTER("push");
136 if (++stacktop > STACKSIZ) {
137 fprintf (DBUG_FILE,"%s: stack overflow (%s:%d)\n",
138 my_name, __FILE__, __LINE__);
139 exit (EX_SOFTWARE);
140 }
141 DBUG_PRINT ("push", ("%d %ld",name_pos,time_entered));
142 t = &fn_stack[stacktop];
143 t -> pos = name_pos;
144 t -> time = time_entered;
145 t -> children = 0;
146 DBUG_VOID_RETURN;
147 }
148
149 /*
150 * Pop - pop the top item off the stack, assigning the field values
151 * to the arguments. Returns 0 on stack underflow, or on popping first
152 * item off stack.
153 */
154
pop(name_pos,time_entered,child_time)155 unsigned int pop (name_pos, time_entered, child_time)
156 unsigned int *name_pos;
157 unsigned long *time_entered;
158 unsigned long *child_time;
159 {
160 struct stack_t *temp;
161 unsigned int rtnval;
162
163 DBUG_ENTER ("pop");
164
165 if (stacktop < 1) {
166 rtnval = 0;
167 } else {
168 temp = &fn_stack[stacktop];
169 *name_pos = temp->pos;
170 *time_entered = temp->time;
171 *child_time = temp->children;
172 DBUG_PRINT ("pop", ("%d %lu %lu",*name_pos,*time_entered,*child_time));
173 rtnval = stacktop--;
174 }
175 DBUG_RETURN (rtnval);
176 }
177
178 /*
179 * We keep the function info in another array (serves as a simple
180 * symbol table)
181 */
182
183 struct module_t {
184 char *name;
185 unsigned long m_time;
186 unsigned long m_calls;
187 unsigned long m_stkuse;
188 };
189
190 static struct module_t modules[MAXPROCS];
191
192 /*
193 * We keep a binary search tree in order to look up function names
194 * quickly (and sort them at the end.
195 */
196
197 struct bnode {
198 unsigned int lchild; /* Index of left subtree */
199 unsigned int rchild; /* Index of right subtree */
200 unsigned int pos; /* Index of module_name entry */
201 };
202
203 static struct bnode s_table[MAXPROCS];
204
205 static unsigned int n_items = 0; /* No. of items in the array so far */
206
207 /*
208 * Need a function to allocate space for a string and squirrel it away.
209 */
210
strsave(s)211 char *strsave (s)
212 char *s;
213 {
214 char *retval;
215 unsigned int len;
216
217 DBUG_ENTER ("strsave");
218 DBUG_PRINT ("strsave", ("%s",s));
219 if (!s || (len = strlen (s)) == 0) {
220 DBUG_RETURN (0);
221 }
222 MALLOC (retval, ++len, char);
223 strcpy (retval, s);
224 DBUG_RETURN (retval);
225 }
226
227 /*
228 * add() - adds m_name to the table (if not already there), and returns
229 * the index of its location in the table. Checks s_table (which is a
230 * binary search tree) to see whether or not it should be added.
231 */
232
add(m_name)233 unsigned int add (m_name)
234 char *m_name;
235 {
236 unsigned int ind = 0;
237 int cmp;
238
239 DBUG_ENTER ("add");
240 if (n_items == 0) { /* First item to be added */
241 s_table[0].pos = ind;
242 s_table[0].lchild = s_table[0].rchild = MAXPROCS;
243 addit:
244 modules[n_items].name = strsave (m_name);
245 modules[n_items].m_time = 0;
246 modules[n_items].m_calls = 0;
247 modules[n_items].m_stkuse = 0;
248 DBUG_RETURN (n_items++);
249 }
250 while ((cmp = strcmp (m_name,modules[ind].name))) {
251 if (cmp < 0) { /* In left subtree */
252 if (s_table[ind].lchild == MAXPROCS) {
253 /* Add as left child */
254 if (n_items >= MAXPROCS) {
255 fprintf (DBUG_FILE,
256 "%s: Too many functions being profiled\n",
257 my_name);
258 exit (EX_SOFTWARE);
259 }
260 s_table[n_items].pos = s_table[ind].lchild = n_items;
261 s_table[n_items].lchild = s_table[n_items].rchild = MAXPROCS;
262 #ifdef notdef
263 modules[n_items].name = strsave (m_name);
264 modules[n_items].m_time = modules[n_items].m_calls = 0;
265 DBUG_RETURN (n_items++);
266 #else
267 goto addit;
268 #endif
269
270 }
271 ind = s_table[ind].lchild; /* else traverse l-tree */
272 } else {
273 if (s_table[ind].rchild == MAXPROCS) {
274 /* Add as right child */
275 if (n_items >= MAXPROCS) {
276 fprintf (DBUG_FILE,
277 "%s: Too many functions being profiled\n",
278 my_name);
279 exit (EX_SOFTWARE);
280 }
281 s_table[n_items].pos = s_table[ind].rchild = n_items;
282 s_table[n_items].lchild = s_table[n_items].rchild = MAXPROCS;
283 #ifdef notdef
284 modules[n_items].name = strsave (m_name);
285 modules[n_items].m_time = modules[n_items].m_calls = 0;
286 DBUG_RETURN (n_items++);
287 #else
288 goto addit;
289 #endif
290
291 }
292 ind = s_table[ind].rchild; /* else traverse r-tree */
293 }
294 }
295 DBUG_RETURN (ind);
296 }
297
298 /*
299 * process() - process the input file, filling in the modules table.
300 */
301
process(inf)302 void process (inf)
303 FILE *inf;
304 {
305 char buf[BUFSIZ];
306 char fn_name[64]; /* Max length of fn_name */
307 unsigned long fn_time;
308 unsigned long fn_sbot;
309 unsigned long fn_ssz;
310 unsigned long lastuse;
311 unsigned int pos;
312 unsigned long local_time;
313 unsigned int oldpos;
314 unsigned long oldtime;
315 unsigned long oldchild;
316 struct stack_t *t;
317
318 DBUG_ENTER ("process");
319 while (fgets (buf,BUFSIZ,inf) != NULL) {
320 switch (buf[0]) {
321 case 'E':
322 sscanf (buf+2, "%ld %64s", &fn_time, fn_name);
323 DBUG_PRINT ("erec", ("%ld %s", fn_time, fn_name));
324 pos = add (fn_name);
325 push (pos, fn_time);
326 break;
327 case 'X':
328 sscanf (buf+2, "%ld %64s", &fn_time, fn_name);
329 DBUG_PRINT ("xrec", ("%ld %s", fn_time, fn_name));
330 pos = add (fn_name);
331 /*
332 * An exited function implies that all stacked
333 * functions are also exited, until the matching
334 * function is found on the stack.
335 */
336 while (pop (&oldpos, &oldtime, &oldchild)) {
337 DBUG_PRINT ("popped", ("%lu %lu", oldtime, oldchild));
338 local_time = fn_time - oldtime;
339 t = top ();
340 t -> children += local_time;
341 DBUG_PRINT ("update", ("%s", modules[t -> pos].name));
342 DBUG_PRINT ("update", ("%lu", t -> children));
343 local_time -= oldchild;
344 modules[oldpos].m_time += local_time;
345 modules[oldpos].m_calls++;
346 tot_time += local_time;
347 tot_calls++;
348 if (pos == oldpos) {
349 goto next_line; /* Should be a break2 */
350 }
351 }
352 /*
353 * Assume that item seen started at time 0.
354 * (True for function main). But initialize
355 * it so that it works the next time too.
356 */
357 t = top ();
358 local_time = fn_time - t -> time - t -> children;
359 t -> time = fn_time; t -> children = 0;
360 modules[pos].m_time += local_time;
361 modules[pos].m_calls++;
362 tot_time += local_time;
363 tot_calls++;
364 break;
365 case 'S':
366 sscanf (buf+2, "%lx %lx %64s", &fn_sbot, &fn_ssz, fn_name);
367 DBUG_PRINT ("srec", ("%lx %lx %s", fn_sbot, fn_ssz, fn_name));
368 pos = add (fn_name);
369 lastuse = modules[pos].m_stkuse;
370 #if 0
371 /*
372 * Needs further thought. Stack use is determined by
373 * difference in stack between two functions with DBUG_ENTER
374 * macros. If A calls B calls C, where A and C have the
375 * macros, and B doesn't, then B's stack use will be lumped
376 * in with either A's or C's. If somewhere else A calls
377 * C directly, the stack use will seem to change. Just
378 * take the biggest for now...
379 */
380 if (lastuse > 0 && lastuse != fn_ssz) {
381 fprintf (stderr,
382 "warning - %s stack use changed (%lx to %lx)\n",
383 fn_name, lastuse, fn_ssz);
384 }
385 #endif
386 if (fn_ssz > lastuse) {
387 modules[pos].m_stkuse = fn_ssz;
388 }
389 if (fn_sbot > highstack) {
390 highstack = fn_sbot;
391 } else if (fn_sbot < lowstack) {
392 lowstack = fn_sbot;
393 }
394 break;
395 default:
396 fprintf (stderr, "unknown record type '%c'\n", buf[0]);
397 break;
398 }
399 next_line:;
400 }
401
402 /*
403 * Now, we've hit eof. If we still have stuff stacked, then we
404 * assume that the user called exit, so give everything the exited
405 * time of fn_time.
406 */
407 while (pop (&oldpos,&oldtime,&oldchild)) {
408 local_time = fn_time - oldtime;
409 t = top ();
410 t -> children += local_time;
411 local_time -= oldchild;
412 modules[oldpos].m_time += local_time;
413 modules[oldpos].m_calls++;
414 tot_time += local_time;
415 tot_calls++;
416 }
417 DBUG_VOID_RETURN;
418 }
419
420 /*
421 * out_header () -- print out the header of the report.
422 */
423
out_header(outf)424 void out_header (outf)
425 FILE *outf;
426 {
427 DBUG_ENTER ("out_header");
428 if (verbose) {
429 fprintf (outf, "Profile of Execution\n");
430 fprintf (outf, "Execution times are in milliseconds\n\n");
431 fprintf (outf, " Calls\t\t\t Time\n");
432 fprintf (outf, " -----\t\t\t ----\n");
433 fprintf (outf, "Times\tPercentage\tTime Spent\tPercentage\n");
434 fprintf (outf, "Called\tof total\tin Function\tof total Importance\tFunction\n");
435 fprintf (outf, "======\t==========\t===========\t========== ==========\t========\t\n");
436 } else {
437 fprintf (outf, "%ld bytes of stack used, from %lx down to %lx\n\n",
438 highstack - lowstack, highstack, lowstack);
439 fprintf (outf,
440 " %%time sec #call ms/call %%calls weight stack name\n");
441 }
442 DBUG_VOID_RETURN;
443 }
444
445 /*
446 * out_trailer () - writes out the summary line of the report.
447 */
448
out_trailer(outf,sum_calls,sum_time)449 void out_trailer (outf,sum_calls,sum_time)
450 FILE *outf;
451 unsigned long int sum_calls, sum_time;
452 {
453 DBUG_ENTER ("out_trailer");
454 if (verbose)
455 {
456 fprintf(outf, "======\t==========\t===========\t==========\t========\n");
457 fprintf(outf, "%6ld\t%10.2f\t%11ld\t%10.2f\t\t%-15s\n",
458 sum_calls, 100.0, sum_time, 100.0, "Totals");
459 }
460 DBUG_VOID_RETURN;
461 }
462
463 /*
464 * out_item () - prints out the output line for a single entry,
465 * and sets the calls and time fields appropriately.
466 */
467
out_item(outf,m,called,timed)468 void out_item (outf, m,called,timed)
469 FILE *outf;
470 struct module_t *m;
471 unsigned long int *called, *timed;
472 {
473 char *name = m -> name;
474 unsigned int calls = m -> m_calls;
475 unsigned long local_time = m -> m_time;
476 unsigned long stkuse = m -> m_stkuse;
477 unsigned int import;
478 double per_time = 0.0;
479 double per_calls = 0.0;
480 double ms_per_call, local_ftime;
481
482 DBUG_ENTER ("out_item");
483
484 if (tot_time > 0) {
485 per_time = (double) (local_time * 100) / (double) tot_time;
486 }
487 if (tot_calls > 0) {
488 per_calls = (double) (calls * 100) / (double) tot_calls;
489 }
490 import = (unsigned int) (per_time * per_calls);
491
492 if (verbose) {
493 fprintf (outf, "%6d\t%10.2f\t%11ld\t%10.2f %10d\t%-15s\n",
494 calls, per_calls, local_time, per_time, import, name);
495 } else {
496 ms_per_call = local_time;
497 ms_per_call /= calls;
498 local_ftime = local_time;
499 local_ftime /= 1000;
500 fprintf(outf, "%8.2f%8.3f%8u%8.3f%8.2f%8u%8lu %-s\n",
501 per_time, local_ftime, calls, ms_per_call, per_calls, import,
502 stkuse, name);
503 }
504 *called = calls;
505 *timed = local_time;
506 DBUG_VOID_RETURN;
507 }
508
509 /*
510 * out_body (outf, root,s_calls,s_time) -- Performs an inorder traversal
511 * on the binary search tree (root). Calls out_item to actually print
512 * the item out.
513 */
514
out_body(outf,root,s_calls,s_time)515 void out_body (outf, root,s_calls,s_time)
516 FILE *outf;
517 unsigned int root;
518 unsigned long int *s_calls, *s_time;
519 {
520 unsigned long int calls, local_time;
521
522 DBUG_ENTER ("out_body");
523 DBUG_PRINT ("out_body", ("%lu,%lu",*s_calls,*s_time));
524 if (root == MAXPROCS) {
525 DBUG_PRINT ("out_body", ("%lu,%lu",*s_calls,*s_time));
526 } else {
527 while (root != MAXPROCS) {
528 out_body (outf, s_table[root].lchild,s_calls,s_time);
529 out_item (outf, &modules[s_table[root].pos],&calls,&local_time);
530 DBUG_PRINT ("out_body", ("-- %lu -- %lu --", calls, local_time));
531 *s_calls += calls;
532 *s_time += local_time;
533 root = s_table[root].rchild;
534 }
535 DBUG_PRINT ("out_body", ("%lu,%lu", *s_calls, *s_time));
536 }
537 DBUG_VOID_RETURN;
538 }
539
540 /*
541 * output () - print out a nice sorted output report on outf.
542 */
543
output(outf)544 void output (outf)
545 FILE *outf;
546 {
547 unsigned long int sum_calls = 0;
548 unsigned long int sum_time = 0;
549
550 DBUG_ENTER ("output");
551 if (n_items == 0) {
552 fprintf (outf, "%s: No functions to trace\n", my_name);
553 exit (EX_DATAERR);
554 }
555 out_header (outf);
556 out_body (outf, 0,&sum_calls,&sum_time);
557 out_trailer (outf, sum_calls,sum_time);
558 DBUG_VOID_RETURN;
559 }
560
561
562 #define usage() fprintf (DBUG_FILE,"Usage: %s [-v] [prof-file]\n",my_name)
563
564 extern int optind;
565 extern char *optarg;
566
main(int argc,char ** argv)567 int main (int argc, char **argv)
568 {
569 int c;
570 int badflg = 0;
571 FILE *infile;
572 FILE *outfile = {stdout};
573
574 my_thread_global_init();
575 {
576 DBUG_ENTER ("main");
577 DBUG_PROCESS (argv[0]);
578 my_name = argv[0];
579 while ((c = getopt (argc,argv,"#:v")) != EOF) {
580 switch (c) {
581 case '#': /* Debugging Macro enable */
582 DBUG_PUSH (optarg);
583 break;
584 case 'v': /* Verbose mode */
585 verbose++;
586 break;
587 default:
588 badflg++;
589 break;
590 }
591 }
592 if (badflg) {
593 usage ();
594 DBUG_RETURN (EX_USAGE);
595 }
596 if (optind < argc) {
597 FILEOPEN (infile, argv[optind], "r");
598 } else {
599 FILEOPEN (infile, PRO_FILE, "r");
600 }
601 process (infile);
602 output (outfile);
603 DBUG_RETURN (EX_OK);
604 }
605 }
606