Include SQL query mean number and mean execution time in the output

garethr · Sep 2, 2011 · fce750b · fce750b
1 parent beb3525
commit fce750b
Show file tree

Hide file tree

Showing 2 changed files with 29 additions and 9 deletions.
diff --git a/src/timelog/lib.py b/src/timelog/lib.py
@@ -8,7 +8,7 @@
 from django.core.urlresolvers import resolve, Resolver404
 
 
-PATTERN = r"""^([0-9]{4}-[0-9]{2}-[0-9]{2} [0-9:]{8},[0-9]{3}) (GET|POST|PUT|DELETE|HEAD) "(.*)" \((.*)\) (.*)"""
+PATTERN = r"""^([0-9]{4}-[0-9]{2}-[0-9]{2} [0-9:]{8},[0-9]{3}) (GET|POST|PUT|DELETE|HEAD) "(.*)" \((.*)\) (.*?) \((\d+)q, (.*?)\)"""
 
 CACHED_VIEWS = {}
 
@@ -41,19 +41,22 @@ def view_name_from(path):
 def generate_table_from(data):
     "Output a nicely formatted ascii table"
     table = Texttable(max_width=120)
-    table.add_row(["view", "method", "status", "count", "minimum", "maximum", "mean", "stdev"]) 
-    table.set_cols_align(["l", "l", "l", "r", "r", "r", "r", "r"])
+    table.add_row(["view", "method", "status", "count", "minimum", "maximum", "mean", "stdev", "queries", "querytime"]) 
+    table.set_cols_align(["l", "l", "l", "r", "r", "r", "r", "r", "r", "r"])
 
     for item in data:
         mean = round(sum(data[item]['times'])/data[item]['count'], 3)
+
+        mean_sql = round(sum(data[item]['sql'])/data[item]['count'], 3)
+        mean_sqltime = round(sum(data[item]['sqltime'])/data[item]['count'], 3)
 
         sdsq = sum([(i - mean) ** 2 for i in data[item]['times']])
         try:
             stdev = '%.2f' % ((sdsq / (len(data[item]['times']) - 1)) ** .5)
         except ZeroDivisionError:
             stdev = '0.00'
 
-        table.add_row([data[item]['view'], data[item]['method'], data[item]['status'], data[item]['count'], data[item]['minimum'], data[item]['maximum'], '%.3f' % mean, stdev])
+        table.add_row([data[item]['view'], data[item]['method'], data[item]['status'], data[item]['count'], data[item]['minimum'], data[item]['maximum'], '%.3f' % mean, stdev, mean_sql, mean_sqltime])
 
     return table.draw()
 
@@ -78,6 +81,8 @@ def analyze_log_file(logfile, pattern, reverse_paths=True, progress=True):
         path = parsed[2]
         status = parsed[3]
         time = parsed[4]
+        sql = parsed[5]
+        sqltime = parsed[6]
 
         try:
             ignore = False
@@ -98,6 +103,8 @@ def analyze_log_file(logfile, pattern, reverse_paths=True, progress=True):
                     if time > data[key]['maximum']:
                         data[key]['maximum'] = time
                     data[key]['times'].append(float(time))
+                    data[key]['sql'].append(int(sql))
+                    data[key]['sqltime'].append(float(sqltime))
                 except KeyError:
                     data[key] = {
                         'count': 1,
@@ -107,6 +114,8 @@ def analyze_log_file(logfile, pattern, reverse_paths=True, progress=True):
                         'view': view,
                         'method': method,
                         'times': [float(time)],
+                        'sql': [int(sql)],
+                        'sqltime': [float(sqltime)],
                     }
         except Resolver404:
             pass

diff --git a/src/timelog/middleware.py b/src/timelog/middleware.py
@@ -1,5 +1,6 @@
 import time
 import logging
+from django.db import connection
 from django.utils.encoding import smart_str
 
 logger = logging.getLogger(__name__)
@@ -15,11 +16,21 @@ def process_response(self, request, response):
         # before TimeLogMiddleware then request won't have '_start' attribute
         # and the original traceback will be lost (original exception will be
         # replaced with AttributeError)
+
+        sqltime = 0.0
+
+        for q in connection.queries:
+            sqltime += float(q['time'])
+
         if hasattr(request, '_start'):
-            d = {'method': request.method,
-                 'time': time.time() - request._start,
-                 'code': response.status_code,
-                 'url': smart_str(request.path_info)}
-            msg = '%(method)s "%(url)s" (%(code)s) %(time).2f' % d
+            d = {
+                'method': request.method,
+                'time': time.time() - request._start,
+                'code': response.status_code,
+                'url': smart_str(request.path_info),
+                'sql': len(connection.queries),
+                'sqltime': sqltime,
+            }
+            msg = '%(method)s "%(url)s" (%(code)s) %(time).2f (%(sql)dq, %(sqltime).4f)' % d
             logger.info(msg)
         return response