Merge lp:~wallyworld/launchpad/log-sql-bind-variables into lp:launchpad

Proposed by Ian Booth
Status: Merged
Approved by: Robert Collins
Approved revision: no longer in the source branch.
Merged at revision: 11760
Proposed branch: lp:~wallyworld/launchpad/log-sql-bind-variables
Merge into: lp:launchpad
Diff against target: 44 lines (+10/-3)
1 file modified
lib/canonical/launchpad/webapp/adapter.py (+10/-3)
To merge this branch: bzr merge lp:~wallyworld/launchpad/log-sql-bind-variables
Reviewer Review Type Date Requested Status
Robert Collins (community) Approve
Review via email: mp+37552@code.launchpad.net

Commit message

Add support for logging SQL bind values

Description of the change

Proposal
-----------

This branch provides an extra logging feature for tracing SQL execution. Currently, you can specify LP_DEBUG_SQL=1 to enable logging of the SQL that is executed, but the log does not include the bind parameters eg

select from foo where something = %s

Without the bind parameters being logged, it makes it harder to understand what is happening and to do things like detect duplicate SQL. eg for the above example, there could be 2 executions of that statement, either:

select from foo where something = 'bar'
select from foo where something = 'fred'

or

select from foo where something = 'bar'
select from foo where something = 'bar'

Clearly, the latter case represents something that could be optimised as part of performance tuning. But is it is difficult to see this without the bind parameters being logged.

Implementation
--------------------

Add support for a new environment variable: LP_SQL_DEBUG_VALUES
If this variable is true, and LP_SQL_DEBUG is also specified, then the SQL bind variables are logged.
NB the new setting has no effect if LP_SWL_DEBUG is not specified.

To post a comment you must log in.
Revision history for this message
Robert Collins (lifeless) :
review: Approve
Revision history for this message
Robert Collins (lifeless) wrote :

Couple of small tweaks.

Looking at storm, you probably want to replace
     param_strings = [
40 + (lambda x:
41 + x.get() if isinstance(x, Variable) else str(x))(p)
42 + for p in params]

with

param_strings = Connection.to_database(params)

which will change get() to get(to_db=True) as well as being more pithy.

This may fix your test issue, though there is an obvious open question of 'why is it failing' - and the problem is - I don't know (other than that there are apparently test failures in trunk (eep)).

Preview Diff

[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
2--- lib/canonical/launchpad/webapp/adapter.py 2010-10-04 20:46:55 +0000
3+++ lib/canonical/launchpad/webapp/adapter.py 2010-10-07 05:38:45 +0000
4@@ -171,7 +171,7 @@
5 if request_statements is not None:
6 # Specify a specific sequence object for the timeline.
7 set_request_timeline(request, Timeline(request_statements))
8- else:
9+ else:
10 # Ensure a timeline is created, so that time offset for actions is
11 # reasonable.
12 set_request_timeline(request, Timeline())
13@@ -276,7 +276,7 @@
14
15 def _get_request_timeout(timeout=None):
16 """Get the timeout value in ms for the current request.
17-
18+
19 :param timeout: A custom timeout in ms.
20 :return None or a time in ms representing the budget to grant the request.
21 """
22@@ -586,6 +586,8 @@
23
24 def __init__(self):
25 self._debug_sql = bool(os.environ.get('LP_DEBUG_SQL'))
26+ self._debug_sql_bind_values = bool(
27+ os.environ.get('LP_DEBUG_SQL_VALUES'))
28 self._debug_sql_extra = bool(os.environ.get('LP_DEBUG_SQL_EXTRA'))
29
30 def connection_raw_execute(self, connection, raw_cursor,
31@@ -594,7 +596,12 @@
32 traceback.print_stack()
33 sys.stderr.write("." * 70 + "\n")
34 if self._debug_sql or self._debug_sql_extra:
35- sys.stderr.write(statement + "\n")
36+ stmt_to_log = statement
37+ if self._debug_sql_bind_values:
38+ from storm.database import Connection
39+ param_strings = Connection.to_database(params)
40+ stmt_to_log = statement % tuple(param_strings)
41+ sys.stderr.write(stmt_to_log + "\n")
42 sys.stderr.write("-" * 70 + "\n")
43 # store the last executed statement as an attribute on the current
44 # thread