← Back to branch summary

~launchpad-pqm/launchpad/devel

« back to all changes in this revision

Viewing changes to lib/lp/services/profile/profile.py

  • Committer: Launchpad Patch Queue Manager
  • Date: 2011-08-23 21:54:33 UTC
  • mfrom: (13723.1.7 sqlprofiler)
  • Revision ID: launchpad@pqm.canonical.com-20110823215433-77gtrsn5v1coarbl
[r=gmb][bug=832208, 832215] Add ++profile++sqltrace,
        and extended frame information to LP_DEBUG_SQL_EXTRA.

Show diffs side-by-side

added added

removed removed

Lines of Context:
lib/lp/services/profile/profile.py
13
13
import contextlib
14
14
from cProfile import Profile
15
15
from datetime import datetime
 
16
import heapq
16
17
import os
17
18
import pstats
18
19
import threading
19
20
import StringIO
20
21
 
21
 
from bzrlib import errors
22
22
from bzrlib import lsprof
23
23
import oops_datedir_repo.serializer_rfc822
24
24
from zope.pagetemplate.pagetemplatefile import PageTemplateFile
156
156
        self.actions = None
157
157
        self.profiler = None
158
158
        self.memory_profile_start = None
159
 
        
 
159
 
160
160
_profilers = Profilers()
161
161
 
162
162
 
210
210
    if config.profiling.profile_all_requests:
211
211
        actions.add('callgrind')
212
212
    if actions:
213
 
        if actions.difference(('help',)):
 
213
        if 'sqltrace' in actions:
 
214
            da.start_sql_traceback_logging()
 
215
        if 'show' in actions or actions.intersection(available_profilers):
214
216
            _profilers.profiler = Profiler()
215
217
            _profilers.profiler.start()
216
218
    if config.profiling.memory_profile_log:
340
342
        template_context['multiple_profiles'] = prof_stats.count > 1
341
343
        # Try to free some more memory.
342
344
        del prof_stats
 
345
    trace = None
 
346
    if 'sqltrace' in actions:
 
347
        trace = da.stop_sql_traceback_logging()
 
348
        # The trace is a list of dicts, each with the keys "sql" and
 
349
        # "stack".  "sql" is a tuple of start time, stop time, database
 
350
        # name (with a "SQL-" prefix), and sql statement.  "stack" is a
 
351
        # tuple of filename, line number, function name, text, module
 
352
        # name, optional supplement dict, and optional info string.  The
 
353
        # supplement dict has keys 'source_url', 'line', 'column',
 
354
        # 'expression', 'warnings' (an iterable), and 'extra', any of
 
355
        # which may be None.
 
356
        top_sql = []
 
357
        top_python = []
 
358
        triggers = {}
 
359
        ix = 1  # We display these, so start at 1, not 0.
 
360
        last_stop_time = 0
 
361
        _heappushpop = heapq.heappushpop  # This is an optimization.
 
362
        for step in trace:
 
363
            # Set up an identifier for each trace step.
 
364
            step['id'] = ix
 
365
            step['sql'] = dict(zip(
 
366
                ('start', 'stop', 'name', 'statement'), step['sql']))
 
367
            # Divide up the stack into the more unique (app) and less
 
368
            # unique (db) bits.
 
369
            app_stack = step['app_stack'] = []
 
370
            db_stack = step['db_stack'] = []
 
371
            storm_found = False
 
372
            for f in step['stack']:
 
373
                f_data = dict(zip(
 
374
                    ('filename', 'lineno', 'name', 'line', 'module',
 
375
                     'supplement', 'info'), f))
 
376
                storm_found = storm_found or (
 
377
                    f_data['module'] and
 
378
                    f_data['module'].startswith('storm.'))
 
379
                if storm_found:
 
380
                    db_stack.append(f_data)
 
381
                else:
 
382
                    app_stack.append(f_data)
 
383
            # Begin to gather what app code is triggering the most SQL
 
384
            # calls.
 
385
            trigger_key = tuple(
 
386
                (f['filename'], f['lineno']) for f in app_stack)
 
387
            if trigger_key not in triggers:
 
388
                triggers[trigger_key] = []
 
389
            triggers[trigger_key].append(ix)
 
390
            # Get the nbest (n=10) sql and python times
 
391
            step['python_time'] = step['sql']['start'] - last_stop_time
 
392
            step['sql_time'] = step['sql']['stop'] - step['sql']['start']
 
393
            python_data = (step['python_time'], ix, step)
 
394
            sql_data = (step['sql_time'], ix, step)
 
395
            if ix < 10:
 
396
                top_sql.append(sql_data)
 
397
                top_python.append(python_data)
 
398
            else:
 
399
                if ix == 10:
 
400
                    heapq.heapify(top_sql)
 
401
                    heapq.heapify(top_python)
 
402
                _heappushpop(top_sql, sql_data)
 
403
                _heappushpop(top_python, python_data)
 
404
            # Reset for next loop.
 
405
            last_stop_time = step['sql']['stop']
 
406
            ix += 1
 
407
        # Finish setting up top sql and python times.
 
408
        top_sql.sort(reverse=True)
 
409
        top_python.sort(reverse=True)
 
410
        top_sql_ids = []
 
411
        for rank, (key, ix, step) in enumerate(top_sql):
 
412
            step['sql_rank'] = rank + 1
 
413
            step['sql_class'] = (
 
414
                'sql_danger' if key > 500 else
 
415
                'sql_warning' if key > 100 else None)
 
416
            top_sql_ids.append(dict(
 
417
                value=key,
 
418
                ix=ix,
 
419
                rank=step['sql_rank'],
 
420
                cls=step['sql_class']))
 
421
        top_python_ids = []
 
422
        for rank, (key, ix, step) in enumerate(top_python):
 
423
            step['python_rank'] = rank + 1
 
424
            step['python_class'] = (
 
425
                'python_danger' if key > 500 else
 
426
                'python_warning' if key > 100 else None)
 
427
            top_python_ids.append(dict(
 
428
                value=key,
 
429
                ix=ix,
 
430
                rank=step['python_rank'],
 
431
                cls=step['python_class']))
 
432
        # Identify the repeated Python calls that generated SQL.
 
433
        triggers = triggers.items()
 
434
        triggers.sort(key=lambda x: len(x[1]))
 
435
        triggers.reverse()
 
436
        top_triggers = []
 
437
        for (key, ixs) in triggers:
 
438
            if len(ixs) == 1:
 
439
                break
 
440
            info = trace[ixs[0] - 1]['app_stack'][-1].copy()
 
441
            info['indexes'] = ixs
 
442
            info['count'] = len(ixs)
 
443
            top_triggers.append(info)
 
444
        template_context.update(dict(
 
445
            sqltrace=trace,
 
446
            top_sql=top_sql_ids,
 
447
            top_python=top_python_ids,
 
448
            top_triggers=top_triggers,
 
449
            sql_count=len(trace)))
343
450
    template_context['dump_path'] = os.path.abspath(dump_path)
344
451
    if actions and is_html:
345
452
        # Hack the new HTML in at the end of the page.
397
504
                result.remove('log')
398
505
                result.add('callgrind')
399
506
            # Only honor the available options.
400
 
            available_options = set(('show',))
 
507
            available_options = set(('show', 'sqltrace', 'help'))
401
508
            available_options.update(available_profilers)
402
509
            result.intersection_update(available_options)
403
510
            # If we didn't end up with any known actions, we need to help the