Adding elapsed time to all requests logging.

apps/profile/middleware.py

@@ -1,6 +1,7 @@
 import datetime
 import re
 import random
+import time
 from utils import log as logging
 from django.conf import settings
 from django.db import connection
@@ -29,7 +30,7 @@ class LastSeenMiddleware(object):
 class SQLLogToConsoleMiddleware:
     def process_response(self, request, response): 
         if settings.DEBUG and connection.queries:
-            time = sum([float(q['time']) for q in connection.queries])
+            time_elapsed = sum([float(q['time']) for q in connection.queries])
             queries = connection.queries
             for query in queries:
                 if query.get('mongo'):
@@ -41,7 +42,7 @@ class SQLLogToConsoleMiddleware:
                     query['sql'] = re.sub(r'UPDATE', '~FY~SBUPDATE', query['sql'])
                     query['sql'] = re.sub(r'DELETE', '~FR~SBDELETE', query['sql'])
             t = Template("{% for sql in sqllog %}{% if not forloop.first %}                  {% endif %}[{{forloop.counter}}] ~FC{{sql.time}}s~FW: {{sql.sql|safe}}{% if not forloop.last %}\n{% endif %}{% endfor %}")
-            logging.debug(t.render(Context({'sqllog':queries,'count':len(queries),'time':time})))
+            logging.debug(t.render(Context({'sqllog':queries,'count':len(queries),'time':time_elapsed})))
         return response
 
 SIMPSONS_QUOTES = [
@@ -155,4 +156,7 @@ class SimpsonsMiddleware:
         response["X-%s" % source] = quote[1]
 
         return response
-    
+
+class TimingMiddleware:
+    def process_request(self, request):
+        setattr(request, 'start_time', time.time())

apps/social/views.py

@@ -519,6 +519,7 @@ def shared_stories_public(request, username):
     
 @json.json_view
 def profile(request):
+    time.sleep(1)
     user = get_user(request.user)
     user_id = request.GET.get('user_id', user.pk)
     include_activities_html = request.REQUEST.get('include_activities_html', None)

settings.py

@@ -92,6 +92,7 @@ MIDDLEWARE_CLASSES = (
     'django.middleware.common.CommonMiddleware',
     'django.contrib.sessions.middleware.SessionMiddleware',
     'django.contrib.auth.middleware.AuthenticationMiddleware',
+    'apps.profile.middleware.TimingMiddleware',
     'apps.profile.middleware.LastSeenMiddleware',
     'apps.profile.middleware.SQLLogToConsoleMiddleware',
     'subdomains.middleware.SubdomainMiddleware',

utils/log.py

@@ -1,6 +1,7 @@
 import logging
 import re
 import string
+import time
 from django.core.handlers.wsgi import WSGIRequest
 from django.conf import settings
 
@@ -14,6 +15,7 @@ def getlogger():
 
 def user(u, msg):
     platform = '------'
+    time_elapsed = ""
     if isinstance(u, WSGIRequest):
         request = u
         u = request.user
@@ -46,9 +48,13 @@ def user(u, msg):
             platform = 'Opera'
         elif 'WP7' in user_agent:
             platform = 'WP7'
+
+        if hasattr(request, 'start_time'):
+            now = time.time()
+            time_elapsed = "[%.4ss] " % (now - request.start_time)
     premium = '*' if u.is_authenticated() and u.profile.is_premium else ''
     username = cipher(unicode(u)) if settings.CIPHER_USERNAMES else u
-    info(' ---> [~FB~SN%-6s~SB] [%s%s] %s' % (platform, username, premium, msg))
+    info(' ---> [~FB~SN%-6s~SB] [%s%s] %s%s' % (platform, time_elapsed, username, premium, msg))
 
 def cipher(msg):
     shift = len(msg)