[IMP] profiling: Add profile qweb execution into the performance tools.

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>
```

closes odoo/odoo#74712

Signed-off-by: Xavier Dollé (xdo) <xdo@odoo.com>
This commit is contained in:
Gorash
2021-09-08 10:21:42 +00:00
committed by Xavier-Do
parent dc1e9e6b4f
commit 4d0e111733
12 changed files with 770 additions and 74 deletions
@@ -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
@@ -2,42 +2,54 @@
<templates xml:space="preserve">
<t t-name="web.DebugMenu.ProfilingItem" owl="1">
<DropdownItem class="o_debug_profiling_item" payload="{}">
<span class="o_profiling_switch">
<span class="custom-control custom-switch" t-on-click.stop.prevent="profiling.toggleProfiling()">
<input type="checkbox" class="custom-control-input" id="enable_profiling" t-att-checked="profiling.state.isEnabled"/>
<label class="custom-control-label">
Enable profiling
<span t-if="profiling.state.isEnabled" class="profiling_items text-danger fa fa-circle"></span>
</label>
<DropdownItem payload="{}">
<div class="o_debug_profiling_item">
<span class="o_profiling_switch">
<span class="custom-control custom-switch" t-on-click.stop.prevent="profiling.toggleProfiling()">
<input type="checkbox" class="custom-control-input" id="enable_profiling" t-att-checked="profiling.state.isEnabled"/>
<label class="custom-control-label">
Enable profiling
<span t-if="profiling.state.isEnabled" class="profiling_items text-danger fa fa-circle"></span>
</label>
</span>
<i class="o_open_profiling float-right fa fa-list fa-lg" t-on-click="openProfiles"/>
</span>
<i class="o_open_profiling float-right fa fa-list fa-lg" t-on-click="openProfiles"/>
</span>
<t t-if="profiling.state.isEnabled">
<span class="o_profiling_switch custom-control custom-switch" t-on-click.stop.prevent="profiling.toggleCollector('sql')">
<input type="checkbox" class="custom-control-input" id="profile_sql"
t-att-checked="profiling.isCollectorEnabled('sql')"/>
<label class="custom-control-label" for="profile_sql">Record sql</label>
</span>
<span t-if="profiling.state.isEnabled" class="o_profiling_switch custom-control custom-switch" t-on-click.stop.prevent="profiling.toggleCollector('traces_async')">
<input type="checkbox" class="custom-control-input" id="profile_traces_async"
t-att-checked="profiling.isCollectorEnabled('traces_async')"/>
<label class="custom-control-label" for="profile_traces_async">Record traces</label>
</span>
<div t-if="profiling.isCollectorEnabled('traces_async')" class="input-group input-group-sm" t-on-click.stop.prevent="">
<div class="input-group-prepend">
<div class="input-group-text">Interval</div>
<t t-if="profiling.state.isEnabled">
<span class="o_profiling_switch custom-control custom-switch" t-on-click.stop.prevent="profiling.toggleCollector('sql')">
<input type="checkbox" class="custom-control-input" id="profile_sql"
t-att-checked="profiling.isCollectorEnabled('sql')"/>
<label class="custom-control-label" for="profile_sql">Record sql</label>
</span>
<span class="o_profiling_switch custom-control custom-switch" t-on-click.stop.prevent="profiling.toggleCollector('traces_async')">
<input type="checkbox" class="custom-control-input" id="profile_traces_async"
t-att-checked="profiling.isCollectorEnabled('traces_async')"/>
<label class="custom-control-label" for="profile_traces_async">Record traces</label>
</span>
<div t-if="profiling.isCollectorEnabled('traces_async')" class="input-group input-group-sm" t-on-click.stop.prevent="">
<div class="input-group-prepend">
<div class="input-group-text">Interval</div>
</div>
<select class="profile_param form-control" t-on-change="changeParam('traces_async_interval')">
<t t-set="interval" t-value="profiling.state.params.traces_async_interval"/>
<option value="">Default</option>
<option value="0.001" t-att-selected="interval === '0.001'">0.001</option>
<option value="0.01" t-att-selected="interval === '0.01'">0.01</option>
<option value="0.1" t-att-selected="interval === '0.1'">0.1</option>
<option value="1" t-att-selected="interval === '1'">1</option>
</select>
</div>
<select class="profile_param form-control" t-on-change="changeParam('traces_async_interval')">
<t t-set="interval" t-value="profiling.state.params.traces_async_interval"/>
<option value="">Default</option>
<option value="0.001" t-att-selected="interval === '0.001'">0.001</option>
<option value="0.01" t-att-selected="interval === '0.01'">0.01</option>
<option value="0.1" t-att-selected="interval === '0.1'">0.1</option>
<option value="1" t-att-selected="interval === '1'">1</option>
</select>
</div>
</t>
<span t-if="profiling.isCollectorEnabled('sql') || profiling.isCollectorEnabled('traces_async')" class="o_profiling_switch custom-control custom-switch" t-on-click.stop.prevent="toggleParam('execution_context_qweb')">
<input type="checkbox" class="custom-control-input" id="profile_execution_context_qweb"
t-att-checked="!!profiling.state.params.execution_context_qweb"/>
<label class="custom-control-label" for="profile_execution_context_qweb">Add qweb directive context</label>
</span>
<span class="o_profiling_switch custom-control custom-switch" t-on-click.stop.prevent="profiling.toggleCollector('qweb')">
<input type="checkbox" class="custom-control-input" id="profile_qweb"
t-att-checked="profiling.isCollectorEnabled('qweb')"/>
<label class="custom-control-label" for="profile_qweb">Record qweb</label>
</span>
</t>
</div>
</DropdownItem>
</t>
@@ -0,0 +1,57 @@
<?xml version="1.0" encoding="UTF-8"?>
<templates xml:space="preserve">
<t t-name="web.ProfilingQwebView">
<div class="oe_form_field o_ace_view_editor oe_ace_open o_profiling_qweb_view">
<div class="o_select_view_profiling">
<a role="button" class="dropdown-toggle" data-toggle="dropdown" aria-expanded="false" href="#"></a>
<div class="dropdown-menu" role="menu">
<t t-foreach="widget.views" t-as="view">
<a role="menuitem" href="#" t-att-data-id="view.id">
<div class="o_delay"><t t-if="view.delay" t-esc="view.delay"/> ms</div>
<div class="o_query"><t t-if="view.delay" t-esc="view.query"/> query</div>
<t t-esc="view.display_name"/>
<div class="o_key text-muted">(<t t-esc="view.id"/>, <t t-esc="view.key"/>)</div>
</a>
</t>
</div>
</div>
<div class="ace-view-editor"/>
<small class="text-muted">
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.
</small>
</div>
</t>
<t t-name="web.ProfilingQwebView.hover">
<div class="o_info o_detail">
<div class="o_delay"><t t-esc="delay"/> <span>ms</span></div>
<div class="o_query"><t t-esc="query"/> <span>query</span></div>
</div>
</t>
<t t-name="web.ProfilingQwebView.info">
<div class="o_info">
<div t-if="detail" class="o_more">
<span>*</span>
<table class="o_detail">
<thead>
<tr><th></th><th>ms</th><th>query</th></tr>
</thead>
<tbody>
<tr t-foreach="groups" t-as="directive">
<td><t t-esc="directive"/></td>
<td><t t-esc="groups[directive].delays.join(' ')"/></td>
<td><t t-esc="groups[directive].querys.join(' ')"/></td>
</tr>
</tbody>
</table>
</div>
<div class="o_delay"><t t-esc="delay"/></div>
<div class="o_query"><t t-esc="query"/></div>
</div>
</t>
</templates>
@@ -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);
});
@@ -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;
}
}
}
@@ -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;
+1
View File
@@ -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')
+8 -2
View File
@@ -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.
+35 -34
View File
@@ -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)
+83
View File
@@ -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': '''<t t-name="root">
<t t-foreach="{'a': 3, 'b': 2, 'c': 1}" t-as="item">
[<t t-esc="item_index"/>: <t t-call="base.dummy"/> <t t-esc="item_value"/>]
<b t-esc="add_one_query()"/>
</t>
</t>'''
})
child_template = self.env['ir.ui.view'].create({
'name': 'test',
'type': 'qweb',
'arch_db': '<t t-name="dummy"><span><t t-esc="item"/> <t t-esc="add_one_query()"/></span></t>'
})
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: <span>a query</span> 3]
<b>query</b>
[1: <span>b query</span> 2]
<b>query</b>
[2: <span>c query</span> 1]
<b>query</b>
"""
# 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
@@ -39,6 +39,9 @@
<field name="entry_count"/>
<field name="speedscope_url" widget="url"/>
</group>
<group attrs="{'invisible': [('qweb','=', '')]}">
<field name="qweb" widget="profiling_qweb_view" nolabel="1"/>
</group>
</form>
</field>
</record>
+162
View File
@@ -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):