In some case the frame may have a filename and corresponding file but
no lineno. This may lead to an error
File ".../odoo/tools/profiler.py", line 571, in _add_file_lines
line = filelines[lineno - 1]
TypeError: unsupported operand type(s) for -: 'NoneType' and 'int'
This commit simply fixes this by skipping the logic if we have no lineno.
closesodoo/odoo#98217
X-original-commit: 44715af97413da3608e99f211c361a498f25d964
Signed-off-by: Raphael Collet <rco@odoo.com>
Signed-off-by: Xavier Dollé (xdo) <xdo@odoo.com>
This commit fixes the profiler datetime usage by properly using the
'real_datetime_now' as a callable.
This was breaking the output json file when profiling.
closesodoo/odoo#96456
X-original-commit: 5fec27e42b033f79933afb3d0c85b142360981f9
Signed-off-by: Xavier Dollé (xdo) <xdo@odoo.com>
When freezegun is used, the profiler and sql_db time are freezed,
Making the profile and sql perf counters invalids.
A possible solution would be to black list some modules in freezegun but
this doens't look possible in the pinned version (0.3.x).
Saving the builtin time.time is not enough, it looks like freezegun will
find all occurences and replace them.
We need to get the __call__ instead.
closesodoo/odoo#95100
X-original-commit: 9ac5fdf1e6d00e6e4b4ff4b6e94a3cd28f8cae11
Signed-off-by: Christophe Monniez (moc) <moc@odoo.com>
Signed-off-by: Xavier Dollé (xdo) <xdo@odoo.com>
The methods to generate the attributes are called all the time in order
to reset the attribute dictionary. The profiler is modified so as not to
display directives in the log that do not exist on the tag.
Issue: attributes could be generated by directives and not be used (for
example on <t>). These attributes could end up unwittingly on the next
node.
closesodoo/odoo#93216
Issue: opw-2859447
X-original-commit: 38724f106c0747aef475991c894e9ee93c1db967
Signed-off-by: Vincent Schippefilt (vsc) <vsc@odoo.com>
Signed-off-by: Christophe Matthieu (chm) <chm@odoo.com>
The `t-cache` directive allows you to keep the rendered result
of a template part. The supplied key must be a tuple. This tuple
can contain recordset in this case the zone will be invalidated
each time the write_date of these records changes.
The `t-nocache` directive makes it possible to force rendering
of a part even if it is in a `t-cache`. The values available in
the `t-nocache` are the one provided when calling the template
(and therefore ignores any t-set that could have been done).
Part-of: odoo/odoo#88276
This flat structure makes caching easier if odoo adds shared caches for
example. In addition, the use of idempotent names makes it possible to
compare methods during development.
closesodoo/odoo#85110
Related: odoo/design-themes#554
Related: odoo/enterprise#24622
Signed-off-by: Martin Trigaux (mat) <mat@odoo.com>
There were inconsistencies in the calls to `_render`.
* the view context could contain information that misled developers.
Indeed, the context and value of the view are not supposed to be found
in the rendering. Thus by calling `ir.qweb` with the name of the
template, we ensure that there is no unwanted information and in
addition the cache key is that of the name of the template which saves
a query.
* the context used for rendering was modified by a method on
`ir.ui.view`, except this is not information used by this model. There
is now a `_prepare_environment` method residing on `ir.qweb`. This
method allows to modify the value dictionary as well as the context in
which the rendering will be done. This preparation of the data as well
as my security check is done only once per rendering. This also saves
some queries
* Freeze options for rendering were inconsistent. It could be that
options on which rendering depends were not part of the cache key. Thus,
depending on the user who generated the generation of the rendering
function, there was or was not information in the template. For example
for automatic branding. This is no longer possible, because it is the
context that is used. The options serving as a cache key are only
recorded for information (for the profiling system for example). A
simplification of the `ir.qweb.field` models could be made.
The report rendering and call `ir.qweb` instead of `ir.ui.view`.
Part-of: odoo/odoo#85110
QWeb is the primary templating engine used by Odoo. It is an XML
templating engine and used mostly to generate XML, HTML fragments and
pages.
To create new XML template, please see :doc:`QWeb Templates documentation
<https://www.odoo.com/documentation/15.0/developer/reference/frontend/qweb.html>`
In **input** you have an XML template giving the corresponding input
etree. Each etree input nodes are used to generate a python function.
This fonction is called and will give the XML **output**.
The ``_compile`` method is responsible to generate the function from the
etree, that function is a python generator that yield one output line at a
time. This generator is consumed by ``_render``. The generated function is
orm cached.
In the graphic below you can see theresume of the call of the methods
performed in the IrQweb class.
Odoo
┗━► _render (returns MarkupSafe)
┗━► _compile (returns function) ◄━━━━━━━━━┓
┗━► _compile_node (returns code string array) ◄━━━━━━━┓ ┃
┃ (add technical directives: t-inner-content, t-tag) ┃ ┃
┣━► _directives_eval_order (defined directive order) ┃ ┃
┃ ┃ ┃
┣━► _compile_directives (recursive) ◄━━━━┓ ┃ ┃
┃ ┣━► _compile_directive ┃ ┃ ┃
┃ ┃ ┗━► t-if ━━► _compile_directive_if ━┫ ┃ ┃
┃ ┃ ┗━► t-foreach ━━► _compile_directive_foreach ━┫ ┃ ┃
┃ ┃ ┗━► t-* ━━► ... ━┛ ┃ ┃
┃ ┃ ┗━► t-inner-content ━━► _compile_directive_inner_content ◄━━━━┓ ━┛ ┃
┃ ┃ ┗━► t-tag ━━► _compile_directive_tag ━┫ ┃
┃ ┃ ┗━► t-call ━━► _compile_directive_call ━┫ ━━━┛
┃ ┃ ┗━► t-out ━━► _compile_directive_out ◄━┓ ━┫
┃ ┃ ┗━► t-field ━━► _compile_directive_field ━┛ ┃
┃ ┃ ┃
┗━━┻━► _compile_static_node ━┛
Part-of: odoo/odoo#81024
When using a profiler manually inside the code, and longpolling uses
this part of the code, an error will appear on runbot since gevent
server cannot be profiled properly.
This fix mitigate the issue by disabling the profiler automatically in
this case.
Part-of: odoo/odoo#78514
By activating the profiler debugger, the two qweb options is added. The
qweb templates that need to be rendered are compiled into a new function
to add instructions for saving data.
`Add qweb directive context`
It's a sub-option of "Record sql" or "Record traces", add some context on
thread at current call stack level. This context stored by collector
beside stack and is used by Speedscope to add a level to the stack with
this qweb directive information.
```
directive=t-call='website.layout', xpath=/t/t
t_call_content
directive=t-foreach='5' t-as="'a', xpath=/t/t/div/div
directive=t-esc='website.search([])', xpath=/t/t/div/div/t
execute
```
`Record qweb`
Add profiling data used by ProfilingQwebView widget. In the `ir.profile`
form view, the widget display the duration and number of sql of every qweb
directives with the xml of templates. Every xml is recorded to be
consulted even if the user change the xml templates.
```xml
<t t-call="website.layout">
<div>
<div t-foreach="5" t-as="a">
<t t-esc="website.search([])"/> <!-- will display 5 separate requests -->
</div>
</div>
</t>
```
closesodoo/odoo#74712
Signed-off-by: Xavier Dollé (xdo) <xdo@odoo.com>
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.
closesodoo/odoo#75687
Signed-off-by: Xavier Dollé (xdo) <xdo@odoo.com>
This commit proposes a mechanism to manually add a frame before a
blocking c-call and triggers it before calling libsaas.compile.
closesodoo/odoo#75519
X-original-commit: f836ff3a67d446cd8b3ab2cf573fab649153e6da
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
Sometimes the profiler provides confusing information. This happens
when calling a C library without releasing the GIL (Python's global
interpreter lock). The time spent in the call will be attributed by the
profiler to the former stack trace, because the collector cannot run
during the call.
This commit adds information on the frame when a given stack frame has
lasted for too long.
X-original-commit: 5e193c5dbcdfbdbab38309ed292131ae1f5d3026
Entry count can be useful to estimate the size on disk of a profile
file.
The entry count would be quite expensive to compute and thus should be
stored. It is impossible to use a compute stored in this case, since
ir.profile shouldn't have any "business" logic upon insert.
closesodoo/odoo#71673
Signed-off-by: Raphael Collet (rco) <rco@openerp.com>
Even if only accessible when writing some custom code, the path option
of Profiler looked a little dangerous from a security point of view,
since this option allows to write the result of the collector anywhere.
This shouldn't be a problem, since Profiler shoudn't be accessible
inside a safe_eval() and the path param cannot be user defined, but this
is still a risk.
An alternative option would have been to give a file descriptor instead,
so that the user must have access to `open()`, which is unlikely inside
a server action. This alternative has some disadvantages, though,
because the file descriptor should be given when creating the profiler,
or at least before `__exit__()`, removing the possibility to add the
number of entries in the filename.
This commit proposes another solution: add a generic way to output the
profiler as a json text. The result can thus be saved the way the
developer chooses. A utility method format_path() will help to format
path the same way the profiler did before this change.
The usage of an additional optional context manager leads to the usage
of ExitStack. Unfortunately, this changes the initial format quite a
lot, decreasing readability and adding a loop on context managers, even
if there should be only one most of the time (request).
This commit proposes to a nesting utility for the profiler, allowing to
nest another context manager inside a profiler.
This solution allows an easier integration into http.py, avoids to
manage the "enter_context" case when recovering the init stack and can
be useful in other cases.
This commit adds tooling to profile performance and save execution by
saving stack traces and queries to a file/database in specific format.
----------
Collectors
----------
For now, three different profiling modes (aka Collectors) are available
even if a last once should be introduced by @Gorash to profile qweb
execution.
- SQLCollector (or 'sql'): Saves the current stack trace and the query
every time Cursor.execute() is called. Any query executed on the thread
will be collected, no matter the cursor.
- PeriodicCollector (or 'traces_async'): Saves the stack trace every
'interval' seconds using a parallel thread to profile the caller thread.
The python implementation was optimized to minimize impact on
performance while remaining portable and easy to enable/disable
inside a odoo execution. Higher the frequency (lower the interval),
more impactful the profiling will become on the execution and increase
memory usage. From last experiments, 1ms looks to be a good minimum for
short executions.
- SyncCollector (or 'traces_sync'): Saves the stack trace every function
call/return. This collector is obviously quite impactful on performance
and can quickly overload the memory for long executions, but this is
quite useful to understand the precise path followed by some short
executions. Any time related information will be almost irrelevant with this
collector.
A base Collector defining minimal collectors features can easily be
extended to create custom collectors if needed.
----------------
Profiler & Usage
----------------
Collectors are not supposed to be used by themselves, but should be
given to a Profiler. The Profiler will synchronize collectors starts and
stop, and manage saving them to a file of in a ir_profile in the
database.
Exemple of usage:
```
with Profiler():
do_stuff()
```
This simple example will use the default collectors (sql and
traces_async) and save them to the database. The database is defined
automatically from current_thread 'dbname' if available.
Example of usage:
```
with Profiler(collectors=['sql'], db=False, path=/home/user/logs/do_stuff_profile/{time}):
do_stuff()
```
This more complex example disable the default behavior consisting
to save to the database, gives a path where the profile will be saved
and specify to only use the 'sql' collector. Note that
collectors=[SQLCollector()] would have the same behavior since
Collectors can be either a Collector instance or a string describing the
desired collector. This allows to define custom params for the
collectors and use custom collectors if needed.
Note that it is always possible to get results after execution without
saving it since they are available on the profiler.
```
with Profiler(collectors=['sql'], db=False) as p:
do_stuff()
print(len([None for entry in p.collectors[0].entries if ...]))
```
Profiler will also save the stack below the profiler start point, and
collectors will only collect the part of the stack over this stack.
This is a good way to reduce collectors CPU and memory usage.
Collected entries will be saved as follows:
```
[{
'start': 2.0,
'context': {},
'stack': [
['path_to_file', lno, 'func_name', 'line_content'],
...
],
},
...
]
```
SQLCollector will add three additional keys on each entry:
- query (query without parameters)
- full_query (mogrified query with parameters)
- time (the 'exact' execution time of the query)
----------------
ExecutionContext
----------------
A last tool, ExecutionContext, allows to define some context on some block of code:
Example of usage:
```
def process_modules(modules)
for module in modules:
with ExecutionContext(module=module): # note the 'not linter frienldy but still convenient' 2 spaces indentation
do_stuff(module):
```
This context will automatically be added in the stack as a virtual frame between
process_modules and do_stuff in order to split do_stuff from one single frame to
one frame per module.
----------
Speedscope
----------
The saved data are in a simple json format easy to analyze, but can't be visualized in
speedscope as they are. A utility class `Speedscope` can be used to generate a format
readable by speedscope. The used format is actually the format defined by speedscope,
meaning that all features should be available using it.
The output format is evented, meaning that we need to transform a list of samples
(a list of stack) to a list of event (going in/out a frame).
This is the main task of the Speedscope, as well as combining samples from different
sources, to display SQLCollector and PeriodicCollector results mixed together.
When stored on an ir_profile, the default speedscope generation can easily be generated
with the speedscope computed field.
This class can be used as it is but will mainly be useful for the next commit.
Special thanks to @rco-odoo for the in depth review and @Gorash for support.
The profiler was too optimistic. If the local variable self was not a
cursor, it assumed it was automatically an Odoo model.
Instead, only do the custom tracer methods when self is an instance of
BaseModel.
Full scenario to reproduce explained at odoo/odoo#39237
In case a method like the default_get of utm.mixing was profiled, the
tracer crashed when evaluating `__bool__(request)`.
The tracer considered self as an Odoo model while it was a werkzeug
instance with its custom __getattr__ that crashed while trying to
retrieve the content of `_name`.
Fixesodoo/odoo#39237closesodoo/odoo#39524
X-original-commit: c8fa8fb067dcfb15330acde35d66ac41a255f669
Signed-off-by: Martin Trigaux (mat) <mat@odoo.com>
Multi is the default api for methods, it is not necessary to explicitly
decorate methods with it, adds clutter and most people use it because
they see that the rest of the code uses it.
Done with `find . -type f -name '*.py' | xargs sed -i '/@api.multi/d'`
The previous line in a loop calculates the number of queries made until
the end of the loop. This causes the number of queries to be counted
twice.
Don't blacklist the entry point method.
Check the methods called from a blacklisted method.
Use ``profile`` to decorate an entry point method.
If ``profile`` is used without params, log as shallow mode else log
all methods for all odoo models by applying the optional filters.
:param whitelist: None or list of model names to display in the log
(Default: None)
:type whitelist: list or None
:param files: None or list of filenames to display in the log
(Default: None)
:type files: list or None
:param list blacklist: list model names to remove from the log
(Default: remove non odoo model from the log: [None])
:param int minimum_time: minimum time (ms) to display a method
(Default: 0)
:param int minimum_queries: minimum sql queries to display a method
(Default: 0)
.. code-block:: python
from odoo.tools.profiler import profile
class SaleOrder(models.Model):
...
@api.model
@profile # log only this create method
def create(self, vals):
...
@api.multi
@profile() # log all methods for all odoo models
def unlink(self):
...
@profile(whitelist=['sale.order', 'ir.model.data'])
def action_quotation_send(self):
...
@profile(files=['/home/openerp/odoo/odoo/addons/sale/models/sale.py'])
def write(self):
...
NB: The use of the profiler modifies the execution time
Xavier-Do