<!DOCTYPE html PUBLIC "-//W3C//DTD XHTML 1.1//EN"
"http://www.w3.org/TR/xhtml11/DTD/xhtml11.dtd">
<html xmlns="http://www.w3.org/1999/xhtml">
<head><meta http-equiv="content-type" content="text/html; charset=utf-8" />
<title>[9430] CalendarServer/trunk</title>
</head>
<body>

<style type="text/css"><!--
#msg dl.meta { border: 1px #006 solid; background: #369; padding: 6px; color: #fff; }
#msg dl.meta dt { float: left; width: 6em; font-weight: bold; }
#msg dt:after { content:':';}
#msg dl, #msg dt, #msg ul, #msg li, #header, #footer, #logmsg { font-family: verdana,arial,helvetica,sans-serif; font-size: 10pt;  }
#msg dl a { font-weight: bold}
#msg dl a:link    { color:#fc3; }
#msg dl a:active  { color:#ff0; }
#msg dl a:visited { color:#cc6; }
h3 { font-family: verdana,arial,helvetica,sans-serif; font-size: 10pt; font-weight: bold; }
#msg pre { overflow: auto; background: #ffc; border: 1px #fa0 solid; padding: 6px; }
#logmsg { background: #ffc; border: 1px #fa0 solid; padding: 1em 1em 0 1em; }
#logmsg p, #logmsg pre, #logmsg blockquote { margin: 0 0 1em 0; }
#logmsg p, #logmsg li, #logmsg dt, #logmsg dd { line-height: 14pt; }
#logmsg h1, #logmsg h2, #logmsg h3, #logmsg h4, #logmsg h5, #logmsg h6 { margin: .5em 0; }
#logmsg h1:first-child, #logmsg h2:first-child, #logmsg h3:first-child, #logmsg h4:first-child, #logmsg h5:first-child, #logmsg h6:first-child { margin-top: 0; }
#logmsg ul, #logmsg ol { padding: 0; list-style-position: inside; margin: 0 0 0 1em; }
#logmsg ul { text-indent: -1em; padding-left: 1em; }#logmsg ol { text-indent: -1.5em; padding-left: 1.5em; }
#logmsg > ul, #logmsg > ol { margin: 0 0 1em 0; }
#logmsg pre { background: #eee; padding: 1em; }
#logmsg blockquote { border: 1px solid #fa0; border-left-width: 10px; padding: 1em 1em 0 1em; background: white;}
#logmsg dl { margin: 0; }
#logmsg dt { font-weight: bold; }
#logmsg dd { margin: 0; padding: 0 0 0.5em 0; }
#logmsg dd:before { content:'\00bb';}
#logmsg table { border-spacing: 0px; border-collapse: collapse; border-top: 4px solid #fa0; border-bottom: 1px solid #fa0; background: #fff; }
#logmsg table th { text-align: left; font-weight: normal; padding: 0.2em 0.5em; border-top: 1px dotted #fa0; }
#logmsg table td { text-align: right; border-top: 1px dotted #fa0; padding: 0.2em 0.5em; }
#logmsg table thead th { text-align: center; border-bottom: 1px solid #fa0; }
#logmsg table th.Corner { text-align: left; }
#logmsg hr { border: none 0; border-top: 2px dashed #fa0; height: 1px; }
#header, #footer { color: #fff; background: #636; border: 1px #300 solid; padding: 6px; }
#patch { width: 100%; }
#patch h4 {font-family: verdana,arial,helvetica,sans-serif;font-size:10pt;padding:8px;background:#369;color:#fff;margin:0;}
#patch .propset h4, #patch .binary h4 {margin:0;}
#patch pre {padding:0;line-height:1.2em;margin:0;}
#patch .diff {width:100%;background:#eee;padding: 0 0 10px 0;overflow:auto;}
#patch .propset .diff, #patch .binary .diff  {padding:10px 0;}
#patch span {display:block;padding:0 10px;}
#patch .modfile, #patch .addfile, #patch .delfile, #patch .propset, #patch .binary, #patch .copfile {border:1px solid #ccc;margin:10px 0;}
#patch ins {background:#dfd;text-decoration:none;display:block;padding:0 10px;}
#patch del {background:#fdd;text-decoration:none;display:block;padding:0 10px;}
#patch .lines, .info {color:#888;background:#fff;}
--></style>
<div id="msg">
<dl class="meta">
<dt>Revision</dt> <dd><a href="http://trac.macosforge.org/projects/calendarserver/changeset/9430">9430</a></dd>
<dt>Author</dt> <dd>cdaboo@apple.com</dd>
<dt>Date</dt> <dd>2012-07-11 10:09:36 -0700 (Wed, 11 Jul 2012)</dd>
</dl>

<h3>Log Message</h3>
<pre>Add additional access log request time break downs (off by default).</pre>

<h3>Modified Paths</h3>
<ul>
<li><a href="#CalendarServertrunkcalendarserveraccesslogpy">CalendarServer/trunk/calendarserver/accesslog.py</a></li>
<li><a href="#CalendarServertrunktwextweb2logpy">CalendarServer/trunk/twext/web2/log.py</a></li>
<li><a href="#CalendarServertrunktwextweb2serverpy">CalendarServer/trunk/twext/web2/server.py</a></li>
<li><a href="#CalendarServertrunktwistedcaldavstdconfigpy">CalendarServer/trunk/twistedcaldav/stdconfig.py</a></li>
</ul>

</div>
<div id="patch">
<h3>Diff</h3>
<a id="CalendarServertrunkcalendarserveraccesslogpy"></a>
<div class="modfile"><h4>Modified: CalendarServer/trunk/calendarserver/accesslog.py (9429 => 9430)</h4>
<pre class="diff"><span>
<span class="info">--- 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)
</span><span class="lines">@@ -1,5 +1,5 @@
</span><span class="cx"> ##
</span><del>-# Copyright (c) 2006-2009 Apple Inc. All rights reserved.
</del><ins>+# Copyright (c) 2006-2012 Apple Inc. All rights reserved.
</ins><span class="cx"> #
</span><span class="cx"> # Licensed under the Apache License, Version 2.0 (the &quot;License&quot;);
</span><span class="cx"> # you may not use this file except in compliance with the License.
</span><span class="lines">@@ -124,8 +124,24 @@
</span><span class="cx">                 formats = [
</span><span class="cx">                     format,
</span><span class="cx">                     # Performance monitoring extensions
</span><del>-                    'i=%(serverInstance)s t=%(timeSpent).1f or=%(outstandingRequests)s',
</del><ins>+                    'i=%(serverInstance)s or=%(outstandingRequests)s',
</ins><span class="cx">                 ]
</span><ins>+
+                # 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] = (&quot;t&quot;, time.time(),)
+                    for tag, timestamp in request.timeStamps:
+                        formats.append(&quot;%s=%.1f&quot; % (tag, (timestamp - basetime) * 1000))
+                        if tag != &quot;t&quot;:
+                            basetime = timestamp
+                    if len(request.timeStamps) &gt; 1:
+                        formats.append(&quot;%s=%.1f&quot; % (&quot;t-log&quot;, (nowtime - basetime) * 1000))
+                else:
+                    formats.append(&quot;%s=%.1f&quot; % (&quot;t&quot;, (nowtime - request.timeStamps[0][1]) * 1000))
+
</ins><span class="cx">                 if hasattr(request, &quot;extendedLogItems&quot;):
</span><span class="cx">                     for k, v in request.extendedLogItems.iteritems():
</span><span class="cx">                         k = str(k).replace('&quot;', &quot;%22&quot;)
</span><span class="lines">@@ -158,7 +174,6 @@
</span><span class="cx">                 &quot;referer&quot;             : request.headers.getHeader(&quot;referer&quot;, &quot;-&quot;),
</span><span class="cx">                 &quot;userAgent&quot;           : request.headers.getHeader(&quot;user-agent&quot;, &quot;-&quot;),
</span><span class="cx">                 &quot;serverInstance&quot;      : config.LogID,
</span><del>-                &quot;timeSpent&quot;           : (time.time() - request.initTime) * 1000,
</del><span class="cx">                 &quot;outstandingRequests&quot; : request.chanRequest.channel.factory.outstandingRequests,
</span><span class="cx">                 &quot;fwd&quot;                 : forwardedFor,
</span><span class="cx">             }
</span><span class="lines">@@ -199,7 +214,7 @@
</span><span class="cx">         self.logpath = logpath
</span><span class="cx">         self.globalHitCount = 0 
</span><span class="cx">         self.globalHitHistory = [] 
</span><del>-        for i in range(0, config.GlobalStatsLoggingFrequency + 1): 
</del><ins>+        for _ignore in range(0, config.GlobalStatsLoggingFrequency + 1): 
</ins><span class="cx">             self.globalHitHistory.append({&quot;time&quot;:int(time.time()), &quot;hits&quot;:0})
</span><span class="cx"> 
</span><span class="cx">     def logMessage(self, message, allowrotate=True):
</span></span></pre></div>
<a id="CalendarServertrunktwextweb2logpy"></a>
<div class="modfile"><h4>Modified: CalendarServer/trunk/twext/web2/log.py (9429 => 9430)</h4>
<pre class="diff"><span>
<span class="info">--- 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)
</span><span class="lines">@@ -1,7 +1,7 @@
</span><span class="cx"> # -*- test-case-name: twext.web2.test.test_log -*-
</span><span class="cx"> ##
</span><span class="cx"> # Copyright (c) 2001-2004 Twisted Matrix Laboratories.
</span><del>-# Copyright (c) 2010 Apple Computer, Inc. All rights reserved.
</del><ins>+# Copyright (c) 2010-2012 Apple Computer, Inc. All rights reserved.
</ins><span class="cx"> #
</span><span class="cx"> # Permission is hereby granted, free of charge, to any person obtaining a copy
</span><span class="cx"> # of this software and associated documentation files (the &quot;Software&quot;), to deal
</span><span class="lines">@@ -90,12 +90,15 @@
</span><span class="cx">         loginfo.bytesSent=length
</span><span class="cx">         loginfo.responseCompleted=success
</span><span class="cx">         loginfo.secondsTaken=time.time()-startTime
</span><del>-        
</del><ins>+
+        if length:        
+            request.timeStamp(&quot;t-resp-wr&quot;)
</ins><span class="cx">         log.msg(interface=iweb.IRequest, request=request, response=response,
</span><span class="cx">                  loginfo=loginfo)
</span><span class="cx">         # Or just...
</span><span class="cx">         # ILogger(ctx).log(...) ?
</span><span class="cx"> 
</span><ins>+    request.timeStamp(&quot;t-resp-gen&quot;)
</ins><span class="cx">     if response.stream:
</span><span class="cx">         response.stream=_LogByteCounter(response.stream, _log)
</span><span class="cx">     else:
</span></span></pre></div>
<a id="CalendarServertrunktwextweb2serverpy"></a>
<div class="modfile"><h4>Modified: CalendarServer/trunk/twext/web2/server.py (9429 => 9430)</h4>
<pre class="diff"><span>
<span class="info">--- 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)
</span><span class="lines">@@ -1,7 +1,7 @@
</span><span class="cx"> # -*- test-case-name: twext.web2.test.test_server -*-
</span><span class="cx"> ##
</span><span class="cx"> # Copyright (c) 2001-2008 Twisted Matrix Laboratories.
</span><del>-# Copyright (c) 2010-2011 Apple Computer, Inc. All rights reserved.
</del><ins>+# Copyright (c) 2010-2012 Apple Computer, Inc. All rights reserved.
</ins><span class="cx"> #
</span><span class="cx"> # Permission is hereby granted, free of charge, to any person obtaining a copy
</span><span class="cx"> # of this software and associated documentation files (the &quot;Software&quot;), to deal
</span><span class="lines">@@ -192,7 +192,7 @@
</span><span class="cx"> 
</span><span class="cx">     def __init__(self, *args, **kw):
</span><span class="cx">         
</span><del>-        self.initTime = time.time()
</del><ins>+        self.timeStamps = [(&quot;t&quot;, time.time(),)]
</ins><span class="cx"> 
</span><span class="cx">         if kw.has_key('site'):
</span><span class="cx">             self.site = kw['site']
</span><span class="lines">@@ -214,6 +214,9 @@
</span><span class="cx">         except AttributeError:
</span><span class="cx">             self.serverInstance = &quot;Unknown&quot;
</span><span class="cx"> 
</span><ins>+    def timeStamp(self, tag):
+        self.timeStamps.append((tag, time.time(),))
+
</ins><span class="cx">     def addResponseFilter(self, filter, atEnd=False, onlyOnce=False):
</span><span class="cx">         &quot;&quot;&quot;
</span><span class="cx">         Add a response filter to this request.
</span><span class="lines">@@ -369,12 +372,17 @@
</span><span class="cx">         d = defer.Deferred()
</span><span class="cx">         d.addCallback(self._getChild, self.site.resource, self.postpath)
</span><span class="cx">         d.addCallback(self._rememberResource, &quot;/&quot; + &quot;/&quot;.join(quote(s) for s in self.postpath))
</span><ins>+        d.addCallback(self._processTimeStamp)
</ins><span class="cx">         d.addCallback(lambda res, req: res.renderHTTP(req), self)
</span><span class="cx">         d.addCallback(self._cbFinishRender)
</span><span class="cx">         d.addErrback(self._processingFailed)
</span><span class="cx">         d.callback(None)
</span><span class="cx">         return d
</span><span class="cx"> 
</span><ins>+    def _processTimeStamp(self, res):
+        self.timeStamp(&quot;t-req-proc&quot;)
+        return res
+
</ins><span class="cx">     def preprocessRequest(self):
</span><span class="cx">         &quot;&quot;&quot;Do any request processing that doesn't follow the normal
</span><span class="cx">         resource lookup procedure. &quot;OPTIONS *&quot; is handled here, for
</span></span></pre></div>
<a id="CalendarServertrunktwistedcaldavstdconfigpy"></a>
<div class="modfile"><h4>Modified: CalendarServer/trunk/twistedcaldav/stdconfig.py (9429 => 9430)</h4>
<pre class="diff"><span>
<span class="info">--- 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)
</span><span class="lines">@@ -435,6 +435,7 @@
</span><span class="cx">     &quot;PIDFile&quot;        : &quot;caldavd.pid&quot;,
</span><span class="cx">     &quot;RotateAccessLog&quot;   : False,
</span><span class="cx">     &quot;EnableExtendedAccessLog&quot;: True,
</span><ins>+    &quot;EnableExtendedTimingAccessLog&quot;: False,
</ins><span class="cx">     &quot;DefaultLogLevel&quot;   : &quot;&quot;,
</span><span class="cx">     &quot;LogLevels&quot;         : {},
</span><span class="cx">     &quot;LogID&quot;             : &quot;&quot;,
</span></span></pre>
</div>
</div>

</body>
</html>