def test_sqltrace_filtered_start(self):
self.pushProfilingConfig(profiling_allowed='True')
profile.start_request(self._get_start_event(
'/++profile++sqltrace:includes bugsubscription/'))
self.assertIs(getattr(profile._profilers, 'profiler', None), None)
self.assertEquals(set(profile._profilers.actions), set(('sql', )))
data = profile._profilers.actions['sql']
self.assertTrue(data['condition']('SELECT BUGSUBSCRIPTION FROM FOO'))
self.assertEqual([], da.stop_sql_logging())
def test_sqltrace_filtered_start(self):
self.pushProfilingConfig(profiling_allowed='True')
profile.start_request(self._get_start_event(
'/++profile++sqltrace:includes bugsubscription/'))
self.assertIs(getattr(profile._profilers, 'profiler', None), None)
self.assertEqual(set(profile._profilers.actions), set(('sql', )))
data = profile._profilers.actions['sql']
self.assertTrue(data['condition']('SELECT BUGSUBSCRIPTION FROM FOO'))
self.assertEqual([], da.stop_sql_logging())
def test_data_logging_with_conditional_stacktrace_normalized_whitespace(
self):
# The whitespace in the SQL is normalized
da.start_sql_logging(
tracebacks_if=lambda sql: 'FROM KUMQUAT WHERE' in sql)
self.execute(statement='SELECT * FROM kumquat \nWHERE bing = 42')
result = da.stop_sql_logging()
self.assertEqual(1, len(result))
self.assertIsNot(None, result[0]['stack'])
def test_print_queries_without_tracebacks(self):
da.start_sql_logging()
self.execute()
result = da.stop_sql_logging()
with stdout() as file:
da.print_queries(result)
self.assertEqual(
'1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
"-" * 70 + "\n", file.getvalue())
def test_print_queries_without_tracebacks(self):
da.start_sql_logging()
self.execute()
result = da.stop_sql_logging()
with stdout() as file:
da.print_queries(result)
self.assertEqual(
'1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
"-" * 70 + "\n", file.getvalue())
def test_data_logging_with_conditional_stacktrace_normalized_whitespace(
self):
# The whitespace in the SQL is normalized
da.start_sql_logging(
tracebacks_if=lambda sql: 'FROM KUMQUAT WHERE' in sql)
self.execute(statement='SELECT * FROM kumquat \nWHERE bing = 42')
result = da.stop_sql_logging()
self.assertEqual(1, len(result))
self.assertIsNot(None, result[0]['stack'])
def test_print_queries_with_tracebacks(self):
da.start_sql_logging(tracebacks_if=True)
self.execute()
result = da.stop_sql_logging()
with stdout() as file:
da.print_queries(result)
self.assertStartsWith(file.getvalue(), ' File "')
self.assertEndsWith(
file.getvalue(), "." * 70 + "\n" +
'1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
"-" * 70 + "\n")
def test_data_logging_with_conditional_stacktrace(self):
# Conditions must be normalized to uppercase.
da.start_sql_logging(tracebacks_if=lambda sql: 'KUMQUAT' in sql)
with stderr() as file:
self.execute()
self.execute(statement='SELECT * FROM kumquat WHERE bing = 42')
self.assertEqual('', file.getvalue())
result = da.stop_sql_logging()
self.assertEqual(2, len(result))
self.assertIs(None, result[0]['stack'])
self.assertIsNot(None, result[1]['stack'])
def test_data_logging_with_conditional_stacktrace(self):
# Conditions must be normalized to uppercase.
da.start_sql_logging(tracebacks_if=lambda sql: 'KUMQUAT' in sql)
with stderr() as file:
self.execute()
self.execute(statement='SELECT * FROM kumquat WHERE bing = 42')
self.assertEqual('', file.getvalue())
result = da.stop_sql_logging()
self.assertEqual(2, len(result))
self.assertIs(None, result[0]['stack'])
self.assertIsNot(None, result[1]['stack'])
def test_print_queries_with_tracebacks(self):
da.start_sql_logging(tracebacks_if=True)
self.execute()
result = da.stop_sql_logging()
with stdout() as file:
da.print_queries(result)
self.assertStartsWith(file.getvalue(), ' File "')
self.assertEndsWith(
file.getvalue(), "." * 70 + "\n" +
'1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
"-" * 70 + "\n")
def test_data_logging_with_stacktrace(self):
da.start_sql_logging(tracebacks_if=True)
with stderr() as file:
self.execute()
self.assertEqual('', file.getvalue())
result = da.stop_sql_logging()
self.assertEqual(1, len(result))
self.assertIsNot(None, result[0]['stack'])
self.assertIs(None, result[0]['exception'])
self.assertEqual((1, 2, 'SQL-stub-database',
'SELECT * FROM bar WHERE bing = 42', None),
result[0]['sql'])
def test_data_logging_with_stacktrace(self):
da.start_sql_logging(tracebacks_if=True)
with stderr() as file:
self.execute()
self.assertEqual('', file.getvalue())
result = da.stop_sql_logging()
self.assertEqual(1, len(result))
self.assertIsNot(None, result[0]['stack'])
self.assertIs(None, result[0]['exception'])
self.assertEqual((1, 2, 'SQL-stub-database',
'SELECT * FROM bar WHERE bing = 42', None),
result[0]['sql'])
def test_data_logging_with_broken_conditional_stacktrace(self):
error = ValueError('rutebega')
def ow(sql):
raise error
da.start_sql_logging(tracebacks_if=ow)
with stderr() as file:
self.execute()
self.assertEqual('', file.getvalue())
result = da.stop_sql_logging()
self.assertEqual(1, len(result))
self.assertIsNot(None, result[0]['stack'])
self.assertEqual((ValueError, error), result[0]['exception'])
self.assertEqual((1, 2, 'SQL-stub-database',
'SELECT * FROM bar WHERE bing = 42', None),
result[0]['sql'])
def test_print_queries_with_exceptions(self):
def ow(sql):
raise ValueError('rutebega')
da.start_sql_logging(tracebacks_if=ow)
self.execute()
result = da.stop_sql_logging()
with stdout() as file:
da.print_queries(result)
self.assertStartsWith(
file.getvalue(),
'Error when determining whether to generate a stacktrace.\n' +
'Traceback (most recent call last):\n' + ' File "')
self.assertEndsWith(
file.getvalue(), "ValueError: rutebega\n" + "." * 70 + "\n" +
'1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
"-" * 70 + "\n")
def test_data_logging_with_broken_conditional_stacktrace(self):
error = ValueError('rutebega')
def ow(sql):
raise error
da.start_sql_logging(tracebacks_if=ow)
with stderr() as file:
self.execute()
self.assertEqual('', file.getvalue())
result = da.stop_sql_logging()
self.assertEqual(1, len(result))
self.assertIsNot(None, result[0]['stack'])
self.assertEqual((ValueError, error), result[0]['exception'])
self.assertEqual((1, 2, 'SQL-stub-database',
'SELECT * FROM bar WHERE bing = 42', None),
result[0]['sql'])
def test_print_queries_with_exceptions(self):
def ow(sql):
raise ValueError('rutebega')
da.start_sql_logging(tracebacks_if=ow)
self.execute()
result = da.stop_sql_logging()
with stdout() as file:
da.print_queries(result)
self.assertStartsWith(
file.getvalue(),
'Error when determining whether to generate a stacktrace.\n' +
'Traceback (most recent call last):\n' + ' File "')
self.assertEndsWith(
file.getvalue(), "ValueError: rutebega\n" + "." * 70 + "\n" +
'1-2@SQL-stub-database SELECT * FROM bar WHERE bing = 42\n' +
"-" * 70 + "\n")
def test_sql_start(self):
self.pushProfilingConfig(profiling_allowed='True')
profile.start_request(self._get_start_event('/++profile++sql/'))
self.assertIs(getattr(profile._profilers, 'profiler', None), None)
self.assertEquals(profile._profilers.actions, dict(sql=False))
self.assertEqual([], da.stop_sql_logging())
def end_request(event):
"""If profiling is turned on, save profile data for the request."""
try:
if not _profilers.profiling:
return
_profilers.profiling = False
except AttributeError:
# Some tests don't go through all the proper motions, like firing off
# a start request event. Just be quiet about it.
return
actions = _profilers.actions
_profilers.actions = None
request = event.request
# Create a timestamp including milliseconds.
now = datetime.fromtimestamp(da.get_request_start_time())
timestamp = "%s.%d" % (
now.strftime('%Y-%m-%d_%H:%M:%S'), int(now.microsecond / 1000.0))
pageid = request._orig_env.get('launchpad.pageid', 'Unknown')
oopsid = getattr(request, 'oopsid', None)
content_type = request.response.getHeader('content-type')
if content_type is None:
content_type_params = {}
is_html = False
else:
_major, _minor, content_type_params = parse(content_type)
is_html = _major == 'text' and _minor == 'html'
template_context = {
'actions': dict((key, True) for key in actions),
'always_log': config.profiling.profile_all_requests}
dump_path = config.profiling.profile_dir
if _profilers.profiler is not None:
prof_stats = _profilers.profiler.stop()
# Free some memory (at least for the BzrProfiler).
_profilers.profiler = None
if oopsid is None:
# Log an OOPS to get a log of the SQL queries, and other
# useful information, together with the profiling
# information.
info = (ProfilingOops, None, None)
error_utility = getUtility(IErrorReportingUtility)
oops_report = error_utility.raising(info, request)
oopsid = oops_report['id']
else:
oops_report = request.oops
filename = '%s-%s-%s-%s' % (
timestamp, pageid, oopsid,
threading.currentThread().getName())
if 'callgrind' in actions:
# The stats class looks at the filename to know to use
# callgrind syntax.
callgrind_path = os.path.join(
dump_path, 'callgrind.out.' + filename)
prof_stats.save(callgrind_path, callgrind=True)
template_context['callgrind_path'] = os.path.abspath(
callgrind_path)
if 'pstats' in actions:
pstats_path = os.path.join(
dump_path, filename + '.prof')
prof_stats.save(pstats_path)
template_context['pstats_path'] = os.path.abspath(
pstats_path)
if is_html and 'show' in actions:
# Generate rfc822 OOPS result (might be nice to have an html
# serializer..).
template_context['oops'] = ''.join(
oops_datedir_repo.serializer_rfc822.to_chunks(oops_report))
# Generate profile summaries.
prof_stats.strip_dirs()
for name in ('time', 'cumulative', 'calls'):
prof_stats.sort(name)
f = StringIO.StringIO()
prof_stats.pprint(file=f)
template_context[name] = f.getvalue()
template_context['profile_count'] = prof_stats.count
template_context['multiple_profiles'] = prof_stats.count > 1
# Try to free some more memory.
del prof_stats
# Dump memory profiling info.
if 'memory_profile_start' in actions:
log = file(config.profiling.memory_profile_log, 'a')
vss_start, rss_start = actions.pop('memory_profile_start')
vss_end, rss_end = memory(), resident()
if oopsid is None:
oopsid = '-'
log.write('%s %s %s %f %d %d %d %d\n' % (
timestamp, pageid, oopsid, da.get_request_duration(),
vss_start, rss_start, vss_end, rss_end))
log.close()
trace = None
if 'sql' in actions:
trace = da.stop_sql_logging() or ()
# 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), sql statement and possibly a backtrace (backtraces
# are included when the timeline storm trace is installed). "stack" is
# None or 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', 'backtrace'),
step['sql']))
# NB: step['sql']['backtrace'] is a string backtrace, not a live
# stack: less flexible than what the profiler gathers, but cheaper
# to keep alive as it holds no references. For now, its not usable
# here.
if step['stack'] is not None:
# 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)))
if actions['sql'] is True:
template_context['sql_traceback_all'] = True
elif actions['sql'] is False:
template_context['sql_traceback_none'] = True
else:
conditions = actions['sql'].copy()
del conditions['condition']
template_context['sql_traceback_conditions'] = conditions
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.
encoding = content_type_params.get('charset', 'utf-8')
try:
added_html = template(**template_context).encode(encoding)
except (SystemExit, KeyboardInterrupt):
raise
except:
error = ''.join(format_exception(*sys.exc_info(), as_html=True))
added_html = (
'<div class="profiling_info">' + error + '</div>')
existing_html = request.response.consumeBody()
e_start, e_close_body, e_end = existing_html.rpartition(
'</body>')
new_html = ''.join(
(e_start, added_html, e_close_body, e_end))
request.response.setResult(new_html)
def test_sql_start(self):
self.pushProfilingConfig(profiling_allowed='True')
profile.start_request(self._get_start_event('/++profile++sql/'))
self.assertIs(getattr(profile._profilers, 'profiler', None), None)
self.assertEqual(profile._profilers.actions, dict(sql=False))
self.assertEqual([], da.stop_sql_logging())