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
=== modified file 'lib/canonical/launchpad/webapp/adapter.py'
--- lib/canonical/launchpad/webapp/adapter.py 2010-10-04 20:46:55 +0000
+++ lib/canonical/launchpad/webapp/adapter.py 2010-10-07 05:38:45 +0000
@@ -171,7 +171,7 @@
171 if request_statements is not None:171 if request_statements is not None:
172 # Specify a specific sequence object for the timeline.172 # Specify a specific sequence object for the timeline.
173 set_request_timeline(request, Timeline(request_statements))173 set_request_timeline(request, Timeline(request_statements))
174 else: 174 else:
175 # Ensure a timeline is created, so that time offset for actions is175 # Ensure a timeline is created, so that time offset for actions is
176 # reasonable.176 # reasonable.
177 set_request_timeline(request, Timeline())177 set_request_timeline(request, Timeline())
@@ -276,7 +276,7 @@
276276
277def _get_request_timeout(timeout=None):277def _get_request_timeout(timeout=None):
278 """Get the timeout value in ms for the current request.278 """Get the timeout value in ms for the current request.
279 279
280 :param timeout: A custom timeout in ms.280 :param timeout: A custom timeout in ms.
281 :return None or a time in ms representing the budget to grant the request.281 :return None or a time in ms representing the budget to grant the request.
282 """282 """
@@ -586,6 +586,8 @@
586586
587 def __init__(self):587 def __init__(self):
588 self._debug_sql = bool(os.environ.get('LP_DEBUG_SQL'))588 self._debug_sql = bool(os.environ.get('LP_DEBUG_SQL'))
589 self._debug_sql_bind_values = bool(
590 os.environ.get('LP_DEBUG_SQL_VALUES'))
589 self._debug_sql_extra = bool(os.environ.get('LP_DEBUG_SQL_EXTRA'))591 self._debug_sql_extra = bool(os.environ.get('LP_DEBUG_SQL_EXTRA'))
590592
591 def connection_raw_execute(self, connection, raw_cursor,593 def connection_raw_execute(self, connection, raw_cursor,
@@ -594,7 +596,12 @@
594 traceback.print_stack()596 traceback.print_stack()
595 sys.stderr.write("." * 70 + "\n")597 sys.stderr.write("." * 70 + "\n")
596 if self._debug_sql or self._debug_sql_extra:598 if self._debug_sql or self._debug_sql_extra:
597 sys.stderr.write(statement + "\n")599 stmt_to_log = statement
600 if self._debug_sql_bind_values:
601 from storm.database import Connection
602 param_strings = Connection.to_database(params)
603 stmt_to_log = statement % tuple(param_strings)
604 sys.stderr.write(stmt_to_log + "\n")
598 sys.stderr.write("-" * 70 + "\n")605 sys.stderr.write("-" * 70 + "\n")
599 # store the last executed statement as an attribute on the current606 # store the last executed statement as an attribute on the current
600 # thread607 # thread