home *** CD-ROM | disk | FTP | other *** search
/ Gold Fish 1 / GoldFishApril1994_CD1.img / d1xx / d102 / dbug / analyze.c < prev    next >
C/C++ Source or Header  |  1987-09-06  |  13KB  |  532 lines
  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.  *    24-Jul-87: fnf
  32.  *    Because I tend to use functions names like
  33.  *    "ExternalFunctionDoingSomething", I've rearranged the
  34.  *    printout to put the function name last in each line, so
  35.  *    long names don't screw up the formatting unless they are
  36.  *    *very* long and wrap around the screen width...
  37.  *
  38.  *    24-Jul-87: fnf
  39.  *    Modified to put out table very similar to Unix profiler
  40.  *    by default, but also puts out original verbose table
  41.  *    if invoked with -v flag.
  42.  */
  43.  
  44. # include <stdio.h>
  45. # include "useful.h"
  46.  
  47. char *my_name;
  48. int verbose;
  49.  
  50. /*
  51.  * Structure of the stack.
  52.  */
  53.  
  54. # define PRO_FILE    "dbugmon.out" /* Default output file name */
  55. # define STACKSIZ    100    /* Maximum function nesting */
  56. # define MAXPROCS    1000    /* Maximum number of function calls */
  57.  
  58. struct stack_t {
  59.     unsigned int pos;        /* which function? */
  60.     unsigned long time;        /* Time that this was entered */
  61.     unsigned long children;        /* Time spent in called funcs */
  62. }
  63.     fn_stack[STACKSIZ+1];
  64.  
  65. unsigned int stacktop = 0;    /* Lowest stack position is a dummy */
  66.  
  67. /*
  68.  * top() returns a pointer to the top item on the stack.
  69.  * (was a function, now a macro)
  70.  */
  71.  
  72. # define top()    &fn_stack[stacktop]
  73.  
  74. /*
  75.  * Push - Push the given record on the stack.
  76.  */
  77.  
  78. void
  79. push(name_pos,time_entered)
  80. register unsigned int name_pos;
  81. register unsigned long time_entered;
  82. {
  83.     register struct stack_t *t;
  84.  
  85.     DBUG_ENTER("push");
  86.     if (++stacktop > STACKSIZ)
  87.      {
  88.         fprintf(DBUG_FILE,"%s: stack overflow (%s:%d)\n",
  89.             my_name,__FILE__,__LINE__);
  90.         exit(EX_SOFTWARE);
  91.      }
  92.  
  93.     DBUG_PRINT("push",("%d %ld",name_pos,time_entered));
  94.     t = &fn_stack[stacktop];
  95.     t->pos = name_pos;
  96.     t->time = time_entered;
  97.     t->children = 0;
  98.  
  99.     DBUG_VOID_RETURN;
  100. }
  101.  
  102. /*
  103.  * Pop - pop the top item off the stack, assigning the field values
  104.  * to the arguments. Returns 0 on stack underflow, or on popping first
  105.  * item off stack.
  106.  */
  107.  
  108. unsigned int
  109. pop(name_pos, time_entered, child_time)
  110. register unsigned int *name_pos;
  111. register unsigned long *time_entered;
  112. register unsigned long *child_time;
  113. {
  114.     register struct stack_t *temp;
  115.  
  116.     DBUG_ENTER("pop");
  117.  
  118.     if (stacktop < 1)
  119.         DBUG_RETURN(0);
  120.     
  121.     temp =  &fn_stack[stacktop];
  122.     *name_pos = temp->pos;
  123.     *time_entered = temp->time;
  124.     *child_time = temp->children;
  125.  
  126.     DBUG_PRINT("pop",("%d %d %d",*name_pos,*time_entered,*child_time));
  127.     DBUG_RETURN(stacktop--);
  128. }
  129.  
  130. /*
  131.  * We keep the function info in another array (serves as a simple
  132.  * symbol table)
  133.  */
  134.  
  135. struct module_t {
  136.     char *name;
  137.     unsigned long m_time;
  138.     unsigned long m_calls;
  139. }
  140.     modules[MAXPROCS];
  141.  
  142. /*
  143.  * We keep a binary search tree in order to look up function names
  144.  * quickly (and sort them at the end.
  145.  */
  146.  
  147. struct {
  148.     unsigned int lchild;    /* Index of left subtree */
  149.     unsigned int rchild;    /* Index of right subtree */
  150.     unsigned int pos;    /* Index of module_name entry */
  151. }
  152.     s_table[MAXPROCS];
  153.  
  154. unsigned int n_items = 0;    /* No. of items in the array so far */
  155.  
  156. /*
  157.  * Need a function to allocate space for a string and squirrel it away.
  158.  */
  159.  
  160. char *
  161. strsave(s)
  162. char *s;
  163. {
  164.     register char *retval;
  165.     register unsigned int len;
  166.     extern char *malloc ();
  167.  
  168.     DBUG_ENTER("strsave");
  169.     DBUG_PRINT("strsave",("%s",s));
  170.     if (s == Nil(char) || (len = strlen(s)) == 0)
  171.         DBUG_RETURN(Nil(char));
  172.  
  173.     MALLOC(retval, ++len, char);
  174.     strcpy(retval,s);
  175.     DBUG_RETURN(retval);
  176. }
  177.  
  178. /*
  179.  * add() - adds m_name to the table (if not already there), and returns
  180.  * the index of its location in the table.  Checks s_table (which is a
  181.  * binary search tree) to see whether or not it should be added.
  182.  */
  183.  
  184. unsigned int
  185. add(m_name)
  186. char *m_name;
  187. {
  188.     register unsigned int ind = 0;
  189.     register int cmp;
  190.  
  191.     DBUG_ENTER("add");
  192.     if (n_items == 0)    /* First item to be added */
  193.      {
  194.         s_table[0].pos = ind;
  195.         s_table[0].lchild = s_table[0].rchild = MAXPROCS;
  196. addit:
  197.         modules[n_items].name = strsave(m_name);
  198.         modules[n_items].m_time = modules[n_items].m_calls = 0;
  199.         DBUG_RETURN(n_items++);
  200.      }
  201.     while (cmp = strcmp(m_name,modules[ind].name)) {
  202.         if (cmp < 0) {    /* In left subtree */
  203.             if (s_table[ind].lchild == MAXPROCS) {
  204.                 /* Add as left child */
  205.                 if (n_items >= MAXPROCS) {
  206.                     fprintf(DBUG_FILE,
  207.                      "%s: Too many functions being profiled\n",
  208.                         my_name);
  209.                     exit(EX_SOFTWARE);
  210.                 }
  211.                 s_table[n_items].pos =
  212.                     s_table[ind].lchild = n_items;
  213.                 s_table[n_items].lchild =
  214.                     s_table[n_items].rchild = MAXPROCS;
  215. # ifdef notdef
  216.                 modules[n_items].name = strsave(m_name);
  217.                 modules[n_items].m_time = modules[n_items].m_calls = 0;
  218.                 DBUG_RETURN(n_items++);
  219. # else
  220.                 goto addit;
  221. # endif
  222.  
  223.             }
  224.             ind = s_table[ind].lchild; /* else traverse l-tree */
  225.         } else {
  226.             if (s_table[ind].rchild == MAXPROCS) {
  227.                 /* Add as right child */
  228.                 if (n_items >= MAXPROCS) {
  229.                      fprintf(DBUG_FILE,
  230.                       "%s: Too many functions being profiled\n",
  231.                         my_name);
  232.                     exit(EX_SOFTWARE);
  233.                 }
  234.                 s_table[n_items].pos =
  235.                     s_table[ind].rchild = n_items;
  236.                 s_table[n_items].lchild =
  237.                     s_table[n_items].rchild = MAXPROCS;
  238. # ifdef notdef
  239.                 modules[n_items].name = strsave(m_name);
  240.                 modules[n_items].m_time = modules[n_items].m_calls = 0;
  241.                 DBUG_RETURN(n_items++);
  242. # else
  243.                 goto addit;
  244. # endif
  245.  
  246.             }
  247.             ind = s_table[ind].rchild; /* else traverse r-tree */
  248.         }
  249.     }
  250.     DBUG_RETURN(ind);
  251. }
  252.  
  253. unsigned long int tot_time = 0;
  254. unsigned long int tot_calls = 0;
  255.  
  256. /*
  257.  * process() - process the input file, filling in the modules table.
  258.  */
  259.  
  260. void
  261. process(inf)
  262. FILE *inf;
  263. {
  264.     char buf[BUFSIZ];
  265.     char fn_name[25];    /* Max length of fn_name */
  266.     char fn_what[2];
  267.     unsigned long fn_time;
  268.     unsigned int pos;
  269.     unsigned long time;
  270.     unsigned int oldpos;
  271.     unsigned long oldtime;
  272.     unsigned long oldchild;
  273.     struct stack_t *t;
  274.  
  275.     DBUG_ENTER("process");
  276.     while (fgets(buf,BUFSIZ,inf) != NULL)
  277.      {
  278.         sscanf(buf,"%24s %1s %ld", fn_name, fn_what, &fn_time);
  279.         pos = add(fn_name);
  280.         DBUG_PRINT("enter",("%s %s %d",fn_name,fn_what,fn_time));
  281.         if (fn_what[0] == 'E')
  282.             push(pos,fn_time);
  283.         else {
  284.             /*
  285.              * An exited function implies that all stacked
  286.              * functions are also exited, until the matching
  287.              * function is found on the stack.
  288.              */
  289.             while( pop(&oldpos, &oldtime, &oldchild) ) {
  290.                 DBUG_PRINT("popped",("%d %d",oldtime,oldchild));
  291.                 time = fn_time - oldtime;
  292.                 t = top();
  293.                 t -> children += time;
  294.                 DBUG_PRINT("update",("%s",modules[t->pos].name));
  295.                 DBUG_PRINT("update",("%d",t->children));
  296.                 time -= oldchild;
  297.                 modules[oldpos].m_time += time;
  298.                 modules[oldpos].m_calls++;
  299.                 tot_time += time;
  300.                 tot_calls++;
  301.                 if (pos == oldpos)
  302.                     goto next_line;    /* Should be a break2 */
  303.             }
  304.  
  305.             /*
  306.              * Assume that item seen started at time 0.
  307.              * (True for function main).  But initialize
  308.              * it so that it works the next time too.
  309.              */
  310.             t = top();
  311.             time = fn_time - t->time - t->children;
  312.             t->time = fn_time; t->children = 0;
  313.             modules[pos].m_time += time;
  314.             modules[pos].m_calls++;
  315.             tot_time += time;
  316.             tot_calls++;
  317.         }
  318.         next_line:;
  319.      }
  320.  
  321.     /*
  322.      * Now, we've hit eof.  If we still have stuff stacked, then we
  323.      * assume that the user called exit, so give everything the exited
  324.      * time of fn_time.
  325.      */
  326.     while (pop(&oldpos,&oldtime,&oldchild))
  327.      {
  328.         time = fn_time - oldtime;
  329.         t = top();
  330.         t->children += time;
  331.         time -= oldchild;
  332.         modules[oldpos].m_time += time;
  333.         modules[oldpos].m_calls++;
  334.         tot_time += time;
  335.         tot_calls++;
  336.      }
  337.  
  338.     DBUG_VOID_RETURN;
  339. }
  340.  
  341. /*
  342.  * out_header() -- print out the header of the report.
  343.  */
  344.  
  345. void
  346. out_header(outf)
  347. FILE *outf;
  348. {
  349.     DBUG_ENTER("out_header");
  350.     if (verbose) {
  351.         fprintf(outf,"Profile of Execution\n");
  352.         fprintf(outf,"Execution times are in milliseconds\n\n");
  353.         fprintf(outf,"    Calls\t\t\t    Time\n");
  354.         fprintf(outf,"    -----\t\t\t    ----\n");
  355.         fprintf(outf,"Times\tPercentage\tTime Spent\tPercentage\n");
  356.         fprintf(outf,"Called\tof total\tin Function\tof total    Importance\tFunction\n");
  357.         fprintf(outf,"======\t==========\t===========\t==========  ==========\t========\t\n");
  358.     } else {
  359.         fprintf(outf,"   %%time     sec   #call ms/call  %%calls  weight  name\n");
  360.     }
  361.     DBUG_VOID_RETURN;
  362. }
  363.  
  364. /*
  365.  * out_trailer() - writes out the summary line of the report.
  366.  */
  367. void
  368. out_trailer(outf,sum_calls,sum_time)
  369. FILE *outf;
  370. unsigned long int sum_calls, sum_time;
  371. {
  372.     DBUG_ENTER("out_trailer");
  373.     if (verbose) {
  374.         fprintf(outf,"======\t==========\t===========\t==========\t========\n");
  375.         fprintf(outf,"%6d\t%10.2f\t%11d\t%10.2f\t\t%-15s\n",
  376.             sum_calls,100.0,sum_time,100.0,"Totals");
  377.     }
  378.     DBUG_VOID_RETURN;
  379. }
  380.  
  381. /*
  382.  * out_item() - prints out the output line for a single entry,
  383.  * and sets the calls and time fields appropriately.
  384.  */
  385.  
  386. void
  387. out_item(outf,m,called,timed)
  388. FILE *outf;
  389. register struct module_t *m;
  390. unsigned long int *called, *timed;
  391. {
  392.     char *name = m->name;
  393.     register unsigned int calls = m->m_calls;
  394.     register unsigned long time = m->m_time;
  395.     unsigned int import;
  396.     double per_time = 0.0;
  397.     double per_calls = 0.0; 
  398.     double ms_per_call, ftime;
  399.  
  400.     DBUG_ENTER("out_item");
  401.  
  402.     if (tot_time > 0) {
  403.         per_time = (double) (time * 100) / (double) tot_time;
  404.     }
  405.     if (tot_calls > 0) {
  406.         per_calls = (double) (calls * 100) / (double) tot_calls;
  407.     }
  408.     import = (unsigned int) (per_time * per_calls);
  409.  
  410.     if (verbose) {
  411.         fprintf(outf,"%6d\t%10.2f\t%11d\t%10.2f  %10d\t%-15s\n",
  412.             calls, per_calls, time, per_time, import, name);
  413.     } else {
  414.         ms_per_call = time;
  415.         ms_per_call /= calls;
  416.         ftime = time;
  417.         ftime /= 1000;
  418.         fprintf(outf,"%8.2f%8.3f%8u%8.3f%8.2f%8u  %-s\n",
  419.             per_time, ftime, calls, ms_per_call, per_calls, import, name);
  420.     }
  421.     *called = calls; *timed = time;
  422.     DBUG_VOID_RETURN;
  423. }
  424.  
  425. /*
  426.  * out_body(outf,root,s_calls,s_time) -- Performs an inorder traversal
  427.  * on the binary search tree (root).  Calls out_item to actually print
  428.  * the item out.
  429.  */
  430.  
  431. void
  432. out_body(outf,root,s_calls,s_time)
  433. FILE *outf;
  434. register unsigned int root;
  435. register unsigned long int *s_calls, *s_time;
  436. {
  437.     unsigned long int calls, time;
  438.  
  439.     DBUG_ENTER("out_body");
  440.     DBUG_PRINT("out_body",("%d,%d",*s_calls,*s_time));
  441.     if (root == MAXPROCS) {
  442.         DBUG_PRINT("out_body",("%d,%d",*s_calls,*s_time));
  443.         DBUG_VOID_RETURN;
  444.     }
  445.  
  446.     while (root != MAXPROCS) {
  447.         out_body(outf,s_table[root].lchild,s_calls,s_time);
  448.         out_item(outf,&modules[s_table[root].pos],&calls,&time);
  449.         DBUG_PRINT("out_body",("-- %d -- %d --", calls, time));
  450.         *s_calls += calls;
  451.         *s_time += time;
  452.         root = s_table[root].rchild;
  453.     }
  454.  
  455.     DBUG_PRINT("out_body",("%d,%d",*s_calls,*s_time));
  456.     DBUG_VOID_RETURN;
  457. }
  458. /*
  459.  * output() - print out a nice sorted output report on outf.
  460.  */
  461.  
  462. void
  463. output(outf)
  464. FILE *outf;
  465. {
  466.     unsigned long int sum_calls = 0;
  467.     unsigned long int sum_time = 0;
  468.  
  469.     DBUG_ENTER("output");
  470.     if (n_items == 0)
  471.      {
  472.         fprintf(outf,"%s: No functions to trace\n",my_name);
  473.         exit(EX_DATAERR);
  474.      }
  475.     out_header(outf);
  476.     out_body(outf,0,&sum_calls,&sum_time);
  477.     out_trailer(outf,sum_calls,sum_time);
  478.     DBUG_VOID_RETURN;
  479. }
  480.  
  481.  
  482. # define usage() fprintf(DBUG_FILE,"Usage: %s [-v] [prof-file]\n",my_name)
  483.  
  484. main(argc, argv, environ)
  485. int argc;
  486. char *argv[], *environ[];
  487. {
  488.     extern int optind, getopt();
  489.     extern char *optarg;
  490.     register int c;
  491.     int badflg = 0;
  492.     FILE *infile;
  493.     FILE *outfile = {stdout};
  494.  
  495.     DBUG_ENTER("main");
  496.     DBUG_PROCESS(argv[0]);
  497.     my_name = argv[0];
  498.  
  499.     while ((c = getopt(argc,argv,"#:v")) != EOF)
  500.      {
  501.         switch (c)
  502.          {
  503.             case '#': /* Debugging Macro enable */
  504.                 DBUG_PUSH(optarg);
  505.                 break;
  506.  
  507.             case 'v': /* Verbose mode */
  508.                 verbose++;
  509.                 break;
  510.  
  511.             default:
  512.                 badflg++;
  513.                 break;
  514.          }
  515.      }
  516.     
  517.     if (badflg)
  518.      {
  519.         usage();
  520.         DBUG_RETURN(EX_USAGE);
  521.      }
  522.  
  523.     if (optind < argc)
  524.         FILEOPEN(infile,argv[optind],"r");
  525.     else
  526.         FILEOPEN(infile,PRO_FILE,"r");
  527.     
  528.     process(infile);
  529.     output(outfile);
  530.     DBUG_RETURN(EX_OK);
  531. }
  532.