[Checkins] SVN: zc.zservertracelog/trunk/ Added ZODB database statistics.
Jim Fulton
jim at zope.com
Thu Apr 8 10:22:19 EDT 2010
Log message for revision 110638:
Added ZODB database statistics.
Changed:
U zc.zservertracelog/trunk/CHANGES.txt
U zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
U zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml
U zc.zservertracelog/trunk/src/zc/zservertracelog/samples/trace.log
U zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py
-=-
Modified: zc.zservertracelog/trunk/CHANGES.txt
===================================================================
--- zc.zservertracelog/trunk/CHANGES.txt 2010-04-08 14:22:16 UTC (rev 110637)
+++ zc.zservertracelog/trunk/CHANGES.txt 2010-04-08 14:22:18 UTC (rev 110638)
@@ -1,6 +1,13 @@
Changes
=======
+1.3.0 (2010-04-??)
+------------------
+
+- Added 'D' records providing database transfer counts.
+ This is somewhat experimental. The tracereport script ignores D
+ records.
+
1.2.1 (2010-01-27)
------------------
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2010-04-08 14:22:16 UTC (rev 110637)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/README.txt 2010-04-08 14:22:18 UTC (rev 110638)
@@ -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,72 @@
- 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. For each
+database, the number of object's read and written are provided.
+
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml 2010-04-08 14:22:16 UTC (rev 110637)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/configure.zcml 2010-04-08 14:22:18 UTC (rev 110638)
@@ -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/trunk/src/zc/zservertracelog/samples/trace.log
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/samples/trace.log 2010-04-08 14:22:16 UTC (rev 110637)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/samples/trace.log 2010-04-08 14:22:18 UTC (rev 110638)
@@ -1,4 +1,5 @@
C 0.-1429402676 2009-07-30 15:47:18.436894
+D 0.-1429402676 2009-07-30 15:47:21.349080 302 0
A 0.-1429402676 2009-07-30 15:47:21.349080 302 0
E 0.-1429402676 2009-07-30 15:47:21.349251
B 0.-1451819092 2009-07-30 15:47:21.560343 GET /columns/t-jansen
Modified: zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py
===================================================================
--- zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py 2010-04-08 14:22:16 UTC (rev 110637)
+++ zc.zservertracelog/trunk/src/zc/zservertracelog/tracelog.py 2010-04-08 14:22:18 UTC (rev 110638)
@@ -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())
More information about the checkins
mailing list