From de077243ef073696e6230496cac90768949fc9a7 Mon Sep 17 00:00:00 2001 From: Xavier-Do Date: Fri, 27 Aug 2021 09:21:05 +0000 Subject: [PATCH] [IMP] profiling: enable nested Execution context MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit The initial behaviour of ExecutionContext was to - add the context for the current level of the stack on enter - remove the context at this same level on exit. When two ExecutionContext are nested at the same stack level: - the first one adds it's context; - the second one overrides the current context; - the second one removes it at the end; - the first one fails to remove the context at the same level a second time. def call(): with ExecutionContext(foo=1): with ExecutionContext(bar=2): execute() In this case we could imagine to combine both Execution managers in one: def call(): with ExecutionContext(foo=1, bar=2) execute() But the semantics is different: ExecutionContext should add one level to the stack, instead of two. In the first example above, we expect two additionnal levels: call foo=1 bar=2 execute A simple solution would be to transform the value of the context at some level to a list of dict, but this would make the copy more difficult. The decision was taken to change the context storage strategy, going from a dict where the keys are the level to a tuple of tuples where the first element is the level. {3: {foo: 1}, 4: {bar: 2}} => ((3, {foo: 1}), (4, {bar: 2})) The first benefit is to allow multiple contexts at the same level. The second one is that we don't need to copy the data structure, since tuples are immutables and the dicts are coming from kwargs. This means that saving the context is faster, and the tuple is shared between multiple samples. This is interesting if we assume that we do more samples than exec_context mutations. closes odoo/odoo#75687 Signed-off-by: Xavier Dollé (xdo) --- odoo/addons/base/tests/test_profiler.py | 199 +++++++++++++++++++++--- odoo/tools/profiler.py | 13 +- odoo/tools/speedscope.py | 26 +++- 3 files changed, 198 insertions(+), 40 deletions(-) diff --git a/odoo/addons/base/tests/test_profiler.py b/odoo/addons/base/tests/test_profiler.py index 9264fdda559..c7cd735b012 100644 --- a/odoo/addons/base/tests/test_profiler.py +++ b/odoo/addons/base/tests/test_profiler.py @@ -34,48 +34,48 @@ class TestProfileAccess(TransactionCase): class TestSpeedscope(BaseCase): def example_profile(self): return { - 'init_stack_trace': [['/path/tp/file_1.py', 135, '__main__', 'main()']], + 'init_stack_trace': [['/path/to/file_1.py', 135, '__main__', 'main()']], 'result': [{ # init frame 'start': 2.0, - 'context': {}, + 'exec_context': (), 'stack': [ - ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], + ['/path/to/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], ['/path/to/file_1.py', 101, 'do_stuff1', 'cr.execute(query, params)'], ], }, { 'start': 3.0, - 'context': {}, + 'exec_context': (), 'stack': [ - ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], + ['/path/to/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], ['/path/to/file_1.py', 101, 'do_stuff1', 'cr.execute(query, params)'], ['/path/to/sql_db.py', 650, 'execute', 'res = self._obj.execute(query, params)'], ], }, { # duplicate frame 'start': 4.0, - 'context': {}, + 'exec_context': (), 'stack': [ - ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], + ['/path/to/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], ['/path/to/file_1.py', 101, 'do_stuff1', 'cr.execute(query, params)'], ['/path/to/sql_db.py', 650, 'execute', 'res = self._obj.execute(query, params)'], ], }, { # other frame 'start': 6.0, - 'context': {}, + 'exec_context': (), 'stack': [ - ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], + ['/path/to/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], ['/path/to/file_1.py', 101, 'do_stuff1', 'check'], ['/path/to/sql_db.py', 650, 'check', 'assert x = y'], ], }, { # out of frame 'start': 10.0, - 'context': {}, + 'exec_context': (), 'stack': [ - ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], + ['/path/to/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'], ['/path/to/file_1.py', 101, 'do_stuff1', 'for i in range(10):'], ], }, { # final frame 'start': 10.35, - 'context': {}, + 'exec_context': (), 'stack': None, }], } @@ -179,7 +179,8 @@ class TestSpeedscope(BaseCase): self.assertNotIn('query', async_profile[1]['stack']) self.assertNotIn('time', async_profile[1]['stack']) self.assertEqual(async_profile[1]['stack'], async_profile[2]['stack']) - # this last assertion is not really usefull but ensure that the samples are consistent with the sql one, just missing que query + # this last assertion is not really useful but ensures that the samples + # are consistent with the sql one, just missing tue query sp = Speedscope(init_stack_trace=[]) sp.add('sql', async_profile) @@ -187,20 +188,150 @@ class TestSpeedscope(BaseCase): sp.add_output(['sql', 'traces'], complete=False) res = sp.make() profile_combined = res['profiles'][0] - events = [(e['at']+2, e['type'], res['shared']['frames'][e['frame']]['name']) for e in profile_combined['events']] + events = [ + (e['at']+2, e['type'], res['shared']['frames'][e['frame']]['name']) + for e in profile_combined['events'] + ] self.assertEqual(events, [ + # pylint: disable=bad-continuation (2.0, 'O', 'main'), - (2.0, 'O', 'do_stuff1'), - (2.5, 'O', 'execute'), - (2.5, 'O', "sql('SELECT 1')"), - (5.5, 'C', "sql('SELECT 1')"), # select ends at 5.5 as expected despite another concurent frame at 3 and 4 - (5.5, 'C', 'execute'), - (6.0, 'O', 'check'), - (10.0, 'C', 'check'), - (10.35, 'C', 'do_stuff1'), + (2.0, 'O', 'do_stuff1'), + (2.5, 'O', 'execute'), + (2.5, 'O', "sql('SELECT 1')"), + (5.5, 'C', "sql('SELECT 1')"), # select ends at 5.5 as expected despite another concurent frame at 3 and 4 + (5.5, 'C', 'execute'), + (6.0, 'O', 'check'), + (10.0, 'C', 'check'), + (10.35, 'C', 'do_stuff1'), (10.35, 'C', 'main'), ]) + def test_converts_context(self): + stack = [ + ['file.py', 10, 'level1', 'level1'], + ['file.py', 11, 'level2', 'level2'], + ] + profile = { + 'init_stack_trace': [['file.py', 1, 'level0', 'level0)']], + 'result': [{ # init frame + 'start': 2.0, + 'exec_context': ((2, {'a': '1'}), (3, {'b': '1'})), + 'stack': list(stack), + }, { + 'start': 3.0, + 'exec_context': ((2, {'a': '1'}), (3, {'b': '2'})), + 'stack': list(stack), + }, { # final frame + 'start': 10.35, + 'exec_context': (), + 'stack': None, + }], + } + sp = Speedscope(init_stack_trace=profile['init_stack_trace']) + sp.add('profile', profile['result']) + sp.add_output(['profile'], complete=True) + res = sp.make() + events = [ + (e['type'], res['shared']['frames'][e['frame']]['name']) + for e in res['profiles'][0]['events'] + ] + self.assertEqual(events, [ + # pylint: disable=bad-continuation + ('O', 'level0'), + ('O', 'a=1'), + ('O', 'level1'), + ('O', 'b=1'), + ('O', 'level2'), + ('C', 'level2'), + ('C', 'b=1'), + ('O', 'b=2'), + ('O', 'level2'), + ('C', 'level2'), + ('C', 'b=2'), + ('C', 'level1'), + ('C', 'a=1'), + ('C', 'level0'), + ]) + + def test_converts_context_nested(self): + stack = [ + ['file.py', 10, 'level1', 'level1'], + ['file.py', 11, 'level2', 'level2'], + ] + profile = { + 'init_stack_trace': [['file.py', 1, 'level0', 'level0)']], + 'result': [{ # init frame + 'start': 2.0, + 'exec_context': ((3, {'a': '1'}), (3, {'b': '1'})), # two contexts at the same level + 'stack': list(stack), + }, { # final frame + 'start': 10.35, + 'exec_context': (), + 'stack': None, + }], + } + sp = Speedscope(init_stack_trace=profile['init_stack_trace']) + sp.add('profile', profile['result']) + sp.add_output(['profile'], complete=True) + res = sp.make() + events = [ + (e['type'], res['shared']['frames'][e['frame']]['name']) + for e in res['profiles'][0]['events'] + ] + self.assertEqual(events, [ + # pylint: disable=bad-continuation + ('O', 'level0'), + ('O', 'level1'), + ('O', 'a=1'), + ('O', 'b=1'), + ('O', 'level2'), + ('C', 'level2'), + ('C', 'b=1'), + ('C', 'a=1'), + ('C', 'level1'), + ('C', 'level0'), + ]) + + def test_converts_context_lower(self): + stack = [ + ['file.py', 10, 'level4', 'level4'], + ['file.py', 11, 'level5', 'level5'], + ] + profile = { + 'init_stack_trace': [ + ['file.py', 1, 'level0', 'level0'], + ['file.py', 1, 'level1', 'level1'], + ['file.py', 1, 'level2', 'level2'], + ['file.py', 1, 'level3', 'level3'], + ], + 'result': [{ # init frame + 'start': 2.0, + 'exec_context': ((2, {'a': '1'}), (6, {'b': '1'})), + 'stack': list(stack), + }, { # final frame + 'start': 10.35, + 'exec_context': (), + 'stack': None, + }], + } + sp = Speedscope(init_stack_trace=profile['init_stack_trace']) + sp.add('profile', profile['result']) + sp.add_output(['profile'], complete=False) + res = sp.make() + events = [ + (e['type'], res['shared']['frames'][e['frame']]['name']) + for e in res['profiles'][0]['events'] + ] + self.assertEqual(events, [ + # pylint: disable=bad-continuation + ('O', 'level4'), + ('O', 'b=1'), + ('O', 'level5'), + ('C', 'level5'), + ('C', 'b=1'), + ('C', 'level4'), + ]) + @tagged('post_install', '-at_install', 'profiling') class TestProfiling(TransactionCase): @@ -223,10 +354,28 @@ class TestProfiling(TransactionCase): stack_level = profiler.stack_size() with ExecutionContext(letter=letter): self.env.cr.execute('SELECT 1') - stack_level = profiler.stack_size() entries = p.collectors[0].entries - self.assertEqual(entries[0]['exec_context'][stack_level], {'letter': 'a'}) - self.assertEqual(entries[1]['exec_context'][stack_level], {'letter': 'b'}) + self.assertEqual(entries.pop(0)['exec_context'], ((stack_level, {'letter': 'a'}),)) + self.assertEqual(entries.pop(0)['exec_context'], ((stack_level, {'letter': 'b'}),)) + + def test_execution_context_nested(self): + """ + This test checks that an execution can be nested at the same level of the stack. + """ + with Profiler(db=None, collectors=['sql']) as p: + stack_level = profiler.stack_size() + with ExecutionContext(letter='a'): + self.env.cr.execute('SELECT 1') + with ExecutionContext(letter='b'): + self.env.cr.execute('SELECT 1') + with ExecutionContext(letter='c'): + self.env.cr.execute('SELECT 1') + self.env.cr.execute('SELECT 1') + entries = p.collectors[0].entries + self.assertEqual(entries.pop(0)['exec_context'], ((stack_level, {'letter': 'a'}),)) + self.assertEqual(entries.pop(0)['exec_context'], ((stack_level, {'letter': 'a'}), (stack_level, {'letter': 'b'}))) + self.assertEqual(entries.pop(0)['exec_context'], ((stack_level, {'letter': 'a'}), (stack_level, {'letter': 'c'}))) + self.assertEqual(entries.pop(0)['exec_context'], ((stack_level, {'letter': 'a'}),)) def test_sync_recorder(self): def a(): diff --git a/odoo/tools/profiler.py b/odoo/tools/profiler.py index 23c24192db5..41c54baacc9 100644 --- a/odoo/tools/profiler.py +++ b/odoo/tools/profiler.py @@ -112,8 +112,7 @@ class Collector: # todo add entry count limit self._entries.append({ 'stack': self._get_stack_trace(frame), - # make a copy of the current context, because it will change - 'exec_context': dict(getattr(self.profiler.init_thread, 'exec_context', ())), + 'exec_context': getattr(self.profiler.init_thread, 'exec_context', ()), 'start': time.time(), **(entry or {}), }) @@ -281,17 +280,15 @@ class ExecutionContext: """ def __init__(self, **context): self.context = context - self.stack_trace_level = None + self.previous_context = None def __enter__(self): current_thread = threading.current_thread() - self.stack_trace_level = stack_size() - if not hasattr(current_thread, 'exec_context'): - current_thread.exec_context = {} - current_thread.exec_context[self.stack_trace_level] = self.context + self.previous_context = getattr(current_thread, 'exec_context', ()) + current_thread.exec_context = self.previous_context + ((stack_size(), self.context),) def __exit__(self, *_args): - threading.current_thread().exec_context.pop(self.stack_trace_level) + threading.current_thread().exec_context = self.previous_context class Profiler: diff --git a/odoo/tools/speedscope.py b/odoo/tools/speedscope.py index a1540426bdf..8ec778024a2 100644 --- a/odoo/tools/speedscope.py +++ b/odoo/tools/speedscope.py @@ -121,14 +121,26 @@ class Speedscope: return self.frames_indexes[frame] def stack_to_ids(self, stack, context, stack_offset=0): + """ + :param stack: A list of hashable frame + :param context: an iterable of (level, value) ordered by level + :param stack_offset: offeset level for stack + + Assemble stack and context and return a list of ids representing + this stack, adding each corresponding context at the corresponding + level. + """ stack_ids = [] - for level, frame in enumerate(stack): - if context: - current_frame_level = stack_offset + level + 1 - frame_context = context.get(str(current_frame_level)) or context.get(current_frame_level) - if frame_context: - context_frame = (', '.join('%s=%s' % item for item in frame_context.items()), '', '') - stack_ids.append(self.get_frame_id(context_frame)) + context_iterator = iter(context) + context_level, context_value = next(context_iterator, (None, None)) + # consume iterator until we are over stack_offset + while context_level is not None and context_level < stack_offset: + context_level, context_value = next(context_iterator, (None, None)) + for level, frame in enumerate(stack, start=stack_offset + 1): + while context_level == level: + context_frame = (", ".join(f"{k}={v}" for k, v in context_value.items()), '', '') + stack_ids.append(self.get_frame_id(context_frame)) + context_level, context_value = next(context_iterator, (None, None)) stack_ids.append(self.get_frame_id(frame)) return stack_ids