launchpad-reviewers team mailing list archive
-
launchpad-reviewers team
-
Mailing list archive
-
Message #04717
[Merge] lp:~gary/launchpad/sqlprofiler into lp:launchpad
Gary Poster has proposed merging lp:~gary/launchpad/sqlprofiler into lp:launchpad.
Requested reviews:
Launchpad code reviewers (launchpad-reviewers)
For more details, see:
https://code.launchpad.net/~gary/launchpad/sqlprofiler/+merge/72491
This code, like other recent work on ++profile++, has fallen out of analysis work I've done for bug 724025. I worked a bit on extra-work time to polish it up.
This is a big branch, at over 1100 lines. It would be relatively easy to divide it up in two, and I will do so if requested. On the other hand, it is so easy to divide in two that I'm hoping a reviewer who might have had to look at both branches anyway would just run with the existing MP.
This branch makes two feature additions for developers.
First, when you use existing SQL profiling using LP_DEBUG_SQL_EXTRA, the traceback now includes extra information provided by code that follows the patterns from the zope.exceptions package. Practically, this means that tracebacks will show you the information about page template rendering, such as what template, what line and column, and what TAL expression caused the sql call that you see. It also means that you can use the zope.exceptions pattern to add information to your own parsing code and loops to give more information when you analyze these tracebacks.
Second, the ++profile++ page now includes a sqltrace option. This has a number of advantages over using the LP_DEBUG_SQL_EXTRA environmental variable approach. First, generating the tracebacks is not cheap, and it is nice to be able to selectively decide when you want them when you are working. Second, many of our pages now have multiple JS requests to assemble them; when using the environmental variable and multiple threads on the server, requests cause interleaving of the results on stderr. Third, we can get the results of this analysis on qastaging or staging with no or minimal LOSA help. (The minimal help may be necessary to increase the timeout of the page you are examining, using feature flags).
The ++profile++ changes are more feature-full than I intended because of some cool additional ideas from Benji, and some weekend hacking time from me. The page lets you expand tracebacks, and gives a bit of analysis of the results with some convenient controls and links. It certainly now points clearly to some of the problems I have identified on the branch I have been working on.
A third, small change is that the LP_DEBUG_SQL_EXTRA stderr display now includes the start and stop time of the request in milliseconds, as you find it in the OOPS tools.
lint complains as usual about the ++profile++ template, but it's spurious IMO. It is otherwise happy.
./lib/lp/services/profile/profile.pt
26: junk after document element
I did a pretty good job at tests for the underlying feature: a new stacktrace module that replaces some of the stdlib traceback module functions. It's a shame zope.exceptions is not factored in such a way as to not require a new module. I've toyed with the idea of making a new and updated package and releasing it on PyPI. For now, it's fine where it is, I think. I originally called it traceback.py, but I didn't want to mask the standard library traceback module for other lp.services modules, so I changed it to stacktrace.
In contrast, the tests for the new ++profile++ features displaying the stacktraces are only one step above smoketests. I thought it was OK in the context of a developer analysis page, and with the underlying machinery well tested.
The changes to adapter.py are not any more tested than the previous sql profiling code was: not at all.
If I were to divide this up into two branches, I would have one branch for the new stacktrace module and its use with LP_DEBUG_SQL_EXTRA, and another branch for the ++profile++ work.
Thank you
--
https://code.launchpad.net/~gary/launchpad/sqlprofiler/+merge/72491
Your team Launchpad code reviewers is requested to review the proposed merge of lp:~gary/launchpad/sqlprofiler into lp:launchpad.
=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
--- lib/canonical/launchpad/webapp/adapter.py 2011-08-10 01:00:53 +0000
+++ lib/canonical/launchpad/webapp/adapter.py 2011-08-22 19:17:17 +0000
@@ -13,7 +13,6 @@
import thread
import threading
from time import time
-import traceback
import warnings
import psycopg2
@@ -78,6 +77,10 @@
get_request_timeline,
set_request_timeline,
)
+from lp.services.stacktrace import (
+ extract_stack,
+ print_list,
+ )
__all__ = [
@@ -89,6 +92,8 @@
'get_request_duration',
'get_store_name',
'soft_timeout_expired',
+ 'start_sql_traceback_logging',
+ 'stop_sql_traceback_logging',
'StoreSelector',
]
@@ -197,6 +202,7 @@
warnings.warn('clear_request_started() called outside of a request',
stacklevel=2)
_local.request_start_time = None
+ _local.sql_trace = None
request = get_current_browser_request()
set_request_timeline(request, Timeline())
if getattr(_local, 'commit_logger', None) is not None:
@@ -345,6 +351,18 @@
return True
+def start_sql_traceback_logging():
+ """Set the sql traceback data logging for the current request."""
+ _local.sql_trace = []
+
+
+def stop_sql_traceback_logging():
+ """Stop the sql traceback data logging and return the result."""
+ result = getattr(_local, 'sql_trace', None)
+ _local.sql_trace = None
+ return result
+
+
# ---- Prevent database access in the main thread of the app server
class StormAccessFromMainThread(Exception):
@@ -523,8 +541,9 @@
# This is fallback code for old config files. It can be
# removed when all live configs have been updated to use the
# 'database' setting instead of 'dbname' + 'dbhost' settings.
- self._dsn = 'dbname=%s user=%s' % (config.launchpad_session.dbname,
- config.launchpad_session.dbuser)
+ self._dsn = 'dbname=%s user=%s' % (
+ config.launchpad_session.dbname,
+ config.launchpad_session.dbuser)
if config.launchpad_session.dbhost:
self._dsn += ' host=%s' % config.launchpad_session.dbhost
@@ -612,9 +631,17 @@
def connection_raw_execute(self, connection, raw_cursor,
statement, params):
- if self._debug_sql_extra:
- traceback.print_stack()
- sys.stderr.write("." * 70 + "\n")
+ sql_trace = getattr(_local, 'sql_trace', None)
+ if sql_trace is not None or self._debug_sql_extra:
+ # Gather data for the [start|stop]_sql_traceback_logging
+ # feature, as exposed by ++profile++sqltrace, and/or for stderr,
+ # as exposed by LP_DEBUG_SQL_EXTRA.
+ stack = extract_stack()
+ if sql_trace is not None:
+ sql_trace.append(dict(stack=stack, sql=None))
+ if self._debug_sql_extra:
+ print_list(stack)
+ sys.stderr.write("." * 70 + "\n")
statement_to_log = statement
if params:
# There are some bind parameters so we want to insert them into
@@ -629,9 +656,6 @@
param_strings = [repr(p) if isinstance(p, basestring) else p
for p in query_params]
statement_to_log = quoted_statement % tuple(param_strings)
- if self._debug_sql or self._debug_sql_extra:
- sys.stderr.write(statement_to_log + "\n")
- sys.stderr.write("-" * 70 + "\n")
# store the last executed statement as an attribute on the current
# thread
threading.currentThread().lp_last_sql_statement = statement
@@ -649,6 +673,15 @@
# action may be None if the tracer was installed after the
# statement was submitted.
action.finish()
+ # Do data reporting for the [start|stop]_sql_traceback_logging
+ # feature, as exposed by ++profile++sqltrace, and/or for stderr,
+ # as exposed by LP_DEBUG_SQL_EXTRA and LP_DEBUG_SQL.
+ sql_trace = getattr(_local, 'sql_trace', None)
+ if sql_trace and sql_trace[-1]['sql'] is None:
+ sql_trace[-1]['sql'] = action.logTuple()
+ if self._debug_sql or self._debug_sql_extra:
+ sys.stderr.write('%d-%d@%s %s\n' % action.logTuple())
+ sys.stderr.write("-" * 70 + "\n")
def connection_raw_execute_error(self, connection, raw_cursor,
statement, params, error):
=== modified file 'lib/lp/services/profile/profile.pt'
--- lib/lp/services/profile/profile.pt 2011-08-10 21:32:08 +0000
+++ lib/lp/services/profile/profile.pt 2011-08-22 19:17:17 +0000
@@ -1,6 +1,31 @@
+<!-- Style is supposed to go in the head. We don't have one here. This seems
+to work for FF and WebKit. -->
+<style type="text/css">
+.python_topten {margin-bottom: 4px;}
+.python_danger {background-color: red;}
+.python_warning {background-color: yellow;}
+.sql_danger .sqlstep {background-color: red;}
+.sql_warning .sqlstep {background-color: yellow;}
+.trace .dbstack {font-size: smaller; color: gray}
+.sqlinfo {border-bottom: 1px gray dotted; padding-bottom: 2px;}
+.sqlstats {margin-left: 1ex;}
+.sqlstep {border: LightGray solid 1px; margin-bottom: 4px;}
+.sqlstep.sql_danger {border-color: red;}
+.sqlstep.sql_warning {border-color: yellow;}
+.sqlstep .trace {background-color: GhostWhite; font-size: small; clear: both;}
+.sqlstep .trace .line {margin-left: 2em; font-family: monospace;}
+.sqlstep .trace .supplement, .sqlstep .trace .extrainfo {
+ font-weight: bold; margin-left: 2em;}
+.tracebackwarning {color: red;}
+.col1 {width: 60em; float: left;}
+a.clicktext {font-weight: normal;}
+.trace {overflow: hidden;}
+.trace.inner {height: auto; overflow: hidden;}
+.querylinks {margin-left: 2em;}
+</style>
<div class="profiling_info">
<div class="hide_reveal_profiling" id="reveal_profiling">
- Click to REVEAL profiling information
+ <a href="#">Click to REVEAL profiling information</a>
</div>
</div>
<div class="profiling_info" id="profiling_info"
@@ -22,9 +47,11 @@
multiple_profiles options/multiple_profiles|nothing;
inline_ignored actions/inline_ignored|nothing;
inline actions/inline|nothing;
+ sqltrace actions/sqltrace|nothing;
+ sqltrace_steps options/sqltrace|nothing;
">
<div class="hide_reveal_profiling" id="hide_profiling">
- Click to HIDE profiling information
+ <a href="#">Click to HIDE profiling information</a>
</div>
<h1>Profiling Information</h1>
<tal:block condition="help">
@@ -38,12 +65,14 @@
<code>++profile++show</code>.</tal:block> <tal:block condition="not:
always_log">In order to get profiling results, you need to ask for an HTML
view (<code>++profile++show</code>), a KCacheGrind-friendly log on the
- filesystem (<code>++profile++callgrind</code>), or a PStats-friendly log
+ filesystem (<code>++profile++callgrind</code>), a PStats-friendly log
(Python standard library) on the filesystem
- (<code>++profile++pstats</code>). You can also ask for local HTML
- profiling plus one of the two log files
+ (<code>++profile++pstats</code>), or an HTML view of the SQL and the
+ Python stacktrace when each SQL call was made
+ (<code>++profile++sqltrace</code>). You can also combine these
(<code>++profile++show,callgrind</code> or
- <code>++profile++show,pstats</code>).</tal:block></p>
+ <code>++profile++show,pstats</code> or others,
+ with each action separated with commas).</tal:block></p>
<p>The "++profile++" path segment can usually go anywhere in the URL
(e.g., <code>http://launchpad.dev/++profile++show</code> or
<code>http://launchpad.dev/++profile++show/Firefox</code> or
@@ -111,6 +140,110 @@
href="http://docs.python.org/library/profile.html#instant-user-s-manual";
>Python documentation</a>.</p>
</tal:block>
+ <h2>SQL trace</h2>
+ <tal:block condition="not:sqltrace">
+ <p>Use <code>++profile++sqltrace</code> in your URL to see the SQL that
+ the page runs, along with start and stop times, the database used, and the
+ stacktrace for when each sql call is made.</p> <p>Note that if you do not
+ want the tracebacks, <code>++profile++show</code> will include OOPS data
+ at the end of the profiling information, which has what what you want.</p>
+ </tal:block>
+ <tal:block condition="sqltrace">
+ <h3>Top 10 SQL times</h3>
+ <ol>
+ <li tal:repeat="info options/top_sql" tal:attributes="class info/cls">
+ <a tal:attributes="href string:#sqlstep-${info/ix}">Query number
+ <tal:block tal:content="info/ix"></tal:block></a> (<tal:block
+ replace="info/value"></tal:block> milliseconds)
+ </li>
+ </ol>
+ <h3>Top 10 Python times</h3>
+ <ol>
+ <li tal:repeat="info options/top_python" tal:attributes="class info/cls">
+ <a tal:attributes="href string:#pythonstep-${info/ix}">Before query
+ number <tal:block tal:content="info/ix"></tal:block></a> (<tal:block
+ replace="info/value"></tal:block> milliseconds)
+ </li>
+ </ol>
+ <h3>Repeated Python SQL Triggers</h3>
+ <p tal:condition="not: options/top_triggers">None.</p>
+ <div tal:condition="options/top_triggers">
+ <p>Typically, these show loops. The traceback may show extra
+ information, such as from page templates, that indicate the variable
+ within the loop. If you want to add more information to identify the
+ variables in the loop, in your Python add either an informational string
+ with the variable name <code>__traceback_info__</code>, or add a
+ <code>__traceback_supplement__</code> as used in
+ lp.services.stacktrace.</p>
+ <div tal:repeat="trigger options/top_triggers">
+ <div>File "<tal:block replace="trigger/filename"></tal:block>",
+ line <tal:block replace="trigger/lineno"></tal:block></div>
+ <div class="querylinks">
+ <tal:block replace="trigger/count"></tal:block> related queries (<a
+ href="#" class="expandall">expand all tracebacks</a>): <span
+ tal:repeat="ix trigger/indexes"> <a tal:attributes="href
+ string:#sqlstep-${ix}" tal:content="ix"></a> </span>
+ </div>
+ </div>
+ </div>
+ <h3>SQL (<tal:block replace="options/sql_count"></tal:block> queries)</h3>
+ <p>Each sql line begins with the start time and the stop time, along with
+ the name of the database on which the query ran. Times are in
+ milliseconds since request start.</p>
+ <div><a href="#" id="show-all-tracebacks">Show all tracebacks</a> / <a href="#"
+ id="hide-all-tracebacks">Hide all tracebacks</a></div>
+ <div tal:repeat="step sqltrace_steps">
+ <div tal:condition="step/python_rank|nothing" tal:attributes="class
+ string: python_topten ${step/python_class}; id
+ string:pythonstep-${step/id}"><strong>Top ten (# <tal:block
+ replace="step/python_rank"></tal:block>):</strong> Python work took
+ <span tal:replace="step/python_time" /> milliseconds in-between SQL
+ calls.</div>
+ <div tal:attributes="class string: sqlstep ${step/sql_class|nothing};
+ id string:sqlstep-${step/id};">
+ <div class="sqlinfo">
+ <div class="col1"><span><tal:block replace="step/id"></tal:block>.
+ <span class="sqlstats"><span
+ tal:replace="step/sql/start"></span> - <span
+ tal:replace="step/sql/stop"></span> @ <tal:block
+ replace="step/sql/name"></tal:block></span></span> <span
+ tal:condition="step/sql_rank|nothing"><strong>Top ten (# <tal:block
+ replace="step/sql_rank"></tal:block>):</strong> SQL took <span
+ tal:replace="step/sql_time" /> milliseconds</span></div> <a href="#"
+ class="clicktext">Click to toggle Python traceback.</a>
+ </div>
+ <div class="trace"><div class="inner">
+ <div class="appstack" tal:define="stack step/app_stack">
+ <div tal:repeat="frame stack" metal:define-macro="draw-stack">
+ <div>File "<tal:block replace="frame/filename"></tal:block>",
+ line <tal:block replace="frame/lineno"></tal:block>, in
+ <tal:block replace="frame/name"></tal:block></div>
+ <div tal:condition="frame/line" tal:content="frame/line" class="line"></div>
+ <div tal:define="supp frame/supplement" tal:condition="supp" class="supplement">
+ <div tal:condition="supp/source_url" tal:content="supp/source_url"></div>
+ <div tal:define="line supp/line; column supp/column;"
+ tal:condition="python:line or column">
+ <tal:block condition="line">Line <span tal:replace="line"></span><tal:block condition="column">, </tal:block></tal:block>
+ <tal:block condition="column">Column <span tal:replace="column"></span></tal:block>
+ </div>
+ <div tal:condition="supp/expression">Expression: <code tal:content="supp/expression"></code></div>
+ <div tal:condition="supp/warnings">
+ <div tal:repeat="warning supp/warnings" class="tracebackwarning">Warning: <span tal:replace="supp/warnings"></span></div>
+ </div>
+ <pre tal:condition="supp/extra"
+ tal:content="supp/extra"></pre>
+ </div>
+ <pre tal:condition="frame/info" tal:content="frame/info" class="extrainfo"></pre>
+ </div>
+ </div>
+ <div class="dbstack" tal:define="stack step/db_stack">
+ <div metal:use-macro="template/macros/draw-stack"></div>
+ </div>
+ </div></div>
+ <pre tal:attributes="class string: sql ${step/sql_class|nothing}" tal:content="step/sql/statement"></pre>
+ </div>
+ </div>
+ </tal:block>
<h2>Profile quick view</h2>
<tal:block condition="not:show">
<p>Use <code>++profile++show</code> in your URL in order to see immediate
@@ -133,12 +266,74 @@
</tal:block>
</div>
<script>
-LPS.use('node', 'lp', function (Y) {
+LPS.use('node', 'lp', 'transition', function (Y) {
Y.one('div#reveal_profiling').on('click', function (e) {
Y.one('div#profiling_info').setStyle('display', 'block');
+ e.preventDefault();
});
Y.one('div#hide_profiling').on('click', function (e) {
Y.one('div#profiling_info').setStyle('display', 'none');
+ e.preventDefault();
+ });
+ function slideIn(target) {
+ target.transition({
+ easing: 'ease-in',
+ duration: 0.75, // seconds
+ height: '0px'
+ }, function() {
+ target.setStyle('display', 'none');
+ });
+ }
+ function slideOut(target) {
+ target.setStyles({display: 'block', height: '0px'});
+ var inner = target.one('.inner');
+ var height = parseInt(inner.getComputedStyle('height'));
+ target.transition({
+ easing: 'ease-out',
+ duration: 0.75, // seconds
+ height: height+'px'
+ }, function() {
+ target.setStyle('height', 'auto');
+ });
+ }
+ // We use "all" on these two as a lazy way to handle the possibility
+ // that the link may not be there.
+ Y.all('#show-all-tracebacks').on('click', function (e) {
+ // For speed, just force them all open without animation.
+ Y.all('.trace').setStyles({display: 'block', height: 'auto'});
+ e.preventDefault();
+ });
+ Y.all('#hide-all-tracebacks').on('click', function (e) {
+ // For speed, just force them all closed without animation.
+ Y.all('.trace').setStyle('display', 'none');
+ e.preventDefault();
+ });
+ Y.all('.expandall').on('click', function (e) {
+ var links = e.currentTarget.ancestor('.querylinks').all('span a');
+ links.each(function (link) {
+ var href = link.get('href');
+ var identifier = href.slice(href.indexOf('#'));
+ var target = Y.one(identifier).one('.trace');
+ // target.setStyles({display: 'block', height: 'auto'});
+ if (target.getStyle('display') !== 'block') {
+ slideOut(target);
+ }
+ });
+ e.preventDefault();
+ });
+ Y.on('load', function(e) {
+ // We hide the tracebacks with Javascript so that, if the Javascript
+ // does not load, we still can easily see the tracebacks.
+ Y.all('.trace').setStyle('display', 'none');
+ Y.all('.sqlinfo').on('click', function(e) {
+ var trace = e.currentTarget.ancestor('.sqlstep').one('.trace');
+ if (trace.getStyle('display') === 'block') {
+ slideIn(trace);
+ } else {
+ slideOut(trace);
+ }
+ e.preventDefault();
+ });
});
});
</script>
=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py 2011-08-16 00:30:51 +0000
+++ lib/lp/services/profile/profile.py 2011-08-22 19:17:17 +0000
@@ -13,12 +13,12 @@
import contextlib
from cProfile import Profile
from datetime import datetime
+import heapq
import os
import pstats
import threading
import StringIO
-from bzrlib import errors
from bzrlib import lsprof
import oops_datedir_repo.serializer_rfc822
from zope.pagetemplate.pagetemplatefile import PageTemplateFile
@@ -156,7 +156,7 @@
self.actions = None
self.profiler = None
self.memory_profile_start = None
-
+
_profilers = Profilers()
@@ -210,7 +210,9 @@
if config.profiling.profile_all_requests:
actions.add('callgrind')
if actions:
- if actions.difference(('help',)):
+ if 'sqltrace' in actions:
+ da.start_sql_traceback_logging()
+ if 'show' in actions or actions.intersection(available_profilers):
_profilers.profiler = Profiler()
_profilers.profiler.start()
if config.profiling.memory_profile_log:
@@ -340,6 +342,111 @@
template_context['multiple_profiles'] = prof_stats.count > 1
# Try to free some more memory.
del prof_stats
+ trace = None
+ if 'sqltrace' in actions:
+ trace = da.stop_sql_traceback_logging()
+ # The trace is a list of dicts, each with the keys "sql" and
+ # "stack". "sql" is a tuple of start time, stop time, database
+ # name (with a "SQL-" prefix), and sql statement. "stack" is a
+ # tuple of filename, line number, function name, text, module
+ # name, optional supplement dict, and optional info string. The
+ # supplement dict has keys 'source_url', 'line', 'column',
+ # 'expression', 'warnings' (an iterable), and 'extra', any of
+ # which may be None.
+ top_sql = []
+ top_python = []
+ triggers = {}
+ ix = 1 # We display these, so start at 1, not 0.
+ last_stop_time = 0
+ _heappushpop = heapq.heappushpop # This is an optimization.
+ for step in trace:
+ # Set up an identifier for each trace step.
+ step['id'] = ix
+ step['sql'] = dict(zip(
+ ('start', 'stop', 'name', 'statement'), step['sql']))
+ # Divide up the stack into the more unique (app) and less
+ # unique (db) bits.
+ app_stack = step['app_stack'] = []
+ db_stack = step['db_stack'] = []
+ storm_found = False
+ for f in step['stack']:
+ f_data = dict(zip(
+ ('filename', 'lineno', 'name', 'line', 'module',
+ 'supplement', 'info'), f))
+ storm_found = storm_found or (
+ f_data['module'] and
+ f_data['module'].startswith('storm.'))
+ if storm_found:
+ db_stack.append(f_data)
+ else:
+ app_stack.append(f_data)
+ # Begin to gather what app code is triggering the most SQL
+ # calls.
+ trigger_key = tuple(
+ (f['filename'], f['lineno']) for f in app_stack)
+ if trigger_key not in triggers:
+ triggers[trigger_key] = []
+ triggers[trigger_key].append(ix)
+ # Get the nbest (n=10) sql and python times
+ step['python_time'] = step['sql']['start'] - last_stop_time
+ step['sql_time'] = step['sql']['stop'] - step['sql']['start']
+ python_data = (step['python_time'], ix, step)
+ sql_data = (step['sql_time'], ix, step)
+ if ix < 10:
+ top_sql.append(sql_data)
+ top_python.append(python_data)
+ else:
+ if ix == 10:
+ heapq.heapify(top_sql)
+ heapq.heapify(top_python)
+ _heappushpop(top_sql, sql_data)
+ _heappushpop(top_python, python_data)
+ # Reset for next loop.
+ last_stop_time = step['sql']['stop']
+ ix += 1
+ # Finish setting up top sql and python times.
+ top_sql.sort(reverse=True)
+ top_python.sort(reverse=True)
+ top_sql_ids = []
+ for rank, (key, ix, step) in enumerate(top_sql):
+ step['sql_rank'] = rank + 1
+ step['sql_class'] = (
+ 'sql_danger' if key > 500 else
+ 'sql_warning' if key > 100 else None)
+ top_sql_ids.append(dict(
+ value=key,
+ ix=ix,
+ rank=step['sql_rank'],
+ cls=step['sql_class']))
+ top_python_ids = []
+ for rank, (key, ix, step) in enumerate(top_python):
+ step['python_rank'] = rank + 1
+ step['python_class'] = (
+ 'python_danger' if key > 500 else
+ 'python_warning' if key > 100 else None)
+ top_python_ids.append(dict(
+ value=key,
+ ix=ix,
+ rank=step['python_rank'],
+ cls=step['python_class']))
+ # Identify the repeated Python calls that generated SQL.
+ triggers = triggers.items()
+ triggers.sort(key=lambda x: len(x[1]))
+ triggers.reverse()
+ top_triggers = []
+ for (key, ixs) in triggers:
+ if len(ixs) == 1:
+ break
+ info = trace[ixs[0] - 1]['app_stack'][-1].copy()
+ info['indexes'] = ixs
+ info['count'] = len(ixs)
+ top_triggers.append(info)
+ template_context.update(dict(
+ sqltrace=trace,
+ top_sql=top_sql_ids,
+ top_python=top_python_ids,
+ top_triggers=top_triggers,
+ sql_count=len(trace)))
template_context['dump_path'] = os.path.abspath(dump_path)
if actions and is_html:
# Hack the new HTML in at the end of the page.
@@ -397,7 +504,7 @@
result.remove('log')
result.add('callgrind')
# Only honor the available options.
- available_options = set(('show',))
+ available_options = set(('show', 'sqltrace', 'help'))
available_options.update(available_profilers)
result.intersection_update(available_options)
# If we didn't end up with any known actions, we need to help the
=== modified file 'lib/lp/services/profile/tests.py'
--- lib/lp/services/profile/tests.py 2011-08-16 00:30:51 +0000
+++ lib/lp/services/profile/tests.py 2011-08-22 19:17:17 +0000
@@ -12,9 +12,7 @@
import glob
import os
import random
-import time
-from lp.testing import TestCase
from zope.app.publication.interfaces import (
BeforeTraverseEvent,
EndRequestEvent,
@@ -22,15 +20,15 @@
from zope.component import getSiteManager
import canonical.launchpad.webapp.adapter as da
-from canonical.launchpad.webapp.errorlog import (
- ErrorReport,
- ErrorReportingUtility,
- )
+from canonical.launchpad.webapp.errorlog import ErrorReportingUtility
from canonical.launchpad.webapp.servers import LaunchpadTestRequest
from canonical.launchpad.webapp.interfaces import StartRequestEvent
from canonical.testing import layers
from lp.services.features.testing import FeatureFixture
from lp.services.profile import profile
+from lp.testing import (
+ TestCase,
+ TestCaseWithFactory)
EXAMPLE_HTML_START = '''\
<html><head><title>Random!</title></head>
@@ -84,6 +82,7 @@
profile._profilers.actions = None
profile._profilers.memory_profile_start = None
profile._profilers.profiling = False
+ da.stop_sql_traceback_logging()
super(TestCleanupProfiler, self).tearDown()
@@ -271,13 +270,18 @@
self.assertEqual(len(profile._profilers.memory_profile_start), 2)
self.assertEquals(profile._profilers.actions, set(('show', )))
+ def test_sqltrace_start(self):
+ self.pushProfilingConfig(profiling_allowed='True')
+ profile.start_request(self._get_start_event('/++profile++sqltrace/'))
+ self.assertIs(getattr(profile._profilers, 'profiler', None), None)
+ self.assertEquals(profile._profilers.actions, set(('sqltrace', )))
+ self.assertEqual([], da.stop_sql_traceback_logging())
+
class BaseRequestEndHandlerTest(BaseTest):
def setUp(self):
- TestCase.setUp(self)
- self.patch(da, 'get_request_start_time', time.time)
- self.patch(da, 'get_request_duration', lambda: 0.5)
+ super(BaseRequestEndHandlerTest, self).setUp()
self.profile_dir = self.makeTemporaryDirectory()
self.memory_profile_log = os.path.join(self.profile_dir, 'memory_log')
self.pushConfig('profiling', profile_dir=self.profile_dir)
@@ -288,6 +292,7 @@
def endRequest(self, path='/', exception=None, pageid=None, work=None):
start_event = self._get_start_event(path)
+ da.set_request_started()
profile.start_request(start_event)
request = start_event.request
if pageid is not None:
@@ -301,6 +306,7 @@
self.eru.raising(
(type(exception), exception, None), event.request)
profile.end_request(event)
+ da.clear_request_started()
return event.request
def getAddedResponse(self, request,
@@ -519,6 +525,7 @@
def test_memory_profile(self):
# Does the memory profile work?
+ self.patch(da, 'get_request_duration', lambda: 0.5)
self.pushProfilingConfig(
profiling_allowed='True',
memory_profile_log=self.memory_profile_log)
@@ -650,3 +657,23 @@
request = self.endRequest('/', work=work)
self.assertPStatsProfile(
self.assertBasicProfileExists(request, show=True))
+
+
+class TestSqlTrace(TestCaseWithFactory, BaseRequestEndHandlerTest):
+
+ layer = layers.DatabaseFunctionalLayer
+
+ def testLogging(self):
+ # This is basically a smoketest. The underlying machinery has tests.
+ self.pushProfilingConfig(profiling_allowed='True')
+ request = self.endRequest(
+ '/++profile++sqltrace/', work=self.factory.makeBug)
+ response = self.getAddedResponse(request)
+ self.assertIn('Top 10 SQL times', response)
+ self.assertIn('Query number', response)
+ self.assertIn('Top 10 Python times', response)
+ self.assertIn('Before query', response)
+ self.assertIn('Repeated Python SQL Triggers', response)
+ self.assertIn('Show all tracebacks', response)
+ # This file should be part of several of the tracebacks.
+ self.assertIn(__file__.replace('.pyc', '.py'), response)
=== added file 'lib/lp/services/stacktrace.py'
--- lib/lp/services/stacktrace.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/stacktrace.py 2011-08-22 19:17:17 +0000
@@ -0,0 +1,227 @@
+# Copyright 2011 Canonical Ltd. This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Replacement for some standard library traceback module functions.
+
+These honor traceback supplements as defined in zope.exceptions.
+"""
+
+__metaclass__ = type
+__all__ = [
+ 'extract_stack',
+ 'extract_tb',
+ 'format_list',
+ 'print_list',
+ 'print_stack',
+ ]
+
+import linecache
+import sys
+import traceback
+
+DEBUG_EXCEPTION_FORMATTER = False
+
+
+def _get_frame(f):
+ "if the frame is None, make one."
+ if f is None:
+ try:
+ raise ZeroDivisionError
+ except ZeroDivisionError:
+ f = sys.exc_info()[2].tb_frame.f_back.f_back
+ return f
+
+
+def _fmt(string):
+ "Return the string as deemed suitable for the extra information."
+ return ' - %s' % string
+
+
+def print_list(extracted_list, file=None):
+ """Print the list of tuples as returned by extract_tb() or
+ extract_stack() as a formatted stack trace to the given file."""
+ if file is None:
+ file = sys.stderr
+ for line in format_list(extracted_list):
+ file.write(line)
+
+
+def format_list(extracted_list):
+ """Format a list of traceback entry tuples for printing.
+
+ Given a list of tuples as returned by extract_tb() or
+ extract_stack(), return a list of strings ready for printing.
+ Each string in the resulting list corresponds to the item with the
+ same index in the argument list. Each string ends in a newline;
+ the strings may contain internal newlines as well, for those items
+ whose source text line or supplement or info are not None.
+ """
+ list = []
+ for filename, lineno, name, line, modname, supp, info in extracted_list:
+ item = []
+ item.append(
+ ' File "%s", line %d, in %s' % (filename, lineno, name))
+ if line:
+ item.append(' %s' % line.strip())
+ # The "supp" and "info" bits are adapted from zope.exceptions.
+ try:
+ if supp:
+ if supp['source_url']:
+ item.append(_fmt(supp['source_url']))
+ if supp['line']:
+ if supp['column']:
+ item.append(
+ _fmt('Line %(line)s, Column %(column)s' % supp))
+ else:
+ item.append(_fmt('Line %(line)s' % supp))
+ elif supp['column']:
+ item.append(_fmt('Column %(column)s' % supp))
+ if supp['expression']:
+ item.append(_fmt('Expression: %(expression)s' % supp))
+ if supp['warnings']:
+ for warning in supp['warnings']:
+ item.append(_fmt('Warning: %s' % warning))
+ if supp['extra']:
+ item.append(supp['extra']) # We do not include a prefix.
+ if info:
+ item.append(_fmt(info))
+ except (SystemExit, KeyboardInterrupt):
+ raise
+ except:
+ # The values above may not stringify properly, or who knows what
+ # else. Be defensive.
+ if DEBUG_EXCEPTION_FORMATTER:
+ traceback.print_exc()
+ # else just swallow the exception.
+ item.append('') # This gives us a trailing newline.
+ list.append('\n'.join(item))
+ return list
+
+
+def print_stack(f=None, limit=None, file=None):
+ """Print a stack trace from its invocation point.
+
+ The optional 'f' argument can be used to specify an alternate
+ stack frame at which to start. The optional 'limit' and 'file'
+ arguments have the same meaning as for print_exception().
+ """
+ print_list(extract_stack(_get_frame(f), limit), file)
+
+
+def _get_limit(limit):
+ "Return the limit or the globally-set limit, if any."
+ if limit is None:
+ # stdlib uses hasattr here.
+ if hasattr(sys, 'tracebacklimit'):
+ limit = sys.tracebacklimit
+ return limit
+
+
+def _get_frame_data(f, lineno):
+ "Given a frame and a lineno, return data for each item of extract_*."
+ co = f.f_code
+ filename = co.co_filename
+ name = co.co_name
+ linecache.checkcache(filename)
+ line = linecache.getline(filename, lineno, f.f_globals)
+ if line:
+ line = line.strip()
+ else:
+ line = None
+ # Adapted from zope.exceptions.
+ modname = f.f_globals.get('__name__')
+ # Output a traceback supplement, if any.
+ supplement = info = None
+ if '__traceback_supplement__' in f.f_locals:
+ # Use the supplement defined in the function.
+ tbs = f.f_locals['__traceback_supplement__']
+ elif '__traceback_supplement__' in f.f_globals:
+ # Use the supplement defined in the module.
+ tbs = f.f_globals['__traceback_supplement__']
+ else:
+ tbs = None
+ if tbs is not None:
+ factory = tbs[0]
+ args = tbs[1:]
+ try:
+ supplement = factory(*args)
+ except (SystemExit, KeyboardInterrupt):
+ raise
+ except:
+ if DEBUG_EXCEPTION_FORMATTER:
+ traceback.print_exc()
+ # else just swallow the exception.
+ else:
+ # It might be nice if supplements could be dicts, for simplicity.
+ # Historically, though, they are objects.
+ # We will turn the supplement into a dict, so that we have
+ # "getInfo" pre-processed and so that we are not holding on to
+ # anything from the frame.
+ extra = None
+ getInfo = getattr(supplement, 'getInfo', None)
+ if getInfo is not None:
+ try:
+ extra = getInfo()
+ except (SystemExit, KeyboardInterrupt):
+ raise
+ except:
+ if DEBUG_EXCEPTION_FORMATTER:
+ traceback.print_exc()
+ # else just swallow the exception.
+ supplement = dict(
+ # The "_url" suffix is historical.
+ source_url=getattr(supplement, 'source_url', None),
+ line=getattr(supplement, 'line', None),
+ column=getattr(supplement, 'column', None),
+ expression=getattr(supplement, 'expression', None),
+ warnings=getattr(supplement, 'warnings', ()),
+ extra=extra)
+ info = f.f_locals.get('__traceback_info__', None)
+ # End part adapted from zope.exceptions.
+ return (filename, lineno, name, line, modname, supplement, info)
+
+
+def extract_stack(f=None, limit=None):
+ """Extract the raw traceback from the current stack frame.
+
+ The return value has the same format as for extract_tb(). The optional
+ 'f' and 'limit' arguments have the same meaning as for print_stack().
+ Each item in the list is a septuple (filename, line number, function name,
+ text, module name, optional supplement dict, optional info string), and
+ the entries are in order from oldest to newest stack frame.
+ """
+ f = _get_frame(f)
+ limit = _get_limit(limit)
+ list = []
+ n = 0
+ while f is not None and (limit is None or n < limit):
+ list.append(_get_frame_data(f, f.f_lineno))
+ f = f.f_back
+ n = n + 1
+ list.reverse()
+ return list
+
+
+def extract_tb(tb, limit=None):
+ """Return list of up to limit pre-processed entries from traceback.
+
+ This is useful for alternate formatting of stack traces. If 'limit' is
+ omitted or None, all entries are extracted. A pre-processed stack trace
+ entry is a sextuple (filename, line number, function name, text, module
+ name, optional supplement dict, optional info string) representing the
+ information that is printed for a stack trace. The text is a string with
+ leading and trailing whitespace stripped; if the source is not available
+ it is None. The supplement dict has keys 'source_url', 'line', 'column',
+ 'expression', 'warnings' (an iterable), and 'extra', any of which may be
+ None.
+ """
+ # zope.exceptions handles tracebacks. This function is implemented just
+ # to show how this module's patterns might be extended to tracebacks.
+ limit = _get_limit(limit)
+ list = []
+ n = 0
+ while tb is not None and (limit is None or n < limit):
+ list.append(_get_frame_data(tb.tb_frame, tb.tb_lineno))
+ tb = tb.tb_next
+ n = n + 1
+ return list
=== added file 'lib/lp/services/tests/test_stacktrace.py'
--- lib/lp/services/tests/test_stacktrace.py 1970-01-01 00:00:00 +0000
+++ lib/lp/services/tests/test_stacktrace.py 2011-08-22 19:17:17 +0000
@@ -0,0 +1,287 @@
+# Copyright 2011 Canonical Ltd. This software is licensed under the
+# GNU Affero General Public License version 3 (see the file LICENSE).
+
+"""Test the stacktrace module."""
+
+__metaclass__ = type
+
+import StringIO
+import sys
+
+from canonical.testing.layers import BaseLayer
+from lp.services import stacktrace
+from lp.testing import TestCase
+
+# This constant must always be equal to the line number on which it lives for
+# the tests to pass.
+MY_LINE_NUMBER = 17
+
+
+class Supplement:
+ def __init__(self, kwargs):
+ for key, value in kwargs.items():
+ assert key in ('getInfo', 'source_url', 'line', 'column',
+ 'expression', 'warnings'), 'Bad attribute name.'
+ setattr(self, key, value)
+
+
+def get_frame(supplement=None, info=None):
+ if supplement is not None:
+ __traceback_supplement__ = (Supplement, supplement)
+ __traceback_supplement__ # Quiet down the linter.
+ if info is not None:
+ __traceback_info__ = info
+ __traceback_info__ # Quiet down the linter.
+ return sys._getframe()
+
+
+class TestStacktrace(TestCase):
+
+ layer = BaseLayer
+
+ def test_get_frame_helper(self):
+ # non-None argument passed is returned unchanged.
+ self.assertEqual(self, stacktrace._get_frame(self))
+ # Otherwise get the frame two-up.
+
+ def run_get_frame():
+ """run _get_frame from inside another function."""
+ return stacktrace._get_frame(None)
+ self.assertEqual(sys._getframe(), run_get_frame())
+
+ def test_get_limit_helper(self):
+ # non-None argument is returned unchanged.
+ self.assertEqual(self, stacktrace._get_limit(self))
+ # Otherwise return sys.tracebacklimit if it exists, or None if not.
+ original_limit = getattr(sys, 'tracebacklimit', self)
+ try:
+ if original_limit is not self:
+ del sys.tracebacklimit
+ self.assertEqual(None, stacktrace._get_limit(None))
+ sys.tracebacklimit = 1000
+ self.assertEqual(1000, stacktrace._get_limit(None))
+ finally:
+ if (original_limit is self and
+ getattr(sys, 'tracebacklimit', self) is not self):
+ # Clean it off.
+ del sys.tracebacklimit
+ else:
+ sys.tracebacklimit = original_limit
+
+ def test_get_frame_data_standard(self):
+ filename, lineno, name, line, modname, supplement, info = (
+ stacktrace._get_frame_data(get_frame(), MY_LINE_NUMBER))
+ self.assertEqual(__file__, filename)
+ self.assertEqual(MY_LINE_NUMBER, lineno)
+ self.assertEqual('get_frame', name)
+ self.assertStartsWith(line, 'MY_LINE_NUMBER = ')
+ self.assertEqual(__name__, modname)
+ self.assertIs(None, supplement)
+ self.assertIs(None, info)
+
+ def test_get_frame_data_info(self):
+ filename, lineno, name, line, modname, supplement, info = (
+ stacktrace._get_frame_data(
+ get_frame(info='foo bar'), MY_LINE_NUMBER))
+ self.assertEqual('foo bar', info)
+
+ def test_get_frame_data_supplement_empty(self):
+ filename, lineno, name, line, modname, supplement, info = (
+ stacktrace._get_frame_data(
+ get_frame(supplement={}), MY_LINE_NUMBER))
+ self.assertEqual(
+ dict(source_url=None, line=None, column=None, expression=None,
+ warnings=(), extra=None),
+ supplement)
+
+ def test_get_frame_data_supplement_and_info(self):
+ filename, lineno, name, line, modname, supplement, info = (
+ stacktrace._get_frame_data(
+ get_frame(supplement={}, info='foo bar'),
+ MY_LINE_NUMBER))
+ self.assertEqual(
+ dict(source_url=None, line=None, column=None, expression=None,
+ warnings=(), extra=None),
+ supplement)
+ self.assertEqual('foo bar', info)
+
+ def test_get_frame_data_supplement_all(self):
+ filename, lineno, name, line, modname, supplement, info = (
+ stacktrace._get_frame_data(
+ get_frame(
+ supplement=dict(
+ source_url='/foo/bar.pt',
+ line=42,
+ column=84,
+ expression='tal:define="foo view/foo"',
+ warnings=('watch out', 'pass auf'),
+ getInfo=lambda: 'read all about it'
+ )),
+ MY_LINE_NUMBER))
+ self.assertEqual(
+ dict(source_url='/foo/bar.pt', line=42, column=84,
+ expression='tal:define="foo view/foo"',
+ warnings=('watch out', 'pass auf'),
+ extra='read all about it'),
+ supplement)
+
+ def test_get_frame_data_supplement_bad_getInfo(self):
+ def boo_hiss():
+ raise ValueError()
+ filename, lineno, name, line, modname, supplement, info = (
+ stacktrace._get_frame_data(
+ get_frame(supplement=dict(getInfo=boo_hiss)),
+ MY_LINE_NUMBER))
+ self.assertEqual(
+ dict(source_url=None, line=None, column=None, expression=None,
+ warnings=(), extra=None),
+ supplement)
+
+ def test_get_frame_data_supplement_bad_getInfo_with_traceback(self):
+ def boo_hiss():
+ raise ValueError()
+ stderr = sys.stderr = StringIO.StringIO()
+ self.assertFalse(stacktrace.DEBUG_EXCEPTION_FORMATTER)
+ stacktrace.DEBUG_EXCEPTION_FORMATTER = True
+ try:
+ filename, lineno, name, line, modname, supplement, info = (
+ stacktrace._get_frame_data(
+ get_frame(supplement=dict(getInfo=boo_hiss)),
+ MY_LINE_NUMBER))
+ finally:
+ sys.stderr = sys.__stderr__
+ stacktrace.DEBUG_EXCEPTION_FORMATTER = False
+ self.assertEqual(
+ dict(source_url=None, line=None, column=None, expression=None,
+ warnings=(), extra=None),
+ supplement)
+ self.assertIn('boo_hiss', stderr.getvalue())
+
+ def test_extract_stack(self):
+ extracted = stacktrace.extract_stack(get_frame())
+ self.assertTrue(len(extracted) > 1)
+ filename, lineno, name, line, modname, supplement, info = (
+ extracted[-1])
+ self.assertEqual(__file__, filename)
+ self.assertIsInstance(lineno, int)
+ self.assertEqual('get_frame', name)
+ self.assertEqual('return sys._getframe()', line)
+ self.assertEqual(__name__, modname)
+ self.assertIs(None, supplement)
+ self.assertIs(None, info)
+
+ def test_extract_tb(self):
+ try:
+ raise ValueError()
+ except ValueError:
+ type_, value, tb = sys.exc_info()
+ extracted = stacktrace.extract_tb(tb)
+ self.assertEqual(1, len(extracted))
+ filename, lineno, name, line, modname, supplement, info = (
+ extracted[0])
+ self.assertEqual(__file__, filename)
+ self.assertIsInstance(lineno, int)
+ self.assertEqual('test_extract_tb', name)
+ self.assertEqual('raise ValueError()', line)
+ self.assertEqual(__name__, modname)
+ self.assertIs(None, supplement)
+ self.assertIs(None, info)
+
+ def test_format_list_simple(self):
+ extracted = stacktrace.extract_stack(get_frame())
+ formatted = stacktrace.format_list(extracted)
+ self.assertIsInstance(formatted, list)
+ for line in formatted:
+ self.assertEndsWith(line, '\n')
+ line = formatted[-1].split('\n')
+ self.assertStartsWith(
+ line[0], ' File "' + __file__ + '", line ')
+ self.assertEndsWith(line[0], ', in get_frame')
+ self.assertEqual(' return sys._getframe()', line[1])
+
+ def test_format_list_full(self):
+ extracted = stacktrace.extract_stack(
+ get_frame(
+ supplement=dict(
+ source_url='/foo/bar.pt',
+ line=42,
+ column=84,
+ expression='tal:define="foo view/foo"',
+ warnings=('watch out', 'pass auf'),
+ getInfo=lambda: 'read all about it'),
+ info='I am the Walrus'
+ )
+ )
+ formatted = stacktrace.format_list(extracted)
+ self.assertIsInstance(formatted, list)
+ for line in formatted:
+ self.assertEndsWith(line, '\n')
+ line = formatted[-1].split('\n')
+ self.assertStartsWith(
+ line[0], ' File "' + __file__ + '", line ')
+ self.assertEndsWith(line[0], ', in get_frame')
+ self.assertEqual(' return sys._getframe()', line[1])
+ self.assertEqual(' - /foo/bar.pt', line[2])
+ self.assertEqual(' - Line 42, Column 84', line[3])
+ self.assertEqual(
+ ' - Expression: tal:define="foo view/foo"', line[4])
+ self.assertEqual(
+ ' - Warning: watch out', line[5])
+ self.assertEqual(
+ ' - Warning: pass auf', line[6])
+ self.assertEqual(
+ 'read all about it', line[7])
+ self.assertEqual(' - I am the Walrus', line[8])
+
+ def test_format_list_extra_errors(self):
+ extracted = stacktrace.extract_stack(
+ get_frame(
+ supplement=dict(
+ # This will cause an error because it is not iterable.
+ warnings=object()
+ ))
+ )
+ stderr = sys.stderr = StringIO.StringIO()
+ self.assertFalse(stacktrace.DEBUG_EXCEPTION_FORMATTER)
+ stacktrace.DEBUG_EXCEPTION_FORMATTER = True
+ try:
+ formatted = stacktrace.format_list(extracted)
+ finally:
+ sys.stderr = sys.__stderr__
+ stacktrace.DEBUG_EXCEPTION_FORMATTER = False
+ self.assertStartsWith(stderr.getvalue(), 'Traceback (most recent')
+ self.assertEndsWith(formatted[-1], ' return sys._getframe()\n')
+
+ def test_print_list_default(self):
+ extracted = stacktrace.extract_stack(get_frame())
+ stderr = sys.stderr = StringIO.StringIO()
+ try:
+ stacktrace.print_list(extracted)
+ finally:
+ sys.stderr = sys.__stderr__
+ self.assertEndsWith(stderr.getvalue(), 'return sys._getframe()\n')
+
+ def test_print_list_file(self):
+ extracted = stacktrace.extract_stack(get_frame())
+ f = StringIO.StringIO()
+ stacktrace.print_list(extracted, file=f)
+ self.assertEndsWith(f.getvalue(), 'return sys._getframe()\n')
+
+ def test_print_stack_default(self):
+ stderr = sys.stderr = StringIO.StringIO()
+ try:
+ stacktrace.print_stack()
+ finally:
+ sys.stderr = sys.__stderr__
+ self.assertEndsWith(stderr.getvalue(), 'stacktrace.print_stack()\n')
+
+ def test_print_stack_options(self):
+ f = StringIO.StringIO()
+ frame = get_frame()
+ stacktrace.print_stack(f=frame, limit=100, file=f)
+ self.assertEndsWith(f.getvalue(), 'return sys._getframe()\n')
+ self.assertTrue(len(f.getvalue().split('\n')) > 4)
+ f = StringIO.StringIO()
+ stacktrace.print_stack(f=frame, limit=2, file=f)
+ self.assertEqual(4, len(f.getvalue().strip().split('\n')))
+ self.assertEndsWith(f.getvalue(), 'return sys._getframe()\n')
