Mercurial > projects > ldc

comparison druntime/src/compiler/ldc/trace.d @ 1458:e0b2d67cfe7c

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