pengyuthon/odoo_source
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

[IMP] profiling: enable nested Execution context

Browse Source 
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) <xdo@odoo.com>
This commit is contained in:
Xavier-Do
2021-08-30 13:28:05 +00:00
parent aa797792ca
commit de077243ef
3 changed files with 198 additions and 40 deletions
Download Patch File Download Diff File Expand all files Collapse all files
odoo/addons/base/tests/test_profiler.py
+174 -25
View File
@@ -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():
odoo/tools/profiler.py
+5 -8
View File
@@ -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:
odoo/tools/speedscope.py
+19 -7
View File
@@ -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