Mercurial > projects > ldc

comparison druntime/src/compiler/dmd/trace.d @ 759:d3eb054172f9

Find changesets by keywords (author, files, the commit message), revision number or hash, or revset expression.
Added copy of druntime from DMD 2.020 modified for LDC.
author Tomas Lindquist Olsen <tomas.l.olsen@gmail.com>
date Tue, 11 Nov 2008 01:52:37 +0100
parents
children
comparison
equal deleted inserted replaced
758:f04dde6e882c 759:d3eb054172f9
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 }