[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