Merge lp:~lifeless/storm/timelinetracer into lp:storm
- timelinetracer
- Merge into trunk
Proposed by
Robert Collins
Status: | Merged |
---|---|
Merged at revision: | 402 |
Proposed branch: | lp:~lifeless/storm/timelinetracer |
Merge into: | lp:storm |
Diff against target: |
214 lines (+77/-40) 2 files modified
storm/tracer.py (+29/-13) tests/tracer.py (+48/-27) |
To merge this branch: | bzr merge lp:~lifeless/storm/timelinetracer |
Related bugs: |
Reviewer | Review Type | Date Requested | Status |
---|---|---|---|
James Henstridge | Approve | ||
Review via email: mp+75109@code.launchpad.net |
Commit message
Description of the change
Follow on from https:/
To post a comment you must log in.
Revision history for this message
Robert Collins (lifeless) wrote : | # |
all actioned, pushing it up now. Thanks!
Preview Diff
[H/L] Next/Prev Comment, [J/K] Next/Prev File, [N/P] Next/Prev Hunk
1 | === modified file 'storm/tracer.py' | |||
2 | --- storm/tracer.py 2011-09-12 06:43:04 +0000 | |||
3 | +++ storm/tracer.py 2011-09-13 04:08:34 +0000 | |||
4 | @@ -118,12 +118,20 @@ | |||
5 | 118 | # There are some bind parameters so we want to insert them into | 118 | # There are some bind parameters so we want to insert them into |
6 | 119 | # the sql statement so we can log the statement. | 119 | # the sql statement so we can log the statement. |
7 | 120 | query_params = list(connection.to_database(params)) | 120 | query_params = list(connection.to_database(params)) |
11 | 121 | # We need to ensure % symbols used for LIKE statements etc are | 121 | if connection.param_mark == '%s': |
12 | 122 | # properly quoted or else the string format operation will fail. | 122 | # Double the %'s in the string so that python string formatting |
13 | 123 | quoted_statement = re.sub( | 123 | # can restore them to the correct number. Note that %s needs to |
14 | 124 | # be preserved as that is where we are substiting values in. | ||
15 | 125 | quoted_statement = re.sub( | ||
16 | 124 | "%%%", "%%%%", re.sub("%([^s])", r"%%\1", statement)) | 126 | "%%%", "%%%%", re.sub("%([^s])", r"%%\1", statement)) |
19 | 125 | quoted_statement = convert_param_marks( | 127 | else: |
20 | 126 | quoted_statement, connection.param_mark, "%s") | 128 | # Double all the %'s in the statement so that python string |
21 | 129 | # formatting can restore them to the correct number. Any %s in | ||
22 | 130 | # the string should be preserved because the param_mark is not | ||
23 | 131 | # %s. | ||
24 | 132 | quoted_statement = re.sub("%", "%%", statement) | ||
25 | 133 | quoted_statement = convert_param_marks( | ||
26 | 134 | quoted_statement, connection.param_mark, "%s") | ||
27 | 127 | # We need to massage the query parameters a little to deal with | 135 | # We need to massage the query parameters a little to deal with |
28 | 128 | # string parameters which represent encoded binary data. | 136 | # string parameters which represent encoded binary data. |
29 | 129 | render_params = [] | 137 | render_params = [] |
30 | @@ -132,7 +140,12 @@ | |||
31 | 132 | render_params.append(repr(param.encode('utf8'))) | 140 | render_params.append(repr(param.encode('utf8'))) |
32 | 133 | else: | 141 | else: |
33 | 134 | render_params.append(repr(param)) | 142 | render_params.append(repr(param)) |
35 | 135 | statement_to_log = quoted_statement % tuple(render_params) | 143 | try: |
36 | 144 | statement_to_log = quoted_statement % tuple(render_params) | ||
37 | 145 | except TypeError: | ||
38 | 146 | statement_to_log = \ | ||
39 | 147 | "Unformattable query: %r with params %r." % ( | ||
40 | 148 | statement, query_params) | ||
41 | 136 | self._expanded_raw_execute(connection, raw_cursor, statement_to_log) | 149 | self._expanded_raw_execute(connection, raw_cursor, statement_to_log) |
42 | 137 | 150 | ||
43 | 138 | def _expanded_raw_execute(self, connection, raw_cursor, statement): | 151 | def _expanded_raw_execute(self, connection, raw_cursor, statement): |
44 | @@ -146,26 +159,29 @@ | |||
45 | 146 | For more information on timelines see the module at | 159 | For more information on timelines see the module at |
46 | 147 | http://pypi.python.org/pypi/timeline. | 160 | http://pypi.python.org/pypi/timeline. |
47 | 148 | 161 | ||
52 | 149 | The timeline to use is obtained via a threading.local lookup - | 162 | The timeline to use is obtained by calling the timeline_factory supplied to |
53 | 150 | self.threadinfo.timeline. If TimelineTracer is being used in a thread | 163 | the constructor. This simple function takes no parameters and returns a |
54 | 151 | pooling environment, you should set this to the timeline you wish to | 164 | timeline to use. If it returns None, the tracer is bypassed. |
51 | 152 | accumulate actions against before making queries. | ||
55 | 153 | """ | 165 | """ |
56 | 154 | 166 | ||
58 | 155 | def __init__(self, prefix='SQL-'): | 167 | def __init__(self, timeline_factory, prefix='SQL-'): |
59 | 156 | """Create a TimelineTracer. | 168 | """Create a TimelineTracer. |
60 | 157 | 169 | ||
61 | 170 | #param timeline_factory: A factory function to produce the timeline to | ||
62 | 171 | record a query against. | ||
63 | 158 | @param prefix: A prefix to give the connection name when starting an | 172 | @param prefix: A prefix to give the connection name when starting an |
64 | 159 | action. Connection names are found by trying a getattr for 'name' | 173 | action. Connection names are found by trying a getattr for 'name' |
65 | 160 | on the connection object. If no name has been assigned, '<unknown>' | 174 | on the connection object. If no name has been assigned, '<unknown>' |
66 | 161 | is used instead. | 175 | is used instead. |
67 | 162 | """ | 176 | """ |
68 | 163 | super(TimelineTracer, self).__init__() | 177 | super(TimelineTracer, self).__init__() |
69 | 178 | self.timeline_factory = timeline_factory | ||
70 | 179 | self.prefix = prefix | ||
71 | 180 | # Stores the action in progress in a given thread. | ||
72 | 164 | self.threadinfo = threading.local() | 181 | self.threadinfo = threading.local() |
73 | 165 | self.prefix = prefix | ||
74 | 166 | 182 | ||
75 | 167 | def _expanded_raw_execute(self, connection, raw_cursor, statement): | 183 | def _expanded_raw_execute(self, connection, raw_cursor, statement): |
77 | 168 | timeline = getattr(self.threadinfo, 'timeline', None) | 184 | timeline = self.timeline_factory() |
78 | 169 | if timeline is None: | 185 | if timeline is None: |
79 | 170 | return | 186 | return |
80 | 171 | connection_name = getattr(connection, 'name', '<unknown>') | 187 | connection_name = getattr(connection, 'name', '<unknown>') |
81 | 172 | 188 | ||
82 | === modified file 'tests/tracer.py' | |||
83 | --- tests/tracer.py 2011-09-12 10:24:04 +0000 | |||
84 | +++ tests/tracer.py 2011-09-13 04:08:34 +0000 | |||
85 | @@ -361,6 +361,19 @@ | |||
86 | 361 | [(conn, 'cursor', "SELECT * FROM person where name = 'VAR1'")], | 361 | [(conn, 'cursor', "SELECT * FROM person where name = 'VAR1'")], |
87 | 362 | tracer.calls) | 362 | tracer.calls) |
88 | 363 | 363 | ||
89 | 364 | def test_qmark_percent_s_literal_preserved(self): | ||
90 | 365 | """With ? parameters %s in the statement can be kept intact.""" | ||
91 | 366 | tracer = self.LoggingBaseStatementTracer() | ||
92 | 367 | conn = self.StubConnection() | ||
93 | 368 | var1 = MockVariable(1) | ||
94 | 369 | tracer.connection_raw_execute( | ||
95 | 370 | conn, 'cursor', | ||
96 | 371 | "SELECT * FROM person where id > ? AND name LIKE '%s'", [var1]) | ||
97 | 372 | self.assertEqual( | ||
98 | 373 | [(conn, 'cursor', | ||
99 | 374 | "SELECT * FROM person where id > 1 AND name LIKE '%s'")], | ||
100 | 375 | tracer.calls) | ||
101 | 376 | |||
102 | 364 | def test_int_variable_as_int(self): | 377 | def test_int_variable_as_int(self): |
103 | 365 | """Int parameters are formatted as an int literal.""" | 378 | """Int parameters are formatted as an int literal.""" |
104 | 366 | tracer = self.LoggingBaseStatementTracer() | 379 | tracer = self.LoggingBaseStatementTracer() |
105 | @@ -386,21 +399,37 @@ | |||
106 | 386 | "LIKE '%%' || 'substring' || '-suffix%%'")], | 399 | "LIKE '%%' || 'substring' || '-suffix%%'")], |
107 | 387 | tracer.calls) | 400 | tracer.calls) |
108 | 388 | 401 | ||
109 | 402 | def test_unformattable_statements_are_handled(self): | ||
110 | 403 | tracer = self.LoggingBaseStatementTracer() | ||
111 | 404 | conn = self.StubConnection() | ||
112 | 405 | var1 = MockVariable(u'substring') | ||
113 | 406 | tracer.connection_raw_execute( | ||
114 | 407 | conn, 'cursor', "%s %s", | ||
115 | 408 | [var1]) | ||
116 | 409 | self.assertEqual( | ||
117 | 410 | [(conn, 'cursor', | ||
118 | 411 | "Unformattable query: '%s %s' with params [u'substring'].")], | ||
119 | 412 | tracer.calls) | ||
120 | 413 | |||
121 | 389 | 414 | ||
122 | 390 | class TimelineTracerTest(TestHelper): | 415 | class TimelineTracerTest(TestHelper): |
123 | 391 | 416 | ||
124 | 392 | def is_supported(self): | 417 | def is_supported(self): |
125 | 393 | return timeline is not None | 418 | return timeline is not None |
126 | 394 | 419 | ||
127 | 420 | def factory(self): | ||
128 | 421 | self.timeline = timeline.Timeline() | ||
129 | 422 | return self.timeline | ||
130 | 423 | |||
131 | 395 | def test_separate_tracers_own_state(self): | 424 | def test_separate_tracers_own_state(self): |
132 | 396 | """"Check that multiple TimelineTracer's could be used at once.""" | 425 | """"Check that multiple TimelineTracer's could be used at once.""" |
137 | 397 | tracer1 = TimelineTracer() | 426 | tracer1 = TimelineTracer(self.factory) |
138 | 398 | tracer2 = TimelineTracer() | 427 | tracer2 = TimelineTracer(self.factory) |
139 | 399 | tracer1.threadinfo.timeline = 'foo' | 428 | tracer1.threadinfo.action = 'foo' |
140 | 400 | self.assertEqual(None, getattr(tracer2.threadinfo, 'timeline', None)) | 429 | self.assertEqual(None, getattr(tracer2.threadinfo, 'action', None)) |
141 | 401 | 430 | ||
142 | 402 | def test_error_finishes_action(self): | 431 | def test_error_finishes_action(self): |
144 | 403 | tracer = TimelineTracer() | 432 | tracer = TimelineTracer(self.factory) |
145 | 404 | action = timeline.Timeline().start('foo', 'bar') | 433 | action = timeline.Timeline().start('foo', 'bar') |
146 | 405 | tracer.threadinfo.action = action | 434 | tracer.threadinfo.action = action |
147 | 406 | tracer.connection_raw_execute_error( | 435 | tracer.connection_raw_execute_error( |
148 | @@ -408,27 +437,25 @@ | |||
149 | 408 | self.assertNotEqual(None, action.duration) | 437 | self.assertNotEqual(None, action.duration) |
150 | 409 | 438 | ||
151 | 410 | def test_success_finishes_action(self): | 439 | def test_success_finishes_action(self): |
153 | 411 | tracer = TimelineTracer() | 440 | tracer = TimelineTracer(self.factory) |
154 | 412 | action = timeline.Timeline().start('foo', 'bar') | 441 | action = timeline.Timeline().start('foo', 'bar') |
155 | 413 | tracer.threadinfo.action = action | 442 | tracer.threadinfo.action = action |
156 | 414 | tracer.connection_raw_execute_success( | 443 | tracer.connection_raw_execute_success( |
157 | 415 | 'conn', 'cursor', 'statement', 'params') | 444 | 'conn', 'cursor', 'statement', 'params') |
158 | 416 | self.assertNotEqual(None, action.duration) | 445 | self.assertNotEqual(None, action.duration) |
159 | 417 | 446 | ||
164 | 418 | def test_finds_timeline_from_threadinfo(self): | 447 | def test_finds_timeline_from_factory(self): |
165 | 419 | """tracer.threadinfo.timeline is writable as part of the API.""" | 448 | factory_result = timeline.Timeline() |
166 | 420 | tracer = TimelineTracer() | 449 | factory = lambda:factory_result |
167 | 421 | tracer.threadinfo.timeline = timeline.Timeline() | 450 | tracer = TimelineTracer(lambda:factory_result) |
168 | 422 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') | 451 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') |
170 | 423 | self.assertEqual(1, len(tracer.threadinfo.timeline.actions)) | 452 | self.assertEqual(1, len(factory_result.actions)) |
171 | 424 | 453 | ||
172 | 425 | def test_action_details_are_statement(self): | 454 | def test_action_details_are_statement(self): |
173 | 426 | """The detail in the timeline action is the formatted SQL statement.""" | 455 | """The detail in the timeline action is the formatted SQL statement.""" |
176 | 427 | tracer = TimelineTracer() | 456 | tracer = TimelineTracer(self.factory) |
175 | 428 | tracer.threadinfo.timeline = timeline.Timeline() | ||
177 | 429 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') | 457 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') |
180 | 430 | self.assertEqual( | 458 | self.assertEqual('statement', self.timeline.actions[-1].detail) |
179 | 431 | 'statement', tracer.threadinfo.timeline.actions[-1].detail) | ||
181 | 432 | 459 | ||
182 | 433 | def test_category_from_prefix_and_connection_name(self): | 460 | def test_category_from_prefix_and_connection_name(self): |
183 | 434 | class StubConnection(Connection): | 461 | class StubConnection(Connection): |
184 | @@ -438,24 +465,18 @@ | |||
185 | 438 | self._event = None | 465 | self._event = None |
186 | 439 | self._raw_connection = None | 466 | self._raw_connection = None |
187 | 440 | self.name = 'Foo' | 467 | self.name = 'Foo' |
190 | 441 | tracer = TimelineTracer(prefix='bar-') | 468 | tracer = TimelineTracer(self.factory, prefix='bar-') |
189 | 442 | tracer.threadinfo.timeline = timeline.Timeline() | ||
191 | 443 | tracer._expanded_raw_execute(StubConnection(), 'cursor', 'statement') | 469 | tracer._expanded_raw_execute(StubConnection(), 'cursor', 'statement') |
194 | 444 | self.assertEqual( | 470 | self.assertEqual('bar-Foo', self.timeline.actions[-1].category) |
193 | 445 | 'bar-Foo', tracer.threadinfo.timeline.actions[-1].category) | ||
195 | 446 | 471 | ||
196 | 447 | def test_unnamed_connection(self): | 472 | def test_unnamed_connection(self): |
197 | 448 | """A connection with no name has <unknown> put in as a placeholder.""" | 473 | """A connection with no name has <unknown> put in as a placeholder.""" |
200 | 449 | tracer = TimelineTracer(prefix='bar-') | 474 | tracer = TimelineTracer(self.factory, prefix='bar-') |
199 | 450 | tracer.threadinfo.timeline = timeline.Timeline() | ||
201 | 451 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') | 475 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') |
204 | 452 | self.assertEqual( | 476 | self.assertEqual('bar-<unknown>', self.timeline.actions[-1].category) |
203 | 453 | 'bar-<unknown>', tracer.threadinfo.timeline.actions[-1].category) | ||
205 | 454 | 477 | ||
206 | 455 | def test_default_prefix(self): | 478 | def test_default_prefix(self): |
207 | 456 | """By default the prefix "SQL-" is added to the action's category.""" | 479 | """By default the prefix "SQL-" is added to the action's category.""" |
210 | 457 | tracer = TimelineTracer() | 480 | tracer = TimelineTracer(self.factory) |
209 | 458 | tracer.threadinfo.timeline = timeline.Timeline() | ||
211 | 459 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') | 481 | tracer._expanded_raw_execute('conn', 'cursor', 'statement') |
214 | 460 | self.assertEqual( | 482 | self.assertEqual('SQL-<unknown>', self.timeline.actions[-1].category) |
213 | 461 | 'SQL-<unknown>', tracer.threadinfo.timeline.actions[-1].category) |
Looks good. I noticed a few small issues, but it looks pretty much ready to merge:
[1]
+ # be preserved as that is where we are substiting values in.
Should be "substituting"
[2]
+ #param timeline_factory: A factory function to produce the timeline to
Should be "@param"
[3] raw_execute.
It looks like all the tests are running with conn.param_mark == '?'. It'd be good to have at least one that runs with a StubConnection with param_mark set to '%s' to test the other branch in connection_