[Checkins] SVN: zc.zservertracelog/trunk/ merge tracereport fixes.

Alex Smith alex at zope.com
Mon Aug 31 14:32:00 EDT 2009


Log message for revision 103417:
  merge tracereport fixes.
  
  svn merge -r 103242:HEAD svn+ssh://svn.zope.org/repos/main/zc.zservertracelog/branches/asmith-tracereport-fixes .
  
  

Changed:
  U   zc.zservertracelog/trunk/CHANGES.txt
  A   zc.zservertracelog/trunk/src/zc/zservertracelog/samples/
  U   zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py
  U   zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.py
  A   zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.txt

-=-
Modified: zc.zservertracelog/trunk/CHANGES.txt
===================================================================
--- zc.zservertracelog/trunk/CHANGES.txt	2009-08-31 17:26:31 UTC (rev 103416)
+++ zc.zservertracelog/trunk/CHANGES.txt	2009-08-31 18:31:59 UTC (rev 103417)
@@ -2,6 +2,15 @@
  Changes
 =========
 
+unreleased
+----------
+
+- tracereport improvements:
+  - fix parsing bugs.
+  - add basic tests.
+  - report time with microsecond resolution.
+
+
 1.1.5 (2009-04-01)
 ------------------
 

Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py	2009-08-31 17:26:31 UTC (rev 103416)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tests.py	2009-08-31 18:31:59 UTC (rev 103417)
@@ -17,10 +17,12 @@
 __docformat__ = "reStructuredText"
 
 from zope.testing import doctest
+import os
 import re
 import unittest
 import zope.testing.renormalizing
 
+here = os.path.dirname(os.path.abspath(__file__))
 
 checker = zope.testing.renormalizing.RENormalizing([
     # normalize the channel id and iso8601 timestamp
@@ -28,7 +30,6 @@
         '23418928 2008-08-26 10:55:00.000000'),
     ])
 
-
 _null_app = lambda environ, start_response: None
 
 
@@ -46,8 +47,12 @@
     test.globs['FauxApplication'] = FauxApplication
 
 
+def analysis_setUp(test):
+    test.globs['sample_log'] = here + '/samples/trace.log'
+
+
 def test_suite():
-    return unittest.TestSuite([
+    tests = [
         doctest.DocFileTest(
             'README.txt',
             optionflags=(
@@ -57,4 +62,10 @@
             checker=checker,
             setUp=setUp,
             ),
-        ])
+        doctest.DocFileTest(
+            'tracereport.txt',
+            checker=checker,
+            setUp=analysis_setUp),
+        ]
+
+    return unittest.TestSuite(tests)

Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.py
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.py	2009-08-31 17:26:31 UTC (rev 103416)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.py	2009-08-31 18:31:59 UTC (rev 103417)
@@ -14,10 +14,13 @@
 ##############################################################################
 """Yet another trace log analysis tool
 """
+import datetime
+import optparse
+import sys
+import time
 
-import datetime, optparse, sys
 
-class Request:
+class Request(object):
 
     output_bytes = '-'
 
@@ -47,14 +50,15 @@
 
     @property
     def app_seconds(self):
-        return (self.app_time - self.start_app_time).seconds
+        return seconds_difference(self.app_time, self.start_app_time)
 
     @property
     def total_seconds(self):
-        return (self.end - self.start).seconds
+        return seconds_difference(self.end, self.start)
 
-class Times:
 
+class Times(object):
+
     tid = 1l
 
     def __init__(self):
@@ -93,17 +97,19 @@
 
         n = len(times)
         m = self.median
-        return "%9.1f %5d %6.0f %6.2f %6.2f %6.0f %5d" % (
+        return "%9.1f %5d %6.2f %6.2f %6.2f %6.2f %5d" % (
             self.impact, n, times[0], m, self.mean, times[-1], self.hangs)
 
     def html(self):
         times = self.times
         if not times:
-            print td('', 0, '', '', '', '', self.hangs)
+            impact = '<a name="u%s">&nbsp;</a>' % self.tid
+            print td(
+                impact, 0, '&nbsp;', '&nbsp;', '&nbsp;', '&nbsp;', self.hangs)
         else:
+            impact = '<a name="u%s">%s</a>' % (self.tid, self.impact)
             n = len(times)
             m = self.median
-            impact = '<a name="u%s">%s' % (self.tid, self.impact)
             print td(impact, n, times[0], m, self.mean, times[-1],
                      self.hangs)
 
@@ -113,17 +119,35 @@
         result.hangs = self.hangs + other.hangs
         return result
 
-def parsedt(s):
-    date, time = s.split(' ')
-    h_m_s, ms = time.split('.')
-    return datetime.datetime(*(
-        map(int, date.split('-'))
-        +
-        map(int, h_m_s.split(':'))
-        +
-        [int(ms)]
-        ))
 
+def seconds_difference(dt1, dt2):
+    delta = dt1 - dt2
+    micros = float('0.' + str(delta.microseconds))
+    return delta.seconds + micros
+
+
+def parse_line(line):
+    parts = line.split(' ', 4)
+    code, rid, rdate, rtime = parts[:4]
+    if len(parts) > 4:
+        msg = parts[4]
+    else:
+        msg = ''
+    return (code, rid, rdate + ' ' + rtime, msg)
+
+
+def parse_datetime(s):
+    # XXX this chokes on tracelogs with the 'T' time separator.
+    date, t = s.split(' ')
+    try:
+        h_m_s, ms = t.split('.')
+    except ValueError:
+        h_m_s = t.strip()
+        ms = '0'
+    args = [int(arg) for arg in (date.split('-') + h_m_s.split(':') + [ms])]
+    return datetime.datetime(*args)
+
+
 def main(args=None):
     if args is None:
         args = sys.argv[1:]
@@ -171,9 +195,10 @@
         file = open(file)
 
     for record in file:
-        record = record.split()
-        typ, rid, dt, min = record[:4]
-        dt = parsedt(' '.join([dt,min]))
+        typ, rid, strtime, msg = parse_line(record)
+        min = strtime.split('.')[0]
+        min = min[:-3]
+        dt = parse_datetime(strtime)
         if dt == restart:
             continue
         while dt > restart:
@@ -215,10 +240,14 @@
                     input -= 1
 
             input += 1
-            request = Request(dt, *record[3:5])
+            method, url = msg.split(' ', 1)
+            request = Request(dt, method, url.strip())
             if remove_prefix and request.url.startswith(remove_prefix):
                 request.url = request.url[len(remove_prefix):]
             requests[rid] = request
+            times = urls.get(request.url)
+            if times is None:
+                times = urls[request.url] = Times()
         elif typ == 'I':
             if rid in requests:
                 input -= 1
@@ -233,7 +262,12 @@
             if rid in requests:
                 apps -= 1
                 output += 1
-                requests[rid].A(dt, *record[3:5])
+                try:
+                    response_code, bytes_len = msg.split()
+                except ValueError:
+                    response_code = '500'
+                    bytes_len = len(msg)
+                requests[rid].A(dt, response_code, bytes_len)
         elif typ == 'E':
             if rid in requests:
                 output -= 1
@@ -242,10 +276,7 @@
                 spr += request.total_seconds
                 spa += request.app_seconds
                 n += 1
-                url = "%s -> %s" % (request.url, request.response)
-                times = urls.get(url)
-                if times is None:
-                    times = urls[url] = Times()
+                times = urls[request.url]
                 times.finished(request)
 
         elif typ in 'SX':
@@ -261,6 +292,7 @@
         else:
             print 'WTF', record
 
+    record_hung(urls, requests)
     print_app_requests(requests, dt,
                        options.old_requests,
                        options.app_requests,
@@ -344,7 +376,7 @@
     print '</table>'
 
 def output_minute_text(lmin, requests, input, wait, apps, output, n, spr, spa):
-    print lmin.replace('T', ' '), " %5d I=%3d W=%3d A=%3d O=%5d " % (
+    print lmin, "%5d I=%3d W=%3d A=%3d O=%4d" % (
         len(requests), input, wait, apps, output),
     if n:
         print "N=%4d %10.2f %10.2f" % (n, spr/n, spa/n)
@@ -363,9 +395,11 @@
     else:
         print '<tr>'
     apps = '<font size="+2"><strong>%s</strong></font>' % apps
-    print td(lmin.replace('T', ' '), len(requests), input, wait, apps, output)
+    print td(lmin, len(requests), input, wait, apps, output)
     if n:
         print td(n, "%10.2f" % (spr/n), "%10.2f" % (spa/n))
+    else:
+        print td(n, '&nbsp;', '&nbsp;')
     print '</tr>'
 
 def find_restarts(event_log):
@@ -382,10 +416,10 @@
             times = urls[request.url] = Times()
         times.hung()
 
-def print_app_requests_text(requests, dt, min_seconds, max_requests, urls,
+def print_app_requests_text(requests, dt, min_seconds, max_requests, allurls,
                        label=''):
     requests = [
-        ((dt-request.start).seconds, request)
+        (seconds_difference(dt, request.start), request)
         for request in requests.values()
         if request.state == 'app'
     ]
@@ -431,7 +465,7 @@
             print label
             label = ''
         if not printed:
-            minutes_footer_html()
+            print '</table>'
             print '<table border="1">'
             print '<tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>'
             printed = True
@@ -448,8 +482,7 @@
         print '</table>'
         minutes_header_html()
 
-parser = optparse.OptionParser("""
-Usage: %prog [options] trace_log_file
+parser = optparse.OptionParser("""%prog [options] trace_log_file
 
 Output trace log data showing:
 

Copied: zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.txt (from rev 103416, zc.zservertracelog/branches/asmith-tracereport-fixes/src/zc/zservertracelog/tracereport.txt)
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.txt	                        (rev 0)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tracereport.txt	2009-08-31 18:31:59 UTC (rev 103417)
@@ -0,0 +1,618 @@
+===================
+Analyzing Tracelogs
+===================
+
+`tracereport.py` provides a basic means to analyze a tracelog and generate a
+report.
+
+    >>> import zc.zservertracelog.tracereport
+
+The '--help' option displays the following usage information:
+
+    >>> try:
+    ...     zc.zservertracelog.tracereport.main(['--help'])
+    ... except SystemExit:
+    ...     pass
+    usage: test [options] trace_log_file
+    <BLANKLINE>
+    Output trace log data showing:
+    <BLANKLINE>
+    - number of active requests,
+    - number of input requests (requests gathering input),
+    - number of application requests,
+    - number of output requests,
+    - number of requests completed in the minute shown,
+    - mean seconds per request and
+    - mean application seconds per request.
+    <BLANKLINE>
+    Note that we don't seem to be logging when a connection to the client
+    is broken, so the number of active requests, and especially the number
+    of outputing requests tends to grow over time. This is spurious.
+    <BLANKLINE>
+    Also, note that, unfortunately, application requests include requests
+    that are running in application threads and requests waiting to get an
+    application thread.
+    <BLANKLINE>
+    When application threads get above the app request threshold, then we
+    show the requests that have been waiting the longest.
+    <BLANKLINE>
+    <BLANKLINE>
+    <BLANKLINE>
+    options:
+      -h, --help            show this help message and exit
+      -a APPS, --app-request-threshold=APPS
+                             Number of pending application requests at which
+                            detailed request information if printed.
+      -r APP_REQUESTS, --app-requests=APP_REQUESTS
+                             How many requests to show when the maximum number of
+                            pending apps is exceeded.
+      -o OLD_REQUESTS, --old-requests=OLD_REQUESTS
+                             Number of seconds beyond which a request is
+                            considered old.
+      -e EVENT_LOG, --event-log=EVENT_LOG
+                             The name of an event log that goes with the trace
+                            log.  This is used to determine when the server is
+                            restarted, so that the running trace data structures
+                            can be reinitialized.
+      --html                 Generate HTML output.
+      --remove-prefix=REMOVE_PREFIX
+                             A prefex to be removed from URLS.
+      --summary-only         Only output summary lines.
+      --summary-lines=SUMMARY_LINES
+                            The number of summary lines to show
+
+Here, we display the summarized report for a sample trace log.
+
+    >>> zc.zservertracelog.tracereport.main(
+    ...     ['--summary-only', '--app-request-threshold', '0', sample_log])
+    <BLANKLINE>
+    URL statistics:
+       Impact count    min median   mean    max hangs
+    ========= ===== ====== ====== ====== ====== =====
+         62.4     1  62.42  62.42  62.42  62.42     0 /constellations/andromeda.html
+         61.5     1  61.50  61.50  61.50  61.50     0 /stars/alpha-centauri.html
+         60.7     2   0.34  30.34  30.34  60.34     0 /space-travel/plans/supplies.txt
+         60.3     2   0.13  30.13  30.13  60.13     0 /favicon.png
+          9.7     1   9.69   9.69   9.69   9.69     0 /planets/saturn.html
+          8.3     1   8.30   8.30   8.30   8.30     0 /moons/io.html
+          7.3     1   7.34   7.34   7.34   7.34     0 /planets/jupiter.html
+          1.0     3   0.31   0.35   0.35   0.38     0 /space-travel/plans/signals.html
+          0.9     1   0.88   0.88   0.88   0.88     0 /stories/aliens-posing-as-humans.html
+          0.8     2   0.35   0.39   0.39   0.42     0 /space-travel/plans/launchpad.html
+          0.7     1   0.36   0.36   0.36   0.36     1 /space-travel/plans/orbit.html
+          0.7     2   0.34   0.36   0.36   0.38     0 /space-travel/plans/space-logs.txt
+          0.7     2   0.35   0.35   0.35   0.35     0 /space-travel/plans/moon-base.jpg
+          0.6     1   0.64   0.64   0.64   0.64     0 /columns/t-jansen
+          0.5     3   0.15   0.16   0.16   0.18     0 /space-travelers/famous/kirk.jpg
+          0.4     1   0.40   0.40   0.40   0.40     0 /space-travel/plans/moon-buggy.jpg
+          0.4     1   0.38   0.38   0.38   0.38     0 /space-travel/plans/space-diary.txt
+          0.4     2   0.18   0.19   0.19   0.19     0 /faqs/how-to-recognize-lazer-fire.html
+          0.4     1   0.35   0.35   0.35   0.35     0 /js/photo.js
+          0.4     1   0.35   0.35   0.35   0.35     0 /space-travel/plans/visor.jpg
+          0.4     1   0.35   0.35   0.35   0.35     0 /space-travel/plans/lunar-cycles.html
+          0.4     1   0.35   0.35   0.35   0.35     0 /faqs/how-to-charge-lazers.html
+          0.3     1   0.33   0.33   0.33   0.33     0 /space-travel/plans/cryostasis.txt
+          0.3     1   0.32   0.32   0.32   0.32     0 /space-travel/plans/space-suit.jpg
+          0.3     1   0.32   0.32   0.32   0.32     0 /space-travel/ships/tardis.html
+          0.3     1   0.25   0.25   0.25   0.25     0 /approve-photo
+          0.2     1   0.18   0.18   0.18   0.18     0 /ufo-sightings/report
+          0.2     1   0.16   0.16   0.16   0.16     0 /space-travelers/famous/spock.jpg
+          0.2     1   0.16   0.16   0.16   0.16     0 /login
+          0.1     1   0.14   0.14   0.14   0.14     0 /space-travel/ships/soyuz.html
+                  0                                 1 /submit-photo
+
+This can also be displayed as HTML.
+
+    >>> zc.zservertracelog.tracereport.main(
+    ...     ['--summary-only', '--html', '--app-request-threshold', '0', sample_log])
+    <html title="trace log statistics"><body>
+    <BLANKLINE>
+    URL statistics:
+    <table border="1">
+    <tr><th>Impact</th><th>count</th><th>min</th>
+    <th>median</th><th>mean</th><th>max</th><th>hangs</th></tr>
+    <tr>
+    <td><a name="u37">62.41844</a></td><td>1</td><td>62.41844</td><td>62.41844</td><td>62.41844</td><td>62.41844</td><td>0</td>
+    <td>/constellations/andromeda.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u53">61.502412</a></td><td>1</td><td>61.502412</td><td>61.502412</td><td>61.502412</td><td>61.502412</td><td>0</td>
+    <td>/stars/alpha-centauri.html</td>
+    </tr>
+    <tr>
+    <td><a name="u34">60.6803</a></td><td>2</td><td>0.3372</td><td>30.34015</td><td>30.34015</td><td>60.3431</td><td>0</td>
+    <td>/space-travel/plans/supplies.txt</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u44">60.267171</a></td><td>2</td><td>0.132899</td><td>30.1335855</td><td>30.1335855</td><td>60.134272</td><td>0</td>
+    <td>/favicon.png</td>
+    </tr>
+    <tr>
+    <td><a name="u48">9.693661</a></td><td>1</td><td>9.693661</td><td>9.693661</td><td>9.693661</td><td>9.693661</td><td>0</td>
+    <td>/planets/saturn.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u51">8.29953</a></td><td>1</td><td>8.29953</td><td>8.29953</td><td>8.29953</td><td>8.29953</td><td>0</td>
+    <td>/moons/io.html</td>
+    </tr>
+    <tr>
+    <td><a name="u55">7.339574</a></td><td>1</td><td>7.339574</td><td>7.339574</td><td>7.339574</td><td>7.339574</td><td>0</td>
+    <td>/planets/jupiter.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u56">1.0394</a></td><td>3</td><td>0.3092</td><td>0.3526</td><td>0.346466666667</td><td>0.3776</td><td>0</td>
+    <td>/space-travel/plans/signals.html</td>
+    </tr>
+    <tr>
+    <td><a name="u60">0.879732</a></td><td>1</td><td>0.879732</td><td>0.879732</td><td>0.879732</td><td>0.879732</td><td>0</td>
+    <td>/stories/aliens-posing-as-humans.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u36">0.7755</a></td><td>2</td><td>0.3523</td><td>0.38775</td><td>0.38775</td><td>0.4232</td><td>0</td>
+    <td>/space-travel/plans/launchpad.html</td>
+    </tr>
+    <tr>
+    <td><a name="u62">0.729</a></td><td>1</td><td>0.3645</td><td>0.3645</td><td>0.3645</td><td>0.3645</td><td>1</td>
+    <td>/space-travel/plans/orbit.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u38">0.7221</a></td><td>2</td><td>0.3385</td><td>0.36105</td><td>0.36105</td><td>0.3836</td><td>0</td>
+    <td>/space-travel/plans/space-logs.txt</td>
+    </tr>
+    <tr>
+    <td><a name="u35">0.6988</a></td><td>2</td><td>0.3474</td><td>0.3494</td><td>0.3494</td><td>0.3514</td><td>0</td>
+    <td>/space-travel/plans/moon-base.jpg</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u33">0.63826</a></td><td>1</td><td>0.63826</td><td>0.63826</td><td>0.63826</td><td>0.63826</td><td>0</td>
+    <td>/columns/t-jansen</td>
+    </tr>
+    <tr>
+    <td><a name="u45">0.49124</a></td><td>3</td><td>0.1529</td><td>0.16141</td><td>0.163746666667</td><td>0.17693</td><td>0</td>
+    <td>/space-travelers/famous/kirk.jpg</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u46">0.3967</a></td><td>1</td><td>0.3967</td><td>0.3967</td><td>0.3967</td><td>0.3967</td><td>0</td>
+    <td>/space-travel/plans/moon-buggy.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u49">0.3794</a></td><td>1</td><td>0.3794</td><td>0.3794</td><td>0.3794</td><td>0.3794</td><td>0</td>
+    <td>/space-travel/plans/space-diary.txt</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u41">0.374609</a></td><td>2</td><td>0.184486</td><td>0.1873045</td><td>0.1873045</td><td>0.190123</td><td>0</td>
+    <td>/faqs/how-to-recognize-lazer-fire.html</td>
+    </tr>
+    <tr>
+    <td><a name="u58">0.3542</a></td><td>1</td><td>0.3542</td><td>0.3542</td><td>0.3542</td><td>0.3542</td><td>0</td>
+    <td>/js/photo.js</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u63">0.354</a></td><td>1</td><td>0.354</td><td>0.354</td><td>0.354</td><td>0.354</td><td>0</td>
+    <td>/space-travel/plans/visor.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u52">0.3526</a></td><td>1</td><td>0.3526</td><td>0.3526</td><td>0.3526</td><td>0.3526</td><td>0</td>
+    <td>/space-travel/plans/lunar-cycles.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u54">0.350755</a></td><td>1</td><td>0.350755</td><td>0.350755</td><td>0.350755</td><td>0.350755</td><td>0</td>
+    <td>/faqs/how-to-charge-lazers.html</td>
+    </tr>
+    <tr>
+    <td><a name="u40">0.3325</a></td><td>1</td><td>0.3325</td><td>0.3325</td><td>0.3325</td><td>0.3325</td><td>0</td>
+    <td>/space-travel/plans/cryostasis.txt</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u47">0.3211</a></td><td>1</td><td>0.3211</td><td>0.3211</td><td>0.3211</td><td>0.3211</td><td>0</td>
+    <td>/space-travel/plans/space-suit.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u50">0.31994</a></td><td>1</td><td>0.31994</td><td>0.31994</td><td>0.31994</td><td>0.31994</td><td>0</td>
+    <td>/space-travel/ships/tardis.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u39">0.252708</a></td><td>1</td><td>0.252708</td><td>0.252708</td><td>0.252708</td><td>0.252708</td><td>0</td>
+    <td>/approve-photo</td>
+    </tr>
+    <tr>
+    <td><a name="u57">0.181654</a></td><td>1</td><td>0.181654</td><td>0.181654</td><td>0.181654</td><td>0.181654</td><td>0</td>
+    <td>/ufo-sightings/report</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u59">0.15727</a></td><td>1</td><td>0.15727</td><td>0.15727</td><td>0.15727</td><td>0.15727</td><td>0</td>
+    <td>/space-travelers/famous/spock.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u43">0.15669</a></td><td>1</td><td>0.15669</td><td>0.15669</td><td>0.15669</td><td>0.15669</td><td>0</td>
+    <td>/login</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u61">0.137797</a></td><td>1</td><td>0.137797</td><td>0.137797</td><td>0.137797</td><td>0.137797</td><td>0</td>
+    <td>/space-travel/ships/soyuz.html</td>
+    </tr>
+    <tr>
+    <td><a name="u42">&nbsp;</a></td><td>0</td><td>&nbsp;</td><td>&nbsp;</td><td>&nbsp;</td><td>&nbsp;</td><td>1</td>
+    <td>/submit-photo</td>
+    </tr>
+    </table>
+    </body></html>
+
+The full report shows the request activity per minute.
+
+    >>> zc.zservertracelog.tracereport.main(
+    ...     ['--app-request-threshold', '0', sample_log])
+    <BLANKLINE>
+              minute   req input  wait   app output
+    ================ ===== ===== ===== ===== ======
+    2009-07-30 15:47     1 I=  0 W=  0 A=  1 O=   0 N=   1       0.64       0.64
+    60.4106 /space-travel/plans/supplies.txt
+    2009-07-30 15:48     2 I=  0 W=  1 A=  1 O=   0 N=   3      20.43      20.35
+    60.791825 /constellations/andromeda.html
+    2009-07-30 15:49     0 I=  0 W=  0 A=  0 O=   0 N=   4      31.81      15.85
+    2009-07-30 15:50     2 I=  0 W=  0 A=  2 O=   0 N=   2       0.34       0.17
+    60.62335 /submit-photo
+    60.209388 /favicon.png
+    2009-07-30 15:51     3 I=  0 W=  1 A=  1 O=   1 N=   5      12.31      12.25
+    121.301024 /submit-photo
+    2009-07-30 15:52     3 I=  0 W=  1 A=  2 O=   0 N=   8      20.65       2.52
+    200.494494 /submit-photo
+    68.9801 /stars/alpha-centauri.html
+    2009-07-30 15:53     3 I=  0 W=  2 A=  1 O=   0 N=  11      14.53       6.53
+    270.622261 /submit-photo
+    Left over:
+    271.214443 /submit-photo
+    <BLANKLINE>
+    <BLANKLINE>
+    URL statistics:
+       Impact count    min median   mean    max hangs
+    ========= ===== ====== ====== ====== ====== =====
+         62.4     1  62.42  62.42  62.42  62.42     0 /constellations/andromeda.html
+         61.5     1  61.50  61.50  61.50  61.50     0 /stars/alpha-centauri.html
+         60.7     2   0.34  30.34  30.34  60.34     0 /space-travel/plans/supplies.txt
+         60.3     2   0.13  30.13  30.13  60.13     0 /favicon.png
+          9.7     1   9.69   9.69   9.69   9.69     0 /planets/saturn.html
+          8.3     1   8.30   8.30   8.30   8.30     0 /moons/io.html
+          7.3     1   7.34   7.34   7.34   7.34     0 /planets/jupiter.html
+          1.0     3   0.31   0.35   0.35   0.38     0 /space-travel/plans/signals.html
+          0.9     1   0.88   0.88   0.88   0.88     0 /stories/aliens-posing-as-humans.html
+          0.8     2   0.35   0.39   0.39   0.42     0 /space-travel/plans/launchpad.html
+          0.7     1   0.36   0.36   0.36   0.36     1 /space-travel/plans/orbit.html
+          0.7     2   0.34   0.36   0.36   0.38     0 /space-travel/plans/space-logs.txt
+          0.7     2   0.35   0.35   0.35   0.35     0 /space-travel/plans/moon-base.jpg
+          0.6     1   0.64   0.64   0.64   0.64     0 /columns/t-jansen
+          0.5     3   0.15   0.16   0.16   0.18     0 /space-travelers/famous/kirk.jpg
+          0.4     1   0.40   0.40   0.40   0.40     0 /space-travel/plans/moon-buggy.jpg
+          0.4     1   0.38   0.38   0.38   0.38     0 /space-travel/plans/space-diary.txt
+          0.4     2   0.18   0.19   0.19   0.19     0 /faqs/how-to-recognize-lazer-fire.html
+          0.4     1   0.35   0.35   0.35   0.35     0 /js/photo.js
+          0.4     1   0.35   0.35   0.35   0.35     0 /space-travel/plans/visor.jpg
+          0.4     1   0.35   0.35   0.35   0.35     0 /space-travel/plans/lunar-cycles.html
+          0.4     1   0.35   0.35   0.35   0.35     0 /faqs/how-to-charge-lazers.html
+          0.3     1   0.33   0.33   0.33   0.33     0 /space-travel/plans/cryostasis.txt
+          0.3     1   0.32   0.32   0.32   0.32     0 /space-travel/plans/space-suit.jpg
+          0.3     1   0.32   0.32   0.32   0.32     0 /space-travel/ships/tardis.html
+          0.3     1   0.25   0.25   0.25   0.25     0 /approve-photo
+          0.2     1   0.18   0.18   0.18   0.18     0 /ufo-sightings/report
+          0.2     1   0.16   0.16   0.16   0.16     0 /space-travelers/famous/spock.jpg
+          0.2     1   0.16   0.16   0.16   0.16     0 /login
+          0.1     1   0.14   0.14   0.14   0.14     0 /space-travel/ships/soyuz.html
+                  0                                 1 /submit-photo
+
+Again, this report is also available in HTML form.
+
+    >>> zc.zservertracelog.tracereport.main(
+    ...     ['--html', '--app-request-threshold', '0', sample_log])
+    <html title="trace log statistics"><body>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    <tr style="background: lightgrey">
+    <td>2009-07-30 15:47</td><td>1</td><td>0</td><td>0</td><td><font size="+2"><strong>1</strong></font></td><td>0</td>
+    <td>1</td><td>      0.64</td><td>      0.64</td>
+    </tr>
+    </table>
+    <table border="1">
+    <tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>
+    <tr>
+    <td>60</td><td></td><td><a href="#u96">/space-travel/plans/supplies.txt</a></td><td>app</td>
+    </tr>
+    </table>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    <tr>
+    <td>2009-07-30 15:48</td><td>2</td><td>0</td><td>1</td><td><font size="+2"><strong>1</strong></font></td><td>0</td>
+    <td>3</td><td>     20.43</td><td>     20.35</td>
+    </tr>
+    </table>
+    <table border="1">
+    <tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>
+    <tr>
+    <td>60</td><td></td><td><a href="#u99">/constellations/andromeda.html</a></td><td>app</td>
+    </tr>
+    </table>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    <tr style="background: lightgrey">
+    <td>2009-07-30 15:49</td><td>0</td><td>0</td><td>0</td><td><font size="+2"><strong>0</strong></font></td><td>0</td>
+    <td>4</td><td>     31.81</td><td>     15.85</td>
+    </tr>
+    <tr>
+    <td>2009-07-30 15:50</td><td>2</td><td>0</td><td>0</td><td><font size="+2"><strong>2</strong></font></td><td>0</td>
+    <td>2</td><td>      0.34</td><td>      0.17</td>
+    </tr>
+    </table>
+    <table border="1">
+    <tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>
+    <tr>
+    <td>60</td><td></td><td><a href="#u104">/submit-photo</a></td><td>app</td>
+    </tr>
+    <tr>
+    <td>60</td><td></td><td><a href="#u106">/favicon.png</a></td><td>app</td>
+    </tr>
+    </table>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    <tr style="background: lightgrey">
+    <td>2009-07-30 15:51</td><td>3</td><td>0</td><td>1</td><td><font size="+2"><strong>1</strong></font></td><td>1</td>
+    <td>5</td><td>     12.31</td><td>     12.25</td>
+    </tr>
+    </table>
+    <table border="1">
+    <tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>
+    <tr>
+    <td>121</td><td></td><td><a href="#u104">/submit-photo</a></td><td>app</td>
+    </tr>
+    </table>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    <tr>
+    <td>2009-07-30 15:52</td><td>3</td><td>0</td><td>1</td><td><font size="+2"><strong>2</strong></font></td><td>0</td>
+    <td>8</td><td>     20.65</td><td>      2.52</td>
+    </tr>
+    </table>
+    <table border="1">
+    <tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>
+    <tr>
+    <td>200</td><td></td><td><a href="#u104">/submit-photo</a></td><td>app</td>
+    </tr>
+    <tr>
+    <td>68</td><td></td><td><a href="#u115">/stars/alpha-centauri.html</a></td><td>app</td>
+    </tr>
+    </table>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    <tr style="background: lightgrey">
+    <td>2009-07-30 15:53</td><td>3</td><td>0</td><td>2</td><td><font size="+2"><strong>1</strong></font></td><td>0</td>
+    <td>11</td><td>     14.53</td><td>      6.53</td>
+    </tr>
+    </table>
+    <table border="1">
+    <tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>
+    <tr>
+    <td>270</td><td></td><td><a href="#u104">/submit-photo</a></td><td>app</td>
+    </tr>
+    </table>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    Left over:
+    </table>
+    <table border="1">
+    <tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>
+    <tr>
+    <td>271</td><td></td><td><a href="#u104">/submit-photo</a></td><td>app</td>
+    </tr>
+    </table>
+    <table border="2">
+    <tr>
+    <th>Minute</th>
+    <th>Requests</th>
+    <th>Requests inputing</th>
+    <th>Requests waiting</th>
+    <th>Requests executing</th>
+    <th>Requests outputing</th>
+    <th>Requests completed</th>
+    <th>Mean Seconds Per Request Total</th>
+    <th>Mean Seconds Per Request in App</th>
+    </tr>
+    </table>
+    <BLANKLINE>
+    URL statistics:
+    <table border="1">
+    <tr><th>Impact</th><th>count</th><th>min</th>
+    <th>median</th><th>mean</th><th>max</th><th>hangs</th></tr>
+    <tr>
+    <td><a name="u99">62.41844</a></td><td>1</td><td>62.41844</td><td>62.41844</td><td>62.41844</td><td>62.41844</td><td>0</td>
+    <td>/constellations/andromeda.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u115">61.502412</a></td><td>1</td><td>61.502412</td><td>61.502412</td><td>61.502412</td><td>61.502412</td><td>0</td>
+    <td>/stars/alpha-centauri.html</td>
+    </tr>
+    <tr>
+    <td><a name="u96">60.6803</a></td><td>2</td><td>0.3372</td><td>30.34015</td><td>30.34015</td><td>60.3431</td><td>0</td>
+    <td>/space-travel/plans/supplies.txt</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u106">60.267171</a></td><td>2</td><td>0.132899</td><td>30.1335855</td><td>30.1335855</td><td>60.134272</td><td>0</td>
+    <td>/favicon.png</td>
+    </tr>
+    <tr>
+    <td><a name="u110">9.693661</a></td><td>1</td><td>9.693661</td><td>9.693661</td><td>9.693661</td><td>9.693661</td><td>0</td>
+    <td>/planets/saturn.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u113">8.29953</a></td><td>1</td><td>8.29953</td><td>8.29953</td><td>8.29953</td><td>8.29953</td><td>0</td>
+    <td>/moons/io.html</td>
+    </tr>
+    <tr>
+    <td><a name="u117">7.339574</a></td><td>1</td><td>7.339574</td><td>7.339574</td><td>7.339574</td><td>7.339574</td><td>0</td>
+    <td>/planets/jupiter.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u118">1.0394</a></td><td>3</td><td>0.3092</td><td>0.3526</td><td>0.346466666667</td><td>0.3776</td><td>0</td>
+    <td>/space-travel/plans/signals.html</td>
+    </tr>
+    <tr>
+    <td><a name="u122">0.879732</a></td><td>1</td><td>0.879732</td><td>0.879732</td><td>0.879732</td><td>0.879732</td><td>0</td>
+    <td>/stories/aliens-posing-as-humans.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u98">0.7755</a></td><td>2</td><td>0.3523</td><td>0.38775</td><td>0.38775</td><td>0.4232</td><td>0</td>
+    <td>/space-travel/plans/launchpad.html</td>
+    </tr>
+    <tr>
+    <td><a name="u124">0.729</a></td><td>1</td><td>0.3645</td><td>0.3645</td><td>0.3645</td><td>0.3645</td><td>1</td>
+    <td>/space-travel/plans/orbit.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u100">0.7221</a></td><td>2</td><td>0.3385</td><td>0.36105</td><td>0.36105</td><td>0.3836</td><td>0</td>
+    <td>/space-travel/plans/space-logs.txt</td>
+    </tr>
+    <tr>
+    <td><a name="u97">0.6988</a></td><td>2</td><td>0.3474</td><td>0.3494</td><td>0.3494</td><td>0.3514</td><td>0</td>
+    <td>/space-travel/plans/moon-base.jpg</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u95">0.63826</a></td><td>1</td><td>0.63826</td><td>0.63826</td><td>0.63826</td><td>0.63826</td><td>0</td>
+    <td>/columns/t-jansen</td>
+    </tr>
+    <tr>
+    <td><a name="u107">0.49124</a></td><td>3</td><td>0.1529</td><td>0.16141</td><td>0.163746666667</td><td>0.17693</td><td>0</td>
+    <td>/space-travelers/famous/kirk.jpg</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u108">0.3967</a></td><td>1</td><td>0.3967</td><td>0.3967</td><td>0.3967</td><td>0.3967</td><td>0</td>
+    <td>/space-travel/plans/moon-buggy.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u111">0.3794</a></td><td>1</td><td>0.3794</td><td>0.3794</td><td>0.3794</td><td>0.3794</td><td>0</td>
+    <td>/space-travel/plans/space-diary.txt</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u103">0.374609</a></td><td>2</td><td>0.184486</td><td>0.1873045</td><td>0.1873045</td><td>0.190123</td><td>0</td>
+    <td>/faqs/how-to-recognize-lazer-fire.html</td>
+    </tr>
+    <tr>
+    <td><a name="u120">0.3542</a></td><td>1</td><td>0.3542</td><td>0.3542</td><td>0.3542</td><td>0.3542</td><td>0</td>
+    <td>/js/photo.js</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u125">0.354</a></td><td>1</td><td>0.354</td><td>0.354</td><td>0.354</td><td>0.354</td><td>0</td>
+    <td>/space-travel/plans/visor.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u114">0.3526</a></td><td>1</td><td>0.3526</td><td>0.3526</td><td>0.3526</td><td>0.3526</td><td>0</td>
+    <td>/space-travel/plans/lunar-cycles.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u116">0.350755</a></td><td>1</td><td>0.350755</td><td>0.350755</td><td>0.350755</td><td>0.350755</td><td>0</td>
+    <td>/faqs/how-to-charge-lazers.html</td>
+    </tr>
+    <tr>
+    <td><a name="u102">0.3325</a></td><td>1</td><td>0.3325</td><td>0.3325</td><td>0.3325</td><td>0.3325</td><td>0</td>
+    <td>/space-travel/plans/cryostasis.txt</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u109">0.3211</a></td><td>1</td><td>0.3211</td><td>0.3211</td><td>0.3211</td><td>0.3211</td><td>0</td>
+    <td>/space-travel/plans/space-suit.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u112">0.31994</a></td><td>1</td><td>0.31994</td><td>0.31994</td><td>0.31994</td><td>0.31994</td><td>0</td>
+    <td>/space-travel/ships/tardis.html</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u101">0.252708</a></td><td>1</td><td>0.252708</td><td>0.252708</td><td>0.252708</td><td>0.252708</td><td>0</td>
+    <td>/approve-photo</td>
+    </tr>
+    <tr>
+    <td><a name="u119">0.181654</a></td><td>1</td><td>0.181654</td><td>0.181654</td><td>0.181654</td><td>0.181654</td><td>0</td>
+    <td>/ufo-sightings/report</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u121">0.15727</a></td><td>1</td><td>0.15727</td><td>0.15727</td><td>0.15727</td><td>0.15727</td><td>0</td>
+    <td>/space-travelers/famous/spock.jpg</td>
+    </tr>
+    <tr>
+    <td><a name="u105">0.15669</a></td><td>1</td><td>0.15669</td><td>0.15669</td><td>0.15669</td><td>0.15669</td><td>0</td>
+    <td>/login</td>
+    </tr>
+    <tr style="background: lightgrey;">
+    <td><a name="u123">0.137797</a></td><td>1</td><td>0.137797</td><td>0.137797</td><td>0.137797</td><td>0.137797</td><td>0</td>
+    <td>/space-travel/ships/soyuz.html</td>
+    </tr>
+    <tr>
+    <td><a name="u104">&nbsp;</a></td><td>0</td><td>&nbsp;</td><td>&nbsp;</td><td>&nbsp;</td><td>&nbsp;</td><td>1</td>
+    <td>/submit-photo</td>
+    </tr>
+    </table>
+    </body></html>



More information about the checkins mailing list