Пример #1
0
 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())
Пример #2
0
 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")
Пример #17
0
 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())
Пример #18
0
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)
Пример #19
0
 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())