Refactored SQL panel to use datetime objects and added a visual display of both duration and sequence to the SQL template.

7 files changed, 70 insertions, 23 deletions

diff --git a/debug_toolbar/media/debug_toolbar/toolbar.css b/debug_toolbar/media/debug_toolbar/toolbar.css
index ad23f22..c1fd4b0 100644
--- a/debug_toolbar/media/debug_toolbar/toolbar.css
+++ b/debug_toolbar/media/debug_toolbar/toolbar.css
@@ -336,6 +336,27 @@
 	cursor:pointer;
 }
 
+#djDebug .djDebugSqlWrap {
+	position:relative;
+}
+
+#djDebug .djDebugSql {
+	z-index:100000002;
+}
+
+#djDebug span.djDebugLineChart {
+	border-top:3px solid #777;
+	position:absolute;
+	bottom:0;
+	top:0;
+	left:0;
+	display:block;
+	z-index:1000000001;
+}
+#djDebug span.djDebugLineChartWarning {
+	border-top-color:#900;
+}
+
 #djDebug .highlight  { color:#000; }
 #djDebug .highlight .err { color:#000; } /* Error */
 #djDebug .highlight .g { color:#000; } /* Generic */
diff --git a/debug_toolbar/panels/sql.py b/debug_toolbar/panels/sql.py
index f12939e..62c0e58 100644
--- a/debug_toolbar/panels/sql.py
+++ b/debug_toolbar/panels/sql.py
@@ -1,6 +1,6 @@
 import os
 import SocketServer
-import time
+from datetime import datetime
 import traceback
 import django
 from django.conf import settings
@@ -16,6 +16,10 @@ from debug_toolbar.panels import DebugPanel
 django_path = os.path.realpath(os.path.dirname(django.__file__))
 socketserver_path = os.path.realpath(os.path.dirname(SocketServer.__file__))
 
+# TODO:This should be set in the toolbar loader as a default and panels should
+# get a copy of the toolbar object with access to its config dictionary
+SQL_WARNING_THRESHOLD = getattr(settings, 'DEBUG_TOOLBAR_CONFIG', {}).get('SQL_WARNING_THRESHOLD', 500)
+
 def tidy_stacktrace(strace):
     """
     Clean up stacktrace and remove all entries that:
@@ -39,11 +43,12 @@ class DatabaseStatTracker(util.CursorDebugWrapper):
     in `connection.queries`.
     """
     def execute(self, sql, params=()):
-        start = time.time()
+        start = datetime.now()
         try:
             return self.cursor.execute(sql, params)
         finally:
-            stop = time.time()
+            stop = datetime.now()
+            duration = ms_from_timedelta(stop - start)
             stacktrace = tidy_stacktrace(traceback.extract_stack())
             _params = ''
             try:
@@ -53,11 +58,14 @@ class DatabaseStatTracker(util.CursorDebugWrapper):
             # We keep `sql` to maintain backwards compatibility
             self.db.queries.append({
                 'sql': self.db.ops.last_executed_query(self.cursor, sql, params),
-                'time': (stop - start) * 1000, # convert to ms
+                'duration': duration,
                 'raw_sql': sql,
                 'params': _params,
                 'hash': sha_constructor(settings.SECRET_KEY + sql + _params).hexdigest(),
                 'stacktrace': stacktrace,
+                'start_time': start,
+                'stop_time': stop,
+                'is_slow': (duration > SQL_WARNING_THRESHOLD)
             })
 util.CursorDebugWrapper = DatabaseStatTracker
 
@@ -77,14 +85,14 @@ class SQLDebugPanel(DebugPanel):
         return 'SQL'
 
     def nav_subtitle(self):
-        self._sql_time = sum(map(lambda q: float(q['time']), connection.queries))
+        self._sql_time = sum([q['duration'] for q in connection.queries[self._offset:]])
         num_queries = len(connection.queries) - self._offset
         return "%d %s in %.2fms" % (
             num_queries,
             (num_queries == 1) and 'query' or 'queries',
             self._sql_time
         )
-    
+
     def title(self):
         return 'SQL Queries'
 
@@ -93,8 +101,15 @@ class SQLDebugPanel(DebugPanel):
 
     def content(self):
         sql_queries = connection.queries[self._offset:]
+        width_ratio_tally = 0
         for query in sql_queries:
             query['sql'] = reformat_sql(query['sql'])
+            try:
+                query['width_ratio'] = (query['duration'] / self._sql_time) * 100
+            except ZeroDivisionError:
+                query['width_ratio'] = 0
+            query['start_offset'] = width_ratio_tally
+            width_ratio_tally += query['width_ratio']
 
         context = {
             'queries': sql_queries,
@@ -103,6 +118,12 @@ class SQLDebugPanel(DebugPanel):
         }
         return render_to_string('debug_toolbar/panels/sql.html', context)
 
+def ms_from_timedelta(td):
+    """
+    Given a timedelta object, returns a float representing milliseconds
+    """
+    return (td.seconds * 1000) + (td.microseconds / 1000.0)
+
 def reformat_sql(sql):
     sql = sql.replace(',', ', ')
     sql = sql.replace('SELECT ', 'SELECT\n\t')
diff --git a/debug_toolbar/templates/debug_toolbar/panels/sql.html b/debug_toolbar/templates/debug_toolbar/panels/sql.html
index 7aa4c2d..9c8bfa6 100644
--- a/debug_toolbar/templates/debug_toolbar/panels/sql.html
+++ b/debug_toolbar/templates/debug_toolbar/panels/sql.html
@@ -11,13 +11,13 @@
 	<tbody>
 		{% for query in queries %}
 			<tr class="{% cycle 'djDebugOdd' 'djDebugEven' %}">
-				<td>{{ query.time|floatformat:"2" }}</td>
+				<td>{{ query.duration|floatformat:"2" }}</td>
 				<td>
 				{% if query.params %}
-					<a class="remoteCall" href="/__debug__/sql_select/?sql={{ query.raw_sql|urlencode }}&params={{ query.params|urlencode }}&time={{ query.time|floatformat:"2"|urlencode }}&hash={{ query.hash }}">SELECT</a>
-					<a class="remoteCall" href="/__debug__/sql_explain/?sql={{ query.raw_sql|urlencode }}&params={{ query.params|urlencode }}&time={{ query.time|floatformat:"2"|urlencode }}&hash={{ query.hash }}">EXPLAIN</a>
+					<a class="remoteCall" href="/__debug__/sql_select/?sql={{ query.raw_sql|urlencode }}&params={{ query.params|urlencode }}&duration={{ query.duration|floatformat:"2"|urlencode }}&hash={{ query.hash }}">SELECT</a>
+					<a class="remoteCall" href="/__debug__/sql_explain/?sql={{ query.raw_sql|urlencode }}&params={{ query.params|urlencode }}&duration={{ query.duration|floatformat:"2"|urlencode }}&hash={{ query.hash }}">EXPLAIN</a>
 					{% if is_mysql %}
-						<a class="remoteCall" href="/__debug__/sql_profile/?sql={{ query.raw_sql|urlencode }}&params={{ query.params|urlencode }}&time={{ query.time|floatformat:"2"|urlencode }}&hash={{ query.hash }}">PROFILE</a>
+						<a class="remoteCall" href="/__debug__/sql_profile/?sql={{ query.raw_sql|urlencode }}&params={{ query.params|urlencode }}&duration={{ query.duration|floatformat:"2"|urlencode }}&hash={{ query.hash }}">PROFILE</a>
 					{% endif %}
 				{% endif %}
 				</td>
@@ -42,7 +42,12 @@
 					</div>
 					{% endif %}
 				</td>
-				<td class="syntax">{{ query.sql|safe }}</td>
+				<td class="syntax">
+					<div class="djDebugSqlWrap">
+						<div class="djDebugSql">{{ query.sql|safe }}</div>
+						<span class="djDebugLineChart{% if query.is_slow %} djDebugLineChartWarning{% endif %}" style="width:{{ query.width_ratio }}%; left:{{ query.start_offset }}%;"</span>
+					</div>
+				</td>
 			</tr>
 		{% endfor %}
 	</tbody>
diff --git a/debug_toolbar/templates/debug_toolbar/panels/sql_explain.html b/debug_toolbar/templates/debug_toolbar/panels/sql_explain.html
index 38249b3..a21ec59 100644
--- a/debug_toolbar/templates/debug_toolbar/panels/sql_explain.html
+++ b/debug_toolbar/templates/debug_toolbar/panels/sql_explain.html
@@ -6,9 +6,9 @@
 <div class="djDebugPanelContent">
 	<dl>
 		<dt>{% trans "Executed SQL" %}</dt>
-		<dd><pre>{{ sql|safe }}</pre></dd>
+		<dd>{{ sql|safe }}</dd>
 		<dt>{% trans "Time" %}</dt>
-		<dd>{{ time }} ms</dd>
+		<dd>{{ duration }} ms</dd>
 	</dl>
 	<table>
 		<thead>
diff --git a/debug_toolbar/templates/debug_toolbar/panels/sql_profile.html b/debug_toolbar/templates/debug_toolbar/panels/sql_profile.html
index 0dcb0b9..a15574e 100644
--- a/debug_toolbar/templates/debug_toolbar/panels/sql_profile.html
+++ b/debug_toolbar/templates/debug_toolbar/panels/sql_profile.html
@@ -7,9 +7,9 @@
 	{% if result %}
 		<dl>
 			<dt>{% trans "Executed SQL" %}</dt>
-			<dd><pre>{{ sql|safe }}</pre></dd>
+			<dd>{{ sql|safe }}</dd>
 			<dt>{% trans "Time" %}</dt>
-			<dd>{{ time }} ms</dd>
+			<dd>{{ duration }} ms</dd>
 		</dl>
 		<table>
 			<thead>
diff --git a/debug_toolbar/templates/debug_toolbar/panels/sql_select.html b/debug_toolbar/templates/debug_toolbar/panels/sql_select.html
index e4d6027..66835c8 100644
--- a/debug_toolbar/templates/debug_toolbar/panels/sql_select.html
+++ b/debug_toolbar/templates/debug_toolbar/panels/sql_select.html
@@ -6,9 +6,9 @@
 <div class="djDebugPanelContent">
 	<dl>
 		<dt>{% trans "Executed SQL" %}</dt>
-		<dd><pre>{{ sql|safe }}</pre></dd>
+		<dd>{{ sql|safe }}</dd>
 		<dt>{% trans "Time" %}</dt>
-		<dd>{{ time }} ms</dd>
+		<dd>{{ duration }} ms</dd>
 	</dl>
 	{% if result %}
 	<table>
diff --git a/debug_toolbar/views.py b/debug_toolbar/views.py
index 255a49c..3a8cb79 100644
--- a/debug_toolbar/views.py
+++ b/debug_toolbar/views.py
@@ -33,7 +33,7 @@ def sql_select(request):
     Expected GET variables:
         sql: urlencoded sql with positional arguments
         params: JSON encoded parameter values
-        time: time for SQL to execute passed in from toolbar just for redisplay
+        duration: time for SQL to execute passed in from toolbar just for redisplay
         hash: the hash of (secret + sql + params) for tamper checking
     """
     from debug_toolbar.panels.sql import reformat_sql
@@ -52,7 +52,7 @@ def sql_select(request):
         context = {
             'result': result,
             'sql': reformat_sql(cursor.db.ops.last_executed_query(cursor, sql, params)),
-            'time': request.GET.get('time', 0.0),
+            'duration': request.GET.get('duration', 0.0),
             'headers': headers,
         }
         return render_to_response('debug_toolbar/panels/sql_select.html', context)
@@ -65,7 +65,7 @@ def sql_explain(request):
     Expected GET variables:
         sql: urlencoded sql with positional arguments
         params: JSON encoded parameter values
-        time: time for SQL to execute passed in from toolbar just for redisplay
+        duration: time for SQL to execute passed in from toolbar just for redisplay
         hash: the hash of (secret + sql + params) for tamper checking
     """
     from debug_toolbar.panels.sql import reformat_sql
@@ -84,7 +84,7 @@ def sql_explain(request):
         context = {
             'result': result,
             'sql': reformat_sql(cursor.db.ops.last_executed_query(cursor, sql, params)),
-            'time': request.GET.get('time', 0.0),
+            'duration': request.GET.get('duration', 0.0),
             'headers': headers,
         }
         return render_to_response('debug_toolbar/panels/sql_explain.html', context)
@@ -97,7 +97,7 @@ def sql_profile(request):
     Expected GET variables:
         sql: urlencoded sql with positional arguments
         params: JSON encoded parameter values
-        time: time for SQL to execute passed in from toolbar just for redisplay
+        duration: time for SQL to execute passed in from toolbar just for redisplay
         hash: the hash of (secret + sql + params) for tamper checking
     """
     from debug_toolbar.panels.sql import reformat_sql
@@ -127,7 +127,7 @@ def sql_profile(request):
             'result': result,
             'result_error': result_error,
             'sql': reformat_sql(cursor.db.ops.last_executed_query(cursor, sql, params)),
-            'time': request.GET.get('time', 0.0),
+            'duration': request.GET.get('duration', 0.0),
             'headers': headers,
         }
         return render_to_response('debug_toolbar/panels/sql_profile.html', context)