2 /* Trace dynamic profiler.
3 * For use with the Digital Mars DMD compiler.
4 * Copyright (C) 1995-2006 by Digital Mars
6 * Written by Walter Bright
11 * Modified by Sean Kelly for use with the D Runtime Project
27 char* unmangle_ident(char*); // from DMC++ runtime library
31 /////////////////////////////////////
37 Symbol* sym; // function that is called
38 uint count; // number of times sym is called
41 /////////////////////////////////////
42 // A Symbol for each function name.
46 Symbol* Sl, Sr; // left, right children
47 SymPair* Sfanin; // list of calling functions
48 SymPair* Sfanout; // list of called functions
49 timer_t totaltime; // aggregate time
50 timer_t functime; // time excluding subfunction calls
52 char[] Sident; // name of symbol
55 const ubyte SFvisited = 1; // visited
57 static Symbol* root; // root of symbol table
59 //////////////////////////////////
60 // Build a linked list of these.
66 timer_t starttime; // time when function was entered
67 timer_t ohd; // overhead of all the bookkeeping code
68 timer_t subtime; // time used by all subfunctions
71 static Stack* stack_freelist;
72 static Stack* trace_tos; // top of stack
73 static int trace_inited; // !=0 if initialized
74 static timer_t trace_ohd;
76 static Symbol** psymbols;
77 static uint nsymbols; // number of symbols
79 static string trace_logfilename = "trace.log";
82 static string trace_deffilename = "trace.def";
86 ////////////////////////////////////////
87 // Set file name for output.
88 // A file name of "" means write results to stdout.
93 int trace_setlogfilename(string name)
95 trace_logfilename = name;
99 ////////////////////////////////////////
100 // Set file name for output.
101 // A file name of "" means write results to stdout.
106 int trace_setdeffilename(string name)
108 trace_deffilename = name;
112 ////////////////////////////////////////
113 // Output optimal function link order.
115 static void trace_order(Symbol *s)
126 //////////////////////////////////////////////
129 static Stack* stack_malloc()
133 { s = stack_freelist;
134 stack_freelist = s.prev;
137 s = cast(Stack *)trace_malloc(Stack.sizeof);
141 //////////////////////////////////////////////
144 static void stack_free(Stack *s)
146 s.prev = stack_freelist;
150 //////////////////////////////////////
151 // Qsort() comparison routine for array of pointers to SymPair's.
153 static int sympair_cmp(in void* e1, in void* e2)
157 psp1 = cast(SymPair**)e1;
158 psp2 = cast(SymPair**)e2;
160 return (*psp2).count - (*psp1).count;
163 //////////////////////////////////////
164 // Place symbol s, and then place any fan ins or fan outs with
165 // counts greater than count.
167 static void trace_place(Symbol *s, uint count)
171 if (!(s.Sflags & SFvisited))
175 //printf("\t%.*s\t%u\n", s.Sident, count);
176 fprintf(fpdef,"\t%.*s\n", s.Sident);
177 s.Sflags |= SFvisited;
179 // Compute number of items in array
181 for (sp = s.Sfanin; sp; sp = sp.next)
183 for (sp = s.Sfanout; sp; sp = sp.next)
188 // Allocate and fill array
189 base = cast(SymPair**)trace_malloc(SymPair.sizeof * num);
191 for (sp = s.Sfanin; sp; sp = sp.next)
193 for (sp = s.Sfanout; sp; sp = sp.next)
197 qsort(base, num, (SymPair *).sizeof, &sympair_cmp);
199 //for (u = 0; u < num; u++)
200 //printf("\t\t%.*s\t%u\n", base[u].sym.Sident, base[u].count);
203 for (u = 0; u < num; u++)
205 if (base[u].count >= count)
209 u2 = (u + 1 < num) ? u + 1 : u;
213 trace_place(base[u].sym,c2);
224 /////////////////////////////////////
225 // Initialize and terminate.
237 ///////////////////////////////////
239 // Also compute nsymbols.
241 static void trace_report(Symbol* s)
245 //printf("trace_report()\n");
250 fprintf(fplog,"------------------\n");
252 for (sp = s.Sfanin; sp; sp = sp.next)
254 fprintf(fplog,"\t%5d\t%.*s\n", sp.count, sp.sym.Sident);
257 fprintf(fplog,"%.*s\t%u\t%lld\t%lld\n",s.Sident,count,s.totaltime,s.functime);
258 for (sp = s.Sfanout; sp; sp = sp.next)
260 fprintf(fplog,"\t%5d\t%.*s\n",sp.count,sp.sym.Sident);
266 ////////////////////////////////////
267 // Allocate and fill array of symbols.
269 static void trace_array(Symbol *s)
274 psymbols = cast(Symbol **)trace_malloc((Symbol *).sizeof * nsymbols);
285 //////////////////////////////////////
286 // Qsort() comparison routine for array of pointers to Symbol's.
288 static int symbol_cmp(in void* e1, in void* e2)
293 ps1 = cast(Symbol **)e1;
294 ps2 = cast(Symbol **)e2;
296 diff = (*ps2).functime - (*ps1).functime;
297 return (diff == 0) ? 0 : ((diff > 0) ? 1 : -1);
301 ///////////////////////////////////
302 // Report function timings
304 static void trace_times(Symbol* root)
309 qsort(psymbols, nsymbols, (Symbol *).sizeof, &symbol_cmp);
312 QueryPerformanceFrequency(&freq);
313 fprintf(fplog,"\n======== Timer Is %lld Ticks/Sec, Times are in Microsecs ========\n\n",freq);
314 fprintf(fplog," Num Tree Func Per\n");
315 fprintf(fplog," Calls Time Time Call\n\n");
316 for (u = 0; u < nsymbols; u++)
317 { Symbol* s = psymbols[u];
328 char* p = (s.Sident ~ '\0').ptr;
329 p = unmangle_ident(p);
331 id = p[0 .. strlen(p)];
336 for (sp = s.Sfanin; sp; sp = sp.next)
343 tl = (s.totaltime * 1000000) / freq;
344 fl = (s.functime * 1000000) / freq;
345 percall = s.functime / calls;
346 pl = (s.functime * 1000000) / calls / freq;
348 fprintf(fplog,"%7d%12lld%12lld%12lld %.*s\n",
353 tl = s.totaltime / freq;
354 tr = ((s.totaltime - tl * freq) * 10000000) / freq;
356 fl = s.functime / freq;
357 fr = ((s.functime - fl * freq) * 10000000) / freq;
359 percall = s.functime / calls;
361 pr = ((percall - pl * freq) * 10000000) / freq;
363 fprintf(fplog,"%7d\t%3lld.%07lld\t%3lld.%07lld\t%3lld.%07lld\t%.*s\n",
364 calls,tl,tr,fl,fr,pl,pr,id);
372 ///////////////////////////////////
375 static void trace_init()
381 { // See if we can determine the overhead.
389 QueryPerformanceCounter(&starttime);
390 for (u = 0; u < 100; u++)
399 QueryPerformanceCounter(&endtime);
400 trace_ohd = (endtime - starttime) / u;
401 //printf("trace_ohd = %lld\n",trace_ohd);
403 trace_ohd--; // round down
409 /////////////////////////////////
414 //printf("trace_term()\n");
415 if (trace_inited == 1)
420 // Free remainder of the stack
424 stack_free(trace_tos);
428 while (stack_freelist)
430 n = stack_freelist.prev;
431 stack_free(stack_freelist);
435 // Merge in data from any existing file
439 fplog = fopen(trace_logfilename.ptr, "w");
448 // Output function link order
449 fpdef = fopen(trace_deffilename.ptr,"w");
451 { fprintf(fpdef,"\nFUNCTIONS\n");
456 trace_free(psymbols);
461 /////////////////////////////////
462 // Our storage allocator.
464 static void *trace_malloc(size_t nbytes)
473 static void trace_free(void *p)
478 //////////////////////////////////////////////
481 static Symbol* trace_addsym(char[] id)
489 //printf("trace_addsym('%s',%d)\n",p,len);
492 while (rover !is null) // while we haven't run out of tree
494 cmp = dstrcmp(id, rover.Sident);
499 parent = (cmp < 0) ? /* if we go down left side */
500 &(rover.Sl) : /* then get left child */
501 &(rover.Sr); /* else get right child */
502 rover = *parent; /* get child */
504 /* not in table, so insert into table */
505 s = cast(Symbol *)trace_malloc(Symbol.sizeof);
506 memset(s,0,Symbol.sizeof);
508 *parent = s; // link new symbol into tree
512 /***********************************
513 * Add symbol s with count to SymPair list.
516 static void trace_sympair_add(SymPair** psp, Symbol* s, uint count)
519 for (; 1; psp = &sp.next)
524 sp = cast(SymPair *)trace_malloc(SymPair.sizeof);
531 else if (sp.sym == s)
539 //////////////////////////////////////////////
542 static void trace_pro(char[] id)
549 QueryPerformanceCounter(&starttime);
553 trace_init(); // initialize package
557 s = trace_addsym(id);
564 // Accumulate Sfanout and Sfanin
565 prev = trace_tos.prev.sym;
566 trace_sympair_add(&prev.Sfanout,s,1);
567 trace_sympair_add(&s.Sfanin,prev,1);
569 QueryPerformanceCounter(&t);
570 trace_tos.starttime = starttime;
571 trace_tos.ohd = trace_ohd + t - starttime;
572 trace_tos.subtime = 0;
573 //printf("trace_tos.ohd=%lld, trace_ohd=%lld + t=%lld - starttime=%lld\n",
574 // trace_tos.ohd,trace_ohd,t,starttime);
577 /////////////////////////////////////////
580 static void trace_epi()
586 //printf("trace_epi()\n");
592 QueryPerformanceCounter(&endtime);
593 starttime = trace_tos.starttime;
594 totaltime = endtime - starttime - trace_tos.ohd;
596 { //printf("endtime=%lld - starttime=%lld - trace_tos.ohd=%lld < 0\n",
597 // endtime,starttime,trace_tos.ohd);
598 totaltime = 0; // round off error, just make it 0
601 // totaltime is time spent in this function + all time spent in
602 // subfunctions - bookkeeping overhead.
603 trace_tos.sym.totaltime += totaltime;
605 //if (totaltime < trace_tos.subtime)
606 //printf("totaltime=%lld < trace_tos.subtime=%lld\n",totaltime,trace_tos.subtime);
607 trace_tos.sym.functime += totaltime - trace_tos.subtime;
610 stack_free(trace_tos);
613 { QueryPerformanceCounter(&t);
614 n.ohd += ohd + t - endtime;
615 n.subtime += totaltime;
616 //printf("n.ohd = %lld\n",n.ohd);
622 ////////////////////////// FILE INTERFACE /////////////////////////
624 /////////////////////////////////////
625 // Read line from file fp.
627 // trace_malloc'd line buffer
628 // null if end of file
630 static char* trace_readline(FILE* fp)
636 //printf("trace_readline(%p)\n", fp);
646 p = cast(char *)trace_malloc(dim);
669 //printf("line '%s'\n",buf);
673 //////////////////////////////////////
676 static char *skipspace(char *p)
683 ////////////////////////////////////////////////////////
684 // Merge in profiling data from existing file.
686 static void trace_merge()
695 if (trace_logfilename && (fp = fopen(trace_logfilename.ptr,"r")) !is null)
703 buf = trace_readline(fp);
708 case '=': // ignore rest of file
712 case '\t': // fan in or fan out line
713 count = strtoul(buf,&p,10);
714 if (p == buf) // if invalid conversion
719 s = trace_addsym(p[0 .. strlen(p)]);
720 trace_sympair_add(psp,s,count);
727 continue; // regard unrecognized line as separator
737 //printf("trace_addsym('%s')\n",buf);
738 s = trace_addsym(buf[0 .. strlen(buf)]);
742 for (; sfanin; sfanin = sp)
744 trace_sympair_add(&s.Sfanin,sfanin.sym,sfanin.count);
758 count = strtoul(p,&p,10);
759 t = cast(long)strtoull(p,&p,10);
761 t = cast(long)strtoull(p,&p,10);
772 ////////////////////////// COMPILER INTERFACE /////////////////////
774 /////////////////////////////////////////////
775 // Function called by trace code in function prolog.
779 /* Length of string is either:
797 cmp byte ptr 1[ECX],0 ;
815 /////////////////////////////////////////////
816 // Function called by trace code in function epilog.
838 export int QueryPerformanceCounter(timer_t *);
839 export int QueryPerformanceFrequency(timer_t *);
846 void QueryPerformanceCounter(timer_t* ctr)
858 void QueryPerformanceFrequency(timer_t* freq)