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):