Mercurial > projects > ldc
diff druntime/src/compiler/ldc/trace.d @ 1458:e0b2d67cfe7c
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 |
line wrap: on
line diff
--- /dev/null Thu Jan 01 00:00:00 1970 +0000 +++ b/druntime/src/compiler/ldc/trace.d Tue Jun 02 17:43:06 2009 +0100 @@ -0,0 +1,919 @@ +/** + * Contains support code for code profiling. + * + * Copyright: Copyright Digital Mars 1995 - 2009. + * License: <a href="http://www.boost.org/LICENSE_1_0.txt>Boost License 1.0</a>. + * Authors: Walter Bright, Sean Kelly + * + * Copyright Digital Mars 1995 - 2009. + * Distributed under the Boost Software License, Version 1.0. + * (See accompanying file LICENSE_1_0.txt or copy at + * http://www.boost.org/LICENSE_1_0.txt) + */ +module rt.trace; + +private +{ + import rt.util.string; + import core.stdc.ctype; + import core.stdc.stdio; + import core.stdc.string; + import core.stdc.stdlib; +} + +extern (C): + +char* unmangle_ident(char*); // from DMC++ runtime library + +alias long timer_t; + +///////////////////////////////////// +// + +struct SymPair +{ + SymPair* next; + Symbol* sym; // function that is called + uint count; // number of times sym is called +} + +///////////////////////////////////// +// A Symbol for each function name. + +struct Symbol +{ + Symbol* Sl, Sr; // left, right children + SymPair* Sfanin; // list of calling functions + SymPair* Sfanout; // list of called functions + timer_t totaltime; // aggregate time + timer_t functime; // time excluding subfunction calls + ubyte Sflags; + char[] Sident; // name of symbol +} + +const ubyte SFvisited = 1; // visited + + +////////////////////////////////// +// Build a linked list of these. + +struct Stack +{ + Stack* prev; + Symbol* sym; + timer_t starttime; // time when function was entered + timer_t ohd; // overhead of all the bookkeeping code + timer_t subtime; // time used by all subfunctions +} + +__gshared // doesn't work with multithreaded code anyway +{ + Symbol* root; // root of symbol table + + Stack* stack_freelist; + Stack* trace_tos; // top of stack + int trace_inited; // !=0 if initialized + timer_t trace_ohd; + + Symbol** psymbols; + uint nsymbols; // number of symbols + + string trace_logfilename = "trace.log"; + FILE* fplog; + + string trace_deffilename = "trace.def"; + FILE* fpdef; +} + +//////////////////////////////////////// +// Set file name for output. +// A file name of "" means write results to stdout. +// Returns: +// 0 success +// !=0 failure + +int trace_setlogfilename(string name) +{ + trace_logfilename = name; + return 0; +} + +//////////////////////////////////////// +// Set file name for output. +// A file name of "" means write results to stdout. +// Returns: +// 0 success +// !=0 failure + +int trace_setdeffilename(string name) +{ + trace_deffilename = name; + return 0; +} + +//////////////////////////////////////// +// Output optimal function link order. + +static void trace_order(Symbol *s) +{ + while (s) + { + trace_place(s,0); + if (s.Sl) + trace_order(s.Sl); + s = s.Sr; + } +} + +////////////////////////////////////////////// +// + +static Stack* stack_malloc() +{ Stack *s; + + if (stack_freelist) + { s = stack_freelist; + stack_freelist = s.prev; + } + else + s = cast(Stack *)trace_malloc(Stack.sizeof); + return s; +} + +////////////////////////////////////////////// +// + +static void stack_free(Stack *s) +{ + s.prev = stack_freelist; + stack_freelist = s; +} + +////////////////////////////////////// +// Qsort() comparison routine for array of pointers to SymPair's. + +static int sympair_cmp(in void* e1, in void* e2) +{ SymPair** psp1; + SymPair** psp2; + + psp1 = cast(SymPair**)e1; + psp2 = cast(SymPair**)e2; + + return (*psp2).count - (*psp1).count; +} + +////////////////////////////////////// +// Place symbol s, and then place any fan ins or fan outs with +// counts greater than count. + +static void trace_place(Symbol *s, uint count) +{ SymPair* sp; + SymPair** base; + + if (!(s.Sflags & SFvisited)) + { size_t num; + uint u; + + //printf("\t%.*s\t%u\n", s.Sident, count); + fprintf(fpdef,"\t%.*s\n", s.Sident); + s.Sflags |= SFvisited; + + // Compute number of items in array + num = 0; + for (sp = s.Sfanin; sp; sp = sp.next) + num++; + for (sp = s.Sfanout; sp; sp = sp.next) + num++; + if (!num) + return; + + // Allocate and fill array + base = cast(SymPair**)trace_malloc(SymPair.sizeof * num); + u = 0; + for (sp = s.Sfanin; sp; sp = sp.next) + base[u++] = sp; + for (sp = s.Sfanout; sp; sp = sp.next) + base[u++] = sp; + + // Sort array + qsort(base, num, (SymPair *).sizeof, &sympair_cmp); + + //for (u = 0; u < num; u++) + //printf("\t\t%.*s\t%u\n", base[u].sym.Sident, base[u].count); + + // Place symbols + for (u = 0; u < num; u++) + { + if (base[u].count >= count) + { uint u2; + uint c2; + + u2 = (u + 1 < num) ? u + 1 : u; + c2 = base[u2].count; + if (c2 < count) + c2 = count; + trace_place(base[u].sym,c2); + } + else + break; + } + + // Clean up + trace_free(base); + } +} + +///////////////////////////////////// +// Initialize and terminate. + +static this() +{ + trace_init(); +} + +static ~this() +{ + trace_term(); +} + +/////////////////////////////////// +// Report results. +// Also compute nsymbols. + +static void trace_report(Symbol* s) +{ SymPair* sp; + uint count; + + //printf("trace_report()\n"); + while (s) + { nsymbols++; + if (s.Sl) + trace_report(s.Sl); + fprintf(fplog,"------------------\n"); + count = 0; + for (sp = s.Sfanin; sp; sp = sp.next) + { + fprintf(fplog,"\t%5d\t%.*s\n", sp.count, sp.sym.Sident); + count += sp.count; + } + fprintf(fplog,"%.*s\t%u\t%lld\t%lld\n",s.Sident,count,s.totaltime,s.functime); + for (sp = s.Sfanout; sp; sp = sp.next) + { + fprintf(fplog,"\t%5d\t%.*s\n",sp.count,sp.sym.Sident); + } + s = s.Sr; + } +} + +//////////////////////////////////// +// Allocate and fill array of symbols. + +static void trace_array(Symbol *s) +{ + __gshared uint u; + + if (!psymbols) + { u = 0; + psymbols = cast(Symbol **)trace_malloc((Symbol *).sizeof * nsymbols); + } + while (s) + { + psymbols[u++] = s; + trace_array(s.Sl); + s = s.Sr; + } +} + + +////////////////////////////////////// +// Qsort() comparison routine for array of pointers to Symbol's. + +static int symbol_cmp(in void* e1, in void* e2) +{ Symbol** ps1; + Symbol** ps2; + timer_t diff; + + ps1 = cast(Symbol **)e1; + ps2 = cast(Symbol **)e2; + + diff = (*ps2).functime - (*ps1).functime; + return (diff == 0) ? 0 : ((diff > 0) ? 1 : -1); +} + + +/////////////////////////////////// +// Report function timings + +static void trace_times(Symbol* root) +{ uint u; + timer_t freq; + + // Sort array + qsort(psymbols, nsymbols, (Symbol *).sizeof, &symbol_cmp); + + // Print array + QueryPerformanceFrequency(&freq); + fprintf(fplog,"\n======== Timer Is %lld Ticks/Sec, Times are in Microsecs ========\n\n",freq); + fprintf(fplog," Num Tree Func Per\n"); + fprintf(fplog," Calls Time Time Call\n\n"); + for (u = 0; u < nsymbols; u++) + { Symbol* s = psymbols[u]; + timer_t tl,tr; + timer_t fl,fr; + timer_t pl,pr; + timer_t percall; + SymPair* sp; + uint calls; + char[] id; + + version (Windows) + { + char* p = (s.Sident ~ '\0').ptr; + p = unmangle_ident(p); + if (p) + id = p[0 .. strlen(p)]; + } + if (!id) + id = s.Sident; + calls = 0; + for (sp = s.Sfanin; sp; sp = sp.next) + calls += sp.count; + if (calls == 0) + calls = 1; + +version (all) +{ + tl = (s.totaltime * 1000000) / freq; + fl = (s.functime * 1000000) / freq; + percall = s.functime / calls; + pl = (s.functime * 1000000) / calls / freq; + + fprintf(fplog,"%7d%12lld%12lld%12lld %.*s\n", + calls,tl,fl,pl,id); +} +else +{ + tl = s.totaltime / freq; + tr = ((s.totaltime - tl * freq) * 10000000) / freq; + + fl = s.functime / freq; + fr = ((s.functime - fl * freq) * 10000000) / freq; + + percall = s.functime / calls; + pl = percall / freq; + pr = ((percall - pl * freq) * 10000000) / freq; + + fprintf(fplog,"%7d\t%3lld.%07lld\t%3lld.%07lld\t%3lld.%07lld\t%.*s\n", + calls,tl,tr,fl,fr,pl,pr,id); +} + if (id !is s.Sident) + free(id.ptr); + } +} + + +/////////////////////////////////// +// Initialize. + +static void trace_init() +{ + if (!trace_inited) + { + trace_inited = 1; + + { // See if we can determine the overhead. + uint u; + timer_t starttime; + timer_t endtime; + Stack *st; + + st = trace_tos; + trace_tos = null; + QueryPerformanceCounter(&starttime); + for (u = 0; u < 100; u++) + { + asm + { + call _trace_pro_n ; + db 0 ; + call _trace_epi_n ; + } + } + QueryPerformanceCounter(&endtime); + trace_ohd = (endtime - starttime) / u; + //printf("trace_ohd = %lld\n",trace_ohd); + if (trace_ohd > 0) + trace_ohd--; // round down + trace_tos = st; + } + } +} + +///////////////////////////////// +// Terminate. + +void trace_term() +{ + //printf("trace_term()\n"); + if (trace_inited == 1) + { Stack *n; + + trace_inited = 2; + + // Free remainder of the stack + while (trace_tos) + { + n = trace_tos.prev; + stack_free(trace_tos); + trace_tos = n; + } + + while (stack_freelist) + { + n = stack_freelist.prev; + stack_free(stack_freelist); + stack_freelist = n; + } + + // Merge in data from any existing file + trace_merge(); + + // Report results + fplog = fopen(trace_logfilename.ptr, "w"); + if (fplog) + { nsymbols = 0; + trace_report(root); + trace_array(root); + trace_times(root); + fclose(fplog); + } + + // Output function link order + fpdef = fopen(trace_deffilename.ptr,"w"); + if (fpdef) + { fprintf(fpdef,"\nFUNCTIONS\n"); + trace_order(root); + fclose(fpdef); + } + + trace_free(psymbols); + psymbols = null; + } +} + +///////////////////////////////// +// Our storage allocator. + +static void *trace_malloc(size_t nbytes) +{ void *p; + + p = malloc(nbytes); + if (!p) + exit(EXIT_FAILURE); + return p; +} + +static void trace_free(void *p) +{ + free(p); +} + +////////////////////////////////////////////// +// + +static Symbol* trace_addsym(char[] id) +{ + Symbol** parent; + Symbol* rover; + Symbol* s; + int cmp; + char c; + + //printf("trace_addsym('%s',%d)\n",p,len); + parent = &root; + rover = *parent; + while (rover !is null) // while we haven't run out of tree + { + cmp = dstrcmp(id, rover.Sident); + if (cmp == 0) + { + return rover; + } + parent = (cmp < 0) ? /* if we go down left side */ + &(rover.Sl) : /* then get left child */ + &(rover.Sr); /* else get right child */ + rover = *parent; /* get child */ + } + /* not in table, so insert into table */ + s = cast(Symbol *)trace_malloc(Symbol.sizeof); + memset(s,0,Symbol.sizeof); + s.Sident = id; + *parent = s; // link new symbol into tree + return s; +} + +/*********************************** + * Add symbol s with count to SymPair list. + */ + +static void trace_sympair_add(SymPair** psp, Symbol* s, uint count) +{ SymPair* sp; + + for (; 1; psp = &sp.next) + { + sp = *psp; + if (!sp) + { + sp = cast(SymPair *)trace_malloc(SymPair.sizeof); + sp.sym = s; + sp.count = 0; + sp.next = null; + *psp = sp; + break; + } + else if (sp.sym == s) + { + break; + } + } + sp.count += count; +} + +////////////////////////////////////////////// +// + +static void trace_pro(char[] id) +{ + Stack* n; + Symbol* s; + timer_t starttime; + timer_t t; + + QueryPerformanceCounter(&starttime); + if (id.length == 0) + return; + if (!trace_inited) + trace_init(); // initialize package + n = stack_malloc(); + n.prev = trace_tos; + trace_tos = n; + s = trace_addsym(id); + trace_tos.sym = s; + if (trace_tos.prev) + { + Symbol* prev; + int i; + + // Accumulate Sfanout and Sfanin + prev = trace_tos.prev.sym; + trace_sympair_add(&prev.Sfanout,s,1); + trace_sympair_add(&s.Sfanin,prev,1); + } + QueryPerformanceCounter(&t); + trace_tos.starttime = starttime; + trace_tos.ohd = trace_ohd + t - starttime; + trace_tos.subtime = 0; + //printf("trace_tos.ohd=%lld, trace_ohd=%lld + t=%lld - starttime=%lld\n", + // trace_tos.ohd,trace_ohd,t,starttime); +} + +///////////////////////////////////////// +// + +static void trace_epi() +{ Stack* n; + timer_t endtime; + timer_t t; + timer_t ohd; + + //printf("trace_epi()\n"); + if (trace_tos) + { + timer_t starttime; + timer_t totaltime; + + QueryPerformanceCounter(&endtime); + starttime = trace_tos.starttime; + totaltime = endtime - starttime - trace_tos.ohd; + if (totaltime < 0) + { //printf("endtime=%lld - starttime=%lld - trace_tos.ohd=%lld < 0\n", + // endtime,starttime,trace_tos.ohd); + totaltime = 0; // round off error, just make it 0 + } + + // totaltime is time spent in this function + all time spent in + // subfunctions - bookkeeping overhead. + trace_tos.sym.totaltime += totaltime; + + //if (totaltime < trace_tos.subtime) + //printf("totaltime=%lld < trace_tos.subtime=%lld\n",totaltime,trace_tos.subtime); + trace_tos.sym.functime += totaltime - trace_tos.subtime; + ohd = trace_tos.ohd; + n = trace_tos.prev; + stack_free(trace_tos); + trace_tos = n; + if (n) + { QueryPerformanceCounter(&t); + n.ohd += ohd + t - endtime; + n.subtime += totaltime; + //printf("n.ohd = %lld\n",n.ohd); + } + } +} + + +////////////////////////// FILE INTERFACE ///////////////////////// + +///////////////////////////////////// +// Read line from file fp. +// Returns: +// trace_malloc'd line buffer +// null if end of file + +static char* trace_readline(FILE* fp) +{ int c; + int dim; + int i; + char *buf; + + //printf("trace_readline(%p)\n", fp); + i = 0; + dim = 0; + buf = null; + while (1) + { + if (i == dim) + { char *p; + + dim += 80; + p = cast(char *)trace_malloc(dim); + memcpy(p,buf,i); + trace_free(buf); + buf = p; + } + c = fgetc(fp); + switch (c) + { + case EOF: + if (i == 0) + { trace_free(buf); + return null; + } + case '\n': + goto L1; + default: + break; + } + buf[i] = cast(char)c; + i++; + } +L1: + buf[i] = 0; + //printf("line '%s'\n",buf); + return buf; +} + +////////////////////////////////////// +// Skip space + +static char *skipspace(char *p) +{ + while (isspace(*p)) + p++; + return p; +} + +//////////////////////////////////////////////////////// +// Merge in profiling data from existing file. + +static void trace_merge() +{ FILE *fp; + char *buf; + char *p; + uint count; + Symbol *s; + SymPair *sfanin; + SymPair **psp; + + if (trace_logfilename && (fp = fopen(trace_logfilename.ptr,"r")) !is null) + { + buf = null; + sfanin = null; + psp = &sfanin; + while (1) + { + trace_free(buf); + buf = trace_readline(fp); + if (!buf) + break; + switch (*buf) + { + case '=': // ignore rest of file + trace_free(buf); + goto L1; + case ' ': + case '\t': // fan in or fan out line + count = strtoul(buf,&p,10); + if (p == buf) // if invalid conversion + continue; + p = skipspace(p); + if (!*p) + continue; + s = trace_addsym(p[0 .. strlen(p)]); + trace_sympair_add(psp,s,count); + break; + default: + if (!isalpha(*buf)) + { + if (!sfanin) + psp = &sfanin; + continue; // regard unrecognized line as separator + } + case '?': + case '_': + case '$': + case '@': + p = buf; + while (isgraph(*p)) + p++; + *p = 0; + //printf("trace_addsym('%s')\n",buf); + s = trace_addsym(buf[0 .. strlen(buf)]); + if (s.Sfanin) + { SymPair *sp; + + for (; sfanin; sfanin = sp) + { + trace_sympair_add(&s.Sfanin,sfanin.sym,sfanin.count); + sp = sfanin.next; + trace_free(sfanin); + } + } + else + { s.Sfanin = sfanin; + } + sfanin = null; + psp = &s.Sfanout; + + { timer_t t; + + p++; + count = strtoul(p,&p,10); + t = cast(long)strtoull(p,&p,10); + s.totaltime += t; + t = cast(long)strtoull(p,&p,10); + s.functime += t; + } + break; + } + } + L1: + fclose(fp); + } +} + +////////////////////////// COMPILER INTERFACE ///////////////////// + +///////////////////////////////////////////// +// Function called by trace code in function prolog. + +void _trace_pro_n() +{ + /* Length of string is either: + * db length + * ascii string + * or: + * db 0x0FF + * db 0 + * dw length + * ascii string + */ + + version (OSX) + { // 16 byte align stack + asm + { naked ; + pushad ; + mov ECX,8*4[ESP] ; + xor EAX,EAX ; + mov AL,[ECX] ; + cmp AL,0xFF ; + jne L1 ; + cmp byte ptr 1[ECX],0 ; + jne L1 ; + mov AX,2[ECX] ; + add 8*4[ESP],3 ; + add ECX,3 ; + L1: inc EAX ; + inc ECX ; + add 8*4[ESP],EAX ; + dec EAX ; + sub ESP,4 ; + push ECX ; + push EAX ; + call trace_pro ; + add ESP,12 ; + popad ; + ret ; + } + } + else + { + asm + { naked ; + pushad ; + mov ECX,8*4[ESP] ; + xor EAX,EAX ; + mov AL,[ECX] ; + cmp AL,0xFF ; + jne L1 ; + cmp byte ptr 1[ECX],0 ; + jne L1 ; + mov AX,2[ECX] ; + add 8*4[ESP],3 ; + add ECX,3 ; + L1: inc EAX ; + inc ECX ; + add 8*4[ESP],EAX ; + dec EAX ; + push ECX ; + push EAX ; + call trace_pro ; + add ESP,8 ; + popad ; + ret ; + } + } +} + +///////////////////////////////////////////// +// Function called by trace code in function epilog. + + +void _trace_epi_n() +{ + version (OSX) + { // 16 byte align stack + asm + { naked ; + pushad ; + sub ESP,12 ; + } + trace_epi(); + asm + { + add ESP,12 ; + popad ; + ret ; + } + } + else + { + asm + { naked ; + pushad ; + } + trace_epi(); + asm + { + popad ; + ret ; + } + } +} + + +version (Windows) +{ + extern (Windows) + { + export int QueryPerformanceCounter(timer_t *); + export int QueryPerformanceFrequency(timer_t *); + } +} +else version (X86) +{ + extern (D) + { + void QueryPerformanceCounter(timer_t* ctr) + { + asm + { naked ; + mov ECX,EAX ; + rdtsc ; + mov [ECX],EAX ; + mov 4[ECX],EDX ; + ret ; + } + } + + void QueryPerformanceFrequency(timer_t* freq) + { + *freq = 3579545; + } + } +} +else +{ + static assert(0); +}