[CalendarServer-changes] [6088] CalendarServer/trunk/contrib/performance

source_changes at macosforge.org source_changes at macosforge.org
Mon Aug 16 16:58:35 PDT 2010


Revision: 6088
          http://trac.macosforge.org/projects/calendarserver/changeset/6088
Author:   exarkun at twistedmatrix.com
Date:     2010-08-16 16:58:35 -0700 (Mon, 16 Aug 2010)
Log Message:
-----------
Get the SQL recording and all the parsing working reasonably well

Modified Paths:
--------------
    CalendarServer/trunk/contrib/performance/io_measure.d
    CalendarServer/trunk/contrib/performance/mkcal.py

Modified: CalendarServer/trunk/contrib/performance/io_measure.d
===================================================================
--- CalendarServer/trunk/contrib/performance/io_measure.d	2010-08-16 23:47:05 UTC (rev 6087)
+++ CalendarServer/trunk/contrib/performance/io_measure.d	2010-08-16 23:58:35 UTC (rev 6088)
@@ -29,13 +29,14 @@
 {
         self->executing = 1;
         self->sql = "";
-        printf("EXECUTE ENTRY %d\n\1", timestamp);
+	printf("EXECUTE ENTRY %d\n\1", timestamp);
 }
 
 pid$target:_sqlite3.so:_pysqlite_query_execute:return
 {
-        self->executing = 0;
-        printf("EXECUTE RETURN %d %s\n\1", timestamp, self->sql);
+	self->executing = 0;
+	printf("EXECUTE SQL %s\n\1", self->sql);
+	printf("EXECUTE RETURN %d\n\1", timestamp);
 }
 
 pid$target::PyString_AsString:return
@@ -61,7 +62,8 @@
 
 pid$target::PQexec:entry
 {
-        printf("EXECUTE ENTRY %d %s\n\1", timestamp, copyinstr(arg1));
+	printf("EXECUTE ENTRY %d\n\1", timestamp);
+	printf("EXECUTE SQL %s\n\1", copyinstr(arg1));
 }
 
 pid$target::PQexec:return

Modified: CalendarServer/trunk/contrib/performance/mkcal.py
===================================================================
--- CalendarServer/trunk/contrib/performance/mkcal.py	2010-08-16 23:47:05 UTC (rev 6087)
+++ CalendarServer/trunk/contrib/performance/mkcal.py	2010-08-16 23:58:35 UTC (rev 6088)
@@ -213,12 +213,16 @@
     pass
 
 
+class SQLDuration(_Statistic):
+    def summarize(self, data):
+        data = [interval for (sql, interval) in data]
+        return _Statistic.summarize(self, data)
 
+
 class Bytes(_Statistic):
     pass
 
 
-
 class DTraceCollector(object):
     def __init__(self, pids):
         self.pids = pids
@@ -232,45 +236,62 @@
         return {
             Bytes('read'): self._read,
             Bytes('write'): self._write,
-            Duration('execute'): self._execute,
-            Duration('iternext'): self._iternext,
+            SQLDuration('execute'): self._execute,
+            SQLDuration('iternext'): self._iternext,
             }
 
 
     def _parse(self, dtrace):
         file('dtrace.log', 'a').write(dtrace)
 
+        self.sql = self.start = None
+        for L in dtrace.split('\n\1'):
 
-        start = None
-        for L in dtrace.splitlines():
-            parts = L.split(None)
-            if len(parts) >= 4:
-                event = parts[2]
-                func, stage = event.split(':')
-                value = int(parts[3])
-                if stage == 'entry':
-                    start = value
-                elif stage == 'return':
-                    if start is None:
-                        print func, 'return without entry at', parts[3]
-                        continue
-                    end = int(parts[3])
-                    diff = end - start
-                    if func == '_pysqlite_query_execute':
+            # dtrace puts some extra newlines in the output sometimes.  Get rid of them.
+            L = L.strip()
+            if not L:
+                continue
+
+            op, rest = L.split(None, 1)
+            getattr(self, '_op_' + op)(op, rest)
+        self.sql = self.start = None
+
+
+    def _op_EXECUTE(self, cmd, rest):
+        which, when = rest.split(None, 1)
+        if which == 'SQL':
+            self.sql = when
+            return
+
+        when = int(when)
+        if which == 'ENTRY':
+            self.start = when
+        elif which == 'RETURN':
+            if self.start is None:
+                print 'return without entry at', when, 'in', cmd
+            else:
+                diff = when - self.start
+                if diff < 0:
+                    print 'Completely bogus EXECUTE', self.start, when
+                else:        
+                    if cmd == 'EXECUTE':
                         accum = self._execute
-                    elif func == 'pysqlite_cursor_iternext':
+                    elif cmd == 'ITERNEXT':
                         accum = self._iternext
-                    else:
-                        continue
-                    if diff < 0:
-                        print 'Completely bogus dealie', func, start, end
-                    else:
-                        accum.append(diff)
-                    start = None
-                else:
-                    continue
 
+                    accum.append((self.sql, diff))
+                    self.start = None
+                    self.sql = None
+    _op_ITERNEXT = _op_EXECUTE
 
+    def _op_B_READ(self, cmd, rest):
+        self._read.append(int(rest))
+
+
+    def _op_B_WRITE(self, cmd, rest):
+        self._write.append(int(rest))
+
+
     def __enter__(self):
         finished = []
         self.dtraces = {}
@@ -346,6 +367,8 @@
 
 if __name__ == '__main__':
     from twisted.python.log import err
+    from twisted.python.failure import startDebugMode
+    startDebugMode()
     d = main()
     d.addErrback(err)
     d.addCallback(lambda ign: reactor.stop())
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.macosforge.org/pipermail/calendarserver-changes/attachments/20100816/1cdd3f16/attachment-0001.html>


More information about the calendarserver-changes mailing list