Skip to content
Permalink
Browse files

Add additional access log request time break downs (off by default).

  • Loading branch information...
cyrusdaboo committed Jul 11, 2012
1 parent b9a5158 commit 7bf514d1367e6f1f3ed0098287040024b321185f
Showing with 35 additions and 8 deletions.
  1. +19 −4 calendarserver/accesslog.py
  2. +5 −2 twext/web2/log.py
  3. +10 −2 twext/web2/server.py
  4. +1 −0 twistedcaldav/stdconfig.py
@@ -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 @@ def convertUIDtoShortName(uid):
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 @@ def convertUIDtoShortName(uid):
"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 @@ def __init__(self, logpath):
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):
@@ -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 @@ def _log(success, length):
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:
@@ -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 @@ class Request(http.Request):

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 @@ def __init__(self, *args, **kw):
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 @@ def process(self):
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
@@ -435,6 +435,7 @@
"PIDFile" : "caldavd.pid",
"RotateAccessLog" : False,
"EnableExtendedAccessLog": True,
"EnableExtendedTimingAccessLog": False,
"DefaultLogLevel" : "",
"LogLevels" : {},
"LogID" : "",

0 comments on commit 7bf514d

Please sign in to comment.
You can’t perform that action at this time.