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 */
added
removed
dbug/dbug_analyze.c
