Log time spent doing database queries when DEBUG=True.

When DEBUG=False, Django doesn't log the data at all.  We can and
should add tracking of that at some point, but it requires patching
Django; so for now just log the data when DEBUG=True.

(imported from commit 2b9e6a4c68009733373724f38debe4e77313fdeb)

zephyr/middleware.py

@@ -1,5 +1,7 @@
+from django.conf import settings
 from decorator import RequestVariableMissingError, RequestVariableConversionError
 from zephyr.lib.response import json_error
+from django.db import connection
 
 import logging
 import time
@@ -23,14 +25,22 @@ class LogRequests(object):
         if hasattr(request, '_time_started'):
             time_delta = time.time() - request._time_started
 
+        # Get the amount of time spent doing database queries
+        query_time = sum(float(query.get('time', 0)) for query in connection.queries)
+        if settings.DEBUG:
+            db_stats = "(db: %.3fs/%sq) " % (query_time, len(connection.queries),)
+        else:
+            db_stats = ""
+
+        # Get the requestor's email address, if available.
         try:
             email = request._email
         except Exception:
             email = "unauth"
 
-        logger.info('%-15s %-7s %3d %.3fs %s (%s)'
+        logger.info('%-15s %-7s %3d %.3fs %s%s (%s)'
             % (remote_ip, request.method, response.status_code,
-               time_delta, request.get_full_path(), email))
+               time_delta, db_stats, request.get_full_path(), email))
         # Log some additional data whenever we return a 40x error
         if 400 <= response.status_code < 500:
             logger.info('status=%3d, data=%s, uid=%s' % (response.status_code, response.content, email))