[Checkins] SVN: zc.zservertracelog/branches/jim-dev/ checkpoint
Jim Fulton
jim at zope.com
Thu Apr 8 09:44:13 EDT 2010
Log message for revision 110635:
checkpoint
Changed:
U zc.zservertracelog/branches/jim-dev/CHANGES.txt
U zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/README.txt
U zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/configure.zcml
U zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tests.py
U zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracelog.py
U zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.py
U zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.txt
-=-
Modified: zc.zservertracelog/branches/jim-dev/CHANGES.txt
===================================================================
--- zc.zservertracelog/branches/jim-dev/CHANGES.txt 2010-04-08 13:34:20 UTC (rev 110634)
+++ zc.zservertracelog/branches/jim-dev/CHANGES.txt 2010-04-08 13:44:12 UTC (rev 110635)
@@ -1,6 +1,12 @@
Changes
=======
+1.3.0 (2010-04-??)
+------------------
+
+- Added 'D' records providing database transfer counts.
+
+
1.2.1 (2010-01-27)
------------------
Modified: zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/README.txt
===================================================================
--- zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/README.txt 2010-04-08 13:34:20 UTC (rev 110634)
+++ zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/README.txt 2010-04-08 13:44:12 UTC (rev 110635)
@@ -36,8 +36,9 @@
Tracing Applications
====================
-The tracelog machinery is implemented as a WSGI layer, so we'll pass a fake
-WSGI application to tracelog for these examples.
+The tracelog machinery is primarily implemented as an extension to the
+zope.server WSGI server. To test the tracelog machinery, we'll create
+our own application.
>>> faux_app = FauxApplication()
@@ -69,7 +70,23 @@
A 23423600 2008-08-27 10:54:08.000000 200 ?
E 23423600 2008-08-27 10:54:08.000000
+Here we get records for each stage in the request:
+B
+ The request began
+
+I
+ Input was read.
+
+C
+ An application thread began processing the request.
+
+A
+ The esponse was computed.
+
+E
+ The request ended.
+
Application Errors
==================
@@ -102,7 +119,11 @@
response that produces an error when written to.
>>> def response_of_wrong_type(*args, **kwargs):
- ... return object()
+ ... def f():
+ ... if 0:
+ ... yield 1
+ ... raise ValueError("sample error")
+ ... return f()
>>> faux_app.app_hook = response_of_wrong_type
Invoking the request produces log entries for every trace point, and the
@@ -116,7 +137,7 @@
I 21651664 2008-09-02 13:59:02.000000 0
C 21651664 2008-09-02 13:59:02.000000
A 21651664 2008-09-02 13:59:02.000000 200 ?
- E 21651664 2008-09-02 13:59:02.000000 Error: iteration over non-sequence
+ E 21651664 2008-09-02 13:59:02.000000 Error: sample error
Let's clean up before moving on.
@@ -198,3 +219,70 @@
- 21569456 2008-09-12 15:51:05.000000 beep! beep!
A 21569456 2008-09-12 15:51:05.000000 200 ?
E 21569456 2008-09-12 15:51:05.000000
+
+
+Database statistics
+===================
+
+zc.zservertracelog provides event subscrivers that gather statistics
+about database usage in a request. It assumes that requests have
+'ZODB.interfaces.IConnection' annotations that are ZODB database
+connections. To demonstrate how this works, we'll create a number of
+stubs:
+
+ >>> class Connection:
+ ... reads = writes = 0
+ ... db = lambda self: self
+ ... getTransferCounts = lambda self: (self.reads, self.writes)
+ ... def __init__(self, environ, *names):
+ ... self.get = environ.get
+ ... self.databases = names
+ ... self._connections = dict((name, Connection(environ))
+ ... for name in names)
+ ... self.get_connection = self._connections.get
+ ... request = property(lambda self: self)
+ ... @property
+ ... def annotations(self):
+ ... return {'ZODB.interfaces.IConnection': self}
+ ... def update(self, name, reads=0, writes=0):
+ ... c = self._connections[name]
+ ... c.reads, c.writes = reads, writes
+
+The Connection stub is kind of heinous. :) It actually stubs out
+zope.app.publisher request events, requests, connections, and
+databases.
+
+We simulate a request that calls the traversal hooks a couple of
+times,does some database activity and redoes requests due to conflicts.
+
+ >>> def dbapp1(environ, start_response):
+ ... conn = Connection(environ, '', 'x', 'y')
+ ... conn.update('', 1, 1)
+ ... conn.update('x', 2, 2)
+ ... zc.zservertracelog.tracelog.before_traverse(conn)
+ ... conn.update('', 3, 1)
+ ... zc.zservertracelog.tracelog.before_traverse(conn)
+ ... conn.update('', 5, 3)
+ ... conn.update('y', 1, 0)
+ ... zc.zservertracelog.tracelog.request_ended(conn)
+ ... zc.zservertracelog.tracelog.before_traverse(conn)
+ ... conn.update('', 6, 3)
+ ... zc.zservertracelog.tracelog.before_traverse(conn)
+ ... conn.update('', 7, 4)
+ ... conn.update('y', 3, 0)
+ ... zc.zservertracelog.tracelog.request_ended(conn)
+
+ >>> faux_app.app_hook = dbapp1
+
+ >>> invokeRequest(req1)
+ B 49234448 2010-04-07 17:03:41.229648 GET /test-req1
+ I 49234448 2010-04-07 17:03:41.229811 0
+ C 49234448 2010-04-07 17:03:41.229943
+ D 49234448 2010-04-07 17:03:41.230131 4 2 y 1 0
+ D 49234448 2010-04-07 17:03:41.230264 2 1 y 2 0
+ A 49234448 2010-04-07 17:03:41.230364 200 ?
+ E 23418928 2008-08-26 10:55:00.000000
+
+Here we got multiple D records due to conflicts. We show database
+activity for those databases for which there was any. The databases
+are sorted by name, with the unnamed database coming first.
Modified: zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/configure.zcml
===================================================================
--- zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/configure.zcml 2010-04-08 13:34:20 UTC (rev 110634)
+++ zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/configure.zcml 2010-04-08 13:44:12 UTC (rev 110635)
@@ -16,5 +16,7 @@
<adapter factory="zc.zservertracelog.tracelog.get" />
<subscriber handler=".tracelog.started" />
+ <subscriber handler=".tracelog.before_traverse" />
+ <subscriber handler=".tracelog.request_ended" />
</configure>
Modified: zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tests.py
===================================================================
--- zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tests.py 2010-04-08 13:34:20 UTC (rev 110634)
+++ zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tests.py 2010-04-08 13:44:12 UTC (rev 110635)
@@ -28,6 +28,8 @@
# normalize the channel id and iso8601 timestamp
(re.compile(r'-?\d+ \d{4}-\d{2}-\d{2} \d{2}:\d{2}:\d{2}.\d{6}'),
'23418928 2008-08-26 10:55:00.000000'),
+ (re.compile(r'^usage: '), 'Usage: '),
+ (re.compile(r'options:'), 'Options:'),
])
_null_app = lambda environ, start_response: None
Modified: zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracelog.py
===================================================================
--- zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracelog.py 2010-04-08 13:34:20 UTC (rev 110634)
+++ zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracelog.py 2010-04-08 13:44:12 UTC (rev 110635)
@@ -17,12 +17,23 @@
from zope.app.wsgi import WSGIPublisherApplication
from zope.server.http import wsgihttpserver
from zope.server.http.commonaccesslogger import CommonAccessLogger
+
+# Gaaaa, these have moved:
+try:
+ from zope.publisher.interfaces import BeforeTraverseEvent
+ from zope.publisher.interfaces import EndRequestEvent
+except ImportError:
+ from zope.app.publication.interfaces import BeforeTraverseEvent
+ from zope.app.publication.interfaces import EndRequestEvent
+
+
import datetime
import logging
import re
import zc.zservertracelog.interfaces
import zope.app.appsetup.interfaces
import zope.component
+import zope.app.publication.interfaces
import zope.server.http.httprequestparser
import zope.server.http.httpserverchannel
@@ -50,6 +61,8 @@
class TraceLog(object):
zope.interface.implements(zc.zservertracelog.interfaces.ITraceLog)
+ transfer_counts = None
+
def __init__(self, channel_id):
self.channel_id = channel_id
@@ -154,3 +167,38 @@
@zope.component.adapter(zope.app.appsetup.interfaces.IProcessStartingEvent)
def started(event):
tracelog.info('S 0 %s', datetime.datetime.now())
+
+ at zope.component.adapter(BeforeTraverseEvent)
+def before_traverse(event):
+ request = event.request
+ tl = request.get('zc.zservertracelog.interfaces.ITraceLog')
+ if tl is None:
+ return
+ if tl.transfer_counts is None:
+ connection = request.annotations['ZODB.interfaces.IConnection']
+ tl.transfer_counts = dict(
+ (name, connection.get_connection(name).getTransferCounts())
+ for name in connection.db().databases)
+
+ at zope.component.adapter(EndRequestEvent)
+def request_ended(event):
+ request = event.request
+ tl = request.get('zc.zservertracelog.interfaces.ITraceLog')
+ if tl is None:
+ return
+ initial_counts = tl.transfer_counts
+ if not initial_counts:
+ return
+ tl.transfer_counts = None # Reset in case of conflict
+ connection = request.annotations['ZODB.interfaces.IConnection']
+ data = []
+ for name in connection.db().databases:
+ conn = connection.get_connection(name)
+ r, w = conn.getTransferCounts()
+ ir, iw = initial_counts[name]
+ r -= ir
+ w -= iw
+ if r or w:
+ data.append((name, r, w))
+ msg = ' '.join(' '.join(map(str, r)) for r in sorted(data))
+ _log(tl.channel_id, 'D', msg.strip())
Modified: zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.py
===================================================================
--- zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.py 2010-04-08 13:34:20 UTC (rev 110634)
+++ zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.py 2010-04-08 13:44:12 UTC (rev 110635)
@@ -446,19 +446,19 @@
def print_app_requests_html(requests, dt, min_seconds, max_requests, allurls,
label=''):
requests = [
- ((dt-request.start).seconds, request)
+ ((dt-request.start).seconds, request.url, request)
for request in requests.values()
if request.state == 'app'
]
urls = {}
- for s, request in requests:
- urls[request.url] = urls.get(request.url, 0) + 1
+ for s, url, request in requests:
+ urls[url] = urls.get(url, 0) + 1
requests.sort()
requests.reverse()
printed = False
- for s, request in requests[:max_requests]:
+ for s, url, request in requests[:max_requests]:
if s < min_seconds:
continue
if label:
@@ -469,7 +469,6 @@
print '<table border="1">'
print '<tr><th>age</th><th>R</th><th>url</th><th>state</th></tr>'
printed = True
- url = request.url
repeat = urls[url]
print '<tr>'
if repeat <= 1:
Modified: zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.txt
===================================================================
--- zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.txt 2010-04-08 13:34:20 UTC (rev 110634)
+++ zc.zservertracelog/branches/jim-dev/src/zc/zservertracelog/tracereport.txt 2010-04-08 13:44:12 UTC (rev 110635)
@@ -5,6 +5,8 @@
`tracereport.py` provides a basic means to analyze a tracelog and generate a
report.
+ >>> import os
+ >>> os.environ['COLUMNS'] = '70'
>>> import zc.zservertracelog.tracereport
The '--help' option displays the following usage information:
@@ -13,7 +15,7 @@
... zc.zservertracelog.tracereport.main(['--help'])
... except SystemExit:
... pass
- usage: test [options] trace_log_file
+ Usage: test [options] trace_log_file
<BLANKLINE>
Output trace log data showing:
<BLANKLINE>
@@ -38,22 +40,23 @@
<BLANKLINE>
<BLANKLINE>
<BLANKLINE>
- options:
+ 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.
+ 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.
+ 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.
+ 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.
@@ -61,6 +64,7 @@
--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(
More information about the checkins
mailing list