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

source_changes at macosforge.org source_changes at macosforge.org
Wed Apr 20 12:20:07 PDT 2011


Revision: 7335
          http://trac.macosforge.org/projects/calendarserver/changeset/7335
Author:   exarkun at twistedmatrix.com
Date:     2011-04-20 12:20:07 -0700 (Wed, 20 Apr 2011)
Log Message:
-----------
Move latency reporting off of first request in an operation onto the operation start message; some other minor formatting improvements.

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

Modified: CalendarServer/trunk/contrib/performance/loadtest/ical.py
===================================================================
--- CalendarServer/trunk/contrib/performance/loadtest/ical.py	2011-04-20 16:47:11 UTC (rev 7334)
+++ CalendarServer/trunk/contrib/performance/loadtest/ical.py	2011-04-20 19:20:07 UTC (rev 7335)
@@ -28,7 +28,6 @@
 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
@@ -186,11 +185,6 @@
 
 
     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])
@@ -210,8 +204,7 @@
             msg(
                 type="response", success=success, method=method,
                 headers=headers, body=body, code=response.code,
-                user=self.user, duration=(after - before), url=url,
-                lag=lag)
+                user=self.user, duration=(after - before), url=url)
 
             if success:
                 return response
@@ -670,20 +663,13 @@
 
 
 class RequestLogger(object):
-    format = u"%(user)s request %(code)s%(success)s%(lag)s[%(duration)5.2f s] %(method)8s %(url)s"
-    lagFormat = u'{Lag %5.2f ms}'
-    lagSpacer = u' ' * len(lagFormat % (1.0,))
-
+    format = u"%(user)s request %(code)s%(success)s[%(duration)5.2f s] %(method)8s %(url)s"
     success = u"\N{CHECK MARK}"
     failure = u"\N{BALLOT X}"
 
     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,)
             if event['success']:
                 event['success'] = self.success
             else:

Modified: CalendarServer/trunk/contrib/performance/loadtest/profiles.py
===================================================================
--- CalendarServer/trunk/contrib/performance/loadtest/profiles.py	2011-04-20 16:47:11 UTC (rev 7334)
+++ CalendarServer/trunk/contrib/performance/loadtest/profiles.py	2011-04-20 19:20:07 UTC (rev 7335)
@@ -30,10 +30,11 @@
 
 from protocol.caldav.definitions import caldavxml
 
+from twisted.python import context
 from twisted.python.log import msg
 from twisted.python.failure import Failure
 from twisted.internet.defer import succeed, fail
-from twisted.internet.task import LoopingCall, deferLater
+from twisted.internet.task import LoopingCall
 from twisted.web.http import PRECONDITION_FAILED
 
 from loadtest.logger import SummarizingMixin
@@ -75,9 +76,15 @@
         Helper to emit a log event when a new operation is started and
         another one when it completes.
         """
+        # 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)
+
         before = self._reactor.seconds()
         msg(type="operation", phase="start",
-            user=self._client.user, label=label)
+            user=self._client.user, label=label, lag=lag)
+
         def finished(passthrough):
             success = not isinstance(passthrough, Failure)
             after = self._reactor.seconds()
@@ -231,10 +238,8 @@
                     # XXX Base this on something real
                     delay = self.random.gauss(10, 2)
                     self._accepting.add(href)
-                    d = deferLater(
-                        self._reactor, delay,
-                        self._acceptInvitation, href, attendee)
-                    return self._newOperation("accept", d)
+                    self._reactor.callLater(
+                        delay, self._acceptInvitation, href, attendee)
 
 
     def _acceptInvitation(self, href, attendee):
@@ -272,7 +277,7 @@
             self._accepting.remove(href)
             return passthrough
         d.addBoth(finished)
-        return d
+        return self._newOperation("accept", d)
 
 
     def _makeAcceptedAttendee(self, attendee):
@@ -354,7 +359,7 @@
             href = '%s%s.ics' % (
                 calendar.url, vevent.contents[u'uid'][0].value)
             d = self._client.addEvent(href, vcalendar)
-            return self._newOperation("new-event", d)
+            return self._newOperation("create", d)
 
 
 class OperationLogger(SummarizingMixin):
@@ -364,10 +369,12 @@
     logger.
     """
     formats = {
-        u"start": u"%(user)s %(label)s begin",
-        u"end": u"%(user)s %(label)s end [%(duration)5.2f s]",
+        u"start": u"%(user)s - - - - - - - - - - - %(label)8s BEGIN %(lag)s",
+        u"end"  : u"%(user)s - - - - - - - - - - - %(label)8s END [%(duration)5.2f s]",
         }
 
+    lagFormat = u'{lag %5.2f ms}'
+
     _fields = [
         ('operation', 10, '%10s'),
         ('count', 8, '%8s'),
@@ -383,6 +390,10 @@
 
     def observe(self, event):
         if event.get("type") == "operation":
+            if event.get('lag') is None:
+                event['lag'] = ''
+            else:
+                event['lag'] = self.lagFormat % (event['lag'] * 1000.0,)
             print (self.formats[event[u'phase']] % event).encode('utf-8')
             if event[u'phase'] == u'end':
                 dataset = self._perOperationTimes.setdefault(event[u'label'], [])
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20110420/6cb53679/attachment-0001.html>


More information about the calendarserver-changes mailing list