2 * Analyze the profile file (cmon.out) written out by the dbug
3 * routines with profiling enabled.
5 * Copyright June 1987, Binayak Banerjee
8 * This program may be freely distributed under the same terms and
9 * conditions as Fred Fish's Dbug package.
11 * Compile with -- cc -O -s -o %s analyze.c
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.
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.
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).
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...
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.
52 #include <my_global.h>
54 #include <my_pthread.h>
60 * Structure of the stack.
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 */
68 # include <sysexits.h>
70 # define EX_SOFTWARE 1
80 #define __MERF_OO_ "%s: Malloc Failed in %s: %d\n"
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)
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__);\
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)
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);\
104 unsigned int pos
; /* which function? */
105 unsigned long time
; /* Time that this was entered */
106 unsigned long children
; /* Time spent in called funcs */
109 static struct stack_t fn_stack
[STACKSIZ
+1];
111 static unsigned int stacktop
= 0; /* Lowest stack position is a dummy */
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;
119 * top() returns a pointer to the top item on the stack.
120 * (was a function, now a macro)
123 #define top() &fn_stack[stacktop]
126 * Push - Push the given record on the stack.
129 void push (name_pos
, time_entered
)
130 register unsigned int name_pos
;
131 register unsigned long time_entered
;
133 register struct stack_t
*t
;
136 if (++stacktop
> STACKSIZ
) {
137 fprintf (DBUG_FILE
,"%s: stack overflow (%s:%d)\n",
138 my_name
, __FILE__
, __LINE__
);
141 DBUG_PRINT ("push", ("%d %ld",name_pos
,time_entered
));
142 t
= &fn_stack
[stacktop
];
144 t
-> time
= time_entered
;
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
155 unsigned int pop (name_pos
, time_entered
, child_time
)
156 register unsigned int *name_pos
;
157 register unsigned long *time_entered
;
158 register unsigned long *child_time
;
160 register struct stack_t
*temp
;
161 register unsigned int rtnval
;
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
));
175 DBUG_RETURN (rtnval
);
179 * We keep the function info in another array (serves as a simple
185 unsigned long m_time
;
186 unsigned long m_calls
;
187 unsigned long m_stkuse
;
190 static struct module_t modules
[MAXPROCS
];
193 * We keep a binary search tree in order to look up function names
194 * quickly (and sort them at the end.
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 */
203 static struct bnode s_table
[MAXPROCS
];
205 static unsigned int n_items
= 0; /* No. of items in the array so far */
208 * Need a function to allocate space for a string and squirrel it away.
214 register char *retval
;
215 register unsigned int len
;
217 DBUG_ENTER ("strsave");
218 DBUG_PRINT ("strsave", ("%s",s
));
219 if (!s
|| (len
= strlen (s
)) == 0) {
222 MALLOC (retval
, ++len
, char);
224 DBUG_RETURN (retval
);
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.
233 unsigned int add (m_name
)
236 register unsigned int ind
= 0;
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
;
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
++);
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
) {
256 "%s: Too many functions being profiled\n",
260 s_table
[n_items
].pos
= s_table
[ind
].lchild
= n_items
;
261 s_table
[n_items
].lchild
= s_table
[n_items
].rchild
= MAXPROCS
;
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
++);
271 ind
= s_table
[ind
].lchild
; /* else traverse l-tree */
273 if (s_table
[ind
].rchild
== MAXPROCS
) {
274 /* Add as right child */
275 if (n_items
>= MAXPROCS
) {
277 "%s: Too many functions being profiled\n",
281 s_table
[n_items
].pos
= s_table
[ind
].rchild
= n_items
;
282 s_table
[n_items
].lchild
= s_table
[n_items
].rchild
= MAXPROCS
;
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
++);
292 ind
= s_table
[ind
].rchild
; /* else traverse r-tree */
299 * process() - process the input file, filling in the modules table.
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
;
312 unsigned long local_time
;
314 unsigned long oldtime
;
315 unsigned long oldchild
;
318 DBUG_ENTER ("process");
319 while (fgets (buf
,BUFSIZ
,inf
) != NULL
) {
322 sscanf (buf
+2, "%ld %64s", &fn_time
, fn_name
);
323 DBUG_PRINT ("erec", ("%ld %s", fn_time
, fn_name
));
328 sscanf (buf
+2, "%ld %64s", &fn_time
, fn_name
);
329 DBUG_PRINT ("xrec", ("%ld %s", fn_time
, fn_name
));
332 * An exited function implies that all stacked
333 * functions are also exited, until the matching
334 * function is found on the stack.
336 while (pop (&oldpos
, &oldtime
, &oldchild
)) {
337 DBUG_PRINT ("popped", ("%lu %lu", oldtime
, oldchild
));
338 local_time
= fn_time
- oldtime
;
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
;
349 goto next_line
; /* Should be a break2 */
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.
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
;
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
));
369 lastuse
= modules
[pos
].m_stkuse
;
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...
380 if (lastuse
> 0 && lastuse
!= fn_ssz
) {
382 "warning - %s stack use changed (%lx to %lx)\n",
383 fn_name
, lastuse
, fn_ssz
);
386 if (fn_ssz
> lastuse
) {
387 modules
[pos
].m_stkuse
= fn_ssz
;
389 if (fn_sbot
> highstack
) {
391 } else if (fn_sbot
< lowstack
) {
396 fprintf (stderr
, "unknown record type '%c'\n", buf
[0]);
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
407 while (pop (&oldpos
,&oldtime
,&oldchild
)) {
408 local_time
= fn_time
- oldtime
;
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
;
421 * out_header () -- print out the header of the report.
424 void out_header (outf
)
427 DBUG_ENTER ("out_header");
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");
437 fprintf (outf
, "%ld bytes of stack used, from %lx down to %lx\n\n",
438 highstack
- lowstack
, highstack
, lowstack
);
440 " %%time sec #call ms/call %%calls weight stack name\n");
446 * out_trailer () - writes out the summary line of the report.
449 void out_trailer (outf
,sum_calls
,sum_time
)
451 unsigned long int sum_calls
, sum_time
;
453 DBUG_ENTER ("out_trailer");
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");
464 * out_item () - prints out the output line for a single entry,
465 * and sets the calls and time fields appropriately.
468 void out_item (outf
, m
,called
,timed
)
470 register struct module_t
*m
;
471 unsigned long int *called
, *timed
;
473 char *name
= m
-> name
;
474 register unsigned int calls
= m
-> m_calls
;
475 register unsigned long local_time
= m
-> m_time
;
476 register unsigned long stkuse
= m
-> m_stkuse
;
478 double per_time
= 0.0;
479 double per_calls
= 0.0;
480 double ms_per_call
, local_ftime
;
482 DBUG_ENTER ("out_item");
485 per_time
= (double) (local_time
* 100) / (double) tot_time
;
488 per_calls
= (double) (calls
* 100) / (double) tot_calls
;
490 import
= (unsigned int) (per_time
* per_calls
);
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
);
496 ms_per_call
= local_time
;
497 ms_per_call
/= calls
;
498 local_ftime
= local_time
;
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
,
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
515 void out_body (outf
, root
,s_calls
,s_time
)
517 register unsigned int root
;
518 register unsigned long int *s_calls
, *s_time
;
520 unsigned long int calls
, local_time
;
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
));
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
));
532 *s_time
+= local_time
;
533 root
= s_table
[root
].rchild
;
535 DBUG_PRINT ("out_body", ("%lu,%lu", *s_calls
, *s_time
));
541 * output () - print out a nice sorted output report on outf.
547 unsigned long int sum_calls
= 0;
548 unsigned long int sum_time
= 0;
550 DBUG_ENTER ("output");
552 fprintf (outf
, "%s: No functions to trace\n", my_name
);
556 out_body (outf
, 0,&sum_calls
,&sum_time
);
557 out_trailer (outf
, sum_calls
,sum_time
);
562 #define usage() fprintf (DBUG_FILE,"Usage: %s [-v] [prof-file]\n",my_name)
565 extern int getopt(int argc
, char **argv
, char *opts
);
570 int main (int argc
, char **argv
)
575 FILE *outfile
= {stdout
};
578 #if defined(HAVE_PTHREAD_INIT)
579 pthread_init(); /* Must be called before DBUG_ENTER */
581 my_thread_global_init();
585 DBUG_PROCESS (argv
[0]);
587 while ((c
= getopt (argc
,argv
,"#:v")) != EOF
) {
589 case '#': /* Debugging Macro enable */
592 case 'v': /* Verbose mode */
602 DBUG_RETURN (EX_USAGE
);
605 FILEOPEN (infile
, argv
[optind
], "r");
607 FILEOPEN (infile
, PRO_FILE
, "r");
618 * From std-unix@ut-sally.UUCP (Moderator, John Quarterman) Sun Nov 3 14:34:15 1985
619 * Relay-Version: version B 2.10.3 4.3bsd-beta 6/6/85; site gatech.CSNET
620 * Posting-Version: version B 2.10.2 9/18/84; site ut-sally.UUCP
621 * Path: gatech!akgua!mhuxv!mhuxt!mhuxr!ulysses!allegra!mit-eddie!genrad!panda!talcott!harvard!seismo!ut-sally!std-unix
622 * From: std-unix@ut-sally.UUCP (Moderator, John Quarterman)
623 * Newsgroups: mod.std.unix
624 * Subject: public domain AT&T getopt source
625 * Message-ID: <3352@ut-sally.UUCP>
626 * Date: 3 Nov 85 19:34:15 GMT
627 * Date-Received: 4 Nov 85 12:25:09 GMT
628 * Organization: IEEE/P1003 Portable Operating System Environment Committee
630 * Approved: jsq@ut-sally.UUCP
632 * Here's something you've all been waiting for: the AT&T public domain
633 * source for getopt(3). It is the code which was given out at the 1985
634 * UNIFORUM conference in Dallas. I obtained it by electronic mail
635 * directly from AT&T. The people there assure me that it is indeed
636 * in the public domain.
638 * There is no manual page. That is because the one they gave out at
639 * UNIFORUM was slightly different from the current System V Release 2
640 * manual page. The difference apparently involved a note about the
641 * famous rules 5 and 6, recommending using white space between an option
642 * and its first argument, and not grouping options that have arguments.
643 * Getopt itself is currently lenient about both of these things White
644 * space is allowed, but not mandatory, and the last option in a group can
645 * have an argument. That particular version of the man page evidently
646 * has no official existence, and my source at AT&T did not send a copy.
647 * The current SVR2 man page reflects the actual behavor of this getopt.
648 * However, I am not about to post a copy of anything licensed by AT&T.
650 * I will submit this source to Berkeley as a bug fix.
652 * I, personally, make no claims or guarantees of any kind about the
653 * following source. I did compile it to get some confidence that
654 * it arrived whole, but beyond that you're on your own.
665 static void _ERR(s
,c
,argv
)
675 (void) fprintf(stderr
, "%s", argv
[0]);
676 (void) fprintf(stderr
, "%s", s
);
677 (void) fprintf(stderr
, "%s", errbuf
);
681 int getopt(argc
, argv
, opts
)
691 argv
[optind
][0] != '-' || argv
[optind
][1] == '\0')
693 else if(strcmp(argv
[optind
], "--") == 0) {
697 optopt
= c
= argv
[optind
][sp
];
698 if(c
== ':' || (cp
=strchr(opts
, c
)) == NULL
) {
699 _ERR(": illegal option -- ", c
, argv
);
700 if(argv
[optind
][++sp
] == '\0') {
707 if(argv
[optind
][sp
+1] != '\0')
708 optarg
= &argv
[optind
++][sp
+1];
709 else if(++optind
>= argc
) {
710 _ERR(": option requires an argument -- ", c
, argv
);
714 optarg
= argv
[optind
++];
717 if(argv
[optind
][++sp
] == '\0') {
726 #endif /* !unix && !xenix */