[CalendarServer-changes] [9430] CalendarServer/trunk

source_changes at macosforge.org source_changes at macosforge.org
Wed Jul 11 10:09:36 PDT 2012


Revision: 9430
          http://trac.macosforge.org/projects/calendarserver/changeset/9430
Author:   cdaboo at apple.com
Date:     2012-07-11 10:09:36 -0700 (Wed, 11 Jul 2012)
Log Message:
-----------
Add additional access log request time break downs (off by default).

Modified Paths:
--------------
    CalendarServer/trunk/calendarserver/accesslog.py
    CalendarServer/trunk/twext/web2/log.py
    CalendarServer/trunk/twext/web2/server.py
    CalendarServer/trunk/twistedcaldav/stdconfig.py

Modified: CalendarServer/trunk/calendarserver/accesslog.py
===================================================================
--- CalendarServer/trunk/calendarserver/accesslog.py	2012-07-11 17:07:27 UTC (rev 9429)
+++ CalendarServer/trunk/calendarserver/accesslog.py	2012-07-11 17:09:36 UTC (rev 9430)
@@ -1,5 +1,5 @@
 ##
-# Copyright (c) 2006-2009 Apple Inc. All rights reserved.
+# Copyright (c) 2006-2012 Apple Inc. All rights reserved.
 #
 # Licensed under the Apache License, Version 2.0 (the "License");
 # you may not use this file except in compliance with the License.
@@ -124,8 +124,24 @@
                 formats = [
                     format,
                     # Performance monitoring extensions
-                    'i=%(serverInstance)s t=%(timeSpent).1f or=%(outstandingRequests)s',
+                    'i=%(serverInstance)s or=%(outstandingRequests)s',
                 ]
+
+                # Tags for time stamps collected along the way - the first one in the list is the initial
+                # time for request creation - we use that to track the entire request/response time
+                nowtime = time.time()
+                if config.EnableExtendedTimingAccessLog:
+                    basetime = request.timeStamps[0][1]
+                    request.timeStamps[0] = ("t", time.time(),)
+                    for tag, timestamp in request.timeStamps:
+                        formats.append("%s=%.1f" % (tag, (timestamp - basetime) * 1000))
+                        if tag != "t":
+                            basetime = timestamp
+                    if len(request.timeStamps) > 1:
+                        formats.append("%s=%.1f" % ("t-log", (nowtime - basetime) * 1000))
+                else:
+                    formats.append("%s=%.1f" % ("t", (nowtime - request.timeStamps[0][1]) * 1000))
+
                 if hasattr(request, "extendedLogItems"):
                     for k, v in request.extendedLogItems.iteritems():
                         k = str(k).replace('"', "%22")
@@ -158,7 +174,6 @@
                 "referer"             : request.headers.getHeader("referer", "-"),
                 "userAgent"           : request.headers.getHeader("user-agent", "-"),
                 "serverInstance"      : config.LogID,
-                "timeSpent"           : (time.time() - request.initTime) * 1000,
                 "outstandingRequests" : request.chanRequest.channel.factory.outstandingRequests,
                 "fwd"                 : forwardedFor,
             }
@@ -199,7 +214,7 @@
         self.logpath = logpath
         self.globalHitCount = 0 
         self.globalHitHistory = [] 
-        for i in range(0, config.GlobalStatsLoggingFrequency + 1): 
+        for _ignore in range(0, config.GlobalStatsLoggingFrequency + 1): 
             self.globalHitHistory.append({"time":int(time.time()), "hits":0})
 
     def logMessage(self, message, allowrotate=True):

Modified: CalendarServer/trunk/twext/web2/log.py
===================================================================
--- CalendarServer/trunk/twext/web2/log.py	2012-07-11 17:07:27 UTC (rev 9429)
+++ CalendarServer/trunk/twext/web2/log.py	2012-07-11 17:09:36 UTC (rev 9430)
@@ -1,7 +1,7 @@
 # -*- test-case-name: twext.web2.test.test_log -*-
 ##
 # Copyright (c) 2001-2004 Twisted Matrix Laboratories.
-# Copyright (c) 2010 Apple Computer, Inc. All rights reserved.
+# Copyright (c) 2010-2012 Apple Computer, Inc. All rights reserved.
 #
 # Permission is hereby granted, free of charge, to any person obtaining a copy
 # of this software and associated documentation files (the "Software"), to deal
@@ -90,12 +90,15 @@
         loginfo.bytesSent=length
         loginfo.responseCompleted=success
         loginfo.secondsTaken=time.time()-startTime
-        
+
+        if length:        
+            request.timeStamp("t-resp-wr")
         log.msg(interface=iweb.IRequest, request=request, response=response,
                  loginfo=loginfo)
         # Or just...
         # ILogger(ctx).log(...) ?
 
+    request.timeStamp("t-resp-gen")
     if response.stream:
         response.stream=_LogByteCounter(response.stream, _log)
     else:

Modified: CalendarServer/trunk/twext/web2/server.py
===================================================================
--- CalendarServer/trunk/twext/web2/server.py	2012-07-11 17:07:27 UTC (rev 9429)
+++ CalendarServer/trunk/twext/web2/server.py	2012-07-11 17:09:36 UTC (rev 9430)
@@ -1,7 +1,7 @@
 # -*- test-case-name: twext.web2.test.test_server -*-
 ##
 # Copyright (c) 2001-2008 Twisted Matrix Laboratories.
-# Copyright (c) 2010-2011 Apple Computer, Inc. All rights reserved.
+# Copyright (c) 2010-2012 Apple Computer, Inc. All rights reserved.
 #
 # Permission is hereby granted, free of charge, to any person obtaining a copy
 # of this software and associated documentation files (the "Software"), to deal
@@ -192,7 +192,7 @@
 
     def __init__(self, *args, **kw):
         
-        self.initTime = time.time()
+        self.timeStamps = [("t", time.time(),)]
 
         if kw.has_key('site'):
             self.site = kw['site']
@@ -214,6 +214,9 @@
         except AttributeError:
             self.serverInstance = "Unknown"
 
+    def timeStamp(self, tag):
+        self.timeStamps.append((tag, time.time(),))
+
     def addResponseFilter(self, filter, atEnd=False, onlyOnce=False):
         """
         Add a response filter to this request.
@@ -369,12 +372,17 @@
         d = defer.Deferred()
         d.addCallback(self._getChild, self.site.resource, self.postpath)
         d.addCallback(self._rememberResource, "/" + "/".join(quote(s) for s in self.postpath))
+        d.addCallback(self._processTimeStamp)
         d.addCallback(lambda res, req: res.renderHTTP(req), self)
         d.addCallback(self._cbFinishRender)
         d.addErrback(self._processingFailed)
         d.callback(None)
         return d
 
+    def _processTimeStamp(self, res):
+        self.timeStamp("t-req-proc")
+        return res
+
     def preprocessRequest(self):
         """Do any request processing that doesn't follow the normal
         resource lookup procedure. "OPTIONS *" is handled here, for

Modified: CalendarServer/trunk/twistedcaldav/stdconfig.py
===================================================================
--- CalendarServer/trunk/twistedcaldav/stdconfig.py	2012-07-11 17:07:27 UTC (rev 9429)
+++ CalendarServer/trunk/twistedcaldav/stdconfig.py	2012-07-11 17:09:36 UTC (rev 9430)
@@ -435,6 +435,7 @@
     "PIDFile"        : "caldavd.pid",
     "RotateAccessLog"   : False,
     "EnableExtendedAccessLog": True,
+    "EnableExtendedTimingAccessLog": False,
     "DefaultLogLevel"   : "",
     "LogLevels"         : {},
     "LogID"             : "",
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20120711/2e40867f/attachment.html>


More information about the calendarserver-changes mailing list