Last active
October 10, 2019 12:34
-
-
Save mgedmin/4321416 to your computer and use it in GitHub Desktop.
Visualize a Zope trace.log with d3.js
This file contains hidden or bidirectional Unicode text that may be interpreted or compiled differently than what appears below. To review, open the file in an editor that reveals hidden Unicode characters.
Learn more about bidirectional Unicode characters
| #!/usr/bin/python3 | |
| """ | |
| Show recent requests on a timeline | |
| Parses a ZServer trace.log file. The format is documented at | |
| https://pypi.python.org/pypi/zc.zservertracelog | |
| """ | |
| import json | |
| import re | |
| import os | |
| import optparse | |
| import subprocess | |
| import datetime | |
| from time import mktime | |
| __version__ = '1.3.0' | |
| __url__ = 'https://gist.github.com/mgedmin/4321416' | |
| __author__ = 'Marius Gedminas <[email protected]>' | |
| __licence__ = 'GPL' # or ask me for MIT | |
| D3_URL = 'https://d3js.org/d3.v2.js' | |
| TEMPLATE = r""" | |
| <html> | |
| <head> | |
| <title>Request timeline</title> | |
| <!-- generated by scripts/timeline --> | |
| <script src="{d3url}"></script> | |
| <meta charset="UTF-8" /> | |
| <style type="text/css"> | |
| .chart { | |
| font: 10px sans-serif; | |
| shape-rendering: crispEdges; | |
| cursor: pointer; | |
| } | |
| .chart rect.input { | |
| fill: green; | |
| } | |
| .chart rect.waiting { | |
| fill: yellow; | |
| } | |
| .chart rect.running { | |
| fill: orange; | |
| } | |
| .chart rect.running2 { | |
| fill: red; | |
| } | |
| .chart rect.running3 { | |
| fill: orange; | |
| } | |
| .chart rect.running4 { | |
| fill: red; | |
| } | |
| .chart rect.postcommit { | |
| fill: violet; | |
| } | |
| .chart rect.output { | |
| fill: blue; | |
| } | |
| .chart text.bar { | |
| fill: white; | |
| overflow: hidden; | |
| } | |
| .controls a { | |
| cursor: pointer; | |
| padding: 5px; | |
| background: #eee; | |
| color: black; | |
| text-decoration: none; | |
| } | |
| .controls a:hover, | |
| .controls a:active, | |
| .controls a:focus { | |
| background: steelblue; | |
| color: white; | |
| } | |
| </style> | |
| </head> | |
| <body> | |
| <p class="controls"> | |
| <a href="" id="zoom-out">Zoom out</a> | |
| <a href="" id="zoom-in">Zoom in</a> | |
| <a href="" id="zoom-start">First 1s</a> | |
| <a href="" id="zoom-end-15">Last 15 min</a> | |
| <a href="" id="zoom-end-5">Last 5 min</a> | |
| <a href="" id="zoom-full">Full range</a> | |
| <span id="scale-text"></span> | |
| </p> | |
| <div id="chart"></div> | |
| <script> | |
| {data} | |
| // subtract 24 for the scrollbar | |
| var fullWidth = d3.select('#chart')[0][0].clientWidth - 24; | |
| var fullHeight = 800; | |
| var padding = {x: 0, y: 0}; | |
| var width = fullWidth - 2 * padding.x; | |
| var height = fullHeight - 2 * padding.y; | |
| var n_ticklines = 10; | |
| var stagger = 1; // try 2 or 3 to see the effect | |
| var label_height = 10; | |
| var x_axis_height = 20 + label_height * stagger; | |
| var y_axis_width = 40; | |
| var bar_height = 20; | |
| // range of the data | |
| var tmin = d3.min(data, function(d) { return d.start; }); | |
| var tmax = d3.max(data, function(d) { return d.stop; }); | |
| // the peculiar rounding is optimized to show 1 second of data with the | |
| // first request somewhere in the 1st quarter of the screen, with the ticks | |
| // aligned to 100ms | |
| var t0 = Math.round((tmin - 0.25) * 10) / 10; | |
| var tMAX = Math.floor(tmax + 1); | |
| var max_level = d3.max(data, function(d) { return d.level; }); | |
| // initial zoom level: show 1 second of data | |
| // this will be overridden very very soon to show the full range | |
| var t1 = t0 + 1; | |
| // TODO: figure out d3.time.scale maybe, for smarter tickline alignment | |
| var x = d3.scale.linear() | |
| .domain([t0, t1]) | |
| .range([0, width - y_axis_width]); | |
| var x0 = x.copy(); // because either d3.behavior.zoom is dumb or I am | |
| var y = d3.scale.linear() | |
| .domain([0, max_level]) | |
| .range([0, bar_height*max_level]); | |
| // let me tell you a secret: I don't grok svg | |
| var svg = d3.select('#chart').append('svg') | |
| .attr('class', 'chart') | |
| .attr('width', fullWidth) | |
| .attr('height', fullHeight) | |
| var vis = svg.append('g') | |
| .attr("transform", "translate(" + padding.x + "," + padding.y + ")") | |
| // big background so I can drag things | |
| var plot = vis.append('rect') | |
| .attr('width', width) | |
| .attr('height', height) | |
| .attr('pointer-events', 'all') | |
| .style('fill', '#fff') | |
| // or maybe | |
| //.attr('visibility', 'hidden') | |
| // separate groups so tick lines always appear behind bars | |
| var axes = vis.append('g') | |
| svg.append('clipPath').attr('id', 'clip').append('rect') | |
| .attr("x", 0) | |
| .attr("y", 0) | |
| .attr("width", width - y_axis_width) | |
| .attr("height", height) | |
| svg.append('clipPath').attr('id', 'level_clip').append('rect') | |
| .attr("x", 0) | |
| .attr("y", x_axis_height) | |
| .attr("width", width) | |
| .attr("height", height) | |
| var chart = vis.append('g') | |
| .attr("transform", "translate(" + 0 + "," + x_axis_height + ")") | |
| .attr('clip-path', 'url(#clip)') | |
| function describe_seconds(s) { | |
| if (s < 1) | |
| return Math.round(s * 1000) + 'ms'; | |
| else if (s < 60) | |
| return Math.round(s) + 's'; | |
| else if (s < 60 * 60) | |
| return Math.round(s / 60) + ' min'; | |
| else if (s < 60 * 60 * 24) { | |
| var n = Math.round(s / 60 / 60); | |
| return n == 1 ? '1 hour' : n + ' hours'; | |
| } else { | |
| var n = Math.round(s / 60 / 60 / 24); | |
| return n == 1 ? '1 day' : n + ' days'; | |
| } | |
| } | |
| // Scale conversion: 1px represents how many seconds? | |
| function px_to_s(px) { | |
| return x.invert(px) - x.invert(0); | |
| } | |
| function describe_scale() { | |
| var arr = x.ticks(n_ticklines), px, s; | |
| if (arr.length >= 2) { | |
| var first = arr[0], last = arr[arr.length-1]; | |
| px = Math.round((x(last) - x(first)) / (arr.length-1)); | |
| s = (last - first) / (arr.length-1); | |
| } else { | |
| px = width; | |
| s = px_to_s(px); | |
| } | |
| var full_range = x.domain()[1] - x.domain()[0]; | |
| return px + 'px = ' + describe_seconds(s) + | |
| ', full range shown: ' + describe_seconds(full_range) + | |
| '. All times are UTC.'; | |
| } | |
| function redraw() { | |
| // draw ticklines and labels | |
| var ticks = axes.selectAll("line").data(x.ticks(n_ticklines)) | |
| ticks.enter().append("line") | |
| .attr("y1", x_axis_height - 5) | |
| .attr("y2", height) | |
| .style("stroke", "#ccc") | |
| ticks | |
| .attr("x1", x) | |
| .attr("x2", x) | |
| ticks.exit().remove() | |
| var dates = axes.selectAll(".date").data(x.ticks(n_ticklines)) | |
| dates.enter().append("text") | |
| .attr("class", "date") | |
| .attr("dy", x_axis_height - label_height) | |
| .attr("text-anchor", "middle") | |
| .style('fill', '#444') | |
| dates | |
| .attr("x", x) | |
| .attr("y", function(t, i) { return label_height * (i % stagger - stagger); }) | |
| .text(function(t) { | |
| var d = new Date(t*1000); | |
| return d.toISOString().slice(0, 10); // YYYY-MM-DD | |
| }) | |
| dates.exit().remove() | |
| var times = axes.selectAll(".time").data(x.ticks(n_ticklines)) | |
| times.enter().append("text") | |
| .attr("class", "time") | |
| .attr("dy", x_axis_height) | |
| .attr("text-anchor", "middle") | |
| .style('fill', '#888') | |
| times | |
| .attr("x", x) | |
| .attr("y", function(t, i) { return label_height * (i % stagger - stagger); }) | |
| .text(function(t) { | |
| var d = new Date(t*1000); | |
| return d.toISOString().slice(11, -1); // HH:MM:SS.sss | |
| }) | |
| times.exit().remove() | |
| // draw level names | |
| var levels = axes.selectAll(".level").data(y.ticks(max_level)) | |
| levels.enter().append("text") | |
| .attr("class", "level") | |
| .style('fill', '#888') | |
| .attr("dx", 10) | |
| .attr("dy", x_axis_height + bar_height / 2 + 2) | |
| .attr('clip-path', 'url(#level_clip)') | |
| levels | |
| .attr("x", width - y_axis_width) | |
| .attr("y", y) | |
| .text(function(l) { return l <= max_level ? l + 1 : ""; }) | |
| levels.exit().remove() | |
| // draw request bars | |
| var bars = chart.selectAll('rect').data(data) | |
| bars.enter().append('rect') | |
| .attr('height', bar_height - 1) | |
| .attr('class', function(d) { | |
| return d.state + ' ' + (d.value.slice(0, 3) == 'GET' ? 'get' : 'post'); }) | |
| .append('title') | |
| .text(function(d) { return d.value + "\n" + d.duration + ' ' + d.state; }) | |
| bars | |
| .attr('x', function(d) { return x(d.start); }) | |
| .attr('y', function(d) { return y(d.level); }) | |
| .attr('width', function(d) { return Math.max(1, x(d.stop)-x(d.start)); }) | |
| bars.exit().remove() | |
| // update scale text | |
| d3.select('#scale-text').text(describe_scale()) | |
| // make sure drag events are registered on newly added bars and labels | |
| chart.call(zoomer); | |
| axes.call(zoomer); | |
| } | |
| var prev_scale = null, prev_translate; | |
| function zoom() { | |
| // don't adjust y scale on mouse wheel zoom | |
| if (prev_scale != null && (prev_scale != d3.event.scale | |
| || prev_scale == zoomer.scaleExtent()[0] | |
| || prev_scale == zoomer.scaleExtent()[1])) { | |
| // XXX this check breaks down when we reach maximum/minimum scale: | |
| // we can either disable panning or suffer unexpected jumps | |
| // when mouse wheel reaches max zoom. Let's disable panning. | |
| d3.event.translate[1] = prev_translate[1]; | |
| } | |
| prev_scale = d3.event.scale; | |
| prev_translate = d3.event.translate; | |
| // make sure the y axis doesn't scale | |
| var first_bar = -Math.round(d3.event.translate[1] / bar_height); | |
| first_bar = Math.max(0, Math.min(first_bar, max_level)) | |
| zoomer.translate([d3.event.translate[0], -first_bar * bar_height]); | |
| y.domain([first_bar, first_bar + max_level]) | |
| .range([0, bar_height*max_level]) | |
| redraw() | |
| } | |
| var zoomer = d3.behavior.zoom().x(x).y(y).on("zoom", zoom); | |
| zoomer.scaleExtent([1e-8, 10]); // from ~3 years down to ~1 ms | |
| plot.call(zoomer); | |
| function get_zoom() { | |
| return zoomer.scale() | |
| } | |
| function zoom_to(scale) { | |
| scale = Math.max(zoomer.scaleExtent()[0], | |
| Math.min(scale, | |
| zoomer.scaleExtent()[1])); | |
| var translate = zoomer.translate(); | |
| // Invariant: x.invert(width / 2) should be the same before and after adjustment | |
| tmid = (width / 2 - translate[0]) / zoomer.scale() | |
| translate[0] = width / 2 - tmid * scale; | |
| zoomer.scale(scale); | |
| zoomer.translate(translate); | |
| x.domain(x0.range().map(function(ax) { return (ax - translate[0]) / scale; }).map(x0.invert)); | |
| redraw(); | |
| } | |
| function zoom_to_show(tmin, tmax) { | |
| // Invariant: x0.range().map(function(ax) { return (ax - translate[0]) / scale; }).map(x0.invert) == [tmin, tmax] | |
| var scale = 1 / (tmax - tmin); | |
| var translate = [- x0(tmin) * scale, 0]; | |
| zoomer.scale(scale); | |
| zoomer.translate(translate); | |
| x.domain([tmin, tmax]); | |
| redraw(); | |
| } | |
| function reset_y_pan() { | |
| y.domain([0, max_level]).range([0, bar_height*max_level]); | |
| } | |
| zoom_to_show(t0, tMAX); | |
| d3.selectAll("#zoom-in") | |
| .on("click", function() { | |
| zoom_to(get_zoom() * 1.10); | |
| d3.event.preventDefault(); | |
| d3.event.stopPropagation(); | |
| }); | |
| d3.selectAll("#zoom-out") | |
| .on("click", function() { | |
| zoom_to(get_zoom() / 1.10); | |
| d3.event.preventDefault(); | |
| d3.event.stopPropagation(); | |
| }); | |
| d3.selectAll("#zoom-start") | |
| .on("click", function() { | |
| reset_y_pan(); | |
| zoom_to_show(t0, t0 + 1.0); | |
| d3.event.preventDefault(); | |
| d3.event.stopPropagation(); | |
| }); | |
| d3.selectAll("#zoom-end-15") | |
| .on("click", function() { | |
| reset_y_pan(); | |
| zoom_to_show(tMAX - 15*60, tMAX); | |
| d3.event.preventDefault(); | |
| d3.event.stopPropagation(); | |
| }); | |
| d3.selectAll("#zoom-end-5") | |
| .on("click", function() { | |
| reset_y_pan(); | |
| zoom_to_show(tMAX - 5*60, tMAX); | |
| d3.event.preventDefault(); | |
| d3.event.stopPropagation(); | |
| }); | |
| d3.selectAll("#zoom-full") | |
| .on("click", function() { | |
| reset_y_pan(); | |
| zoom_to_show(t0, tMAX); | |
| d3.event.preventDefault(); | |
| d3.event.stopPropagation(); | |
| }); | |
| </script> | |
| </body> | |
| </html> | |
| """.strip() | |
| # 1200.001 -> '1,200.001' (overkill, no request is gonna last >= 1000s) | |
| fmt_duration = '{:,.3f}s'.format | |
| def parse_datetime(date, time): | |
| """Parse ISO-8601 date and time, return a time_t value. | |
| Assumes the time was in the local timezone. | |
| >>> parse_datetime('2013-09-23', '19:34:50') | |
| 1379954090 | |
| >>> parse_datetime('2013-09-23', '19:34:50.351631') | |
| 1379954090.351631 | |
| """ | |
| y, m, d = map(int, date.split('-')) | |
| hms, _, us = time.partition('.') | |
| hh, mm, ss = map(int, hms.split(':')) | |
| if us: | |
| assert len(us) == 6 | |
| us = int(us) | |
| else: | |
| us = 0 | |
| return mktime((y, m, d, hh, mm, ss, 0, 0, -1)) + us * 1e-6 | |
| class RequestState(object): | |
| """State of a particular request. | |
| Has the following attributes: | |
| level presentation level (to display overlapping requests each gets a | |
| unique level; levels are reused) | |
| start time_t value when this state was entered | |
| method HTTP method | |
| path URL path | |
| state request state (INPUT, WAITING, RUNNING, OUTPUT) | |
| In case of retries (which is the mechanism used by Zope to handle database | |
| conflict errors), ``state`` goes from 'running' to 'running2', then | |
| 'running3' etc. | |
| """ | |
| INPUT = 'input' # reading request from client | |
| WAITING = 'waiting' # waiting for an idle worker | |
| RUNNING = 'running' # a worker is processing this request | |
| OUTPUT = 'output' # writing response to client | |
| def __init__(self, level, start, method, path, state): | |
| self.level = level | |
| self.start = start | |
| self.method = method | |
| self.path = path | |
| self.state = state | |
| def update(self, start, state): | |
| """Update to new request state. | |
| Keeps track of retries, e.g. | |
| >>> rs = RequestState(1, 1379954090, 'GET', '/', RequestState.INPUT) | |
| >>> rs.update(1379954091, RequestState.RUNNING) | |
| >>> rs.state | |
| 'running' | |
| >>> rs.update(1379954092, RequestState.RUNNING) | |
| >>> rs.state | |
| 'running2' | |
| >>> rs.update(1379954093, RequestState.RUNNING) | |
| >>> rs.state | |
| 'running3' | |
| """ | |
| if state == self.RUNNING and self.state.startswith(self.RUNNING): | |
| if self.state == self.RUNNING: | |
| n = 1 | |
| else: | |
| n = int(self.state[len(self.RUNNING):]) | |
| state = self.RUNNING + str(n + 1) | |
| self.state = state | |
| self.start = start | |
| class EventTracker(object): | |
| """Request event tracker. | |
| Parses a trace.log file with the following events:: | |
| B <req_id> <timestamp> <method> <path> | |
| I <req_id> <timestamp> <request_body_size> | |
| C <req_id> <timestamp> | |
| D <req_id> <timestamp> <reads> <writes> [<dbname> <reads> <writes> ...] | |
| A <req_id> <timestamp> <status> <response_size> | |
| E <req_id> <timestamp> | |
| S 0 <timestamp> | |
| Full documentation of the trace.log format can be found at | |
| https://pypi.python.org/pypi/zc.zservertracelog | |
| (except note that the timestamps in real life are ``YYYY-MM-DD | |
| HH:MM:SS.uuuuuu`` instead of ``YYYY-MM-DDTHH:MM:SS.uuuuuu``) | |
| The parsing is incremental: call et.parse(line) for evey line in | |
| trace.log, then call et.reset() to emit information about unfinished | |
| requests. | |
| The result of the process is a list of dicts that describe the time | |
| each request spent in each state. The dicst have the following | |
| attributes: | |
| start time_t when the request entered this state | |
| stop time_t when the request left this state | |
| level presentation level (to display overlapping requests each gets a | |
| unique level; levels are reused) | |
| value request method and path, with optional suffix indicating that | |
| the request hasn't completed cleanly | |
| state request state (see RequestState.state, also one extra | |
| allowed value is 'postcommit'; which is like running | |
| except after the ZODB commit) | |
| duration pretty-printed duration in this state | |
| some states have additional attributes | |
| input_size (for state 'input'): request body size in bytes | |
| reads (for state 'running'): number of ZODB object reads | |
| writes (for state 'running'): number of ZODB object writes | |
| response_status (for state 'running' or 'postcommit'): response status code | |
| output_size (for state 'running' or 'postcommit') response body size in bytes | |
| Sometimes ZODB stats are not available, in which case don't look for | |
| 'reads'/'writes' in the dict for state 'running'. | |
| """ | |
| BEGIN_REQUEST = 'B' # new request appears, enters INPUT state | |
| INPUT_COMPLETE = 'I' # request transitions from INPUT to WAITING | |
| START_PROCESSING = 'C' # request transitions from WAITING to RUNNING | |
| DATABASE_ACTIVITY = 'D' # database activity at the end of RUNNING | |
| APP_DONE = 'A' # request transitions from RUNNING to OUTPUT | |
| REQUEST_DONE = 'E' # request completely processed | |
| SERVER_RESTART = 'S' # server restart, all requests cancelled | |
| def __init__(self): | |
| self.req_status = {} | |
| self.levels = set() | |
| self.bars = [] | |
| self.last_stamp = None | |
| def get_level(self): | |
| """Find a free presentation level.""" | |
| level = 0 | |
| while level in self.levels: | |
| level += 1 | |
| self.levels.add(level) | |
| return level | |
| def put_level(self, level): | |
| """Mark this presentation level as free.""" | |
| self.levels.remove(level) | |
| def emit(self, rs, stop, extra='', **kw): | |
| """Emit a bar for a request state.""" | |
| text = rs.method + ' ' + rs.path + extra | |
| self.bars.append(dict( | |
| start=rs.start, stop=stop, level=rs.level, value=text, | |
| state=rs.state, duration=fmt_duration(stop - rs.start), **kw)) | |
| def reset(self, stamp, extra): | |
| """Close all pending requests.""" | |
| for rs in self.req_status.values(): | |
| self.emit(rs, stamp, extra=extra) | |
| self.req_status.clear() | |
| self.levels.clear() | |
| def parse(self, line): | |
| """Parse a single line from trace.log""" | |
| bits = line.rstrip().split(None, 4) | |
| (event, reqid, date, time), args = bits[:4], bits[4:] | |
| stamp = parse_datetime(date, time) | |
| self.process(event, reqid, stamp, *args) | |
| def process(self, event, reqid, stamp, args=''): | |
| """Process a single request.""" | |
| if self.last_stamp and stamp < self.last_stamp: | |
| raise ValueError('timestamps are not in order: %r, %r' % | |
| (self.last_stamp, stamp)) | |
| self.last_stamp = stamp | |
| if event == self.BEGIN_REQUEST: | |
| method, _, path = args.partition(' ') | |
| self.req_status[reqid] = RequestState( | |
| self.get_level(), stamp, method, path, RequestState.INPUT) | |
| elif event == self.SERVER_RESTART: | |
| self.reset(stamp, extra=' [ABORTED BY SERVER RESTART]') | |
| elif reqid not in self.req_status: | |
| # requests started before the log excerpt we're processing | |
| return | |
| elif event == self.INPUT_COMPLETE: | |
| input_size = int(args) | |
| rs = self.req_status[reqid] | |
| self.emit(rs, stamp, extra=' [request body size %d]' % input_size, | |
| input_size=input_size) | |
| rs.update(stamp, RequestState.WAITING) | |
| elif event == self.START_PROCESSING: | |
| rs = self.req_status[reqid] | |
| self.emit(rs, stamp) | |
| rs.update(stamp, RequestState.RUNNING) | |
| elif event == self.DATABASE_ACTIVITY: | |
| bits = args.split(None) if args else [] | |
| # r w dbname r w dbname r w ... | |
| reads = sum(map(int, bits[::3])) | |
| writes = sum(map(int, bits[1::3])) | |
| rs = self.req_status[reqid] | |
| self.emit(rs, stamp, reads=reads, writes=writes, | |
| extra=' [ZODB: %d reads, %d writes]' % (reads, writes)) | |
| rs.update(stamp, RequestState.RUNNING) | |
| elif event == self.APP_DONE: | |
| status, size = map(int, args.split()) | |
| rs = self.req_status[reqid] | |
| if rs.state.startswith('running') and rs.state != 'running': | |
| rs.state = 'postcommit' | |
| self.emit(rs, stamp, response_status=status, output_size=size, | |
| extra=' [status %d, body size %d]' % (status, size)) | |
| rs.update(stamp, RequestState.OUTPUT) | |
| elif event == self.REQUEST_DONE: | |
| rs = self.req_status.pop(reqid) | |
| self.emit(rs, stamp) | |
| self.put_level(rs.level) | |
| class ApacheLogParser(object): | |
| """Parse an Apache access.log that uses | |
| LogFormat "%h %l %u %t \"%r\" %>s %O \"%{Referer}i\" \"%{User-Agent}i\" %Ts %Dus %v:%p" combined_with_time | |
| """ | |
| _epoch = datetime.datetime(1970, 1, 1, 0, 0, 0) | |
| _rx = re.compile(r'^\S+ \S+ \S+ (\[[^\]]+\]) "([^"\\]*(?:\\.[^"\\]*)*)"' | |
| r' (\S+) (\S+) "[^"\\]*(?:\\.[^"\\]*)*"' | |
| r' "[^"\\]*(?:\\.[^"\\]*)*" \S+s (\S+)us \S+:\S+$') | |
| BEGIN = 'B' | |
| END = 'E' | |
| def __init__(self): | |
| self.parsed = 0 | |
| self.skipped = 0 | |
| self.events = [] | |
| def parse_timestamp(self, ts, utc=True): | |
| # ts == '[dd/Mmm/YYYY:HH:MM:SS +ZZZZ]' | |
| dt, _, tz = ts.partition(' ') | |
| dt = datetime.datetime.strptime(dt, '[%d/%b/%Y:%H:%M:%S') | |
| if utc: | |
| tz_offset_min = int(tz[1:3]) * 60 + int(tz[3:5]) | |
| if tz[0] == '-': | |
| tz_offset_min = -tz_offset_min | |
| dt -= datetime.timedelta(minutes=tz_offset_min) | |
| return dt | |
| def as_time_t(self, dt): | |
| return (dt - self._epoch).total_seconds() | |
| def parse(self, line): | |
| m = self._rx.match(line) | |
| if not m: | |
| self.skipped += 1 | |
| return False | |
| self.parsed += 1 | |
| timestamp, request_line, status, size, duration = m.groups() | |
| timestamp = self.parse_timestamp(timestamp) | |
| try: | |
| method, path, protocol = request_line.split() | |
| method_path = '%s %s' % (method, path) | |
| except ValueError: | |
| method_path = request_line | |
| duration = datetime.timedelta(microseconds=int(duration)) | |
| start = self.as_time_t(timestamp) | |
| stop = self.as_time_t(timestamp + duration) | |
| self.events.append((start, self.BEGIN, self.parsed, method_path, status, size)) | |
| self.events.append((stop, self.END, self.parsed, method_path, status, size)) | |
| return True | |
| def emit(self, et): | |
| self.events.sort() | |
| for stamp, event, reqid, method_path, status, size in self.events: | |
| if event == self.BEGIN: | |
| et.process(EventTracker.BEGIN_REQUEST, reqid, stamp, method_path) | |
| et.process(EventTracker.INPUT_COMPLETE, reqid, stamp, '0') | |
| et.process(EventTracker.START_PROCESSING, reqid, stamp) | |
| else: | |
| et.process(EventTracker.APP_DONE, reqid, stamp, '%s %s' % (status, size)) | |
| et.process(EventTracker.REQUEST_DONE, reqid, stamp) | |
| def parse_trace_log(trace_log): | |
| et = EventTracker() | |
| for line in trace_log: | |
| if not isinstance(line, str): | |
| line = line.decode('UTF-8', 'replace') | |
| et.parse(line) | |
| et.reset(et.last_stamp, extra=' [IN PROGRESS]') | |
| return et | |
| def parse_access_log(access_log): | |
| p = ApacheLogParser() | |
| for line in access_log: | |
| if not isinstance(line, str): | |
| line = line.decode('UTF-8', 'replace') | |
| p.parse(line) | |
| et = EventTracker() | |
| p.emit(et) | |
| return et | |
| def slurp(filename, max_lines=10000): | |
| pipe = subprocess.Popen(['tail', '-n', str(max_lines), filename], | |
| stdout=subprocess.PIPE).stdout | |
| return pipe | |
| def render(et, d3url=D3_URL): | |
| data = "var data = %s" % json.dumps(et.bars) | |
| return TEMPLATE.replace('{d3url}', d3url).replace('{data}', data) | |
| class App(object): | |
| def __init__(self, filename, parser=parse_trace_log, d3url=D3_URL, | |
| max_lines=10000): | |
| self.filename = filename | |
| self.d3url = d3url | |
| self.parser = parser | |
| self.max_lines = max_lines | |
| def render(self): | |
| et = self.parser(slurp(self.filename, self.max_lines)) | |
| return render(et, self.d3url) | |
| def serve(app, port=8000): | |
| from wsgiref.simple_server import make_server | |
| def wsgi_app(environ, start_response): | |
| PATH_INFO = environ['PATH_INFO'] | |
| if PATH_INFO != '/': | |
| status = '404 Not Found' | |
| headers = [('Content-Type', 'text/plain')] | |
| start_response(status, headers) | |
| return ['404 Not Found'] | |
| status = '200 OK' | |
| headers = [('Content-Type', 'text/html')] | |
| start_response(status, headers) | |
| return [app.render()] | |
| httpd = make_server('localhost', port, wsgi_app) | |
| print("Serving on http://localhost:%d" % port) | |
| httpd.serve_forever() | |
| def main(): | |
| if os.getenv('RUN_AS_CGI'): | |
| import cgitb | |
| cgitb.enable() | |
| filename = os.getenv('TRACELOG_LOCATION') | |
| d3url = os.getenv('D3_URL', D3_URL) | |
| if os.getenv('TRACELOG_FORMAT') == 'apache': | |
| parser = parse_access_log | |
| else: | |
| parser = parse_trace_log | |
| limit = int(os.getenv('TRACELOG_LIMIT', 10000)) | |
| app = App(filename, parser, d3url=d3url, max_lines=limit) | |
| print("Content-Type: text/html") | |
| print("") | |
| else: | |
| parser = optparse.OptionParser( | |
| usage='%prog [var/log/trace.log] > timeline.html\n' | |
| '%prog --serve [var/log/trace.log]') | |
| parser.add_option('-s', '--serve', action='store_true') | |
| parser.add_option('-a', '--apache', action='store_true') | |
| parser.add_option('-n', '--limit', type='int', | |
| default=10000) | |
| opts, args = parser.parse_args() | |
| if opts.apache: | |
| parser = parse_access_log | |
| filename = 'var/log/apache-access.log' | |
| else: | |
| parser = parse_trace_log | |
| filename = 'var/log/trace.log' | |
| if args: | |
| filename = args[0] | |
| app = App(filename, parser, max_lines=opts.limit) | |
| if opts.serve: | |
| return serve(app) | |
| print(app.render()) | |
| if __name__ == '__main__': | |
| main() |
Sign up for free
to join this conversation on GitHub.
Already have an account?
Sign in to comment
For use with log files produced by http://pypi.python.org/pypi/zc.zservertracelog
An older version looked like this: screenshot