Bug 496448: check in python scripts for TraceVis, r=brendan

js/src/tracevis/README

@@ -0,0 +1,37 @@
+This directory contains TraceVis scripts.
+
+
+To use TraceVis:
+
+- Currently it can only be used with the JavaScript shell 'js', not within
+  Firefox.
+
+- Configure using --enable-tracevis.
+
+- If running your program from the command line, use the -T option, i.e.:
+
+    js -j -T <tracevis-file> foo.js
+  
+- If running your programs within the interactive shell, use the
+  startTraceVis() and stopTraceVis() functions to turn TraceVis recording on
+  and off.  startTraceVis() takes an optional parameter which is the name of
+  the file to write the TraceVis output to;  if unspecified, the name
+  defaults to 'tracevis.dat' in the current directory.
+
+- To view the recorded data in graphical form, run:
+
+    python vis.py <tracevis-file> <png-file>
+
+  The graph will be written to the file <png-file> in PNG format.
+
+- To view some basic data about the recorded data, run:
+
+    python binlog.py <tracevis-file>
+
+
+TODO list:
+
+- Make the Python scripts more robust, e.g. handle file opening failures
+  gracefully.
+
+- Make it usable within Firefox.

js/src/tracevis/acts.py

@@ -0,0 +1,54 @@
+# Define JS engine activities
+
+# This must match the C++ enum used by the engine instrumentation patch:
+# For each int value of the enum, there should be a corresponding
+# element in this list with an appropriate name.
+states = [
+    'exitlast',
+    'interpret',
+    'monitor',
+    'record',
+    'compile',
+    'execute',
+    'native',
+]
+
+# Must match C++ enum
+reasons = [
+    'none',
+    'abort',
+    'inner',
+    'doubles',
+    'callback',
+    'anchor',
+    'backoff',
+    'cold',
+    'record',
+    'peers',
+    'execute',
+    'stabilize',
+    'extendFlush',
+    'extendMaxBranches',
+    'extendStart',
+    'extendCold',
+    'extendOuter',
+    'mismatchExit',
+    'oomExit',
+    'overflowExit',
+    'timeoutExit',
+    'deepBailExit',
+    'statusExit',
+    'otherExit',
+    # Special stuff that doesn't match C++
+    'start',
+]
+
+# Estimated speedup vs. the interpreter when doing a given activity.
+# Activities not listed default to 0.
+speedup_d = {
+    'interpret': 1.0,
+    'record': 0.95,
+    'native': 2.5
+}
+
+speedups = [ speedup_d.get(name, 0) for name in states ]

js/src/tracevis/binlog.py

@@ -0,0 +1,194 @@
+# Parse the binary log file of activity timings.
+#
+# If run as a script, print a summary of the log, giving the total
+# time in each activity.
+
+import sys
+import struct
+
+from config import *
+from acts import *
+
+def unpack(raw):
+    for i in range(0, len(raw), 8):
+        ull = struct.unpack_from('Q', raw, i)[0]
+        s = (ull >> 60) & 0xf
+        r = (ull >> 55) & 0x1f
+        t = ull & ~(0x1ff << 55)
+        yield s, r, t
+
+def parse_input(filename):
+    f = open(filename)
+    raw = f.read()
+    return unpack(raw)
+
+class TimeCount(object):
+    def __init__(self):
+        self.t = 0
+        self.t2 = 0
+        self.ta = 1e30
+        self.tz = -1e30
+        self.n = 0
+
+    def add(self, dt):
+        self.t += dt
+        self.t2 += dt*dt
+        self.n += 1
+        if dt < self.ta:
+            self.ta = dt
+        if dt > self.tz:
+            self.tz = dt
+
+class StackPoint(object):
+    def __init__(self, s, r, t):
+        self.s = s
+        self.r = r
+        self.t = t
+
+class TimePoint(object):
+    """Transition from state s0 to s1 at time t."""
+    def __init__(self, t, r, s0, s1):
+        self.t = t
+        self.r = r
+        self.s0 = s0
+        self.s1 = s1
+
+class History(object):
+    def __init__(self):
+        self.state_summary = [ 0 ] * len(states)
+        self.stack = None
+        self.init()
+
+    def init(self):
+        pass
+
+    def record(self, t, r, s0, s1):
+        pass
+
+    def goto(self, s0, t0, s1, r, t1):
+        dt = t1 - t0
+        self.state_summary[s0] += dt
+        self.record(t1, r, s0, s1)
+
+    def enter(self, s, r, t):
+        if self.stack is None:
+            self.stack = [ StackPoint(0, 0, t) ]
+        sp = self.stack[-1]
+        self.goto(sp.s, sp.t, s, r, t)
+        self.stack.append(StackPoint(s, r, t))
+
+    def exit(self, r, t):
+        sp = self.stack.pop()
+        osp = self.stack[-1]
+        self.goto(sp.s, sp.t, osp.s, r, t)
+        osp.t = t
+        osp.r = r
+
+class FullHistory(History):
+    def init(self):
+        self.timeline = []
+
+    def record(self, t1, r, s0, s1):
+        self.timeline.append(TimePoint(t1, r, s0, s1))
+        
+def collect(ts, full=False):
+    if full:
+        cls = FullHistory
+    else:
+        cls = History
+    h = cls()
+
+    for s, r, t in ts:
+        #if t < 1160909415950669-877953307: continue
+        #if t > 1160909415950669: break
+        if s:
+            h.enter(s, r, t)
+        else:
+            h.exit(r, t)
+
+    #assert len(h.stack) == 1
+    #assert sum(h.state_summary) == ts[-1][2] - ts[0][2]
+    return h
+
+reason_cache = {}
+
+def getreason(hist, i):
+    ans = None
+    while True:
+        p0 = hist.timeline[i]
+        r = p0.r
+        if r:
+            ans = reasons[r]
+            break
+
+        if not p0.s0:
+            ans = 'start'
+            break
+
+        name = states[p0.s0]
+        if name != 'interpret':
+            ans = name
+            break
+
+        i -= 1
+        r = reason_cache.get(i)
+        if r:
+            ans = r
+            break
+    reason_cache[i] = ans
+    return ans
+
+def summary(hist):
+    ep = 0       # estimated progress
+
+    print 'Activity duration summary:'
+    print
+    cycles = hist.state_summary
+    for sn, cyc, xf in zip(states, cycles, speedups):
+        if sn == 'exitlast': continue
+        ep += xf * cyc
+        print '%-12s %12.6f'%(sn, cyc/CPU_SPEED * 1000)
+    print '-'*25
+    print '%-12s %12.6f'%('Subtotal', sum(cycles[1:])/CPU_SPEED * 1000)
+    print '%-12s %12.6f'%('Non-JS', cycles[0]/CPU_SPEED * 1000)
+    print '='*25
+    print '%-12s %12.6f'%('Total', sum(cycles)/CPU_SPEED * 1000)
+
+    print 'Estimated speedup:  %.2fx'%(ep/sum(cycles[1:]))
+
+    print
+    print 'Reasons for transitions to interpret:'
+    xd = {}
+    for i in range(len(hist.timeline)-1):
+        p0 = hist.timeline[i]
+        if states[p0.s1] == 'interpret':
+            p1 = hist.timeline[i+1]
+            name = getreason(hist, i)
+            x = xd.get(name)
+            if not x:
+                x = xd[name] = TimeCount()
+            x.add(p1.t - p0.t)
+    print '%-12s %12s %8s %12s %12s %12s'%(
+        'Reason', 'sum (ms)', 'N', 'mean (us)', 'min (us)', 'max (us)')
+    for name, x in sorted(xd.items(), key=lambda p: -p[1].t):
+        if not x.n: continue
+        print '%-12s %12.3f %8d %12.3f %12.3f %12.3f'%(
+            name, 
+            x.t/CPU_SPEED*1000, 
+            x.n, 
+            x.t/CPU_SPEED*1000000/x.n,
+            x.ta/CPU_SPEED*1000000,
+            x.tz/CPU_SPEED*1000000
+            )
+        
+
+if __name__ == '__main__':
+    if len(sys.argv) <= 1:
+        print >> sys.stderr, "usage: python binlog.py infile"
+        sys.exit(1);
+
+    print sys.argv[0]
+    print sys.argv[1]
+
+    filename = sys.argv[1]
+    summary(collect(parse_input(filename), True))

js/src/tracevis/config.py

@@ -0,0 +1,5 @@
+# Local machine configuration.
+
+# CPU speed in clock cycles per second
+CPU_SPEED = 2.2e9
+

js/src/tracevis/vis.py

@@ -0,0 +1,152 @@
+import sys
+import Image, ImageDraw, ImageFont
+
+from config import *
+from acts import *
+from binlog import parse_input, collect
+
+BLACK = (0, 0, 0)
+font = ImageFont.load_default()
+
+states = [
+    (0, 0, 0),
+    (225, 225, 225), #(170, 20, 10),
+    (225, 30, 12),
+    (140, 0, 255),
+    (0, 0, 255),
+    (180, 180, 30),
+    (0, 160, 30),
+]
+
+timeslices_ms = [
+    1, 2, 5, 10, 20, 50, 100, 200, 500, 1000, 2000, 5000, 10000 ]
+
+def parse(filename):
+    return collect(parse_input(filename), True)
+
+def run(filename, outfile):
+    W, H, HA, HB = 1600, 256, 64, 64
+    HZ = H + 4 + HA + 4 + HB
+    im = Image.new('RGBA', (W, HZ + 20))
+    d = ImageDraw.Draw(im)
+
+    hist = parse(filename)
+
+    t0 = hist.timeline[0].t
+    ts = []
+    for x in hist.timeline:
+        ts.append((x.s0, x.t-t0))
+
+    # Filter
+    if 0:
+        a, b = 10*2.2e9, 12*2.2e9
+        ts = [(s, t-a) for s, t in ts if a <= t <= b ]
+    total = ts[-1][1] - ts[0][1]
+    total_ms = total / CPU_SPEED * 1000
+
+    pp = 1.0 * total / (W*H)
+    pc_us = 1.0 * total / CPU_SPEED / W * 1e6
+    print "Parsed %d items, t=%f, t/pixel=%f, t0=%d"%(len(ts), total/CPU_SPEED, pp/CPU_SPEED*1000, hist.timeline[0].t)
+
+    d.rectangle((0, H + 4, W, H + 4 + HA), (255, 255, 255))
+
+    eps = []
+
+    # estimated progress
+    ep = 0
+
+    ti = 0
+    for i in range(W*H):
+        t0 = pp * i
+        t1 = t0 + pp
+        color = [ 0, 0, 0 ]
+        tx = t0
+        while ti < len(ts):
+            q = (min(ts[ti][1], t1)-tx)/pp
+            c = states[ts[ti][0]]
+            color[0] += q * c[0]
+            color[1] += q * c[1]
+            color[2] += q * c[2]
+            ep += q * speedups[ts[ti][0]]
+            if ts[ti][1] > t1:
+                break
+            tx = ts[ti][1]
+            ti += 1
+        
+        color[0] = int(color[0])
+        color[1] = int(color[1])
+        color[2] = int(color[2])
+
+        d.point((i/H, i%H), fill=tuple(color))
+
+        if i % H == H - 1:
+            eps.append(ep)
+            ep = 0
+
+    epmax = 2.5*H
+
+    d.line((0, H+4+HA-1.0*H/epmax*HA, W,  H+4+HA-1.0*H/epmax*HA), fill=(192, 192, 192))
+    d.line((0, H+4+HA-2.5*H/epmax*HA, W,  H+4+HA-2.5*H/epmax*HA), fill=(192, 192, 192))
+
+    last = None
+    for i in range(W):
+        n = 0
+        sm = 0
+        for j in range(max(0, i-3), min(W-1, i+3)):
+            sm += eps[j]
+            n += 1
+        ep = sm / n
+
+        ep_scaled = 1.0 * ep / epmax * HA
+        px = (i, H + 4 + HA - int(ep_scaled))
+        if last:
+            d.line((px, last), fill=(0, 0, 0))
+        last = px
+        #d.point((i, H + 4 + HA - int(ep_scaled)), fill=(0, 0, 0))
+
+    t = 0
+    ppt = 1.0 * W / total
+    for dt, c in zip(hist.state_summary, states):
+        x1 = int(t * ppt)
+        y1 = H + 4 + HA + 5 
+        x2 = int((t+dt) * ppt)
+        y2 = H + 4 + HA + 4 + HB
+        d.rectangle((x1, y1, x2, y2), fill=c)
+        t += dt
+
+    # Time lines
+    i = 0
+    while i < len(timeslices_ms):
+        divs = total_ms / timeslices_ms[i]
+        if divs < 15: break
+        i += 1
+    timeslice = timeslices_ms[i]
+    t = timeslice
+    c = (128, 128, 128)
+    while t < total_ms:
+        x = t / total_ms * W
+        y = 0
+        while y < HZ:
+            d.line((x, y, x, y + 8), fill=c)
+            y += 12
+        text = '%d ms'%t
+        w, h = font.getsize(text)
+        d.text((x-w/2, HZ), text, fill=BLACK, font=font)
+        t += timeslice
+
+    d.text((0, HZ), '[%.1fus]'%pc_us, fill=BLACK)
+
+    im.save(outfile, "PNG")
+
+if __name__ == '__main__':
+    if len(sys.argv) <= 2:
+        print >> sys.stderr, "usage: python vis.py infile outfile"
+        sys.exit(1);
+
+    filename = sys.argv[1]
+    outfile  = sys.argv[2]
+    if not outfile.endswith('.png'):
+        print >> sys.stderr, "warning: output filename does not end with .png; output is in png format."
+
+    run(filename, outfile)
+