Merge lp:~gary/launchpad/bug838878 into lp:launchpad

[Gary Poster]

[r=jcsackett][bug=838878] ++profile++ has a new conditional sqltrace feature and a new sql option.

This branch lets ++profile++ expose the new conditional sqltrace functionality enabled by changes in lp:~gary/launchpad/bug838869 .

This branch is just over the limit, for which I apologize.

The new features for ++profile++ are as follows:

 - ++profile++sqltrace adds a mini-language for specifying what SQL requests you want to trace. ++profile++sqltrace continues to get tracebacks for all SQL. "++profile++sqltrace:includes STRING" only gets tracebacks for SQL statements that include STRING (whitespace- and case-normalized). "++profile++sqltrace:startswith STRING" gets tracebacks for SQL statements that start with STRING. "++profile++sqltrace:endswith STRING" does the same if the SQL ends with STRING. They can be combined with a pipe, "|", meaning logical or. Therefore, "++profile++sqltrace:includes FOOBAR BAZ| includes shazam" will match SQL statements that include "FOOBAR BAZ" or "SHAZAM" (again, case- and whitespace- normalized).

 - ++profile++sql is now available, only giving SQL without any profiling or stacktrace information.

The changes for ++profile++ are as follows:

You combine requests in ++profile++ with "&" now, not ",", so "++profile++show,pstats" becomes "++profile++show&pstats". This is so that the strings used by the conditions described above can include commas, which SQL often does.

Lint is happy except for its usual confusion with the beginning of the template.

Trying this out on a dev machine should be as easy as going to https://launchpad.dev/++profile++ and messing around with some of the new options, like "https://launchpad.dev/++profile++sql" and "https://launchpad.dev/++profile++sqltrace:includes AccountPassword.id".

QA should be similar: https://qastaging.launchpad.net/++profile++ should still work, and https://qastaging.launchpad.net/++profile++show and https://qastaging.launchpad.net/++profile++sql and https://qastaging.launchpad.net/++profile++sqltrace and "https://qastaging.launchpad.net/++profile++sqltrace:includes AccountPassword.id".

[j.c.sackett (jcsackett)]

Gary--

This looks good. I see one possible problem in the updated profile template, pointed out below.

> === modified file 'lib/lp/services/profile/profile.pt'
> --- lib/lp/services/profile/profile.pt 2011-08-22 17:08:02 +0000
> +++ lib/lp/services/profile/profile.pt 2011-09-01 17:17:32 +0000
> @@ -64,15 +64,21 @@
> get immediate profiling results in the browser, use
> <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
> + view of the profile and OOPS data including SQL calls
> + (<code>++profile++show</code>), a KCacheGrind-friendly log on the
> filesystem (<code>++profile++callgrind</code>), a PStats-friendly log
> (Python standard library) on the filesystem
> - (<code>++profile++pstats</code>), or an HTML view of the SQL and the
> + (<code>++profile++pstats</code>), 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> or others,
> - with each action separated with commas).</tal:block></p>
> + (<code>++profile++sqltrace</code>), or an HTML view of only the SQL
> + (<code>++profile++sql</code>). You can also combine these
> + (<code>++profile++show&callgrind</code> or
> + <code>++profile++show&pstats</code> or others, with each action separated
> + with commas).</tal:block></p>

I may be misunderstanding this, but shouldn't this be "separated with ambersands" as shown in the example?

> === modified file 'lib/lp/services/profile/profile.py'
> @@ -505,24 +521,108 @@
> # include traversal in the profile.
> actions, slash, tail = end.partition('/')
> result.update(
> - action for action in (
> - item.strip().lower() for item in actions.split(','))
> - if action)
> + (name.strip(), config.strip())
> + for name, partition, config in (
> + item.strip().lower().partition(':')
> + for item in actions.split('&'))
> + if name.strip())

There's no problem in the above bit, just thought that was one hell of a generator expression. :-P

review: Approve

[Gary Poster (gary)]

On Sep 1, 2011, at 3:45 PM, j.c.sackett wrote:

> Review: Approve
> Gary--
>
> This looks good. I see one possible problem in the updated profile template, pointed out below.

...

>
> I may be misunderstanding this, but shouldn't this be "separated with ambersands" as shown in the example?

Ah, yes, thanks, good catch!

...

> There's no problem in the above bit, just thought that was one hell of a generator expression. :-P

Yeah...not the prettiest thing in the world. Maybe I should have been more explicit/less concise...

Thanks again,

Gary

=== modified file 'lib/lp/services/profile/profile.pt'
--- lib/lp/services/profile/profile.pt	2011-08-22 17:08:02 +0000
+++ lib/lp/services/profile/profile.pt	2011-09-02 16:34:47 +0000
@@ -47,7 +47,7 @@
                  multiple_profiles options/multiple_profiles|nothing;
                  inline_ignored actions/inline_ignored|nothing;
                  inline actions/inline|nothing;
-                 sqltrace actions/sqltrace|nothing;
+                 sqltrace actions/sql|nothing;
                  sqltrace_steps options/sqltrace|nothing;
                  ">
   <div class="hide_reveal_profiling" id="hide_profiling">
@@ -64,15 +64,21 @@
     get immediate profiling results in the browser, use
     <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
+    view of the profile and OOPS data including SQL calls
+    (<code>++profile++show</code>), a KCacheGrind-friendly log on the
     filesystem (<code>++profile++callgrind</code>), a PStats-friendly log
     (Python standard library) on the filesystem
-    (<code>++profile++pstats</code>), or an HTML view of the SQL and the
+    (<code>++profile++pstats</code>), 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> or others,
-    with each action separated with commas).</tal:block></p>
+    (<code>++profile++sqltrace</code>), or an HTML view of only the SQL
+    (<code>++profile++sql</code>). You can also combine these
+    (<code>++profile++show&callgrind</code> or
+    <code>++profile++show&pstats</code> or others, with each action separated
+    with ampersands).</tal:block></p>
+    <p>The <code>++profile++sqltrace</code> can take too much time to let a
+    page practically render, especially on qastaging and staging.  You can
+    filter to only get the stacktraces you want in this case; see information
+    in the &quot;SQL trace&quot; section below on how to do this.</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
@@ -119,8 +125,8 @@
     as in <code>++profile++pstats</code>.  Profiles are logged to <tal:block
     replace="dump_path" />.</p>
     <p> You can see both the log information and immediate results with
-    <code>++profile++callgrind,show</code> or
-    <code>++profile++pstats,show</code>.</p>
+    <code>++profile++callgrind&show</code> or
+    <code>++profile++pstats&show</code>.</p>
   </tal:block>
   <tal:block condition="log">
     <p tal:condition="always_log"><strong>You have configured every
@@ -144,11 +150,72 @@
   <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>
+    stacktrace for when each sql call is made.</p>
+    <p>If you only want SQL and not the tracebacks,
+    <code>++profile++sql</code> will give you what you want, or
+    <code>++profile++show</code> will include OOPS data at the end of the
+    profiling information.</p>
+    <p>If you want stacktraces only for certain SQL statements, you can do
+    that too.  You can use <code>startswith</code>, <code>endswith</code>
+    or <code>includes</code> to specify parts of the SQL that you want to use
+    as triggers.  Note that this is whitespace and case normalized, so you
+    just need to get the spelling right.  Here are some examples.</p>
+    <dl>
+    <dt><code>/++profile++sqltrace: includes Product.blueprints_usage/</code>
+    </dt>
+    <dd>This will get a stacktrace for any SQL statement that has the
+    string &quot;Product.blueprints_usage&quot; in it.</dd>
+    <dt><code>/++profile++sqltrace:startswith SELECT
+    Distribution.answers_usage/</code> </dt>
+    <dd>This will get a stacktrace for any SQL statement that starts with the
+    string &quot;SELECT Distribution.answers_usage&quot; in it.</dd>
+    <dt><code>/++profile++sqltrace:endswith WHERE Project.id = 5 LIMIT
+    1/</code> </dt>
+    <dd>This will get a stacktrace for any SQL statement that ends with the
+    string given.  Note that it does not end in a semicolon, and note that
+    parameters are filled in.</dd>
+    </dl>
+    <p>You can also combine requests with the <code>|</code> mark (the
+    pipe).  Here's an example:
+    <code>/++profile++sqltrace:startswith SELECT Distribution.answers_usage |
+    includes Product.blueprints_usage/</code>.</p>
   </tal:block>
   <tal:block condition="sqltrace">
+    <p tal:condition="options/sql_traceback_all|nothing">You have requested
+    tracebacks for all SQL statements.  You can filter these with conditions
+    like <code>startswith</code>, <code>endswith</code> or
+    <code>includes</code>. Here's a simple example:
+    <code>/++profile++sqltrace: includes Product.blueprints_usage/</code>.</p>
+    <p tal:condition="options/sql_traceback_none|nothing">You have requested no
+    tracebacks.  Use <code>++profile++sqltrace</code> to get tracebacks.</p>
+    <tal:block condition="options/sql_traceback_conditions|nothing">
+      <p>You have requested tracebacks for statements that match only certain
+      conditions.</p>
+      <tal:block
+      condition="not:options/sql_traceback_conditions/included">
+      <p><strong> You had no valid conditions, so no tracebacks were
+      included.</strong> The available conditions are <code>startswith</code>,
+      <code>endswith</code> or <code>includes</code>. Here's a simple
+      example.</p>
+      <pre>++profile++sqltrace: includes Product.blueprints_usage/</pre>
+      </tal:block>
+      <ul>
+      <li tal:repeat="condition options/sql_traceback_conditions/included">
+        <em tal:content="condition/constraint">CONSTRAINT</em>
+        <span tal:replace="condition/value">VALUE</span>
+      </li>
+      </ul>
+      <tal:block condition="options/sql_traceback_conditions/ignored">
+        <p><strong>Warning</strong>: these conditions were not understood, and
+        so ignored.</p>
+        <ul>
+        <li tal:repeat="condition options/sql_traceback_conditions/ignored">
+          <em tal:content="condition/constraint">CONSTRAINT</em>
+          <span tal:replace="condition/value">VALUE</span>
+        </li>
+        </ul>
+      </tal:block>
+    </tal:block>
     <h3>Top 10 SQL times</h3>
     <ol>
       <li tal:repeat="info options/top_sql" tal:attributes="class info/cls">
@@ -158,6 +225,14 @@
       </li>
     </ol>
     <h3>Top 10 Python times</h3>
+    <p tal:condition="options/sql_traceback_all|nothing">Note that generating
+    stacktraces can add significantly to these numbers, and skew results.  Use
+    <code>++profile++sql</code> for a more accurate view.</p>
+    <p tal:condition="options/sql_traceback_conditions|nothing">Note that
+    generating stacktraces can add significantly to these numbers, and
+    selectively choosing when to generate stacktraces will produce so much
+    skew as to potentially make these values meaningless.  Use
+    <code>++profile++sql</code> for the most accurate view.</p>
     <ol>
       <li tal:repeat="info options/top_python" tal:attributes="class info/cls">
         <a tal:attributes="href string:#pythonstep-${info/ix}">Before query
@@ -165,32 +240,37 @@
         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 &quot;<tal:block replace="trigger/filename"></tal:block>&quot;,
-              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>
+    <tal:block condition="not: options/sql_traceback_none|nothing">
+      <h3>Repeated Python SQL Triggers</h3>
+      <p tal:condition="options/sql_traceback_conditions|nothing">These are
+      only calculated for the stacktraces that were collected.</p>
+      <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 &quot;<tal:block
+          replace="trigger/filename"></tal:block>&quot;, 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>
-    </div>
+    </tal:block>
     <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="#"
+    <div tal:condition="not:options/sql_traceback_none|nothing"><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
@@ -210,9 +290,10 @@
           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>
+          class="clicktext" tal:condition="step/stack">Click to toggle Python
+          traceback.</a><span tal:condition="not:step/stack">--</span>
         </div>
-        <div class="trace"><div class="inner">
+        <div class="trace" tal:condition="step/stack"><div class="inner">
           <div class="appstack" tal:define="stack step/app_stack">
             <div tal:repeat="frame stack" metal:define-macro="draw-stack">
               <div>File &quot;<tal:block replace="frame/filename"></tal:block>&quot;,
@@ -247,8 +328,8 @@
   <h2>Profile quick view</h2>
   <tal:block condition="not:show">
     <p>Use <code>++profile++show</code> in your URL in order to see immediate
-    profile results (or <code>++profile++callgrind,show</code> or
-    <code>++profile++pstats,show</code> to see both the log information and
+    profile results (or <code>++profile++callgrind&show</code> or
+    <code>++profile++pstats&show</code> to see both the log information and
     immediate results).</p>
   </tal:block>
   <tal:block condition="show">
@@ -275,6 +356,10 @@
         Y.one('div#profiling_info').setStyle('display', 'none');
         e.preventDefault();
     });
+});
+</script>
+<script tal:condition="not:options/sql_traceback_none|nothing">
+LPS.use('node', 'lp', 'transition', function (Y) {
     function slideIn(target) {
         target.transition({
             easing: 'ease-in',

=== modified file 'lib/lp/services/profile/profile.py'
--- lib/lp/services/profile/profile.py	2011-09-01 14:55:10 +0000
+++ lib/lp/services/profile/profile.py	2011-09-02 16:34:47 +0000
@@ -13,9 +13,11 @@
 import contextlib
 from cProfile import Profile
 from datetime import datetime
+from functools import partial
 import heapq
 import os
 import pstats
+import re
 import StringIO
 import sys
 import threading
@@ -210,11 +212,14 @@
     _profilers.actions = actions
     _profilers.profiling = True
     if config.profiling.profile_all_requests:
-        actions.add('callgrind')
+        actions['callgrind'] = ''
     if actions:
-        if 'sqltrace' in actions:
-            da.start_sql_logging(tracebacks_if=True)
-        if 'show' in actions or actions.intersection(available_profilers):
+        if 'sql' in actions:
+            condition = actions['sql']
+            if condition not in (True, False):
+                condition = condition['condition']
+            da.start_sql_logging(condition)
+        if 'show' in actions or available_profilers.intersection(actions):
             _profilers.profiler = Profiler()
             _profilers.profiler.start()
     if config.profiling.memory_profile_log:
@@ -233,12 +238,14 @@
     actions = _profilers.actions
     profiler = _profilers.profiler
     if actions is None:
-        actions = _profilers.actions = set()
+        actions = _profilers.actions = {}
         _profilers.profiling = True
-    elif actions.difference(('help',)) and 'inline' not in actions:
-        actions.add('inline_ignored')
+    elif 'inline' not in actions and (
+        'show' in actions or available_profilers.intersection(actions)):
+        # We have a request-based profile in progress.  That wins.
+        actions['inline_ignored'] = ''
         return
-    actions.update(('pstats', 'show', 'inline'))
+    actions.update((k, '') for k in ('pstats', 'show', 'inline'))
     if profiler is None:
         profiler = _profilers.profiler = Profiler()
         profiler.start()
@@ -261,8 +268,10 @@
 @contextlib.contextmanager
 def profiling():
     start()
-    yield
-    stop()
+    try:
+        yield
+    finally:
+        stop()
 
 
 @adapter(IEndRequestEvent)
@@ -293,8 +302,7 @@
         _major, _minor, content_type_params = parse(content_type)
         is_html = _major == 'text' and _minor == 'html'
     template_context = {
-        # Dicts are easier for tal expressions.
-        'actions': dict((action, True) for action in actions),
+        '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:
@@ -345,16 +353,15 @@
         # Try to free some more memory.
         del prof_stats
     trace = None
-    if 'sqltrace' in actions:
+    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), 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.
+        # 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 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 = {}
@@ -366,29 +373,30 @@
             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)
+            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']
@@ -449,6 +457,14 @@
             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.
@@ -488,7 +504,7 @@
     URL.  Note that ++profile++ alone without actions is interpreted as
     the "help" action.
     """
-    result = set()
+    result = dict()
     path_info = request.get('PATH_INFO')
     if path_info:
         # if not, this is almost certainly a test not bothering to set up
@@ -505,24 +521,108 @@
             # include traversal in the profile.
             actions, slash, tail = end.partition('/')
             result.update(
-                action for action in (
-                    item.strip().lower() for item in actions.split(','))
-                if action)
+                (name.strip(), config.strip())
+                for name, partition, config in (
+                    item.strip().lower().partition(':')
+                    for item in actions.split('&'))
+                if name.strip())
             # 'log' is backwards compatible for 'callgrind'.
             if 'log' in result:
-                result.remove('log')
-                result.add('callgrind')
+                result['callgrind'] = result.pop('log')
+            if 'sqltrace' in result:
+                condition = result['sqltrace']
+                if condition:
+                    condition = _make_condition_function(condition)
+                else:
+                    condition = True
+                del result['sqltrace']
+                result['sql'] = condition
+            elif 'sql' in result:
+                result['sql'] = False
             # Only honor the available options.
-            available_options = set(('show', 'sqltrace', 'help'))
+            available_options = set(('show', 'sql', 'help'))
             available_options.update(available_profilers)
-            result.intersection_update(available_options)
+            # .keys() gives a list, not mutated during iteration.
+            for key in result.keys():
+                if key not in available_options:
+                    del result[key]
             # If we didn't end up with any known actions, we need to help the
             # user.
             if not result:
-                result.add('help')
+                result['help'] = ''
     return result
 
 
+def _make_startswith(value):
+    """Return a function that returns true if its argument startswith value"""
+    def startswith(sql):
+        return sql.startswith(value)
+    return startswith
+
+
+def _make_endswith(value):
+    """Return a function that returns true if its argument endswith value"""
+    def endswith(sql):
+        return sql.endswith(value)
+    return endswith
+
+
+def _make_includes(value):
+    """Return a function that returns true if its argument includes value"""
+    def includes(sql):
+        return value in sql
+    return includes
+
+_condition_functions = {
+    'STARTSWITH': _make_startswith,
+    'ENDSWITH': _make_endswith,
+    'INCLUDES': _make_includes
+    }
+
+_normalize_whitespace = partial(re.compile('\s+').sub, ' ')
+
+
+def _make_condition_function(condition_string):
+    """Given DSL string, return dict including function implementing string.
+
+    DSL is very simple. Conditions are separated by semicolons, which
+    represent logical or.  Each condition should begin with (case insensitive)
+    "startswith ", "endswith ", or "includes ".  The part of the condition
+    after this word and before the next semicolon or end-of-string is the
+    match string, which is case-insensitive and whitespace-normalized.
+
+    Returned dict has three elements: the function that implements the DSL,
+    the list of conditions that were included, and the list of conditions
+    that were excluded (because they were not understood).
+    """
+    conditions = []
+    included = []
+    ignored = []
+    for constraint, partition, value in (
+        c.strip().partition(' ') for c
+        in condition_string.upper().split('|')):
+        # Process each condition.
+        constraint = constraint.strip()
+        if not constraint:
+            # This was something ignorable, like a trailing | or something.
+            continue
+        value = _normalize_whitespace(value.strip())
+        description = dict(constraint=constraint, value=value)
+        if constraint in _condition_functions:
+            conditions.append(_condition_functions[constraint](value))
+            included.append(description)
+        else:
+            ignored.append(description)
+
+    def condition_aggregate(sql):
+        for condition in conditions:
+            if condition(sql):
+                return True
+        return False
+    return dict(
+        condition=condition_aggregate, included=included, ignored=ignored)
+
+
 class ProfileNamespace(view):
     """A see-through namespace that handles traversals with ++profile++."""
 

=== modified file 'lib/lp/services/profile/tests.py'
--- lib/lp/services/profile/tests.py	2011-09-01 14:55:10 +0000
+++ lib/lp/services/profile/tests.py	2011-09-02 16:34:47 +0000
@@ -43,6 +43,85 @@
 EXAMPLE_HTML = EXAMPLE_HTML_START + EXAMPLE_HTML_END
 
 
+class SQLDSLTest(TestCase):
+
+    def assertCondition(self,
+                        condition_string, succeeds, fails, included, ignored):
+        results = profile._make_condition_function(condition_string)
+        self.assertEqual(included, results['included'])
+        self.assertEqual(ignored, results['ignored'])
+        for example in succeeds:
+            self.assertTrue(results['condition'](example))
+        for example in fails:
+            self.assertFalse(results['condition'](example))
+
+    def test_startswith(self):
+        self.assertCondition(
+            'startswith foo bar',
+            succeeds=['FOO BARBAZ'],
+            fails=['BARBAZ FOO'],
+            included=[dict(constraint='STARTSWITH', value='FOO BAR')],
+            ignored=[])
+
+    def test_endswith(self):
+        self.assertCondition(
+            'endswith foo bar',
+            succeeds=['BAZ FOO BAR'],
+            fails=['BARBAZ FOO'],
+            included=[dict(constraint='ENDSWITH', value='FOO BAR')],
+            ignored=[])
+
+    def test_includes(self):
+        self.assertCondition(
+            'includes foo bar',
+            succeeds=['BAZ FOO BAR BING'],
+            fails=['BARBAZ FOO'],
+            included=[dict(constraint='INCLUDES', value='FOO BAR')],
+            ignored=[])
+
+    def test_whitespace_normalized(self):
+        self.assertCondition(
+            '  startswith        foo     bar  ',
+            succeeds=['FOO BARBAZ'],
+            fails=['BARBAZ FOO'],
+            included=[dict(constraint='STARTSWITH', value='FOO BAR')],
+            ignored=[])
+
+    def test_many_conditions(self):
+        self.assertCondition(
+            'startswith foo bar | endswith shazam|includes balooba',
+            succeeds=['FOO BARBAZ', 'SALAMI SHAZAM', 'FORTUNA BALOOBA CAT'],
+            fails=['BARBAZ FOO'],
+            included=[dict(constraint='STARTSWITH', value='FOO BAR'),
+                      dict(constraint='ENDSWITH', value='SHAZAM'),
+                      dict(constraint='INCLUDES', value='BALOOBA')],
+            ignored=[])
+
+    def test_trailing_or(self):
+        self.assertCondition(
+            'startswith foo bar|',
+            succeeds=['FOO BARBAZ'],
+            fails=['BARBAZ FOO'],
+            included=[dict(constraint='STARTSWITH', value='FOO BAR')],
+            ignored=[])
+
+    def test_one_ignored(self):
+        self.assertCondition(
+            'matches foo bar',
+            succeeds=[],
+            fails=['BARBAZ FOO'],
+            included=[],
+            ignored=[dict(constraint='MATCHES', value='FOO BAR')])
+
+    def test_one_included_one_ignored(self):
+        self.assertCondition(
+            'matches kumquat | startswith foo bar',
+            succeeds=['FOO BAR HAMSTER'],
+            fails=['BARBAZ FOO'],
+            included=[dict(constraint='STARTSWITH', value='FOO BAR')],
+            ignored=[dict(constraint='MATCHES', value='KUMQUAT')])
+
+
 class BaseTest(TestCase):
 
     def _get_request(self, path='/'):
@@ -99,7 +178,7 @@
             profiling_allowed='False', profile_all_requests='True',
             memory_profile_log='.')
         profile.start_request(self._get_start_event(
-            '/++profile++show,callgrind'))
+            '/++profile++show&callgrind'))
         self.assertCleanProfilerState('config was ignored')
 
     def test_optional_profiling_without_marked_request_has_no_profile(self):
@@ -107,7 +186,7 @@
         # request.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(self._get_start_event('/'))
-        self.assertEqual(profile._profilers.actions, set())
+        self.assertEqual(profile._profilers.actions, {})
         self.assertIs(getattr(profile._profilers, 'profiler', None), None)
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None), None)
@@ -121,7 +200,7 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('show', )))
+        self.assertEquals(set(profile._profilers.actions), set(('show', )))
 
     def test_optional_profiling_with_callgrind_request_starts_profiling(self):
         # If profiling is allowed and a request with the "callgrind" marker
@@ -132,7 +211,8 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('callgrind', )))
+        self.assertEquals(
+            set(profile._profilers.actions), set(('callgrind', )))
 
     def test_optional_profiling_with_log_request_starts_profiling(self):
         # If profiling is allowed and a request with the "log" marker URL
@@ -143,20 +223,21 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('callgrind', )))
+        self.assertEquals(
+            set(profile._profilers.actions), set(('callgrind', )))
 
     def test_optional_profiling_with_combined_request_starts_profiling(self):
         # If profiling is allowed and a request with the "callgrind" and
         # "show" marker URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(
-            self._get_start_event('/++profile++callgrind,show/'))
+            self._get_start_event('/++profile++callgrind&show/'))
         self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
         self.assertEquals(
-            profile._profilers.actions, set(('callgrind', 'show')))
+            set(profile._profilers.actions), set(('callgrind', 'show')))
 
     def test_optional_profiling_with_reversed_request_starts_profiling(self):
         # If profiling is allowed and a request with the "show" and the
@@ -166,13 +247,13 @@
         # difference from the previous test.  Also, it doesn't have a
         # trailing slash. :-P
         profile.start_request(
-            self._get_start_event('/++profile++show,callgrind'))
+            self._get_start_event('/++profile++show&callgrind'))
         self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
         self.assertEquals(
-            profile._profilers.actions, set(('callgrind', 'show')))
+            set(profile._profilers.actions), set(('callgrind', 'show')))
 
     def test_optional_profiling_with_pstats_request_starts_profiling(self):
         # If profiling is allowed and a request with the "pstats" marker,
@@ -185,7 +266,7 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('pstats',)))
+        self.assertEquals(set(profile._profilers.actions), set(('pstats',)))
 
     def test_optional_profiling_with_log_pstats(self):
         # If profiling is allowed and a request with the "log" and "pstats"
@@ -193,13 +274,13 @@
         # and pstats request.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(
-            self._get_start_event('/++profile++log,pstats/'))
+            self._get_start_event('/++profile++log&pstats/'))
         self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
         self.assertEquals(
-            profile._profilers.actions, set(('callgrind', 'pstats',)))
+            set(profile._profilers.actions), set(('callgrind', 'pstats',)))
 
     def test_optional_profiling_with_callgrind_pstats(self):
         # If profiling is allowed and a request with both the "pstats" and
@@ -207,14 +288,14 @@
         # profiler.
         self.pushProfilingConfig(profiling_allowed='True')
         profile.start_request(
-            self._get_start_event('/++profile++pstats,callgrind/'))
+            self._get_start_event('/++profile++pstats&callgrind/'))
         self.assertIsInstance(profile._profilers.profiler,
                               profile.Profiler)
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
         self.assertEquals(
-            profile._profilers.actions, set(('pstats', 'callgrind')))
+            set(profile._profilers.actions), set(('pstats', 'callgrind')))
 
     def test_forced_profiling_registers_action(self):
         # profile_all_requests should register as a callgrind action.
@@ -225,7 +306,8 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('callgrind', )))
+        self.assertEquals(
+            set(profile._profilers.actions), set(('callgrind', )))
 
     def test_optional_profiling_with_wrong_request_helps(self):
         # If profiling is allowed and a request with the marker URL segment
@@ -236,7 +318,7 @@
         self.assertIs(
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
-        self.assertEquals(profile._profilers.actions, set(('help', )))
+        self.assertEquals(set(profile._profilers.actions), set(('help', )))
 
     def test_forced_profiling_with_wrong_request_helps(self):
         # If profiling is forced and a request with the marker URL segment
@@ -249,7 +331,7 @@
             getattr(profile._profilers, 'memory_profile_start', None),
             None)
         self.assertEquals(
-            profile._profilers.actions, set(('help', 'callgrind')))
+            set(profile._profilers.actions), set(('help', 'callgrind')))
 
     def test_memory_profile_start(self):
         self.pushProfilingConfig(
@@ -258,7 +340,7 @@
         self.assertIs(getattr(profile._profilers, 'profiler', None), None)
         self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
         self.assertEqual(len(profile._profilers.memory_profile_start), 2)
-        self.assertEqual(profile._profilers.actions, set())
+        self.assertEqual(profile._profilers.actions, {})
 
     def test_combo_memory_and_profile_start(self):
         self.pushProfilingConfig(
@@ -267,13 +349,30 @@
         self.assertIsInstance(profile._profilers.profiler, profile.Profiler)
         self.assertIsInstance(profile._profilers.memory_profile_start, tuple)
         self.assertEqual(len(profile._profilers.memory_profile_start), 2)
-        self.assertEquals(profile._profilers.actions, set(('show', )))
+        self.assertEquals(set(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.assertEquals(profile._profilers.actions, dict(sql=True))
+        self.assertEqual([], da.stop_sql_logging())
+
+    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 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())
 
 
@@ -380,7 +479,7 @@
         self.pushProfilingConfig(
             profiling_allowed='False', profile_all_requests='True',
             memory_profile_log=self.memory_profile_log)
-        request = self.endRequest('/++profile++show,callgrind')
+        request = self.endRequest('/++profile++show&callgrind')
         self.assertIs(getattr(request, 'oops', None), None)
         self.assertEqual(self.getAddedResponse(request), '')
         self.assertEqual(self.getMemoryLog(), [])
@@ -469,7 +568,7 @@
         # If profiling is allowed and a request with the "callgrind" and
         # "show" marker URL segment is made, profiling starts.
         self.pushProfilingConfig(profiling_allowed='True')
-        request = self.endRequest('/++profile++callgrind,show')
+        request = self.endRequest('/++profile++callgrind&show')
         self.assertProfilePaths(
             self.assertBasicProfileExists(request, show=True))
 
@@ -499,7 +598,7 @@
         # "pstats" markers is made, profiling starts with the callgrind
         # approach only.
         self.pushProfilingConfig(profiling_allowed='True')
-        request = self.endRequest('/++profile++callgrind,pstats/')
+        request = self.endRequest('/++profile++callgrind&pstats/')
         self.assertBothProfiles(self.assertBasicProfileExists(request))
         # We had a bug in which the callgrind file was actually a pstats
         # file.  What we can do minimally to prevent this in the future is
@@ -606,14 +705,14 @@
             profiling_allowed='False', profile_all_requests='True',
             memory_profile_log='.')
         event = BeforeTraverseEvent(None,
-            self._get_request('/++profile++show,callgrind'))
+            self._get_request('/++profile++show&callgrind'))
         with FeatureFixture({'profiling.enabled': 'on'}):
             profile.before_traverse(event)
             self.assertTrue(profile._profilers.profiling)
             self.assertIsInstance(
                 profile._profilers.profiler, profile.Profiler)
             self.assertEquals(
-                set(('show', 'callgrind')), profile._profilers.actions)
+                set(('show', 'callgrind')), set(profile._profilers.actions))
 
 
 class TestInlineProfiling(BaseRequestEndHandlerTest):
@@ -643,7 +742,7 @@
         # ++profile++ wins over inline.
         self.pushProfilingConfig(profiling_allowed='True')
         request = self.endRequest(
-            '/++profile++show,callgrind', work=self.make_work())
+            '/++profile++show&callgrind', work=self.make_work())
         response = self.assertBasicProfileExists(request, show=True)
         self.assertCallgrindProfile(response)
         self.assertIn('Inline request ignored', response)
@@ -658,12 +757,23 @@
             self.assertBasicProfileExists(request, show=True))
 
 
-class TestSqlTrace(TestCaseWithFactory, BaseRequestEndHandlerTest):
+class TestSqlLogging(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++sql/', 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.assertTrue('Repeated Python SQL Triggers' not in response)
+        self.assertTrue('Show all tracebacks' not in response)
+
+    def testTraceLogging(self):
         self.pushProfilingConfig(profiling_allowed='True')
         request = self.endRequest(
             '/++profile++sqltrace/', work=self.factory.makeBug)
@@ -676,3 +786,21 @@
         self.assertIn('Show all tracebacks', response)
         # This file should be part of several of the tracebacks.
         self.assertIn(__file__.replace('.pyc', '.py'), response)
+
+    def testTraceLoggingConditionally(self):
+        self.pushProfilingConfig(profiling_allowed='True')
+        request = self.endRequest(
+            '/++profile++sqltrace:includes SELECT/',
+            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)
+        self.assertIn(
+            'You have requested tracebacks for statements that match only',
+            response)
+        # This file should be part of several of the tracebacks.
+        self.assertIn(__file__.replace('.pyc', '.py'), response)