<!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>[15684] CalendarServer/trunk/calendarserver</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.calendarserver.org//changeset/15684">15684</a></dd>
<dt>Author</dt> <dd>cdaboo@apple.com</dd>
<dt>Date</dt> <dd>2016-06-20 06:37:51 -0700 (Mon, 20 Jun 2016)</dd>
</dl>
<h3>Log Message</h3>
<pre>Improve performance of dashboard by logging less data, caching aggregated stats, and removing data older than an hour.</pre>
<h3>Modified Paths</h3>
<ul>
<li><a href="#CalendarServertrunkcalendarserveraccesslogpy">CalendarServer/trunk/calendarserver/accesslog.py</a></li>
<li><a href="#CalendarServertrunkcalendarservertesttest_accesslogpy">CalendarServer/trunk/calendarserver/test/test_accesslog.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 (15683 => 15684)</h4>
<pre class="diff"><span>
<span class="info">--- CalendarServer/trunk/calendarserver/accesslog.py 2016-06-17 20:55:13 UTC (rev 15683)
+++ CalendarServer/trunk/calendarserver/accesslog.py 2016-06-20 13:37:51 UTC (rev 15684)
</span><span class="lines">@@ -36,11 +36,11 @@
</span><span class="cx"> from sys import platform
</span><span class="cx"> import time
</span><span class="cx">
</span><del>-from calendarserver.logAnalysis import getAdjustedMethodName, \
- getAdjustedClientName
</del><ins>+from calendarserver.logAnalysis import getAdjustedMethodName
</ins><span class="cx">
</span><span class="cx"> from twext.python.log import Logger
</span><span class="cx"> from twext.who.idirectory import RecordType
</span><ins>+
</ins><span class="cx"> from txweb2 import iweb
</span><span class="cx"> from txweb2.log import BaseCommonAccessLoggingObserver
</span><span class="cx"> from txweb2.log import LogWrapperResource
</span><span class="lines">@@ -248,6 +248,9 @@
</span><span class="cx">
</span><span class="cx"> self.systemStats = None
</span><span class="cx"> self.statsByMinute = []
</span><ins>+ self.stats1m = None
+ self.stats5m = None
+ self.stats1h = None
</ins><span class="cx">
</span><span class="cx">
</span><span class="cx"> def accessLog(self, message, allowrotate=True):
</span><span class="lines">@@ -412,32 +415,35 @@
</span><span class="cx"> currentStats = self.ensureSequentialStats()
</span><span class="cx">
</span><span class="cx"> # Get previous minute details
</span><del>- index = min(2, len(self.statsByMinute))
- if index > 0:
- previousMinute = self.statsByMinute[-index][1]
- else:
- previousMinute = self.initStats()
</del><ins>+ if self.stats1m is None:
+ index = min(2, len(self.statsByMinute))
+ if index > 0:
+ self.stats1m = self.statsByMinute[-index][1]
+ else:
+ self.stats1m = self.initStats()
</ins><span class="cx">
</span><span class="cx"> # Do five minute aggregate
</span><del>- fiveMinutes = self.initStats()
- index = min(6, len(self.statsByMinute))
- for i in range(-index, -1):
- stat = self.statsByMinute[i][1]
- self.mergeStats(fiveMinutes, stat)
</del><ins>+ if self.stats5m is None:
+ self.stats5m = self.initStats()
+ index = min(6, len(self.statsByMinute))
+ for i in range(-index, -1):
+ stat = self.statsByMinute[i][1]
+ self.mergeStats(self.stats5m, stat)
</ins><span class="cx">
</span><span class="cx"> # Do one hour aggregate
</span><del>- oneHour = self.initStats()
- index = min(61, len(self.statsByMinute))
- for i in range(-index, -1):
- stat = self.statsByMinute[i][1]
- self.mergeStats(oneHour, stat)
</del><ins>+ if self.stats1h is None:
+ self.stats1h = self.initStats()
+ index = min(61, len(self.statsByMinute))
+ for i in range(-index, -1):
+ stat = self.statsByMinute[i][1]
+ self.mergeStats(self.stats1h, stat)
</ins><span class="cx">
</span><span class="cx"> printStats = {
</span><span class="cx"> "system": self.systemStats.items,
</span><span class="cx"> "current": currentStats,
</span><del>- "1m": previousMinute,
- "5m": fiveMinutes,
- "1h": oneHour,
</del><ins>+ "1m": self.stats1m,
+ "5m": self.stats5m,
+ "1h": self.stats1h,
</ins><span class="cx"> }
</span><span class="cx"> return printStats
</span><span class="cx">
</span><span class="lines">@@ -451,11 +457,30 @@
</span><span class="cx"> if len(self.statsByMinute) > 0:
</span><span class="cx"> if self.statsByMinute[-1][0] != dtindex:
</span><span class="cx"> oldindex = self.statsByMinute[-1][0]
</span><ins>+ if oldindex != dtindex:
+ # Adding a new minutes worth of data - clear out any cached
+ # historical data
+ self.stats1m = None
+ self.stats5m = None
+ self.stats1h = None
+
+ # Add enough new stats to account for any idle minutes between
+ # the last recorded stat and the current one
</ins><span class="cx"> while oldindex != dtindex:
</span><span class="cx"> oldindex += 60
</span><span class="cx"> self.statsByMinute.append((oldindex, self.initStats(),))
</span><span class="cx"> else:
</span><span class="cx"> self.statsByMinute.append((dtindex, self.initStats(),))
</span><ins>+ self.stats1m = None
+ self.stats5m = None
+ self.stats1h = None
+
+ # We only need up to 1 hour's worth of data, so truncate the cached data
+ # to avoid filling memory
+ threshold = 65
+ if len(self.statsByMinute) > threshold:
+ self.statsByMinute = self.statsByMinute[-threshold:]
+
</ins><span class="cx"> return self.statsByMinute[-1][1]
</span><span class="cx">
</span><span class="cx">
</span><span class="lines">@@ -478,8 +503,6 @@
</span><span class="cx"> "requests" : 0,
</span><span class="cx"> "method" : collections.defaultdict(int),
</span><span class="cx"> "method-t" : collections.defaultdict(float),
</span><del>- "uid" : collections.defaultdict(int),
- "user-agent" : collections.defaultdict(int),
</del><span class="cx"> "500" : 0,
</span><span class="cx"> "401" : 0,
</span><span class="cx"> "t" : 0.0,
</span><span class="lines">@@ -496,15 +519,12 @@
</span><span class="cx"> def updateStats(self, current, stats):
</span><span class="cx"> # Gather specific information and aggregate into our persistent stats
</span><span class="cx"> adjustedMethod = getAdjustedMethodName(stats)
</span><del>- adjustedClient = getAdjustedClientName(stats)
</del><span class="cx">
</span><span class="cx"> if current["requests"] == 0:
</span><span class="cx"> current["cpu"] = 0.0
</span><span class="cx"> current["requests"] += 1
</span><span class="cx"> current["method"][adjustedMethod] += 1
</span><span class="cx"> current["method-t"][adjustedMethod] += stats.get("t", 0.0)
</span><del>- current["uid"][stats["uid"]] += 1
- current["user-agent"][adjustedClient] += 1
</del><span class="cx"> if stats["statusCode"] >= 500:
</span><span class="cx"> current["500"] += 1
</span><span class="cx"> elif stats["statusCode"] == 401:
</span><span class="lines">@@ -553,10 +573,6 @@
</span><span class="cx"> current["method"][method] += stats["method"][method]
</span><span class="cx"> for method in stats["method-t"].keys():
</span><span class="cx"> current["method-t"][method] += stats["method-t"][method]
</span><del>- for uid in stats["uid"].keys():
- current["uid"][uid] += stats["uid"][uid]
- for ua in stats["user-agent"].keys():
- current["user-agent"][ua] += stats["user-agent"][ua]
</del><span class="cx"> current["500"] += stats["500"]
</span><span class="cx"> current["401"] += stats["401"]
</span><span class="cx"> current["t"] += stats["t"]
</span></span></pre></div>
<a id="CalendarServertrunkcalendarservertesttest_accesslogpy"></a>
<div class="modfile"><h4>Modified: CalendarServer/trunk/calendarserver/test/test_accesslog.py (15683 => 15684)</h4>
<pre class="diff"><span>
<span class="info">--- CalendarServer/trunk/calendarserver/test/test_accesslog.py 2016-06-17 20:55:13 UTC (rev 15683)
+++ CalendarServer/trunk/calendarserver/test/test_accesslog.py 2016-06-20 13:37:51 UTC (rev 15684)
</span><span class="lines">@@ -19,6 +19,7 @@
</span><span class="cx"> RotatingFileAccessLoggingObserver
</span><span class="cx"> from twistedcaldav.stdconfig import config as stdconfig
</span><span class="cx"> from twistedcaldav.config import config
</span><ins>+import time
</ins><span class="cx">
</span><span class="cx"> hasattr(stdconfig, "Servers") # Quell pyflakes
</span><span class="cx">
</span><span class="lines">@@ -97,3 +98,42 @@
</span><span class="cx">
</span><span class="cx"> with open(logpath) as f:
</span><span class="cx"> self.assertIn("log this", f.read())
</span><ins>+
+
+ def test_truncateStats(self):
+ """
+ Make sure L{RotatingFileAccessLoggingObserver.ensureSequentialStats}
+ properly truncates stats data.
+ """
+
+ logpath = self.mktemp()
+ observer = RotatingFileAccessLoggingObserver(logpath)
+ observer.systemStats = SystemMonitor()
+ observer.start()
+
+ # Fill stats with some old entries
+ t = int(time.time() / 60.0) * 60
+ t -= 100 * 60
+ for i in range(10):
+ observer.statsByMinute.append((t + i * 60, observer.initStats(),))
+
+ self.assertEqual(len(observer.statsByMinute), 10)
+ observer.ensureSequentialStats()
+ self.assertEqual(len(observer.statsByMinute), 65)
+ observer.stop()
+
+
+ def test_smallerStats(self):
+ """
+ Make sure "uid" and "user-agent" are not in the
+ L{RotatingFileAccessLoggingObserver} stats data.
+ """
+
+ logpath = self.mktemp()
+ observer = RotatingFileAccessLoggingObserver(logpath)
+ observer.systemStats = SystemMonitor()
+ observer.start()
+ stats = observer.initStats()
+ observer.stop()
+ self.assertTrue("uid" not in stats)
+ self.assertTrue("user-agent" not in stats)
</ins></span></pre>
</div>
</div>
</body>
</html>