From 4d0e1117338fcda082bab99ec67d13dc07d7bc2d Mon Sep 17 00:00:00 2001 From: Gorash Date: Wed, 1 Sep 2021 12:47:19 +0000 Subject: [PATCH] [IMP] profiling: Add profile qweb execution into the performance tools. MIME-Version: 1.0 Content-Type: text/plain; charset=UTF-8 Content-Transfer-Encoding: 8bit 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
``` closes odoo/odoo#74712 Signed-off-by: Xavier Dollé (xdo) --- .../core/debug/profiling/profiling_item.js | 4 + .../core/debug/profiling/profiling_item.xml | 80 +++--- .../core/debug/profiling/profiling_qweb.xml | 57 +++++ .../debug/profiling/profiling_qweb_view.js | 242 ++++++++++++++++++ .../debug/profiling/profiling_qweb_view.scss | 129 ++++++++++ .../static/src/scss/web_editor.common.scss | 4 - odoo/addons/base/models/ir_profile.py | 1 + odoo/addons/base/models/ir_qweb.py | 10 +- odoo/addons/base/models/qweb.py | 69 ++--- odoo/addons/base/tests/test_profiler.py | 83 ++++++ odoo/addons/base/views/ir_profile_views.xml | 3 + odoo/tools/profiler.py | 162 ++++++++++++ 12 files changed, 770 insertions(+), 74 deletions(-) create mode 100644 addons/web/static/src/core/debug/profiling/profiling_qweb.xml create mode 100644 addons/web/static/src/core/debug/profiling/profiling_qweb_view.js create mode 100644 addons/web/static/src/core/debug/profiling/profiling_qweb_view.scss diff --git a/addons/web/static/src/core/debug/profiling/profiling_item.js b/addons/web/static/src/core/debug/profiling/profiling_item.js index b56f85d9c45..a6a1cae7968 100644 --- a/addons/web/static/src/core/debug/profiling/profiling_item.js +++ b/addons/web/static/src/core/debug/profiling/profiling_item.js @@ -14,6 +14,10 @@ export class ProfilingItem extends Component { changeParam(param, ev) { this.profiling.setParam(param, ev.target.value); } + toggleParam(param, ev) { + const value = this.profiling.state.params.execution_context_qweb; + this.profiling.setParam(param, !value); + } openProfiles() { if (this.env.services.action) { // using doAction in the backend to preserve breadcrumbs and stuff diff --git a/addons/web/static/src/core/debug/profiling/profiling_item.xml b/addons/web/static/src/core/debug/profiling/profiling_item.xml index a6e43a0e4b8..940f18131cc 100644 --- a/addons/web/static/src/core/debug/profiling/profiling_item.xml +++ b/addons/web/static/src/core/debug/profiling/profiling_item.xml @@ -2,42 +2,54 @@ - - - - - + +
+ + + + + + - - - - - - - - - - - -
-
-
Interval
+ + + + + + + + + +
+
+
Interval
+
+
- -
- + + + + + + + + + +
diff --git a/addons/web/static/src/core/debug/profiling/profiling_qweb.xml b/addons/web/static/src/core/debug/profiling/profiling_qweb.xml new file mode 100644 index 00000000000..918535bbddb --- /dev/null +++ b/addons/web/static/src/core/debug/profiling/profiling_qweb.xml @@ -0,0 +1,57 @@ + + + + +
+
+ + +
+
+ + It is possible that the "t-call" time does not correspond to the overall time of the + template. Because the global time (in the drop down) does not take into account the + duration which is not in the rendering (look for the template, read, inheritance, + compilation...). During rendering, the global time also takes part of the time to make + the profile as well as some part not logged in the function generated by the qweb. + +
+ + +
+
ms
+
query
+
+ + +
+
+ * + + + + + + + + + + + +
msquery
+
+
+
+
+ + + diff --git a/addons/web/static/src/core/debug/profiling/profiling_qweb_view.js b/addons/web/static/src/core/debug/profiling/profiling_qweb_view.js new file mode 100644 index 00000000000..0b9e81976a0 --- /dev/null +++ b/addons/web/static/src/core/debug/profiling/profiling_qweb_view.js @@ -0,0 +1,242 @@ +/* eslint-disable comma-dangle */ +odoo.define('web.profiling_qweb_view', function (require) { +'use strict'; + +const registry = require('web.field_registry'); +const basicFfields = require('web.basic_fields'); +const core = require('web.core'); +const qweb = core.qweb; + +/** + * This widget is intended to be used on Text fields. It will provide Ace Editor + * for display XML and Python profiling. + */ +const ProfilingQwebView = basicFfields.AceEditor.extend({ + template: "web.ProfilingQwebView", + xmlDependencies: ['/web/static/src/xml/debug.xml'], + events: _.extend({}, basicFfields.AceEditor.prototype.events, { + 'click .dropdown-menu a': '_onSelectView', + }), + /** + * @override + * @params parent {Widget} + */ + init: function () { + this._super.apply(this, arguments); + // {template, xpath, directive, time, duration, query }[] + const results = this.value && JSON.parse(this.value)[0].results || {archs: {}, data: []}; + this.profileLines = results.data; + this.viewArch = results.archs; + this.viewIDs = Array.from(new Set(this.profileLines.map(line => line.view_id))); + for (const line of this.profileLines) { + line.xpath = line.xpath.replace(/([^\]])\//g, '$1[1]/').replace(/([^\]])$/g, '$1[1]'); + } + this.viewID = this.profileLines.length ? this.profileLines[0].view_id : 0; + this.mode = 'readonly'; + }, + /** + * Search xml view + * + * @override + * @returns {Promise} + */ + willStart: async function () { + const _super = this._super; + this.views = await this._rpc({ + model: 'ir.ui.view', + method: 'search_read', + fields: ['id', 'display_name', 'key'], + domain: [['id', 'in', this.viewIDs]], + }); + for (const view of this.views) { + view.delay = 0; + view.query = 0; + const lines = this.profileLines.filter(l => l.view_id === view.id); + const root = lines.find(l => l.xpath === ''); + if (root) { + view.delay += root.delay; + view.query += root.query; + } else { + view.delay = lines.map(l => l.delay).reduce((a, b) => a + b); + view.query = lines.map(l => l.query).reduce((a, b) => a + b); + } + view.delay = Math.ceil(view.delay * 10) / 10; + } + await _super.call(this); + }, + + //-------------------------------------------------------------------------- + // Private + //-------------------------------------------------------------------------- + + /** + * Set view to render + * + * @override + * @returns {Promise} + */ + _render: function () { + this.view = this.views.find(view => view.id === this.viewID); + if (this.view) { + const content = this.$('.dropdown-menu a[data-id=' + this.view.id + ']').html(); + this.$('.dropdown-toggle').empty().append(content); + const arch = this.viewArch[this.view.id] || ''; + if (this.aceSession.getValue() !== arch) { + this.aceSession.setValue(arch); + } + } else { + this.aceSession.setValue(''); + } + }, + _renderProfilingInformation: function () { + let flat = {}; + let arch = [{ xpath: '', children: [] }]; + const $rows = this.$('.ace_gutter .ace_gutter-cell'); + $rows.find('.o_info').remove(); + + this.$('.ace_tag-open, .ace_end-tag-close, .ace_end-tag-open, .ace_qweb').each((i, node) => { + const $node = $(node); + const parent = arch[arch.length - 1]; + let xpath = parent.xpath; + if ($node.hasClass('ace_end-tag-close')) { + // Close tag. + const tag = $node.prevAll('.ace_tag-name:first').text(); + if (parent.tag === tag) { + // can be different when scroll because ace does not display the previous lines. + arch.pop(); + } + } else if ($node.hasClass('ace_end-tag-open')) { + // Auto close tag. + const tag = $node.next().text(); + if (parent.tag === tag) { + // can be different when scroll because ace does not display the previous lines. + arch.pop(); + } + } else if ($node.hasClass('ace_qweb')) { + // QWeb attribute. + const directive = $node.text(); + parent.directive.push({ + el: node, + directive: directive, + }); + + // Compute delay and query number. + let delay = 0; + let query = 0; + for (const line of this.profileLines) { + if (line.view_id === this.viewID && line.xpath === xpath && line.directive.includes(directive)) { + delay += line.delay; + query += line.query; + } + } + + // Render delay and query number in span visible on hover. + if ((delay || query) && !$node.children('.o_info').length) { + $(qweb.render('web.ProfilingQwebView.hover', { delay: this._formatDelay(delay), query: query })).prependTo($node); + } + } else if ($node.hasClass('ace_tag-open')) { + // Open tag. + const $tag = $node.next('.ace_tag-name'); + const tag = $tag.text(); + const $row = $($rows[$tag.parent('.ace_line').index()]); + + // Add a children to the arch and compute the xpath. + xpath += '/' + tag; + let i = 1; + while (flat[xpath + '[' + i + ']']) { + i++; + } + xpath += '[' + i + ']'; + flat[xpath] = { xpath: xpath, tag: tag, children: [], directive: [] }; + arch.push(flat[xpath]); + parent.children.push(flat[xpath]); + + // Compute delay and query number. + const closed = !!$row.find('.ace_closed').length; + const delays = []; + const querys = []; + const groups = {}; + let displayDetail = false; + for (const line of this.profileLines) { + if (line.view_id === this.viewID && (closed ? line.xpath.startsWith(xpath) : line.xpath === xpath)) { + delays.push(line.delay); + querys.push(line.query); + const directive = line.directive.split("=")[0]; + if (!groups[directive]) { + groups[directive] = { + delays: [], + querys: [], + }; + } else { + displayDetail = true; + } + groups[directive].delays.push(this._formatDelay(line.delay)); + groups[directive].querys.push(line.query); + } + } + + // Display delay and query number in front of the line. + if (delays.length && !$row.children('.o_info').length) { + $(qweb.render('web.ProfilingQwebView.info', { + delay: this._formatDelay(delays.reduce((a, b) => a + b, 0)), + query: querys.reduce((a, b) => a + b, 0) || '.', + detail: displayDetail, + groups: groups, + })).prependTo($row); + } + } + $node.attr('data-xpath', xpath); + }); + }, + _formatDelay: function (delay) { + return delay ? _.str.sprintf('%.1f', Math.ceil(delay * 10) / 10) : '.'; + }, + /** + * Starts the ace library on the given DOM element. This initializes the + * ace editor in readonly mode. + * + * @private + * @param {Node} node - the DOM element the ace library must initialize on + */ + _startAce: function (node) { + this.aceEditor = window.ace.edit(node); + this.aceEditor.setOptions({ + maxLines: Infinity, + showPrintMargin: false, + highlightActiveLine: false, + highlightGutterLine: true, + readOnly: true, + }); + this.aceEditor.renderer.setOptions({ + displayIndentGuides: true, + showGutter: true, + }); + this.aceEditor.renderer.$gutter.removeAttribute('aria-hidden'); + this.aceEditor.renderer.$cursorLayer.element.style.display = "none"; + + this.aceEditor.$blockScrolling = true; + this.aceSession = this.aceEditor.getSession(); + this.aceSession.setOptions({ + useWorker: false, + mode: "ace/mode/qweb", + tabSize: 2, + useSoftTabs: true, + }); + + // Ace render 3 times when change the value and 1 time per click. + this.aceEditor.renderer.on("afterRender", this._renderProfilingInformation.bind(this)); + }, + /** + * @private + * @param {MouseEvent} ev + */ + _onSelectView: function (ev) { + ev.preventDefault(); + this.viewID = +$(ev.currentTarget).data('id'); + this._render(); + }, +}); + +registry.add('profiling_qweb_view', ProfilingQwebView); + +}); diff --git a/addons/web/static/src/core/debug/profiling/profiling_qweb_view.scss b/addons/web/static/src/core/debug/profiling/profiling_qweb_view.scss new file mode 100644 index 00000000000..43ba4dfdae2 --- /dev/null +++ b/addons/web/static/src/core/debug/profiling/profiling_qweb_view.scss @@ -0,0 +1,129 @@ +.o_form_view .o_ace_view_editor { + background: transparent; +} + +.o_profiling_qweb_view { + user-select: none; + .o_select_view_profiling { + margin-bottom: 10px; + .dropdown-menu { + overflow: auto; + max-height: 240px; + } + a { + margin: 3px 0; + display: block; + .o_delay, .o_query { + font-size: 0.8em; + display: inline-block; + color: $body-color; + text-align: right; + width: 50px; + margin-right: 10px; + white-space: nowrap; + } + .o_key { + display: inline-block; + margin-left: 10px; + font-size: 0.8em; + } + } + } + .ace_editor { + overflow: visible; + .ace_qweb, .ace_tag-name { + cursor: default; + pointer-events: all; + position: relative; + .o_info { + display: none; + left: 8px; + top: 14px; + width: 100px; + .o_delay span, .o_query span { + text-align: left; + display: inline-block; + width: 40px; + } + } + &:hover .o_info { + display: block; + &:hover { + display: none; + } + } + } + .ace_gutter { + overflow: visible; + } + .ace_gutter-layer { + width: 134px !important; + overflow: visible; + } + .ace_gutter-cell .o_info { + display: block; + float: left; + font-size: 0.8em; + white-space: nowrap; + .o_more { + float: left; + position: relative; + span { + color: orange !important; + cursor: default; + margin-left: -12px; + } + .o_detail { + left: 30px; + top: -30px; + min-width: 120px; + display: none; + th { + text-align: center; + } + td { + min-width: 60px; + vertical-align: top; + text-align: left; + } + tr td:first-child { + padding-right: 10px; + white-space: nowrap; + } + tr th:last-child, tr td:last-child { + padding-left: 10px; + } + } + &:hover > .o_detail { + display: block; + &:hover { + display: none; + } + } + } + .o_delay, .o_query { + display: block; + float: left; + margin-right: 10px; + width: 30px; + } + } + .ace_line { + border-bottom: 1px #dddddd dotted; + } + .ace_scrollbar-h { + z-index: 3; + } + + .o_detail { + position: absolute; + z-index: 1; + background: #ffedcb; + color: orange !important; + border: 1px orange solid; + padding: 6px; + white-space: normal; + text-align: right; + } + } +} diff --git a/addons/web_editor/static/src/scss/web_editor.common.scss b/addons/web_editor/static/src/scss/web_editor.common.scss index f89ced84c4d..38c6901d4ed 100644 --- a/addons/web_editor/static/src/scss/web_editor.common.scss +++ b/addons/web_editor/static/src/scss/web_editor.common.scss @@ -442,10 +442,6 @@ a.o_underline { } } -.ace_editor > .ace_gutter { - display: block !important; // display even with aria-hidden -} - .o_ace_select2_dropdown { width: auto !important; padding-top: 4px; diff --git a/odoo/addons/base/models/ir_profile.py b/odoo/addons/base/models/ir_profile.py index 9375ee86dca..b9987897405 100644 --- a/odoo/addons/base/models/ir_profile.py +++ b/odoo/addons/base/models/ir_profile.py @@ -34,6 +34,7 @@ class IrProfile(models.Model): sql = fields.Text('Sql', prefetch=False) traces_async = fields.Text('Traces Async', prefetch=False) traces_sync = fields.Text('Traces Sync', prefetch=False) + qweb = fields.Text('Qweb', prefetch=False) entry_count = fields.Integer('Entry count') speedscope = fields.Binary('Speedscope', compute='_compute_speedscope') diff --git a/odoo/addons/base/models/ir_qweb.py b/odoo/addons/base/models/ir_qweb.py index bdcdf570dc7..9e7e7e5bc92 100644 --- a/odoo/addons/base/models/ir_qweb.py +++ b/odoo/addons/base/models/ir_qweb.py @@ -5,7 +5,6 @@ import copy import logging import re import markupsafe -from time import time from lxml import html, etree from odoo import api, models, tools @@ -13,6 +12,7 @@ from odoo.tools.safe_eval import check_values, assert_valid_codeobj, _BUILTINS, from odoo.tools.misc import get_lang from odoo.http import request from odoo.modules.module import get_resource_path +from odoo.tools.profiler import QwebTracker from odoo.addons.base.models.qweb import QWeb from odoo.addons.base.models.assetsbundle import AssetsBundle @@ -51,6 +51,7 @@ class IrQWeb(models.AbstractModel, QWeb): _available_objects = dict(_BUILTINS) _empty_lines = re.compile(r'\n\s*\n') + @QwebTracker.wrap_render @api.model def _render(self, template, values=None, **options): """ render(template, values, **options) @@ -109,13 +110,14 @@ class IrQWeb(models.AbstractModel, QWeb): # assume cache will be invalidated by third party on write to ir.ui.view def _get_template_cache_keys(self): """ Return the list of context keys to use for caching ``_get_template``. """ - return ['lang', 'inherit_branding', 'editable', 'translatable', 'edit_translations', 'website_id'] + return ['lang', 'inherit_branding', 'editable', 'translatable', 'edit_translations', 'website_id', 'profile'] # apply ormcache_context decorator unless in dev mode... @tools.conditional( 'xml' not in tools.config['dev_mode'], tools.ormcache('id_or_xml_id', 'tuple(options.get(k) for k in self._get_template_cache_keys())'), ) + @QwebTracker.wrap_compile def _compile(self, id_or_xml_id, options): try: id_or_xml_id = int(id_or_xml_id) @@ -168,6 +170,10 @@ class IrQWeb(models.AbstractModel, QWeb): # compile directives + @QwebTracker.wrap_compile_directive + def _compile_directive(self, el, options, directive, indent): + return super()._compile_directive(el, options, directive, indent) + def _compile_directive_groups(self, el, options, indent): """Compile `t-groups` expressions into a python code as a list of strings. diff --git a/odoo/addons/base/models/qweb.py b/odoo/addons/base/models/qweb.py index e552eab8a69..85413fed62f 100644 --- a/odoo/addons/base/models/qweb.py +++ b/odoo/addons/base/models/qweb.py @@ -370,34 +370,10 @@ class QWeb(object): # compile the first directive present on the element for directive in options['iter_directives']: if ('t-' + directive) in el.attrib: - mname = directive.replace('-', '_') - compile_handler = getattr(self, f'_compile_directive_{mname}', None) - return compile_handler(el, options, indent) + return self._compile_directive(el, options, directive, indent) return [] - def _compile_options(self, el, varname, options, indent): - """ - compile t-options and add to the dict the t-options-xxx values - """ - code = [] - dict_arg = [] - for key in list(el.attrib): - if key.startswith('t-options-'): - value = el.attrib.pop(key) - option_name = key[10:] - dict_arg.append(f'{repr(option_name)}:{self._compile_expr(value)}') - - t_options = el.attrib.pop('t-options', None) - if t_options and dict_arg: - code.append(self._indent(f"{varname} = {{**{self._compile_expr(t_options)}, {', '.join(dict_arg)}}}", indent)) - elif dict_arg: - code.append(self._indent(f"{varname} = {{{', '.join(dict_arg)}}}", indent)) - elif t_options: - code.append(self._indent(f"{varname} = {self._compile_expr(t_options)}", indent)) - - return code - def _compile_format(self, expr): """ Parses the provided format string and compiles it to a single expression python, uses string with format method. @@ -835,6 +811,10 @@ class QWeb(object): # compile directives + def _compile_directive(self, el, options, directive, indent): + compile_handler = getattr(self, f"_compile_directive_{directive.replace('-', '_')}", None) + return compile_handler(el, options, indent) + def _compile_directive_debug(self, el, options, indent): """Compile `t-debug` expressions into a python code as a list of strings. @@ -851,6 +831,29 @@ class QWeb(object): code.extend(self._compile_directives(el, options, indent)) return code + def _compile_directive_options(self, el, options, indent): + """ + compile t-options and add to the dict the t-options-xxx values + """ + varname = options.get('t_options_varname', 't_options') + code = [] + dict_arg = [] + for key in list(el.attrib): + if key.startswith('t-options-'): + value = el.attrib.pop(key) + option_name = key[10:] + dict_arg.append(f'{repr(option_name)}:{self._compile_expr(value)}') + + t_options = el.attrib.pop('t-options', None) + if t_options and dict_arg: + code.append(self._indent(f"{varname} = {{**{self._compile_expr(t_options)}, {', '.join(dict_arg)}}}", indent)) + elif dict_arg: + code.append(self._indent(f"{varname} = {{{', '.join(dict_arg)}}}", indent)) + elif t_options: + code.append(self._indent(f"{varname} = {self._compile_expr(t_options)}", indent)) + + return code + def _compile_directive_tag(self, el, options, indent): """Compile the element tag into a python code as a list of strings. @@ -1089,14 +1092,14 @@ class QWeb(object): expr = el.attrib.pop('t-raw') code = self._flushText(options, indent) - code_options = self._compile_options(el, 't_out_t_options', options, indent) + options['t_options_varname'] = 't_out_t_options' + code_options = self._compile_directive(el, options, 'options', indent) code.extend(code_options) if expr == "0": if code_options: code.append(self._indent("content = Markup(''.join(values.get('0', [])))", indent)) else: - code.extend(code_options) code.extend(self._compile_tag_open(el, options, indent)) code.extend(self._flushText(options, indent)) code.append(self._indent("yield from values.get('0', [])", indent)) @@ -1167,12 +1170,9 @@ class QWeb(object): record, field_name = expression.rsplit('.', 1) code = [] - code_options = self._compile_options(el, 't_field_t_options', options, indent) - if code_options: - code.extend(code_options) - else: - code.append(self._indent('t_field_t_options = {}', indent)) - + options['t_options_varname'] = 't_field_t_options' + code_options = self._compile_directive(el, options, 'options', indent) or [self._indent("t_field_t_options = {}", indent)] + code.extend(code_options) code.append(self._indent(f"attrs, content, force_display = self._get_field({self._compile_expr(record, raise_on_missing=True)}, {repr(field_name)}, {repr(expression)}, {repr(tagName)}, t_field_t_options, compile_options, values)", indent)) code.append(self._indent("content = self._compile_to_str(content)", indent)) code.extend(self._compile_widget_value(el, options, indent)) @@ -1237,7 +1237,8 @@ class QWeb(object): nsmap = options.get('nsmap') code = self._flushText(options, indent) - code_options = self._compile_options(el, 't_call_t_options', options, indent) + options['t_options_varname'] = 't_call_t_options' + code_options = self._compile_directive(el, options, 'options', indent) or [self._indent("t_call_t_options = {}", indent)] code.extend(code_options) # content (t-out="0" and variables) diff --git a/odoo/addons/base/tests/test_profiler.py b/odoo/addons/base/tests/test_profiler.py index 5d1dc32cbd9..a56a3ef5fdc 100644 --- a/odoo/addons/base/tests/test_profiler.py +++ b/odoo/addons/base/tests/test_profiler.py @@ -457,6 +457,89 @@ class TestProfiling(TransactionCase): self.assertEqual(stacks_lines[1][0] + 1, stacks_lines[3][0], "Call of b() in a() should be one line before call of c()") + def test_qweb_recorder(self): + template = self.env['ir.ui.view'].create({ + 'name': 'test', + 'type': 'qweb', + 'arch_db': ''' + + [: ] + + + ''' + }) + child_template = self.env['ir.ui.view'].create({ + 'name': 'test', + 'type': 'qweb', + 'arch_db': ' ' + }) + self.env.cr.execute("INSERT INTO ir_model_data(name, model, res_id, module)" + "VALUES ('dummy', 'ir.ui.view', %s, 'base')", [child_template.id]) + + values = {'add_one_query': lambda: self.env.cr.execute('SELECT id FROM ir_ui_view LIMIT 1') or 'query'} + result = u""" + [0: a query 3] + query + [1: b query 2] + query + [2: c query 1] + query + """ + + # test rendering without profiling + rendered = self.env['ir.qweb']._render(template.id, values) + self.assertEqual(rendered.strip(), result.strip(), 'Without profiling') + + # This rendering is used to cache the compiled template method so as + # not to have a number of requests that vary according to the modules + # installed. + with Profiler(description='test', collectors=['qweb'], db=None): + self.env['ir.qweb']._render(template.id, values) + + with Profiler(description='test', collectors=['qweb'], db=None) as p: + rendered = self.env['ir.qweb']._render(template.id, values) + # check if qweb is ok + self.assertEqual(rendered.strip(), result.strip()) + + # check if the arch of all used templates is includes in the result + self.assertEqual(p.collectors[0].entries[0]['results']['archs'], { + template.id: template.arch_db, + child_template.id: child_template.arch_db, + }) + + # check all directives without duration information + for data in p.collectors[0].entries[0]['results']['data']: + data.pop('delay') + + expected = [ + # pylint: disable=bad-whitespace + # first template and first directive + {'view_id': template.id, 'xpath': '/t/t', 'directive': """t-foreach="{'a': 3, 'b': 2, 'c': 1}" t-as='item'""", 'query': 0}, + # first pass in the loop + {'view_id': template.id, 'xpath': '/t/t/t[1]', 'directive': "t-esc='item_index'", 'query': 0}, + {'view_id': template.id, 'xpath': '/t/t/t[2]', 'directive': "t-call='base.dummy'", 'query': 0}, # the compiled template method is in cache + # first pass in the loop: content of the child template + {'view_id': child_template.id, 'xpath': '/t/span/t[1]', 'directive': "t-esc='item'", 'query': 0}, + {'view_id': child_template.id, 'xpath': '/t/span/t[2]', 'directive': "t-esc='add_one_query()'", 'query': 1}, + {'view_id': template.id, 'xpath': '/t/t/t[3]', 'directive': "t-esc='item_value'", 'query': 0}, + {'view_id': template.id, 'xpath': '/t/t/b', 'directive': "t-esc='add_one_query()'", 'query':1}, + # second pass in the loop + {'view_id': template.id, 'xpath': '/t/t/t[1]', 'directive': "t-esc='item_index'", 'query': 0}, + {'view_id': template.id, 'xpath': '/t/t/t[2]', 'directive': "t-call='base.dummy'", 'query': 0}, # 0 because the template is in cache + {'view_id': child_template.id, 'xpath': '/t/span/t[1]', 'directive': "t-esc='item'", 'query': 0}, + {'view_id': child_template.id, 'xpath': '/t/span/t[2]', 'directive': "t-esc='add_one_query()'", 'query': 1}, + {'view_id': template.id, 'xpath': '/t/t/t[3]', 'directive': "t-esc='item_value'", 'query': 0}, + {'view_id': template.id, 'xpath': '/t/t/b', 'directive': "t-esc='add_one_query()'", 'query':1}, + # third pass in the loop + {'view_id': template.id, 'xpath': '/t/t/t[1]', 'directive': "t-esc='item_index'", 'query': 0}, + {'view_id': template.id, 'xpath': '/t/t/t[2]', 'directive': "t-call='base.dummy'", 'query': 0}, + {'view_id': child_template.id, 'xpath': '/t/span/t[1]', 'directive': "t-esc='item'", 'query': 0}, + {'view_id': child_template.id, 'xpath': '/t/span/t[2]', 'directive': "t-esc='add_one_query()'", 'query': 1}, + {'view_id': template.id, 'xpath': '/t/t/t[3]', 'directive': "t-esc='item_value'", 'query': 0}, + {'view_id': template.id, 'xpath': '/t/t/b', 'directive': "t-esc='add_one_query()'", 'query':1}, + ] + self.assertEqual(p.collectors[0].entries[0]['results']['data'], expected) + def test_default_recorders(self): with Profiler(db=None) as p: queries_start = self.env.cr.sql_log_count diff --git a/odoo/addons/base/views/ir_profile_views.xml b/odoo/addons/base/views/ir_profile_views.xml index 1030c76fd9a..775610a58c9 100644 --- a/odoo/addons/base/views/ir_profile_views.xml +++ b/odoo/addons/base/views/ir_profile_views.xml @@ -39,6 +39,9 @@ + + + diff --git a/odoo/tools/profiler.py b/odoo/tools/profiler.py index 41c54baacc9..1ed51804533 100644 --- a/odoo/tools/profiler.py +++ b/odoo/tools/profiler.py @@ -9,6 +9,7 @@ import sys import time import threading import re +import functools from psycopg2 import sql @@ -272,6 +273,163 @@ class SyncCollector(Collector): super().post_process() +class QwebTracker(): + + @classmethod + def wrap_render(cls, method_render): + @functools.wraps(method_render) + def _tracked_method_render(self, template, values=None, **options): + current_thread = threading.current_thread() + execution_context_enabled = getattr(current_thread, 'profiler_params', {}).get('execution_context_qweb') + qweb_hooks = getattr(current_thread, 'qweb_hooks', ()) + if execution_context_enabled or qweb_hooks: + # To have the new compilation cached because the generated code will change. + # Therefore 'profile' is a key to the cache. + options['profile'] = True + return method_render(self, template, values, **options) + return _tracked_method_render + + @classmethod + def wrap_compile(cls, method_compile): + @functools.wraps(method_compile) + def _tracked_compile(self, template, options): + if not options.get('profile'): + return method_compile(self, template, options) + + render_template = method_compile(self, template, options) + def profiled_method_compile(self, values): + ref = options.get('ref') + ref_xml = options.get('ref_xml') + qweb_tracker = QwebTracker(ref, ref_xml, self.env.cr) + self = self.with_context(qweb_tracker=qweb_tracker) + if qweb_tracker.execution_context_enabled: + with ExecutionContext(template=ref): + return render_template(self, values) + return render_template(self, values) + return profiled_method_compile + return _tracked_compile + + @classmethod + def wrap_compile_directive(cls, method_compile_directive): + @functools.wraps(method_compile_directive) + def _tracked_compile_directive(self, el, options, directive, indent): + if not options.get('profile') or directive in ('content', 'tag'): + return method_compile_directive(self, el, options, directive, indent) + + enter = self._indent(f"self.env.context['qweb_tracker'].enter_directive({directive!r}, {el.attrib!r}, {options['last_path_node']!r})", indent) + leave = self._indent("self.env.context['qweb_tracker'].leave_directive()", indent) + code_directive = method_compile_directive(self, el, options, directive, indent) + return [enter, *code_directive, leave] if code_directive else [] + return _tracked_compile_directive + + def __init__(self, view_id, arch, cr): + current_thread = threading.current_thread() # don't store current_thread on self + self.execution_context_enabled = getattr(current_thread, 'profiler_params', {}).get('execution_context_qweb') + self.qweb_hooks = getattr(current_thread, 'qweb_hooks', ()) + self.context_stack = [] + self.cr = cr + self.view_id = view_id + for hook in self.qweb_hooks: + hook('render', self.cr.sql_log_count, view_id=view_id, arch=arch) + + def enter_directive(self, directive, attrib, xpath): + execution_context = None + if self.execution_context_enabled: + execution_context = tools.profiler.ExecutionContext(directive=directive, xpath=xpath) + execution_context.__enter__() + self.context_stack.append(execution_context) + + for hook in self.qweb_hooks: + hook('enter', self.cr.sql_log_count, view_id=self.view_id, xpath=xpath, directive=directive, attrib=attrib) + + def leave_directive(self): + if self.execution_context_enabled: + self.context_stack.pop().__exit__() + + for hook in self.qweb_hooks: + hook('leave', self.cr.sql_log_count) + + +class QwebCollector(Collector): + """ + Record qweb execution with directive trace. + """ + name = 'qweb' + + def __init__(self): + super().__init__() + self.events = [] + + def hook(event, sql_log_count, **kwargs): + self.events.append((event, kwargs, sql_log_count, time.time())) + self.hook = hook + + def _get_directive_profiling_name(self, directive, attrib): + expr = '' + if directive == 'set': + expr = f"t-set={repr(attrib['t-set'])}" + if 't-value' in attrib: + expr = f"{expr} t-value={repr(attrib['t-value'])}" + if 't-valuef' in attrib: + expr = f"{expr} t-valuef={repr(attrib['t-valuef'])}" + elif directive == 'foreach': + expr = f"t-foreach={repr(attrib['t-foreach'])} t-as={repr(attrib['t-as'])}" + elif directive == 'options': + if attrib.get('t-options'): + expr = f"t-options={repr(attrib['t-options'])}" + for key in list(attrib): + if key.startswith('t-options-'): + expr = f"{expr} {key}={repr(attrib[key])}" + elif directive and ('t-' + directive) in attrib: + expr = f"t-{directive}={repr(attrib['t-' + directive])}" + return expr + + def start(self): + init_thread = self.profiler.init_thread + if not hasattr(init_thread, 'qweb_hooks'): + init_thread.qweb_hooks = [] + init_thread.qweb_hooks.append(self.hook) + + def stop(self): + self.profiler.init_thread.qweb_hooks.remove(self.hook) + + def post_process(self): + last_event_query = None + last_event_time = None + stack = [] + results = [] + archs = {} + for event, kwargs, sql_count, time in self.events: + if event == 'render': + archs[kwargs['view_id']] = kwargs['arch'] + continue + + # update the active directive with the elapsed time and queries + if stack: + top = stack[-1] + top['delay'] += time - last_event_time + top['query'] += sql_count - last_event_query + last_event_time = time + last_event_query = sql_count + + if event == 'enter': + data = { + 'view_id': kwargs['view_id'], + 'xpath': kwargs['xpath'], + 'directive': self._get_directive_profiling_name(kwargs['directive'], kwargs['attrib']), + 'delay': 0, + 'query': 0, + } + results.append(data) + stack.append(data) + else: + assert event == "leave" + data = stack.pop() + + self.add({'results': {'archs': archs, 'data': results}}) + super().post_process() + + class ExecutionContext: """ Add some context on thread at current call stack level. @@ -349,6 +507,8 @@ class Profiler: frame = self.init_frame code = frame.f_code self.description = f"{frame.f_code.co_name} ({code.co_filename}:{frame.f_lineno})" + if self.params: + self.init_thread.profiler_params = self.params if self.disable_gc and gc.isenabled(): gc.disable() self.start_time = time.time() @@ -388,6 +548,8 @@ class Profiler: finally: if self.disable_gc: gc.enable() + if self.params: + del self.init_thread.profiler_params def _add_file_lines(self, stack): for index, frame in enumerate(stack):