[CalendarServer-changes] [7315] CalendarServer/trunk/contrib/performance/loadtest

[source_changes at macosforge.org]

Revision: 7315
          http://trac.macosforge.org/projects/calendarserver/changeset/7315
Author:   exarkun at twistedmatrix.com
Date:     2011-04-13 11:58:40 -0700 (Wed, 13 Apr 2011)
Log Message:
-----------
Include latency measurements in the request logger output

Modified Paths:
--------------
    CalendarServer/trunk/contrib/performance/loadtest/ical.py
    CalendarServer/trunk/contrib/performance/loadtest/sim.py

Modified: CalendarServer/trunk/contrib/performance/loadtest/ical.py
===================================================================
--- CalendarServer/trunk/contrib/performance/loadtest/ical.py	2011-04-13 15:04:23 UTC (rev 7314)
+++ CalendarServer/trunk/contrib/performance/loadtest/ical.py	2011-04-13 18:58:40 UTC (rev 7315)
@@ -28,6 +28,7 @@
 from vobject.base import ContentLine
 from vobject.icalendar import VEvent, dateTimeToString
 
+from twisted.python import context
 from twisted.python.log import addObserver, err, msg
 from twisted.python.filepath import FilePath
 from twisted.internet.defer import Deferred, inlineCallbacks, returnValue
@@ -185,6 +186,11 @@
 
 
     def _request(self, expectedResponseCode, method, url, headers=None, body=None):
+        # If this is a scheduled request, record the lag in the
+        # scheduling now so it can be reported when the response is
+        # received.
+        lag = context.get('lag', None)
+
         if headers is None:
             headers = Headers({})
         headers.setRawHeaders('User-Agent', [self.USER_AGENT])
@@ -204,7 +210,8 @@
             msg(
                 type="response", success=success, method=method,
                 headers=headers, body=body, code=response.code,
-                user=self.user, duration=(after - before), url=url)
+                user=self.user, duration=(after - before), url=url,
+                lag=lag)
 
             if success:
                 return response
@@ -663,10 +670,17 @@
 
 
 class RequestLogger(object):
-    format = "%(user)s request %(code)s [%(duration)0.2f ms] %(method)8s %(url)s"
+    format = "%(user)s request %(code)s %(lag)s[%(duration)0.2f ms] %(method)8s %(url)s"
+    lagFormat = '{Lag %0.2f ms} '
+    lagSpacer = ' ' * len(lagFormat % (1.0,))
+
     def observe(self, event):
         if event.get("type") == "response":
             event['url'] = urlunparse(('', '') + urlparse(event['url'])[2:])
+            if event.get('lag') is None:
+                event['lag'] = self.lagSpacer
+            else:
+                event['lag'] = self.lagFormat % (event['lag'] * 1000.0,)
             print self.format % event
 
 

Modified: CalendarServer/trunk/contrib/performance/loadtest/sim.py
===================================================================
--- CalendarServer/trunk/contrib/performance/loadtest/sim.py	2011-04-13 15:04:23 UTC (rev 7314)
+++ CalendarServer/trunk/contrib/performance/loadtest/sim.py	2011-04-13 18:58:40 UTC (rev 7315)
@@ -20,6 +20,7 @@
 from plistlib import readPlist
 from collections import namedtuple
 
+from twisted.python import context
 from twisted.python.filepath import FilePath
 from twisted.python.log import addObserver
 from twisted.python.usage import UsageError, Options
@@ -32,6 +33,30 @@
     CalendarClientSimulator)
 
 
+class LagTrackingReactor(object):
+    """
+    This reactor wraps another reactor and proxies all attribute
+    access (including method calls).  It only changes the behavior of
+    L{IReactorTime.callLater} to insert a C{"lag"} key into the
+    context which delayed function calls are invoked with.  This key
+    has a float value which gives the difference in time between when
+    the call was original scheduled and when the call actually took
+    place.
+    """
+    def __init__(self, reactor):
+        self._reactor = reactor
+
+    def __getattr__(self, name):
+        return getattr(self._reactor, name)
+
+    def callLater(self, delay, function, *args, **kwargs):
+        expected = self._reactor.seconds() + delay
+        def modifyContext():
+            now = self._reactor.seconds()
+            context.call({'lag': now - expected}, function, *args, **kwargs)
+        return self._reactor.callLater(delay, modifyContext)
+
+
 class SimOptions(Options):
     """
     Command line configuration options for the load simulator.
@@ -103,7 +128,7 @@
         self.arrival = arrival
         self.parameters = parameters
         self.observers = observers
-        self.reactor = reactor
+        self.reactor = LagTrackingReactor(reactor)
 
 
     @classmethod
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20110413/0c133d82/attachment.html>