diff bd1305a0b9841d65f95b4d81fa0d29067425833a uncommitted --- a/sys/man/1/prof +++ b/sys/man/1/prof @@ -59,7 +59,7 @@ .I symbol is the entry point of the call, .I time -is in milliseconds, +is in seconds, and .I ncall is the number of times that entry point was called at that --- a/sys/src/cmd/file.c +++ b/sys/src/cmd/file.c @@ -918,6 +918,7 @@ "MThd", "midi audio", 4, "audio/midi", "MUS\x1a", "mus audio", 4, "audio/mus", "Creative Voice File\x1a", "voc audio", 20, "audio/x-voc", + "pr\x0f", "Plan 9 profile data", 3, OCTET, "\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff" "\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff\xff" "\x00\x00\x00\xbb\x11\x22\x00\x44\xff\xff\xff\xff\xff\xff\xff\xff" --- a/sys/src/cmd/prof.c +++ b/sys/src/cmd/prof.c @@ -13,8 +13,9 @@ ushort right; ulong pc; ulong count; - ulong time; + uvlong time; }; +enum { Datasz = 2+2+4+4+8 }; struct Pc { @@ -26,13 +27,13 @@ { char *name; ulong pc; - ulong ms; + double sec; ulong calls; }; Data* data; Acc* acc; -ulong ms; +double sec; long nsym; long ndata; int dflag; @@ -40,6 +41,7 @@ Biobuf bout; int tabstop = 4; int verbose; +double cyclefreq; void syms(char*); void datas(char*); @@ -89,26 +91,16 @@ exits(0); } -void -swapdata(Data *dp) -{ - dp->down = beswab(dp->down); - dp->right = beswab(dp->right); - dp->pc = beswal(dp->pc); - dp->count = beswal(dp->count); - dp->time = beswal(dp->time); -} - int acmp(void *va, void *vb) { Acc *a, *b; - ulong ua, ub; + double ua, ub; a = va; b = vb; - ua = a->ms; - ub = b->ms; + ua = a->sec; + ub = b->sec; if(ua > ub) return 1; @@ -142,6 +134,11 @@ close(fd); } +#define GET2(p) (u16int)(p)[1] | (u16int)(p)[0]<<8 +#define GET4(p) (u32int)(p)[3] | (u32int)(p)[2]<<8 | (u32int)(p)[1]<<16 | (u32int)(p)[0]<<24 +#define GET8(p) (u64int)(p)[7] | (u64int)(p)[6]<<8 | (u64int)(p)[5]<<16 | (u64int)(p)[4]<<24 | \ + (u64int)(p)[3]<<32 | (u64int)(p)[2]<<40 | (u64int)(p)[1]<<48 | (u64int)(p)[0]<<56 + void datas(char *dout) { @@ -148,6 +145,8 @@ int fd; Dir *d; int i; + uchar hdr[4+8], *buf, *p; + uvlong freq; if((fd = open(dout, 0)) < 0){ perror(dout); @@ -158,20 +157,40 @@ perror(dout); exits("stat"); } - ndata = d->length/sizeof(data[0]); + d->length -= sizeof hdr; + ndata = d->length/Datasz; data = malloc(ndata*sizeof(Data)); - if(data == 0){ - fprint(2, "prof: can't malloc data\n"); - exits("data malloc"); + buf = malloc(d->length); + if(buf == 0 || data == 0){ + fprint(2, "prof: can't malloc\n"); + exits("malloc"); } - if(read(fd, data, d->length) != d->length){ + if(read(fd, hdr, sizeof hdr) != sizeof hdr){ + fprint(2, "prof: can't read data header\n"); + exits("header read"); + } + if(memcmp(hdr, "pr\x0f", 3) != 0){ + fprint(2, "prof: bad magic\n"); + exits("magic check"); + } + freq = GET8(hdr+4); + if(freq == 0) + freq = 1000; + cyclefreq = (double)freq; + if(readn(fd, buf, d->length) != d->length){ fprint(2, "prof: can't read data file\n"); exits("data read"); } + for(p = buf, i = 0; i < ndata; i++){ + data[i].down = GET2(p); p += 2; + data[i].right = GET2(p); p += 2; + data[i].pc = GET4(p); p += 4; + data[i].count = GET4(p); p += 4; + data[i].time = GET8(p); p += 8; + } + free(buf); free(d); close(fd); - for (i = 0; i < ndata; i++) - swapdata(data+i); } char* @@ -189,7 +208,8 @@ void graph(int ind, ulong i, Pc *pc) { - long time, count, prgm; + long count, prgm; + vlong time; Pc lpc; if(i >= ndata){ @@ -205,9 +225,9 @@ graph(ind, data[i].right, pc); indent(ind); if(count == 1) - Bprint(&bout, "%s:%lud\n", name(prgm), time); + Bprint(&bout, "%s:%.9f\n", name(prgm), time/cyclefreq); else - Bprint(&bout, "%s:%lud/%lud\n", name(prgm), time, count); + Bprint(&bout, "%s:%.9f/%lud\n", name(prgm), time/cyclefreq, count); if(data[i].down == 0xFFFF) return; lpc.next = pc; @@ -246,10 +266,11 @@ return -1; } -ulong +uvlong sum(ulong i) { - long j, dtime, time; + long j; + vlong dtime, time; int k; static indent; @@ -264,7 +285,7 @@ if (verbose){ for(k = 0; k < indent; k++) print(" "); - print("%lud: %ld/%lud", i, data[i].time, data[i].count); + print("%lud: %llud/%.9f/%lud", i, time, time/cyclefreq, data[i].count); if (j >= 0) print(" %s\n", acc[j].name); else @@ -278,8 +299,8 @@ } j = symind(data[i].pc); if (j >= 0) { - acc[j].ms += time - dtime; - ms += time - dtime; + acc[j].sec += (time - dtime)/cyclefreq; + sec += (time - dtime)/cyclefreq; acc[j].calls += data[i].count; } if(data[i].right == 0xFFFF) @@ -300,18 +321,18 @@ } acc[nsym].name = s.name; acc[nsym].pc = s.value; - acc[nsym].calls = acc[nsym].ms = 0; + acc[nsym].calls = acc[nsym].sec = 0; } sum(data[0].down); qsort(acc, nsym, sizeof(Acc), acmp); Bprint(&bout, " %% Time Calls Name\n"); - if(ms == 0) - ms = 1; + if(sec == 0) + sec = 1; while (--nsym >= 0) { if(acc[nsym].calls) Bprint(&bout, "%4.1f %8.3f %8lud\t%s\n", - (100.0*acc[nsym].ms)/ms, - acc[nsym].ms/1000.0, + (100.0*acc[nsym].sec)/sec, + acc[nsym].sec, acc[nsym].calls, acc[nsym].name); } --- a/sys/src/libc/port/profile.c +++ b/sys/src/libc/port/profile.c @@ -6,9 +6,7 @@ extern uintptr _saveret(void); extern uintptr _savearg(void); -static ulong khz; static ulong perr; -static int havecycles; typedef struct Plink Plink; struct Plink @@ -18,8 +16,7 @@ Plink *link; long pc; long count; - vlong time; - uint rec; + vlong time; }; #pragma profile off @@ -45,11 +42,6 @@ pp = _tos->prof.pp; if(pp == 0 || (_tos->prof.pid && _tos->pid != _tos->prof.pid)) return _restore(arg, ret); - if(pc == pp->pc){ - pp->rec++; - p = pp; - goto out; - } for(p=pp->down; p; p=p->link) if(p->pc == pc) goto out; @@ -119,10 +111,7 @@ p->time = p->time + _tos->clock; break; } - if(p->rec) - p->rec--; - else - _tos->prof.pp = p->old; + _tos->prof.pp = p->old; return _restore(arg, ret); } @@ -130,10 +119,11 @@ _profdump(void) { int f; - long n; + vlong n; Plink *p; char *vp; char filename[64]; + uchar hdr[4+8] = {'p', 'r', 0x0f, 0x2}; if (_tos->prof.what == 0) return; /* No profiling */ @@ -168,8 +158,17 @@ _tos->prof.first->time = _tos->clock; break; } - vp = (char*)_tos->prof.first; + hdr[4+0] = _tos->cyclefreq>>56; + hdr[4+1] = _tos->cyclefreq>>48; + hdr[4+2] = _tos->cyclefreq>>40; + hdr[4+3] = _tos->cyclefreq>>32; + hdr[4+4] = _tos->cyclefreq>>24; + hdr[4+5] = _tos->cyclefreq>>16; + hdr[4+6] = _tos->cyclefreq>>8; + hdr[4+7] = _tos->cyclefreq; + write(f, hdr, sizeof hdr); + vp = (char*)_tos->prof.first; for(p = _tos->prof.first; p <= _tos->prof.next; p++) { /* @@ -214,16 +213,16 @@ /* * vlong time */ - if (havecycles){ - n = (vlong)(p->time / (vlong)khz); - }else - n = p->time; - - vp[0] = n>>24; - vp[1] = n>>16; - vp[2] = n>>8; - vp[3] = n; - vp += 4; + n = p->time; + vp[0] = n>>56; + vp[1] = n>>48; + vp[2] = n>>40; + vp[3] = n>>32; + vp[4] = n>>24; + vp[5] = n>>16; + vp[6] = n>>8; + vp[7] = n; + vp += 8; } write(f, (char*)_tos->prof.first, vp - (char*)_tos->prof.first); close(f); @@ -250,10 +249,6 @@ int n, f; n = 256*1024; - if (_tos->cyclefreq != 0LL){ - khz = _tos->cyclefreq / 1000; /* Report times in milliseconds */ - havecycles = 1; - } f = open("/env/profsize", OREAD|OCEXEC); if(f >= 0) { memset(ename, 0, sizeof(ename));