]> git.llucax.com Git - software/druntime.git/blob - src/compiler/dmd/trace.d
fix support for file/line
[software/druntime.git] / src / compiler / dmd / trace.d
1
2 /* Trace dynamic profiler.
3  * For use with the Digital Mars DMD compiler.
4  * Copyright (C) 1995-2006 by Digital Mars
5  * All Rights Reserved
6  * Written by Walter Bright
7  * www.digitalmars.com
8  */
9
10 /*
11  *  Modified by Sean Kelly for use with the D Runtime Project
12  */
13
14 module rt.trace;
15
16 private
17 {
18     import util.string;
19     import stdc.ctype;
20     import stdc.stdio;
21     import stdc.string;
22     import stdc.stdlib;
23 }
24
25 extern (C):
26
27 char* unmangle_ident(char*);    // from DMC++ runtime library
28
29 alias long timer_t;
30
31 /////////////////////////////////////
32 //
33
34 struct SymPair
35 {
36     SymPair* next;
37     Symbol* sym;        // function that is called
38     uint count;         // number of times sym is called
39 }
40
41 /////////////////////////////////////
42 // A Symbol for each function name.
43
44 struct Symbol
45 {
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
51         ubyte Sflags;
52         char[] Sident;          // name of symbol
53 }
54
55 const ubyte SFvisited = 1;      // visited
56
57 static Symbol* root;            // root of symbol table
58
59 //////////////////////////////////
60 // Build a linked list of these.
61
62 struct Stack
63 {
64     Stack* prev;
65     Symbol* sym;
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
69 }
70
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;
75
76 static Symbol** psymbols;
77 static uint nsymbols;           // number of symbols
78
79 static string trace_logfilename = "trace.log";
80 static FILE* fplog;
81
82 static string trace_deffilename = "trace.def";
83 static FILE* fpdef;
84
85
86 ////////////////////////////////////////
87 // Set file name for output.
88 // A file name of "" means write results to stdout.
89 // Returns:
90 //      0       success
91 //      !=0     failure
92
93 int trace_setlogfilename(string name)
94 {
95     trace_logfilename = name;
96     return 0;
97 }
98
99 ////////////////////////////////////////
100 // Set file name for output.
101 // A file name of "" means write results to stdout.
102 // Returns:
103 //      0       success
104 //      !=0     failure
105
106 int trace_setdeffilename(string name)
107 {
108     trace_deffilename = name;
109     return 0;
110 }
111
112 ////////////////////////////////////////
113 // Output optimal function link order.
114
115 static void trace_order(Symbol *s)
116 {
117     while (s)
118     {
119         trace_place(s,0);
120         if (s.Sl)
121             trace_order(s.Sl);
122         s = s.Sr;
123     }
124 }
125
126 //////////////////////////////////////////////
127 //
128
129 static Stack* stack_malloc()
130 {   Stack *s;
131
132     if (stack_freelist)
133     {   s = stack_freelist;
134         stack_freelist = s.prev;
135     }
136     else
137         s = cast(Stack *)trace_malloc(Stack.sizeof);
138     return s;
139 }
140
141 //////////////////////////////////////////////
142 //
143
144 static void stack_free(Stack *s)
145 {
146     s.prev = stack_freelist;
147     stack_freelist = s;
148 }
149
150 //////////////////////////////////////
151 // Qsort() comparison routine for array of pointers to SymPair's.
152
153 static int sympair_cmp(in void* e1, in void* e2)
154 {   SymPair** psp1;
155     SymPair** psp2;
156
157     psp1 = cast(SymPair**)e1;
158     psp2 = cast(SymPair**)e2;
159
160     return (*psp2).count - (*psp1).count;
161 }
162
163 //////////////////////////////////////
164 // Place symbol s, and then place any fan ins or fan outs with
165 // counts greater than count.
166
167 static void trace_place(Symbol *s, uint count)
168 {   SymPair* sp;
169     SymPair** base;
170
171     if (!(s.Sflags & SFvisited))
172     {   size_t num;
173         uint u;
174
175         //printf("\t%.*s\t%u\n", s.Sident, count);
176         fprintf(fpdef,"\t%.*s\n", s.Sident);
177         s.Sflags |= SFvisited;
178
179         // Compute number of items in array
180         num = 0;
181         for (sp = s.Sfanin; sp; sp = sp.next)
182             num++;
183         for (sp = s.Sfanout; sp; sp = sp.next)
184             num++;
185         if (!num)
186             return;
187
188         // Allocate and fill array
189         base = cast(SymPair**)trace_malloc(SymPair.sizeof * num);
190         u = 0;
191         for (sp = s.Sfanin; sp; sp = sp.next)
192             base[u++] = sp;
193         for (sp = s.Sfanout; sp; sp = sp.next)
194             base[u++] = sp;
195
196         // Sort array
197         qsort(base, num, (SymPair *).sizeof, &sympair_cmp);
198
199         //for (u = 0; u < num; u++)
200             //printf("\t\t%.*s\t%u\n", base[u].sym.Sident, base[u].count);
201
202         // Place symbols
203         for (u = 0; u < num; u++)
204         {
205             if (base[u].count >= count)
206             {   uint u2;
207                 uint c2;
208
209                 u2 = (u + 1 < num) ? u + 1 : u;
210                 c2 = base[u2].count;
211                 if (c2 < count)
212                     c2 = count;
213                 trace_place(base[u].sym,c2);
214             }
215             else
216                 break;
217         }
218
219         // Clean up
220         trace_free(base);
221     }
222 }
223
224 /////////////////////////////////////
225 // Initialize and terminate.
226
227 static this()
228 {
229     trace_init();
230 }
231
232 static ~this()
233 {
234     trace_term();
235 }
236
237 ///////////////////////////////////
238 // Report results.
239 // Also compute nsymbols.
240
241 static void trace_report(Symbol* s)
242 {   SymPair* sp;
243     uint count;
244
245     //printf("trace_report()\n");
246     while (s)
247     {   nsymbols++;
248         if (s.Sl)
249             trace_report(s.Sl);
250         fprintf(fplog,"------------------\n");
251         count = 0;
252         for (sp = s.Sfanin; sp; sp = sp.next)
253         {
254             fprintf(fplog,"\t%5d\t%.*s\n", sp.count, sp.sym.Sident);
255             count += sp.count;
256         }
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)
259         {
260             fprintf(fplog,"\t%5d\t%.*s\n",sp.count,sp.sym.Sident);
261         }
262         s = s.Sr;
263     }
264 }
265
266 ////////////////////////////////////
267 // Allocate and fill array of symbols.
268
269 static void trace_array(Symbol *s)
270 {   static uint u;
271
272     if (!psymbols)
273     {   u = 0;
274         psymbols = cast(Symbol **)trace_malloc((Symbol *).sizeof * nsymbols);
275     }
276     while (s)
277     {
278         psymbols[u++] = s;
279         trace_array(s.Sl);
280         s = s.Sr;
281     }
282 }
283
284
285 //////////////////////////////////////
286 // Qsort() comparison routine for array of pointers to Symbol's.
287
288 static int symbol_cmp(in void* e1, in void* e2)
289 {   Symbol** ps1;
290     Symbol** ps2;
291     timer_t diff;
292
293     ps1 = cast(Symbol **)e1;
294     ps2 = cast(Symbol **)e2;
295
296     diff = (*ps2).functime - (*ps1).functime;
297     return (diff == 0) ? 0 : ((diff > 0) ? 1 : -1);
298 }
299
300
301 ///////////////////////////////////
302 // Report function timings
303
304 static void trace_times(Symbol* root)
305 {   uint u;
306     timer_t freq;
307
308     // Sort array
309     qsort(psymbols, nsymbols, (Symbol *).sizeof, &symbol_cmp);
310
311     // Print array
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];
318         timer_t tl,tr;
319         timer_t fl,fr;
320         timer_t pl,pr;
321         timer_t percall;
322         SymPair* sp;
323         uint calls;
324         char[] id;
325
326         version (Windows)
327         {
328             char* p = (s.Sident ~ '\0').ptr;
329             p = unmangle_ident(p);
330             if (p)
331                 id = p[0 .. strlen(p)];
332         }
333         if (!id)
334             id = s.Sident;
335         calls = 0;
336         for (sp = s.Sfanin; sp; sp = sp.next)
337             calls += sp.count;
338         if (calls == 0)
339             calls = 1;
340
341 version (all)
342 {
343         tl = (s.totaltime * 1000000) / freq;
344         fl = (s.functime  * 1000000) / freq;
345         percall = s.functime / calls;
346         pl = (s.functime * 1000000) / calls / freq;
347
348         fprintf(fplog,"%7d%12lld%12lld%12lld     %.*s\n",
349             calls,tl,fl,pl,id);
350 }
351 else
352 {
353         tl = s.totaltime / freq;
354         tr = ((s.totaltime - tl * freq) * 10000000) / freq;
355
356         fl = s.functime  / freq;
357         fr = ((s.functime  - fl * freq) * 10000000) / freq;
358
359         percall = s.functime / calls;
360         pl = percall  / freq;
361         pr = ((percall  - pl * freq) * 10000000) / freq;
362
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);
365 }
366         if (id !is s.Sident)
367             free(id.ptr);
368     }
369 }
370
371
372 ///////////////////////////////////
373 // Initialize.
374
375 static void trace_init()
376 {
377     if (!trace_inited)
378     {
379         trace_inited = 1;
380
381         {   // See if we can determine the overhead.
382             uint u;
383             timer_t starttime;
384             timer_t endtime;
385             Stack *st;
386
387             st = trace_tos;
388             trace_tos = null;
389             QueryPerformanceCounter(&starttime);
390             for (u = 0; u < 100; u++)
391             {
392                 asm
393                 {
394                     call _trace_pro_n   ;
395                     db   0              ;
396                     call _trace_epi_n   ;
397                 }
398             }
399             QueryPerformanceCounter(&endtime);
400             trace_ohd = (endtime - starttime) / u;
401             //printf("trace_ohd = %lld\n",trace_ohd);
402             if (trace_ohd > 0)
403                 trace_ohd--;            // round down
404             trace_tos = st;
405         }
406     }
407 }
408
409 /////////////////////////////////
410 // Terminate.
411
412 void trace_term()
413 {
414     //printf("trace_term()\n");
415     if (trace_inited == 1)
416     {   Stack *n;
417
418         trace_inited = 2;
419
420         // Free remainder of the stack
421         while (trace_tos)
422         {
423             n = trace_tos.prev;
424             stack_free(trace_tos);
425             trace_tos = n;
426         }
427
428         while (stack_freelist)
429         {
430             n = stack_freelist.prev;
431             stack_free(stack_freelist);
432             stack_freelist = n;
433         }
434
435         // Merge in data from any existing file
436         trace_merge();
437
438         // Report results
439         fplog = fopen(trace_logfilename.ptr, "w");
440         if (fplog)
441         {   nsymbols = 0;
442             trace_report(root);
443             trace_array(root);
444             trace_times(root);
445             fclose(fplog);
446         }
447
448         // Output function link order
449         fpdef = fopen(trace_deffilename.ptr,"w");
450         if (fpdef)
451         {   fprintf(fpdef,"\nFUNCTIONS\n");
452             trace_order(root);
453             fclose(fpdef);
454         }
455
456         trace_free(psymbols);
457         psymbols = null;
458     }
459 }
460
461 /////////////////////////////////
462 // Our storage allocator.
463
464 static void *trace_malloc(size_t nbytes)
465 {   void *p;
466
467     p = malloc(nbytes);
468     if (!p)
469         exit(EXIT_FAILURE);
470     return p;
471 }
472
473 static void trace_free(void *p)
474 {
475     free(p);
476 }
477
478 //////////////////////////////////////////////
479 //
480
481 static Symbol* trace_addsym(char[] id)
482 {
483     Symbol** parent;
484     Symbol* rover;
485     Symbol* s;
486     int cmp;
487     char c;
488
489     //printf("trace_addsym('%s',%d)\n",p,len);
490     parent = &root;
491     rover = *parent;
492     while (rover !is null)               // while we haven't run out of tree
493     {
494         cmp = dstrcmp(id, rover.Sident);
495         if (cmp == 0)
496         {
497             return rover;
498         }
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                    */
503     }
504     /* not in table, so insert into table       */
505     s = cast(Symbol *)trace_malloc(Symbol.sizeof);
506     memset(s,0,Symbol.sizeof);
507     s.Sident = id;
508     *parent = s;                        // link new symbol into tree
509     return s;
510 }
511
512 /***********************************
513  * Add symbol s with count to SymPair list.
514  */
515
516 static void trace_sympair_add(SymPair** psp, Symbol* s, uint count)
517 {   SymPair* sp;
518
519     for (; 1; psp = &sp.next)
520     {
521         sp = *psp;
522         if (!sp)
523         {
524             sp = cast(SymPair *)trace_malloc(SymPair.sizeof);
525             sp.sym = s;
526             sp.count = 0;
527             sp.next = null;
528             *psp = sp;
529             break;
530         }
531         else if (sp.sym == s)
532         {
533             break;
534         }
535     }
536     sp.count += count;
537 }
538
539 //////////////////////////////////////////////
540 //
541
542 static void trace_pro(char[] id)
543 {
544     Stack* n;
545     Symbol* s;
546     timer_t starttime;
547     timer_t t;
548
549     QueryPerformanceCounter(&starttime);
550     if (id.length == 0)
551         return;
552     if (!trace_inited)
553         trace_init();                   // initialize package
554     n = stack_malloc();
555     n.prev = trace_tos;
556     trace_tos = n;
557     s = trace_addsym(id);
558     trace_tos.sym = s;
559     if (trace_tos.prev)
560     {
561         Symbol* prev;
562         int i;
563
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);
568     }
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);
575 }
576
577 /////////////////////////////////////////
578 //
579
580 static void trace_epi()
581 {   Stack* n;
582     timer_t endtime;
583     timer_t t;
584     timer_t ohd;
585
586     //printf("trace_epi()\n");
587     if (trace_tos)
588     {
589         timer_t starttime;
590         timer_t totaltime;
591
592         QueryPerformanceCounter(&endtime);
593         starttime = trace_tos.starttime;
594         totaltime = endtime - starttime - trace_tos.ohd;
595         if (totaltime < 0)
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
599         }
600
601         // totaltime is time spent in this function + all time spent in
602         // subfunctions - bookkeeping overhead.
603         trace_tos.sym.totaltime += totaltime;
604
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;
608         ohd = trace_tos.ohd;
609         n = trace_tos.prev;
610         stack_free(trace_tos);
611         trace_tos = n;
612         if (n)
613         {   QueryPerformanceCounter(&t);
614             n.ohd += ohd + t - endtime;
615             n.subtime += totaltime;
616             //printf("n.ohd = %lld\n",n.ohd);
617         }
618     }
619 }
620
621
622 ////////////////////////// FILE INTERFACE /////////////////////////
623
624 /////////////////////////////////////
625 // Read line from file fp.
626 // Returns:
627 //      trace_malloc'd line buffer
628 //      null if end of file
629
630 static char* trace_readline(FILE* fp)
631 {   int c;
632     int dim;
633     int i;
634     char *buf;
635
636     //printf("trace_readline(%p)\n", fp);
637     i = 0;
638     dim = 0;
639     buf = null;
640     while (1)
641     {
642         if (i == dim)
643         {   char *p;
644
645             dim += 80;
646             p = cast(char *)trace_malloc(dim);
647             memcpy(p,buf,i);
648             trace_free(buf);
649             buf = p;
650         }
651         c = fgetc(fp);
652         switch (c)
653         {
654             case EOF:
655                 if (i == 0)
656                 {   trace_free(buf);
657                     return null;
658                 }
659             case '\n':
660                 goto L1;
661             default:
662                 break;
663         }
664         buf[i] = cast(char)c;
665         i++;
666     }
667 L1:
668     buf[i] = 0;
669     //printf("line '%s'\n",buf);
670     return buf;
671 }
672
673 //////////////////////////////////////
674 // Skip space
675
676 static char *skipspace(char *p)
677 {
678     while (isspace(*p))
679         p++;
680     return p;
681 }
682
683 ////////////////////////////////////////////////////////
684 // Merge in profiling data from existing file.
685
686 static void trace_merge()
687 {   FILE *fp;
688     char *buf;
689     char *p;
690     uint count;
691     Symbol *s;
692     SymPair *sfanin;
693     SymPair **psp;
694
695     if (trace_logfilename && (fp = fopen(trace_logfilename.ptr,"r")) !is null)
696     {
697         buf = null;
698         sfanin = null;
699         psp = &sfanin;
700         while (1)
701         {
702             trace_free(buf);
703             buf = trace_readline(fp);
704             if (!buf)
705                 break;
706             switch (*buf)
707             {
708                 case '=':               // ignore rest of file
709                     trace_free(buf);
710                     goto L1;
711                 case ' ':
712                 case '\t':              // fan in or fan out line
713                     count = strtoul(buf,&p,10);
714                     if (p == buf)       // if invalid conversion
715                         continue;
716                     p = skipspace(p);
717                     if (!*p)
718                         continue;
719                     s = trace_addsym(p[0 .. strlen(p)]);
720                     trace_sympair_add(psp,s,count);
721                     break;
722                 default:
723                     if (!isalpha(*buf))
724                     {
725                         if (!sfanin)
726                             psp = &sfanin;
727                         continue;       // regard unrecognized line as separator
728                     }
729                 case '?':
730                 case '_':
731                 case '$':
732                 case '@':
733                     p = buf;
734                     while (isgraph(*p))
735                         p++;
736                     *p = 0;
737                     //printf("trace_addsym('%s')\n",buf);
738                     s = trace_addsym(buf[0 .. strlen(buf)]);
739                     if (s.Sfanin)
740                     {   SymPair *sp;
741
742                         for (; sfanin; sfanin = sp)
743                         {
744                             trace_sympair_add(&s.Sfanin,sfanin.sym,sfanin.count);
745                             sp = sfanin.next;
746                             trace_free(sfanin);
747                         }
748                     }
749                     else
750                     {   s.Sfanin = sfanin;
751                     }
752                     sfanin = null;
753                     psp = &s.Sfanout;
754
755                     {   timer_t t;
756
757                         p++;
758                         count = strtoul(p,&p,10);
759                         t = cast(long)strtoull(p,&p,10);
760                         s.totaltime += t;
761                         t = cast(long)strtoull(p,&p,10);
762                         s.functime += t;
763                     }
764                     break;
765             }
766         }
767     L1:
768         fclose(fp);
769     }
770 }
771
772 ////////////////////////// COMPILER INTERFACE /////////////////////
773
774 /////////////////////////////////////////////
775 // Function called by trace code in function prolog.
776
777 void _trace_pro_n()
778 {
779     /* Length of string is either:
780      *  db      length
781      *  ascii   string
782      * or:
783      *  db      0x0FF
784      *  db      0
785      *  dw      length
786      *  ascii   string
787      */
788
789     asm
790     {   naked                           ;
791         pushad                          ;
792         mov     ECX,8*4[ESP]            ;
793         xor     EAX,EAX                 ;
794         mov     AL,[ECX]                ;
795         cmp     AL,0xFF                 ;
796         jne     L1                      ;
797         cmp     byte ptr 1[ECX],0       ;
798         jne     L1                      ;
799         mov     AX,2[ECX]               ;
800         add     8*4[ESP],3              ;
801         add     ECX,3                   ;
802     L1: inc     EAX                     ;
803         inc     ECX                     ;
804         add     8*4[ESP],EAX            ;
805         dec     EAX                     ;
806         push    ECX                     ;
807         push    EAX                     ;
808         call    trace_pro               ;
809         add     ESP,8                   ;
810         popad                           ;
811         ret                             ;
812     }
813 }
814
815 /////////////////////////////////////////////
816 // Function called by trace code in function epilog.
817
818
819 void _trace_epi_n()
820 {
821     asm
822     {   naked   ;
823         pushad  ;
824     }
825     trace_epi();
826     asm
827     {
828         popad   ;
829         ret     ;
830     }
831 }
832
833
834 version (Windows)
835 {
836     extern (Windows)
837     {
838         export int QueryPerformanceCounter(timer_t *);
839         export int QueryPerformanceFrequency(timer_t *);
840     }
841 }
842 else version (X86)
843 {
844     extern (D)
845     {
846         void QueryPerformanceCounter(timer_t* ctr)
847         {
848             asm
849             {   naked                   ;
850                 mov       ECX,EAX       ;
851                 rdtsc                   ;
852                 mov   [ECX],EAX         ;
853                 mov   4[ECX],EDX        ;
854                 ret                     ;
855             }
856         }
857
858         void QueryPerformanceFrequency(timer_t* freq)
859         {
860             *freq = 3579545;
861         }
862     }
863 }
864 else
865 {
866     static assert(0);
867 }