/** * Contains support code for code profiling. * * Copyright: Copyright Digital Mars 1995 - 2015. * License: Distributed under the * $(LINK2 http://www.boost.org/LICENSE_1_0.txt, Boost Software License 1.0). * (See accompanying file LICENSE) * Authors: Walter Bright, Sean Kelly * Source: $(DRUNTIMESRC src/rt/_trace.d) */ module rt.trace; private { import core.demangle; import core.stdc.ctype; import core.stdc.stdio; import core.stdc.stdlib; import core.stdc.string; import core.internal.string; version (CRuntime_Microsoft) alias core.stdc.stdlib._strtoui64 strtoull; } extern (C): alias long timer_t; ///////////////////////////////////// // struct SymPair { SymPair* next; Symbol* sym; // function that is called ulong 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; // SFxxxx uint recursion; // call recursion level const(char)[] Sident; // name of symbol } enum 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 } Symbol* root; // root of symbol table bool trace_inited; Stack* stack_freelist; Stack* trace_tos; // top of stack __gshared { Symbol* groot; // merged symbol table int gtrace_inited; // !=0 if initialized timer_t trace_ohd; string trace_logfilename = "trace.log"; string trace_deffilename = "trace.def"; } //////////////////////////////////////// // Set file name for output. // A file name of "" means write results to stdout. // Returns: // 0 success // !=0 failure void trace_setlogfilename(string name) { trace_logfilename = name; } //////////////////////////////////////// // Set file name for output. // A file name of "" means write results to stdout. // Returns: // 0 success // !=0 failure void trace_setdeffilename(string name) { trace_deffilename = name; } //////////////////////////////////////// // Output optimal function link order. private void trace_order(FILE* fpdef, Symbol *s) { while (s) { trace_place(fpdef, s, 0); if (s.Sl) trace_order(fpdef, s.Sl); s = s.Sr; } } ////////////////////////////////////////////// // private Stack* stack_push() { Stack *s; if (stack_freelist) { s = stack_freelist; stack_freelist = s.prev; } else { s = cast(Stack *)trace_malloc(Stack.sizeof); } s.prev = trace_tos; trace_tos = s; return s; } ////////////////////////////////////////////// // private void stack_free(Stack *s) { s.prev = stack_freelist; stack_freelist = s; } ////////////////////////////////////// // Qsort() comparison routine for array of pointers to SymPair's. private int sympair_cmp(in void* e1, in void* e2) { auto count1 = (*cast(SymPair**)e1).count; auto count2 = (*cast(SymPair**)e2).count; if (count1 < count2) return -1; else if (count1 > count2) return 1; return 0; } ////////////////////////////////////// // Place symbol s, and then place any fan ins or fan outs with // counts greater than count. private void trace_place(FILE* fpdef, Symbol* s, ulong count) { if (!(s.Sflags & SFvisited)) { //printf("\t%.*s\t%llu\n", s.Sident.length, s.Sident.ptr, count); fprintf(fpdef,"\t%.*s\n", s.Sident.length, s.Sident.ptr); s.Sflags |= SFvisited; // Compute number of items in array size_t num = 0; for (auto sp = s.Sfanin; sp; sp = sp.next) num++; for (auto sp = s.Sfanout; sp; sp = sp.next) num++; if (!num) return; // Allocate and fill array auto base = cast(SymPair**)trace_malloc(SymPair.sizeof * num); size_t u = 0; for (auto sp = s.Sfanin; sp; sp = sp.next) base[u++] = sp; for (auto sp = s.Sfanout; sp; sp = sp.next) base[u++] = sp; assert(u == num); // Sort array qsort(base, num, (SymPair *).sizeof, &sympair_cmp); //for (u = 0; u < num; u++) //printf("\t\t%.*s\t%llu\n", base[u].sym.Sident.length, base[u].sym.Sident.ptr, base[u].count); // Place symbols for (u = 0; u < num; u++) { if (base[u].count >= count) { auto u2 = (u + 1 < num) ? u + 1 : u; auto c2 = base[u2].count; if (c2 < count) c2 = count; trace_place(fpdef, base[u].sym,c2); } else break; } // Clean up trace_free(base); } } /////////////////////////////////// // Report results. // Also compute and return number of symbols. private size_t trace_report(FILE* fplog, Symbol* s) { //printf("trace_report()\n"); size_t nsymbols; while (s) { ++nsymbols; if (s.Sl) nsymbols += trace_report(fplog, s.Sl); fprintf(fplog,"------------------\n"); ulong count = 0; for (auto sp = s.Sfanin; sp; sp = sp.next) { fprintf(fplog,"\t%5llu\t%.*s\n", sp.count, sp.sym.Sident.length, sp.sym.Sident.ptr); count += sp.count; } fprintf(fplog,"%.*s\t%llu\t%lld\t%lld\n", s.Sident.length, s.Sident.ptr, count, s.totaltime, s.functime); for (auto sp = s.Sfanout; sp; sp = sp.next) { fprintf(fplog,"\t%5llu\t%.*s\n", sp.count, sp.sym.Sident.length, sp.sym.Sident.ptr); } s = s.Sr; } return nsymbols; } //////////////////////////////////// // Allocate and fill array of symbols. private void trace_array(Symbol*[] psymbols, Symbol *s, ref uint u) { while (s) { psymbols[u++] = s; trace_array(psymbols, s.Sl, u); s = s.Sr; } } ////////////////////////////////////// // Qsort() comparison routine for array of pointers to Symbol's. private int symbol_cmp(in void* e1, in void* e2) { auto ps1 = cast(Symbol **)e1; auto ps2 = cast(Symbol **)e2; auto diff = (*ps2).functime - (*ps1).functime; return (diff == 0) ? 0 : ((diff > 0) ? 1 : -1); } /////////////////////////////////// // Report function timings private void trace_times(FILE* fplog, Symbol*[] psymbols) { // Sort array qsort(psymbols.ptr, psymbols.length, (Symbol *).sizeof, &symbol_cmp); // Print array timer_t freq; 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"); foreach (s; psymbols) { timer_t tl,tr; timer_t fl,fr; timer_t pl,pr; timer_t percall; char[8192] buf = void; SymPair* sp; ulong calls; char[] id; calls = 0; id = demangle(s.Sident, buf); for (sp = s.Sfanin; sp; sp = sp.next) calls += sp.count; if (calls == 0) calls = 1; tl = (s.totaltime * 1000000) / freq; fl = (s.functime * 1000000) / freq; percall = s.functime / calls; pl = (s.functime * 1000000) / calls / freq; fprintf(fplog,"%7llu%12lld%12lld%12lld %.*s\n", calls, tl, fl, pl, id.length, id.ptr); } } /////////////////////////////////// // Initialize. private void trace_init() { synchronized // protects gtrace_inited { if (!gtrace_inited) { gtrace_inited = 1; { // See if we can determine the overhead. timer_t starttime; timer_t endtime; auto st = trace_tos; trace_tos = null; QueryPerformanceCounter(&starttime); uint u; for (u = 0; u < 100; u++) { _c_trace_pro(0,null); _c_trace_epi(); } 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. static ~this() { // Free remainder of the thread local stack while (trace_tos) { auto n = trace_tos.prev; stack_free(trace_tos); trace_tos = n; } // And free the thread local stack's memory while (stack_freelist) { auto n = stack_freelist.prev; stack_free(stack_freelist); stack_freelist = n; } synchronized // protects groot { // Merge thread local root into global groot if (!groot) { groot = root; // that was easy root = null; } else { void mergeSymbol(Symbol** proot, const(Symbol)* s) { while (s) { auto gs = trace_addsym(proot, s.Sident); gs.totaltime += s.totaltime; gs.functime += s.functime; static void mergeFan(Symbol** proot, SymPair** pgf, const(SymPair)* sf) { for (; sf; sf = sf.next) { auto sym = trace_addsym(proot, sf.sym.Sident); for (auto gf = *pgf; 1; gf = gf.next) { if (!gf) { auto sp = cast(SymPair *)trace_malloc(SymPair.sizeof); sp.next = *pgf; *pgf = sp; sp.sym = sym; sp.count = sf.count; break; } if (gf.sym == sym) { gf.count += sf.count; break; } } } } mergeFan(proot, &gs.Sfanin, s.Sfanin); mergeFan(proot, &gs.Sfanout, s.Sfanout); mergeSymbol(proot, s.Sl); s = s.Sr; } } mergeSymbol(&groot, root); } } // Free the memory for the thread local symbol table (root) static void freeSymbol(Symbol* s) { while (s) { freeSymbol(s.Sl); auto next = s.Sr; static void freeSymPair(SymPair* sp) { while (sp) { auto spnext = sp.next; trace_free(sp); sp = spnext; } } freeSymPair(s.Sfanin); freeSymPair(s.Sfanout); trace_free(s); s = next; } } freeSymbol(root); root = null; } shared static ~this() { //printf("shared static ~this() groot = %p\n", groot); if (gtrace_inited == 1) { gtrace_inited = 2; // Merge in data from any existing file trace_merge(&groot); // Report results FILE* fplog = trace_logfilename.length == 0 ? stdout : fopen((trace_logfilename ~ '\0').ptr, "w"); if (fplog) { auto nsymbols = trace_report(fplog, groot); auto p = cast(Symbol **)trace_malloc((Symbol *).sizeof * nsymbols); auto psymbols = p[0 .. nsymbols]; uint u; trace_array(psymbols, groot, u); trace_times(fplog, psymbols); fclose(fplog); trace_free(psymbols.ptr); psymbols = null; } else fprintf(stderr, "cannot write '%s'", trace_logfilename.ptr); // Output function link order FILE* fpdef = trace_deffilename.length == 0 ? stdout : fopen((trace_deffilename ~ '\0').ptr, "w"); if (fpdef) { fprintf(fpdef,"\nFUNCTIONS\n"); trace_order(fpdef, groot); fclose(fpdef); } else fprintf(stderr, "cannot write '%s'", trace_deffilename.ptr); } } ///////////////////////////////// // Our storage allocator. private void *trace_malloc(size_t nbytes) { auto p = malloc(nbytes); if (!p) exit(EXIT_FAILURE); return p; } private void trace_free(void *p) { free(p); } ////////////////////////////////////////////// // private Symbol* trace_addsym(Symbol** proot, const(char)[] id) { //printf("trace_addsym('%s',%d)\n",p,len); auto parent = proot; auto rover = *parent; while (rover !is null) // while we haven't run out of tree { auto 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 */ auto 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. */ private void trace_sympair_add(SymPair** psp, Symbol* s, ulong 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; } ////////////////////////////////////////////// // This one is called by DMD private void trace_pro(char[] id) { //printf("trace_pro(ptr = %p, length = %lld)\n", id.ptr, id.length); //printf("trace_pro(id = '%.*s')\n", id.length, id.ptr); if (!trace_inited) { trace_inited = true; trace_init(); // initialize package } timer_t starttime; QueryPerformanceCounter(&starttime); if (id.length == 0) return; auto tos = stack_push(); auto s = trace_addsym(&root, id); tos.sym = s; if (tos.prev) { // Accumulate Sfanout and Sfanin auto prev = tos.prev.sym; trace_sympair_add(&prev.Sfanout,s,1); trace_sympair_add(&s.Sfanin,prev,1); } timer_t t; QueryPerformanceCounter(&t); tos.starttime = starttime; tos.ohd = trace_ohd + t - starttime; tos.subtime = 0; ++s.recursion; //printf("tos.ohd=%lld, trace_ohd=%lld + t=%lld - starttime=%lld\n", // tos.ohd,trace_ohd,t,starttime); } // Called by some old versions of DMD void _c_trace_pro(size_t idlen, char* idptr) { char[] id = idptr[0 .. idlen]; trace_pro(id); } ///////////////////////////////////////// // Called by DMD generated code void _c_trace_epi() { //printf("_c_trace_epi()\n"); auto tos = trace_tos; if (tos) { timer_t endtime; QueryPerformanceCounter(&endtime); auto starttime = tos.starttime; auto totaltime = endtime - starttime - tos.ohd; if (totaltime < 0) { //printf("endtime=%lld - starttime=%lld - tos.ohd=%lld < 0\n", // endtime,starttime,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. --tos.sym.recursion; if(tos.sym.recursion == 0) tos.sym.totaltime += totaltime; //if (totaltime < tos.subtime) //printf("totaltime=%lld < tos.subtime=%lld\n",totaltime,tos.subtime); tos.sym.functime += totaltime - tos.subtime; auto ohd = tos.ohd; auto n = tos.prev; stack_free(tos); trace_tos = n; if (n) { timer_t t; 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 private char* trace_readline(FILE* fp) { int dim; int i; char *buf; //printf("trace_readline(%p)\n", fp); while (1) { if (i == dim) { dim += 80; auto p = cast(char *)trace_malloc(dim); memcpy(p,buf,i); trace_free(buf); buf = p; } int c = fgetc(fp); switch (c) { case EOF: if (i == 0) { trace_free(buf); return null; } goto L1; 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 private char *skipspace(char *p) { while (isspace(*p)) p++; return p; } //////////////////////////////////////////////////////// // Merge in profiling data from existing file. private void trace_merge(Symbol** proot) { FILE *fp; if (trace_logfilename.length && (fp = fopen(trace_logfilename.ptr,"r")) !is null) { char* buf = null; SymPair* sfanin = null; auto psp = &sfanin; char *p; ulong count; Symbol *s; 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(proot, 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 } goto case; case '?': case '_': case '$': case '@': p = buf; while (isgraph(*p)) p++; *p = 0; //printf("trace_addsym('%s')\n",buf); s = trace_addsym(proot, 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; { p++; count = strtoul(p,&p,10); timer_t 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 ///////////////////// version (Windows) { extern (Windows) { export int QueryPerformanceCounter(timer_t *); export int QueryPerformanceFrequency(timer_t *); } } else version (D_InlineAsm_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 version (D_InlineAsm_X86_64) { extern (D) { void QueryPerformanceCounter(timer_t* ctr) { asm { naked ; rdtsc ; mov [RDI],EAX ; mov 4[RDI],EDX ; ret ; } } void QueryPerformanceFrequency(timer_t* freq) { *freq = 3579545; } } } else { static assert(0); }