/* use chronicle.cqct and debug-l1.cqct. this file exists merely for benchmarking. */ @include @include @include @include chroot = getenv("HOME")+"/ch/"; verbose = 0; chvalgrpath = chroot+"bin/valgrind"; chquerypath = chroot+"/bin/chronicle-query"; @global exe, gcs, exedom; Segsize = 1ULL<<20; ns = @names clp64le { typedef struct Ctx { /* kernel's register set */ @0x0 uint64 r15; @0x8 uint64 r14; @0x10 uint64 r13; @0x18 uint64 r12; @0x20 uint64 rbp; @0x20 uint64 fp; @0x28 uint64 rbx; @0x30 uint64 r11; @0x38 uint64 r10; @0x40 uint64 r9; @0x48 uint64 r8; @0x50 uint64 rax; @0x58 uint64 rcx; @0x60 uint64 rdx; @0x68 uint64 rsi; @0x70 uint64 rdi; @0x78 uint64 orig_rax; @0x80 uint64 rip; @0x80 uint64 pc; @0x88 uint64 cs; @0x90 uint64 eflags; @0x98 uint64 rsp; @0x98 uint64 sp; @0xa0 uint64 ss; @0xa8 uint64 fs_base; @0xb0 uint64 gs_base; @0xb8 uint64 ds; @0xc0 uint64 es; @0xc8 uint64 fs; @0xd0 uint64 gs; @0xd8 uint64 thread; /* chronicle construction */ @0xe0; } Ctx; }; @define dumpctx(ctx) { printf("\t rip %016x\n", ctx->rip); printf("\t rsp %016x\n", ctx->rsp); printf("\t rbp %016x\n", ctx->rbp); printf("\t rax %016x\n", ctx->rax); printf("\t rbx %016x\n", ctx->rbx); printf("\t rcx %016x\n", ctx->rcx); printf("\t rdx %016x\n", ctx->rdx); printf("\t rsi %016x\n", ctx->rsi); printf("\t rdi %016x\n", ctx->rdi); printf("\t r8 %016x\n", ctx->r8); printf("\t r9 %016x\n", ctx->r9); printf("\t r10 %016x\n", ctx->r10); printf("\t r11 %016x\n", ctx->r11); printf("\t r12 %016x\n", ctx->r12); printf("\t r13 %016x\n", ctx->r13); printf("\t r14 %016x\n", ctx->r14); printf("\t r15 %016x\n", ctx->r15); printf("\t flags %016x\n", ctx->eflags); printf("\tthread %016x\n", ctx->thread); } @define tobin(x) { if(x >= '0' && x <= '9') return x-'0'; if(x >= 'A' && x <= 'F') return x-'A'+10; if(x >= 'a' && x <= 'f') return x-'a'+10; error("bad hex digit"); } @define hextobin(s) { @local i, n, m, t; t = m = mkxs(); n = length(s); for(i = 0; i < n; i += 2) *t++ = (tobin(s[i])<<4)|tobin(s[i+1]); return getbytes(m, n/2); } @define join(ss) { @local buf, p, m; m = 0; foreach(@lambda(s) { m += length(s); }, ss); buf = mkstr(m); p = (char*)buf; foreach(@lambda(s) { putbytes(p, s); p += length(s); }, ss); return buf; } @global stats; @define resetstats() { stats = mktab(0); } //resetstats(); @define summarizetime(id) { @local tot; tot = stats[id]; foreach(@lambda(k, v){ if(k == id) return; printf("%25s%10d (%6.2f%%)\n", k, v, ((float)v/tot)*100.0); }, stats); printf("%25s%10d (100.00%%)\n", id, tot); } @define xtime(id, fn) { @local b, e, rv; b = gettimeofday(); rv = fn(); e = gettimeofday(); stats[id] += e-b; return rv; } @define tjson2val(j) { @local b, e, rv; b = gettimeofday(); rv = json2val(j); e = gettimeofday(); stats['json2val] += e-b; return rv; } @define tval2json(v) { @local b, e, rv; b = gettimeofday(); rv = val2json(v); e = gettimeofday(); stats['val2json] += e-b; return rv; } @define val2json(v) { if(isstring(v) || iscid(v)) return sprintfa("\"%s\"", v); else if(iscvalue(v)) return sprintfa("%u", v); else if(islist(v)) return list2json(v); else if(istable(v)) return tab2json(v); else error("invalid value: %a", v); } @define tab2json(tab) { @local ss, m; ss = []; m = length(tab); append(ss, "{"); foreach(@lambda(key, val){ append(ss, val2json(key)); append(ss, ":"); append(ss, val2json(val)); if(--m > 0) append(ss, ","); }, tab); append(ss, "}"); return join(ss); } @define list2json(l) { @local ss, m; ss = []; m = length(l); append(ss, "["); foreach(@lambda(val){ append(ss, val2json(val)); if(--m > 0) append(ss, ","); }, l); append(ss, "]"); return join(ss); } /* quoted {'s and }'s lose */ @define _json2val(s) { @local p, m, e, c, t, f; m = length(s); p = (char*)s; e = p+m; while(p < e){ c = *p; if(c == '{') *p = '['; if(c == '}') *p = ']'; p++; } /* this sucks */ if(strstr(s, "true") && strstr(s, "false")) f = sprintfa("{ @local true, false; true = 1; false = 0; %s; }\n", s); else if(strstr(s, "true")) f = sprintfa("{ @local true; true = 1; %s; }\n", s); else if(strstr(s, "false")) f = sprintfa("{ @local false; false = 1; %s; }\n", s); else f = s+";"; t = eval(f); return t; } @define test() { @local t, s, x; t = [ "cmd" : "scan", "id" : 1, "map" : "INSTR_EXEC", "beginTStamp" : 0, "endTStamp" : 146664, "ranges" : [ [ "start":4195672, "length":1 ]], ]; s = val2json(t); printf("%s\n", s); x = json2val(s); return x; } @define elfloadaddr(filename) { @local elfdom, data, e, p, i; data = mapfile(filename); if(!iself(data)) return nil; elfdom = mkelfrec(data).elf; if(sizeof(nsptr(elfdom.ns)) == 4){ e = (Elf32_Ehdr*){elfdom}0; p = (Elf32_Phdr*)e->e_phoff; }else{ e = (Elf64_Ehdr*){elfdom}0; p = (Elf64_Phdr*)e->e_phoff; } for(i = 0; i < e->e_phnum; i++){ if(p[i].p_type != elfdom`PT_LOAD) continue; return (uintptr)(p[i].p_vaddr); } return nil; } @define mklinebuf(fd) { @local part; @record lb { read, write }; part = ""; @defloc tstrstr(s, p) { xtime('strstr, @lambda() { strstr(s, p); }); } @defloc tsubstr(s, b, e) { xtime('substr, @lambda() { substr(s, b, e); }); } @defloc tread(id, fd, m) { @local f; f = @lambda() { read(fd, m); }; xtime(id, f); } @defloc r(id) { @local s, m, rv; while(1){ m = tstrstr(part, "\n"); if(m){ rv = tsubstr(part, 0, m); part = tsubstr(part, m+1, length(part)); return rv; } s = tread(id, fd, 1024); if(s == nil) return nil; /* discard part */ part += s; } } @defloc w(s) { return write(fd, s); } return lb(r, w); } @define chconnect(db) { @local lb, fds; fds = popen(chquerypath, "--db", db, 2|8); lb = mklinebuf(fds[0]); return lb; } nextid = 1; @define chquery(lb, t) { @local s, r, rvs, id, cmd; id = nextid++; t["id"] = id; rvs = []; cmd = mkcid("read"+t["cmd"]); t = tval2json(t)+"\n"; @defloc lbread() { lb.read(cmd); } lb.write(t); if(verbose) printf("--> %s", t); while(1){ s = xtime('lbread, lbread); if(verbose) printf("<-- %s\n", s); if(s == nil){ error("unexpected eof of chquery channel"); break; } r = tjson2val(s); if(r["id"] == nil) continue; if(r["id"] != id) error("unexpected id on chquery channel (on %d, got %d)", id, r["id"]); if(r["terminated"]) return rvs; append(rvs, r); } return rvs; } @define chcollect(rs, field) { @local l; l = []; foreach(@lambda(t) { @local v; v = t[field]; if(v) append(l, v); }, rs); return l; } @define chfilter(rs, pred) { @local l; l = []; foreach(@lambda(t) { if(pred(t)) append(l, t); }, rs); return l; } @define chflatten(rs) { @local rv; rv = [:]; foreach(@lambda(t) { foreach(@lambda(k,v) { rv[k] = v; }, t); }, rs); return rv; } @define fmtframe(ctl, ctx, t) { @local s, src; s = ""; /* pc */ s += sprintfa("%016p", ctx->pc); /* symbol */ s += sprintfa("\t%-30y", {ctl.dom(t, ctx->pc)}ctx->pc); /* source */ src = ctl.looksrc(ctx->pc); if(src) s += sprintfa("\t%s:%d", src.file, src.line); return s; } @define fmtldom(ctl, ctx, t) { @local s, ldom; s = ""; ldom = ctl.ldom(t, ctx); if(ldom == nil) return s; foreach(@lambda(id, l){ s += sprintfa("\t%016p\t%t\n", symoff(l), l); }, ldom.enumsym()); return s; } @define dumpstack(ctl, t) { @local ctxs; ctxs = ctl.unwind(t); // printf("@%d:\n", t); foreach(@lambda(ctx){ printf("%s\n", fmtframe(ctl, ctx, t)); }, ctxs); printf("\n"); } @define dumpstacklocs(ctl, t) { @local ctxs; ctxs = ctl.unwind(t); foreach(@lambda(ctx){ printf("%s\n", fmtframe(ctl, ctx, t)); printf("%s", fmtldom(ctl, ctx, t)); }, ctxs); printf("\n"); } @record chctl { intvl, scan, findret, mem, ctx, nsmap, ns, dom, ldom, unwind, looksrc }; @define mkchctl(db) { @local endtstamp, lb, rs, nsmap; lb = chconnect(db); rs = chquery(lb, [ "cmd" : "info" ]); rs = chcollect(rs, "endTStamp"); if(length(rs) != 1) error("unexpected endTStamp response: %a", rs); endtstamp = rs[0]; if(verbose) printf("*** bound to execution %s; interval [0,%u]\n", db, endtstamp); rs = chquery(lb, [ "cmd" : "scan", "map" : "MEM_MAP", "beginTStamp" : 0, "endTStamp" : endtstamp, "ranges" : [ [ "start" : 0, "length" : -1ULL ]] ]); rs = chfilter(rs, @lambda(t) { @local v; v = t["filename"]; return v; }); rs = chfilter(rs, @lambda(t) { @local v; v = t["offset"]; v != nil && v == 0; }); rs = chfilter(rs, @lambda(t) { @local v; v = t["execute"]; v != nil && v; }); nsmap = mknsmap(atnames); foreach(@lambda(t){ @local f, abase, vbase; f = t["filename"]; if(strstr(f, "valgrind") != nil) return; abase = t["start"]; vbase = elfloadaddr(f); if(vbase == nil) return; /* presume it's not an elf */ printf("\t0x%016p\t%s\n", abase-vbase, f); nsmap.add(abase-vbase, f); }, rs); nsmap.setexe(0); /* hack */ printf("\tend timestamp: %d\n", endtstamp); @defloc scan(kind, rest ...) { @local beg, end, addr, len; @defloc defrange(args) { if(length(args) == 2){ beg = args[0]; end = args[1]; if(beg > end) error("bad interval [%d,%d]", beg, end); if(end > endtstamp) error("interval exceeds execution"); }else{ beg = 0; end = endtstamp; } } switch(kind){ case 'exec: addr = pop(rest); defrange(rest); rs = chquery(lb, [ "cmd" : "scan", "map" : "INSTR_EXEC", "beginTStamp" : beg, "endTStamp" : end, "ranges" : [ [ "start" : addr, "length" : 1 ] ] ]); rs = chfilter(rs, @lambda(t) { @local v; v = t["type"]; return v && v == "normal"; }); return chcollect(rs, "TStamp"); case 'lastexec: addr = pop(rest); defrange(rest); rs = chquery(lb, [ "cmd" : "scan", "map" : "INSTR_EXEC", "beginTStamp" : beg, "endTStamp" : end, "termination" : "findLast", "ranges" : [ [ "start" : addr, "length" : 1 ] ] ]); rs = chfilter(rs, @lambda(t) { @local v; v = t["type"]; return v && v == "normal"; }); return chcollect(rs, "TStamp"); case 'write: addr = pop(rest); len = pop(rest); defrange(rest); rs = chquery(lb, [ "cmd" : "scan", "map" : "MEM_WRITE", "beginTStamp" : beg, "endTStamp" : end, "ranges" : [ [ "start" : addr, "length" : len ] ] ]); rs = chfilter(rs, @lambda(t) { @local v; v = t["type"]; return v && v == "normal"; }); return chcollect(rs, "TStamp"); case 'read: addr = pop(rest); len = pop(rest); defrange(rest); rs = chquery(lb, [ "cmd" : "scan", "map" : "MEM_READ", "beginTStamp" : beg, "endTStamp" : end, "ranges" : [ [ "start" : addr, "length" : len ] ] ]); rs = chfilter(rs, @lambda(t) { @local v; v = t["type"]; return v && v == "normal"; }); return chcollect(rs, "TStamp"); case 'lastwrite: addr = pop(rest); len = pop(rest); defrange(rest); rs = chquery(lb, [ "cmd" : "scan", "map" : "MEM_WRITE", "beginTStamp" : beg, "endTStamp" : end, "termination" : "findLast", "ranges" : [ [ "start" : addr, "length" : len ] ] ]); rs = chfilter(rs, @lambda(t) { @local v; v = t["type"]; return v && v == "normal"; }); return chcollect(rs, "TStamp"); case 'lastread: addr = pop(rest); len = pop(rest); defrange(rest); rs = chquery(lb, [ "cmd" : "scan", "map" : "MEM_READ", "beginTStamp" : beg, "endTStamp" : end, "termination" : "findLast", "ranges" : [ [ "start" : addr, "length" : len ] ] ]); rs = chfilter(rs, @lambda(t) { @local v; v = t["type"]; return v && v == "normal"; }); return chcollect(rs, "TStamp"); default: error("invalid scan kind: %a", kind); } } @defloc tctx(t) { xtime('ctx, @lambda() { ctx2(t); }); } @defloc findret(t) { @local rs, sp, tid; [sp, tid] = tctx(t); @defloc doquery() { chquery(lb, [ "cmd" : "findSPGreaterThan", "beginTStamp" : t, "endTStamp" : endtstamp, "thread" : tid, "threshold" : sp ]); } // rs = chquery(lb, [ "cmd" : "findSPGreaterThan", // "beginTStamp" : t, // "endTStamp" : endtstamp, // "thread" : x->thread, // "threshold" : x->sp ]); rs = xtime('findSP, doquery); rs = chcollect(rs, "TStamp"); if(length(rs) == 0) return nil; else if(length(rs) > 1) error("too many return points"); else return rs[0]-1; } @defloc mem(tstamp) { if(tstamp >= endtstamp) error("invalid timestamp"); @defloc get(this, r) { @local rs, ts; rs = chquery(lb, [ "cmd" : "readMem", "TStamp" : tstamp, "ranges" : [ [ "start" : rangebeg(r), "length" : rangelen(r) ] ] ]); ts = chcollect(rs, "bytes"); if(length(ts) == 0) error("no bytes -- what do i do?"); if(length(ts) > 1){ ts = chfilter(rs, @lambda(r) { r["bytes"]; }); sort(ts, @lambda(r1, r2) { cvalcmp(r1["start"], r2["start"]); }); ts = chcollect(ts, "bytes"); return(hextobin(join(ts))); } return hextobin(ts[0]); } @defloc put(this, r, s) { error("attempt to write to chronicle address space"); } @defloc map(this) { return vector(mkrange(0, 1ULL)); } @defloc ismapped(this, r) { return 1; /* for now */ } return mkas([ "get" : get, "put" : put, "map" : map, "ismapped" : ismapped ]); } @defloc ctx2(tstamp) { @local rs, rv; rs = chquery(lb, [ "cmd" : "readReg", "TStamp" : tstamp, "rsp" : 64, "thread" : 64, ]); rs = chflatten(rs); rv = [ strton(rs["rsp"], 16), strton(rs["thread"], 16) ]; return rv; } @defloc ctx(tstamp) { @local rs, rv; rs = chquery(lb, [ "cmd" : "readReg", "TStamp" : tstamp, "r15" : 64, "r14" : 64, "r13" : 64, "r12" : 64, "rbp" : 64, "rbx" : 64, "r11" : 64, "r10" : 64, "r9" : 64, "r8" : 64, "rax" : 64, "rcx" : 64, "rdx" : 64, "rsi" : 64, "rdi" : 64, "pc" : 64, "rsp" : 64, "thread" : 64, ]); rs = chflatten(rs); rv = (ns`Ctx*){mkzas(sizeof(ns`Ctx))}0; rv->r15 = strton(rs["r15"], 16); rv->r14 = strton(rs["r14"], 16); rv->r13 = strton(rs["r13"], 16); rv->r12 = strton(rs["r12"], 16); rv->r11 = strton(rs["r11"], 16); rv->r10 = strton(rs["r10"], 16); rv->r9 = strton(rs["r9"], 16); rv->r8 = strton(rs["r8"], 16); rv->rbp = strton(rs["rbp"], 16); rv->rbx = strton(rs["rbx"], 16); rv->rax = strton(rs["rax"], 16); rv->rcx = strton(rs["rcx"], 16); rv->rdx = strton(rs["rdx"], 16); rv->rsi = strton(rs["rsi"], 16); rv->rdi = strton(rs["rdi"], 16); rv->rip = strton(rs["pc"], 16); rv->rsp = strton(rs["rsp"], 16); rv->thread = strton(rs["thread"], 16); return rv; } @defloc _ns(arg...) { @local idx; if(length(arg) == 0) return nsmap.exe(); idx = arg[0]; if(isstring(idx)) return nsmap.byname(idx); if(iscvalue(idx)) return nsmap.byaddr(idx); error("wrong type of index"); } @defloc dom(t, arg...) { @local n; n = apply(_ns, arg); if(n == nil) return nil; return mkdom(n, mem(t)); } @defloc ldom(t, arg...) { @local x; if(length(arg) == 0) x = ctx(t); else x = arg[0]; return dwlocaldom(x, mem(t), nsmap); } @defloc unwind(t) { dwunwind(ctx(t), mem(t), nsmap); } @defloc looksrc(addr) { @local n; n = _ns(addr); if(n == nil) return n; n.looksrc(addr); } @defloc intvl() { return interval(0, endtstamp); } return chctl(intvl, scan, findret, mem, ctx, nsmap, _ns, dom, ldom, unwind, looksrc); } @define chronicle(cmd) { @local fds, buf, args, db; db = "/tmp/foo.db"; setenv("CHRONICLE_DB", db); args = copy(cmd); push(args, "--tool=chronicle"); push(args, chvalgrpath); fds = apply(popen, args); while(buf = read(fds[2], 1024)) // if(verbose) printf("*** %s", buf); while(buf = read(fds[1], 1024)) // if(verbose) printf("*** %s", buf); return mkchctl(db); } @define chronicledb(db) { @local exe; exe = mkchctl(db); exedom = exe.dom(1); return exe; } @define showlist(h) { printf("\tlist ="); while(h){ printf(" %d", h->v); h = h->next; } printf("\n"); } @define run(cmd) { @local exe, exedom, ts; /* ask chronicle for the execution */ exe = chronicle(cmd); exedom = exe.dom(1); /* scan execution for all calls to 'insert'. receive a list of timestamps -- instants at which first insn of 'insert' was executed. */ ts = exe.scan('exec, &exedom`insert); if(length(ts) == 0) error("no exec events for insert"); /* dump the list at time T location PTR */ @defloc dumplist(t, ptr) { @local as, dom; /* address space for time t */ as = exe.mem(t); /* domain for time t */ dom = mkdom(exedom.ns, as); showlist((Node*){dom}ptr); dumpstacklocs(exe, t); } /* find call and return points for calls to insert; dump argument and return value list */ @defloc dumpinsert(t) { @local ctx; @local rt; printf("enter at timestamp %d: ", t); ctx = exe.ctx(t); dumplist(t, ctx->rdi); rt = exe.findret(t); if(rt == nil) error("cannot find return time for %a\n", t); ctx = exe.ctx(rt); printf("leave at timestamp %d: ", rt); dumplist(rt, ctx->rax); } foreach(dumpinsert, ts); } /* expects to be run in l1 directory, with l1/demo directory build. */ @define runlist() { run(["demo/list"]); } @define runls() { chronicle(["/bin/ls"]); } rdsetfmt(@record interval { beg, end }, @lambda(r) { sprintfa("<@%d - @%d>", r.beg, r.end); }); @define viewl1gc() { @local exe, exedom, is, i0, cis; exe = chronicledb("/tmp/l1.db"); exedom = exe.dom(1); @defloc callintervals(i, func) { @local ts, rs; ts = exe.scan('exec, func, i.beg, i.end); if(length(ts) == 0) return []; rs = map(@lambda(t){ @local r; r = exe.findret(t); if(r == nil) error("cannot find return time for %a\n", t); return r; }, ts); return map(@lambda(t, r) { interval(t,r); }, ts, rs); } @defloc dumpinterval(i) { printf("@%-16d enter:\n", i.beg); dumpstack(exe, i.beg); printf("@%-16d leave:\n", i.end); dumpstack(exe, i.end); } is = callintervals(exe.intvl(), &exedom`_gc); printf("%d calls to _gc\n", length(is)); foreach(dumpinterval, is); return; /* copies in interval 0 */ if(length(is) < 1) error("out of moves"); i0 = is[0]; cis = callintervals(i0, &exedom`copy); printf("%d calls to copy in _gc interval 0\n", length(cis)); } @define getargs(exe, n, t) { @local ctx, rs, rv, i; ctx = exe.ctx(t); rv = []; rs = [ ctx->rdi, ctx->rsi, ctx->rdx, ctx->rcx, ctx->r8, ctx->r9 ]; i = 0; for(i = 0; i < n; i++) append(rv, pop(rs)); return rv; } @define showargs(exe, n, t) { @local args; args = getargs(exe, n, t); printf("args:"); foreach(@lambda(a) { printf(" %d", a); }, args); printf("\n"); } @define vkind(p) { p = (Head*)p; (p->bits>>1)&0x1f; } @define fmtval(p) { @local k; k = vkind(p); switch(k){ case 0: return ""; case 1: return "nil"; case 3: return sprintfa("box(%s)", fmtval(((Box*)p)->v)); case 4: return ""; case 6: return ""; case 9: return ""; case 19: return ""; case 20: return ""; case 8: p = (Cval*)p; return sprintfa("%d", p->v.u); case 15: return sprintfa("cons(%s, %s)", fmtval(xcar(p)), fmtval(xcdr(p))); default: return sprintfa("", k); } } @define xcar(p) { p = (Pair*)p; return p->car; } @define xcdr(p) { p = (Pair*)p; return p->cdr; } @define mtname(mt) { @local mts, rv; mts = [ 0 : "MThole", 8 : "MTnix", 16 : "MTfree", 48 : "MTdata", 56 : "MTode", 64 : "MTcode", 24 : "MTweak", 32 : "MTbox", 40 : "MTmutable", 50 : "MTbigdata", 58 : "MTbigode", 66 : "MTbigcode" ]; rv = mts[mt]; if(rv == nil) return sprintfa("undefined mt %d", mt); return rv; } @define genname(g) { @local gs; gs = ["G0", "G1", "G2", "G3", "Gstatic", "Gunused", "Glock"]; if(g >= length(gs)) return sprintfa("undefined gen %d", g); return gs[g]; } @define _fmtseg(s) { @local r, dom, o, a; dom = domof(s); if(s == 0) return "no segment!"; o = (Seg*)s-dom`segmap.map; a = dom`segmap.lo+o*Segsize; r = sprintfa("seg %p (%p-%p) %s %s", s, a, a+Segsize, genname(s->gen), mtname(s->mt)); return r; } @define a2s(a) { @local dom, segmap, o; dom = domof(a); segmap = &dom`segmap; o = ((void*)a-segmap->lo)/Segsize; return segmap->map+o; } @define fmtseg(p) { @local dom, segmap, o, s; dom = domof(p); segmap = &dom`segmap; o = ((void*)p-segmap->lo)/Segsize; s = segmap->map+o; return _fmtseg(s); } @define dumpguards(exe, t) { @local dom, H, i, p, o, k; dom = exe.dom(t); H = &dom`H; printf("@%d user guard list\n", t); for(i = 0; i < 4; i++){ p = H->ug.gd[i]; printf("gen %d user guard list:\n", i); while(vkind(p) != 1){ k = vkind(xcar(xcar(p))); printf("\t%p %d", p, k); printf(" %s", fmtseg(p)); if(k == 15){ o = xcar(xcar(p)); printf(" (object is %p pair(%d,%d))", o, vkind(xcar(o)), vkind(xcdr(o))); printf("\n"); } p = (Pair*)p->cdr; } } } @define callintervals(exe, i, func) { @local ts, rs; ts = exe.scan('exec, func, i.beg, i.end); if(length(ts) == 0) return []; rs = map(@lambda(t){ @local r; r = exe.findret(t); if(r == nil) error("cannot find return time for %a\n", t); return r; }, ts); return map(@lambda(t, r) { interval(t,r); }, ts, rs); } /* assume is is contained in iv */ @define invert(is, iv) { @local rv, b, e; b = iv.beg; e = iv.end; rv = []; foreach(@lambda(i){ if(i.beg < b) error("bug"); if(i.end > e) error("bug"); if(i.beg == b) b = i.end; else{ append(rv, interval(b, i.beg)); b = i.end; } }, is); if(b < e) append(rv, interval(b, e)); return rv; } @define clip(is, iv) { @local rv, b, e; b = iv.beg; e = iv.end; rv = []; foreach(@lambda(i){ /* draw a picture; there are six cases */ if(i.end <= b) return; if(i.beg >= e) return; if(i.beg >= b && i.end <= e) append(rv, i); else if(i.beg <= b && i.end >= e) append(rv, interval(b, e)); else if(i.beg <= b && i.end < e) append(rv, interval(b, i.end)); else if(i.beg < e && i.end >= e) append(rv, interval(i.beg, e)); else error("confusion"); }, is); return rv; } @define clipend(is, t) { @local rv; rv = []; foreach(@lambda(i){ if(i.beg > t) return; else if(i.end >= t) append(rv, interval(i.beg, t)); else append(rv, i); }, is); return rv; } @define clipbeg(is, t) { @local rv; rv = []; foreach(@lambda(i){ if(i.end <= t) return; if(i.beg < t) append(rv, interval(t, i.end)); else append(rv, i); }, is); return rv; } @define indexof(is, t) { @defloc loop(is, n) { @local iv; if(length(is) == 0) return nil; iv = pop(is); if(t >= iv.beg && t < iv.end) return n; loop(is, n+1); } loop(copy(is), 0); } rdsetfmt(@record copyevent { time, from, to }, @lambda(r) { sprintfa(" %p", r.time, r.from, r.to); }); rdsetfmt(@record malevent { time, addr }, @lambda(r) { sprintfa(" %p\n", c.time, ndx, c.from, c.to); // dumpstack(exe, c.time); // uncovercopy(exe, c); }else error("bug"); }, cs); } /* determine the future of the value at ADDR at time T */ @define valfuture(exe, addr, t) { @local exedom; @local gcs, copyt, rvs; exedom = exe.dom(1); /* find all intervals of gc execution */ gcs = callintervals(exe, exe.intvl(), &exedom`_gc); @defloc findcopy(addr, t) { @local is, wi; /* clip gc history to those up to T */ is = clipbeg(gcs, t); /* find next write to value header by a gc in forward order */ foreach(@lambda(gc){ @local ws; if(wi) return; /* shitty control logic */ ws = exe.scan('write, addr, sizeof(exedom`Head), gc.beg, gc.end); if(length(ws) == 0) return; if(length(ws) > 1){ printf("valfuture picking first of %d writes for %p in gc interval:\n", length(ws), addr); foreach(@lambda(w){ printf("@%d\n", w); dumpstack(exe, w); printf("\n"); }, ws); } wi = ws[0]; }, is); return wi; } rvs = []; while(copyt = findcopy(addr, t)){ @local fwd, ldom, ev; ldom = exe.ldom(copyt); fwd = ldom`nh; ev = copyevent(copyt, addr, fwd); append(rvs, ev); addr = fwd; t = copyt; } dumpvalpath(exe, rvs); return rvs; } /* determine the history of the value at ADDR at time T */ @define valhistory(exe, addr, t) { @local exedom; @local gcs; @local ev, evs, ms; @local orig, origt; exedom = exe.dom(1); /* find all intervals of gc execution */ gcs = callintervals(exe, exe.intvl(), &exedom`_gc); printf("%d calls to _gc\n", length(gcs)); @defloc findcopy(addr, t) { @local is, wi, copyt, ts, m, args, dom, p; /* clip gc history to those up to T */ is = clipend(gcs, t); /* find last write to value header by a gc in reverse order */ m = length(is); foreach(@lambda(gc){ @local ws; m--; if(wi) return; /* shitty control logic */ ws = exe.scan('write, addr, sizeof(exedom`Head), gc.beg, gc.end); if(length(ws) == 0) return; // printf("found %d writes to header for %p in gc %d\n", length(ws), addr, m); // printf("write at %-16d:\n", ws[0]); // dumpstack(exe, ws[0]); /* whack this interval to prevent detection of later write event to the from pointer */ gc.end = ws[0]; /* assume every write occurs in the context of a single call to copy; pick one */ wi = interval(gc.beg, ws[0]); }, reverse(is)); if(wi == nil) return nil; /* find the corresponding call to copy lower bound does not matter, but must include prefix of the gc interval */ ts = exe.scan('lastexec, &exedom`copy, wi.beg, wi.end); if(length(ts) != 1) error("no call event!"); copyt = ts[0]; args = getargs(exe, 1, copyt); dom = mkdom(exedom.ns, exe.mem(copyt)); p = (Val*){dom}args[0]; return copyevent(copyt, *p, addr); } evs = []; while(ev = findcopy(addr, t)){ append(evs, ev); addr = ev.from; t = ev.time; } evs = reverse(evs); if(length(evs) == 0){ orig = addr; origt = t; }else{ orig = evs[0].from; origt = evs[0].time; } /* now try to find the allocation event: the last write to the header prior to the first copy over the entire execution prefix */ ms = exe.scan('lastwrite, orig, sizeof(exedom`Head), 0, origt); if(length(ms) != 1) error("no original write event!"); push(evs, malevent(ms[0], orig)); printf("found mal event for %p\n", orig); dumpstack(exe, ms[0]); return evs; } @define viewl1() { @local exe, exedom, is, m, cs; exe = chronicledb("/tmp/gp.db"); exedom = exe.dom(1); m = 0; @defloc dumpinterval(i) { printf("#%-3d @%-16d enter:\n", m++, i.beg); showargs(exe, 2, i.beg); dumpstack(exe, i.beg); printf("@%-16d leave:\n", i.end); dumpstack(exe, i.end); } is = callintervals(exe, exe.intvl(), &exedom`_gc); printf("%d calls to _gc\n", length(is)); m = 0; foreach(@lambda(i){ printf("\t#%d @%d - @%d", m++, i.beg, i.end); showargs(exe, 2, i.beg); }, is); @defloc guardsover(i) { printf("guards over #%3d @%-16d - @%-16d:\n", i, is[i].beg, is[i].end); dumpguards(exe, is[i].beg); printf("\n"); dumpguards(exe, is[i].end); } // guardsover(4); // guardsover(5); cs = valhistory(exe, 0x7500048, is[4].end); foreach(@lambda(c){ @local ndx; if(ismalevent(c)) printf("@%d mal %p\n", c.time, c.addr); else if(iscopyevent(c)){ ndx = indexof(is, c.time); printf("@%d (gc #%d) copy %p -> %p\n", c.time, ndx, c.from, c.to); }else error("bug"); }, cs); } @define lookinterval(is, t) { @local i, iv, m; m = length(is); for(i = 0; i < m; i++){ iv = is[i]; if(t < iv.beg) continue; if(t >= iv.beg && t < iv.end) return iv; if(t >= iv.end) continue; } return nil; } /* this function assumes the intervals are disjoint */ @define mergeivs(as, bs) { @local rv, a, b; as = copy(as); bs = copy(bs); rv = []; a = pop(as); b = pop(bs); while(a && b){ if(a.beg < b.beg){ append(rv, a); a = pop(as); }else{ append(rv, b); b = pop(bs); } } while(a){ append(rv, a); a = pop(as); } while(b){ append(rv, b); b = pop(bs); } return rv; } @define stackat(t) { @local ndx; if(exe == nil) error("no exe defined"); if(gcs != nil) ndx = indexof(gcs, t); printf("@%d", t); if(ndx != nil) printf(" gc #%d", ndx); printf("\n"); dumpstack(exe, t); } @define gcintervals(exe) { @local whole, exedom, is; exedom = exe.dom(1); whole = exe.intvl(); is = callintervals(exe, whole, &exedom`_gc); return is; } @define gcsummary(exe) { @local is, m; is = gcintervals(exe); printf("%d calls to _gc\n", length(is)); m = 0; foreach(@lambda(i){ printf("\t#%d @%d - @%d ", m++, i.beg, i.end); showargs(exe, 2, i.beg); }, is); gcs = is; return nil; } @define foreachgc(exe, beg, end) { @local whole, exedom, is, m; exedom = exe.dom(1); whole = exe.intvl(); is = callintervals(exe, whole, &exedom`_gc); printf("%d calls to _gc\n", length(is)); m = 0; foreach(@lambda(i){ printf("\t#%d @%d - @%d ", m++, i.beg, i.end); showargs(exe, 2, i.beg); if(beg){ printf("\t@%d:\n", i.beg); beg(exe, i.beg); } if(end){ printf("\t@%d:\n", i.end); end(exe, i.end); printf("\n"); } }, is); } @define badwrites(exe) { @local whole; @local nfs, fss, frs; @local inits, finis, window, unstable, stable, m; @local exedom; exedom = exe.dom(1); whole = exe.intvl(); /* critical sections on free list */ nfs = callintervals(exe, whole, &exedom`nextfree); fss = callintervals(exe, whole, &exedom`freeseg); frs = callintervals(exe, whole, &exedom`freerange); unstable = mergeivs(nfs, mergeivs(fss, frs)); printf(" %3d calls to nextfree\n", length(nfs)); printf(" %3d calls to freeseg\n", length(fss)); printf(" %3d calls to freerange\n", length(frs)); printf("= %3d calls to segment free list critical sections\n", length(unstable)); /* define window to search: from return of initmem to return of finimem */ inits = callintervals(exe, whole, &exedom`initmem); finis = callintervals(exe, whole, &exedom`finimem); if(length(inits) != 1 || length(finis) != 1) error("non-standard l1 execution"); window = interval(inits[0].end, finis[0].end); /* subdivide window into intervals where free list is constant */ stable = invert(clip(unstable, window), window); printf("%d stable intervals in window\n", length(stable)); /* look for writes into free segments during any of these intervals */ /* helper: extract list of free segments at time T */ @defloc freesegs(t) { @local dom, f, rs, sz; rs = []; dom = exe.dom(t); sz = 1ULL<<20; f = dom`segmap.free; while(f){ append(rs, mkrange(f, sz)); f = *(void**)f; } return rs; } m = 0; foreach(@lambda(s){ @local ws, fs; fs = freesegs(s.beg); printf("stable interval #%3d (%010d - %010d) %d free segments\n", m, s.beg, s.end, length(fs)); foreach(@lambda(f){ ws = exe.scan('write, rangebeg(f), rangelen(f), s.beg, s.end); foreach(@lambda(w){ printf("\t@%d write into free segment %016p-%016p\n", w, rangebeg(f), rangebeg(f)+rangelen(f)); }, ws); }, fs); m++; }, stable); } /* given a copy event, find the object it was scanned from. */ @define uncovercopy(exe, ctime) { @local exedom, ts, callt, scant, ldom, ctx, sym; exedom = exe.dom(1); /* who called us? */ ts = exe.scan('lastexec, &exedom`copy, 0, ctime); if(length(ts) != 1) error("cannot find call to copy!"); callt = ts[0]-1; printf("copy was called @%d\n", callt); dumpstack(exe, callt); ctx = exe.ctx(callt); sym = exedom.ns.lookaddr(ctx->pc); if(symid(sym) == 'scan1){ printf("it's a scan1 call!\n"); ts = exe.scan('lastexec, &exedom`scan1, 0, callt); if(length(ts) != 1) error("cannot find call to scan1"); scant = ts[0]-1; ldom = exe.ldom(scant); printf("object was encountered while scanning %p %s\n", ldom`h, fmtval(ldom`h)); /* really want to bound this to the current gc */ ts = exe.scan('lastwrite, ldom`h, sizeof(exedom`Head), 0, scant); if(length(ts) != 1) error("cannot find previous write"); printf("header for object %p was last written @%d\n", ldom`h, ts[0]); uncovercopy(exe, ts[0]); }else printf("it's a %s call!\n", symid(sym)); } @define ptr(exe, addr, t) { @local exedom; exedom = exe.dom(t); return (void*){exedom}addr; } /* dump the gc locked segments */ @define dumplocked(exe, t) { @local dom, s, es, p; dom = exe.dom(t); s = a2s(dom`segmap.lo); es = a2s(dom`segmap.hi); while(s < es){ if(s->gen == dom`Glock){ printf("\tlocked segment %p\n", s); p = s->p; while(p){ @local o; o = xcdr(xcar(p)); printf("\t\t%p %s\n", o, fmtval(o)); p = xcdr(p); } } s++; } } testdb = "/tmp/gp.db"; bugdb = "/home/vic/src/l1.bug/lock.bug.db"; nobugdb = "/home/vic/src/l1.bug/lock.nobug.db"; @define viewlock() { @local exe, exedom, is, m, cs; exe = chronicledb(bugdb); exedom = exe.dom(1); @defloc dumpinterval(i) { printf("#%-3d @%-16d enter:\n", m++, i.beg); showargs(exe, 2, i.beg); dumpstack(exe, i.beg); printf("@%-16d leave:\n", i.end); dumpstack(exe, i.end); } is = callintervals(exe, exe.intvl(), &exedom`_gc); printf("%d calls to _gc\n", length(is)); m = 0; foreach(@lambda(i){ printf("\t#%d @%d - @%d ", m++, i.beg, i.end); showargs(exe, 2, i.beg); }, is); @defloc dumpgcend(n) { printf("at the end of gc #%d:\n", n); dumplocked(exe, is[n].end); printf("\n"); } dumpgcend(5); dumpgcend(6); dumpgcend(7); cs = valfuture(exe, 0x9200024, is[5].end); foreach(@lambda(c){ @local ndx; if(ismalevent(c)) printf("@%d mal %p\n", c.time, c.addr); else if(iscopyevent(c)){ ndx = indexof(is, c.time); printf("@%d (gc #%d) copy %p -> %p\n", c.time, ndx, c.from, c.to); dumpstack(exe, c.time); uncovercopy(exe, c); }else error("bug"); }, cs); } @define chbench() { @local exe, mals, lim; lim = 1000000; /* any l1 execution with at least LIM mal events. l1.simple.db is l1 repl start to end on EOF input */ resetstats(); exe = chronicledb("../l1.debug/l1.simple.db"); @defloc calls() { mals = exe.scan('exec, &exedom`__mal, 0, lim); } @defloc rets() { map(@lambda(t) { exe.findret(t); }, mals); } resetstats(); xtime('calls, calls); printf("\ntime (usec) for __mal call events before time %d; got %d events\n", lim, length(mals)); summarizetime('calls); printf("\n"); resetstats(); xtime('rets, rets); printf("time (usec) for corresponding ret events\n"); summarizetime('rets); printf("%d usec per event\n", stats['rets]/length(mals)); printf("\n"); } /* eval-based json2val: u% ./l1 ; @include /u/vic/src/l1/lib/ch.cqct:1412: warning: variable defined but not referenced: guardsover /u/vic/src/l1/lib/ch.cqct:1394: warning: variable defined but not referenced: dumpinterval /u/vic/src/l1/lib/ch.cqct:1689: warning: variable defined but not referenced: dumpinterval ; chbench(); 0x0000000000000000 /u/vic/src/l1.debug/l1 0x0000000004000000 /lib/ld-2.11.1.so 0x0000000004c24000 /lib/libc-2.11.1.so end timestamp: 684378287 time (usec) for __mal call events before time 1000000; got 2214 events strstr 6606 ( 0.77%) json2val 801344 ( 93.80%) readscan 2742 ( 0.32%) lbread 26849 ( 3.14%) substr 2724 ( 0.32%) val2json 8714 ( 1.02%) calls 854303 (100.00%) time (usec) for corresponding ret events lbread 15619983 ( 81.84%) val2json 386641 ( 2.03%) substr 8421 ( 0.04%) readfindSPGreaterThan 8836139 ( 46.30%) ctx 8653180 ( 45.34%) findSP 10401696 ( 54.50%) strstr 28624 ( 0.15%) readreadReg 6638946 ( 34.79%) json2val 2897998 ( 15.18%) rets 19085313 (100.00%) 8620 usec per event jsmn-based json2val: u% l1 ; @include /u/vic/src/l1/lib/ch.cqct:1412: warning: variable defined but not referenced: guardsover /u/vic/src/l1/lib/ch.cqct:1394: warning: variable defined but not referenced: dumpinterval /u/vic/src/l1/lib/ch.cqct:1689: warning: variable defined but not referenced: dumpinterval ; chbench(); 0x0000000000000000 /u/vic/src/l1.debug/l1 0x0000000004000000 /lib/ld-2.11.1.so 0x0000000004c24000 /lib/libc-2.11.1.so end timestamp: 684378287 time (usec) for __mal call events before time 1000000; got 2214 events lbread 35011 ( 44.69%) json2val 23615 ( 30.14%) val2json 208 ( 0.27%) readscan 2910 ( 3.71%) substr 2217 ( 2.83%) strstr 5746 ( 7.33%) calls 78339 (100.00%) time (usec) for corresponding ret events readfindSPGreaterThan 9078711 ( 52.47%) readreadReg 7327410 ( 42.34%) strstr 29191 ( 0.17%) ctx 7791783 ( 45.03%) json2val 70169 ( 0.41%) val2json 504402 ( 2.91%) lbread 16554244 ( 95.67%) substr 7974 ( 0.05%) findSP 9486270 ( 54.82%) rets 17304232 (100.00%) 7815 usec per event */