diff --git a/addons/web/static/src/js/fields/basic_fields.js b/addons/web/static/src/js/fields/basic_fields.js
index a3313269ce9..8c3072c267a 100644
--- a/addons/web/static/src/js/fields/basic_fields.js
+++ b/addons/web/static/src/js/fields/basic_fields.js
@@ -1732,7 +1732,7 @@ var UrlWidget = InputField.extend({
}
let href = this.value;
if (this.value && !this.websitePath) {
- const regex = /^(?:[fF]|[hH][tT])[tT][pP][sS]?:\/\//;
+ const regex = /^((ftp|http)s?:\/)?\//i; // http(s)://... ftp(s)://... /...
href = !regex.test(this.value) ? `http://${href}` : href;
}
this.el.classList.add("o_form_uri", "o_text_overflow");
diff --git a/odoo/addons/base/__manifest__.py b/odoo/addons/base/__manifest__.py
index 87c59505a57..bc6d8fc01ae 100644
--- a/odoo/addons/base/__manifest__.py
+++ b/odoo/addons/base/__manifest__.py
@@ -63,6 +63,7 @@ The kernel of Odoo, needed for all installation.
'wizard/base_partner_merge_views.xml',
'data/ir_actions_data.xml',
'data/ir_demo_failure_data.xml',
+ 'views/ir_profile_views.xml',
'views/res_company_views.xml',
'views/res_lang_views.xml',
'views/res_partner_views.xml',
diff --git a/odoo/addons/base/models/__init__.py b/odoo/addons/base/models/__init__.py
index 3c39ad85530..b3d7f66202d 100644
--- a/odoo/addons/base/models/__init__.py
+++ b/odoo/addons/base/models/__init__.py
@@ -33,6 +33,7 @@ from . import ir_demo_failure
from . import report_layout
from . import report_paperformat
+from . import ir_profile
from . import image_mixin
from . import avatar_mixin
diff --git a/odoo/addons/base/models/ir_profile.py b/odoo/addons/base/models/ir_profile.py
new file mode 100644
index 00000000000..1a9b100a95a
--- /dev/null
+++ b/odoo/addons/base/models/ir_profile.py
@@ -0,0 +1,52 @@
+# -*- coding: utf-8 -*-
+# Part of Odoo. See LICENSE file for full copyright and licensing details.
+
+import json
+import base64
+import datetime
+
+from odoo import fields, models, api
+from odoo.exceptions import UserError
+from odoo.http import request
+from odoo.tools.profiler import make_session
+from odoo.tools.speedscope import Speedscope
+
+
+class IrProfile(models.Model):
+ _name = 'ir.profile'
+ _description = 'Profiling results'
+ _log_access = False # avoid useless foreign key on res_user
+ _order = 'session desc, id desc'
+
+ create_date = fields.Datetime('Creation Date')
+
+ session = fields.Char('Session', index=True)
+ name = fields.Char('Description')
+ duration = fields.Float('Duration')
+
+ init_stack_trace = fields.Text('Initial stack trace', prefetch=False)
+
+ sql = fields.Text('Sql', prefetch=False)
+ traces_async = fields.Text('Traces Async', prefetch=False)
+ traces_sync = fields.Text('Traces Sync', prefetch=False)
+
+ speedscope = fields.Binary('Speedscope', compute='_compute_speedscope')
+
+ @api.autovacuum
+ def _gc_profile(self):
+ # remove profiles older than 30 days
+ domain = [('create_date', '<', fields.Datetime.now() - datetime.timedelta(days=30))]
+ return self.sudo().search(domain).unlink()
+
+ def _compute_speedscope(self):
+ for execution in self:
+ sp = Speedscope(init_stack_trace=json.loads(execution.init_stack_trace))
+ if execution.sql:
+ sp.add('sql', json.loads(execution.sql))
+ if execution.traces_async:
+ sp.add('frames', json.loads(execution.traces_async))
+ if execution.traces_sync:
+ sp.add('settrace', json.loads(execution.traces_sync))
+
+ result = json.dumps(sp.add_default().make())
+ execution.speedscope = base64.b64encode(result.encode('utf-8'))
diff --git a/odoo/addons/base/security/ir.model.access.csv b/odoo/addons/base/security/ir.model.access.csv
index 0908b667918..581755cea21 100644
--- a/odoo/addons/base/security/ir.model.access.csv
+++ b/odoo/addons/base/security/ir.model.access.csv
@@ -121,3 +121,4 @@
"access_base_update_translations","access.base.update.translations","model_base_update_translations","base.group_system",1,1,1,0
"access_base_partner_merge_line","access.base.partner.merge.line","model_base_partner_merge_line","base.group_partner_manager",1,1,1,0
"access_base_partner_merge_automatic_wizard","access.base.partner.merge.automatic.wizard","model_base_partner_merge_automatic_wizard","base.group_partner_manager",1,1,1,0
+"access_ir_profile","ir_profile","model_ir_profile","group_system",1,1,1,1
diff --git a/odoo/addons/base/tests/__init__.py b/odoo/addons/base/tests/__init__.py
index cade7f5db65..03928fcee45 100644
--- a/odoo/addons/base/tests/__init__.py
+++ b/odoo/addons/base/tests/__init__.py
@@ -45,4 +45,5 @@ from . import test_reports
from . import test_tests_tags
from . import test_form_create
from . import test_cloc
+from . import test_profiler
from . import test_pdf
diff --git a/odoo/addons/base/tests/test_profiler.py b/odoo/addons/base/tests/test_profiler.py
new file mode 100644
index 00000000000..9264fdda559
--- /dev/null
+++ b/odoo/addons/base/tests/test_profiler.py
@@ -0,0 +1,367 @@
+# -*- coding: utf-8 -*-
+# Part of Odoo. See LICENSE file for full copyright and licensing details.
+import time
+
+from odoo.exceptions import AccessError
+from odoo.tests.common import BaseCase, TransactionCase, tagged, new_test_user
+from odoo.tools import profiler
+from odoo.tools.profiler import Profiler, ExecutionContext
+from odoo.tools.speedscope import Speedscope
+
+
+@tagged('post_install', '-at_install', 'profiling')
+# post_install to ensure mail is already loaded if installed (new_test_user would fail otherwise because of notification_type)
+class TestProfileAccess(TransactionCase):
+
+ @classmethod
+ def setUpClass(cls):
+ super().setUpClass()
+ cls.test_profile = cls.env['ir.profile'].create({})
+
+ def test_admin_has_access(self):
+ self.assertEqual(self.env['ir.profile'].search([('id', '=', self.test_profile.id)]), self.test_profile)
+ self.test_profile.read(['name'])
+
+ def test_user_no_access(self):
+ user = new_test_user(self.env, login='noProfile', groups='base.group_user')
+ with self.with_user('noProfile'), self.assertRaises(AccessError):
+ self.env['ir.profile'].search([])
+ with self.assertRaises(AccessError):
+ self.test_profile.with_user(user).read(['name'])
+
+
+@tagged('post_install', '-at_install', 'profiling')
+class TestSpeedscope(BaseCase):
+ def example_profile(self):
+ return {
+ 'init_stack_trace': [['/path/tp/file_1.py', 135, '__main__', 'main()']],
+ 'result': [{ # init frame
+ 'start': 2.0,
+ 'context': {},
+ 'stack': [
+ ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'],
+ ['/path/to/file_1.py', 101, 'do_stuff1', 'cr.execute(query, params)'],
+ ],
+ }, {
+ 'start': 3.0,
+ 'context': {},
+ 'stack': [
+ ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'],
+ ['/path/to/file_1.py', 101, 'do_stuff1', 'cr.execute(query, params)'],
+ ['/path/to/sql_db.py', 650, 'execute', 'res = self._obj.execute(query, params)'],
+ ],
+ }, { # duplicate frame
+ 'start': 4.0,
+ 'context': {},
+ 'stack': [
+ ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'],
+ ['/path/to/file_1.py', 101, 'do_stuff1', 'cr.execute(query, params)'],
+ ['/path/to/sql_db.py', 650, 'execute', 'res = self._obj.execute(query, params)'],
+ ],
+ }, { # other frame
+ 'start': 6.0,
+ 'context': {},
+ 'stack': [
+ ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'],
+ ['/path/to/file_1.py', 101, 'do_stuff1', 'check'],
+ ['/path/to/sql_db.py', 650, 'check', 'assert x = y'],
+ ],
+ }, { # out of frame
+ 'start': 10.0,
+ 'context': {},
+ 'stack': [
+ ['/path/tp/file_1.py', 10, 'main', 'do_stuff1(test=do_tests)'],
+ ['/path/to/file_1.py', 101, 'do_stuff1', 'for i in range(10):'],
+ ],
+ }, { # final frame
+ 'start': 10.35,
+ 'context': {},
+ 'stack': None,
+ }],
+ }
+
+ def test_convert_empty(self):
+ Speedscope().make()
+
+ def test_converts_profile_simple(self):
+ profile = self.example_profile()
+
+ sp = Speedscope(init_stack_trace=profile['init_stack_trace'])
+ sp.add('profile', profile['result'])
+ sp.add_output(['profile'], complete=False)
+ res = sp.make()
+
+ frames = res['shared']['frames']
+ self.assertEqual(len(frames), 4)
+
+ profile_combined = res['profiles'][0]
+ events = [(e['type'], e['frame']) for e in profile_combined['events']]
+ self.assertEqual(events, [
+ ('O', 0), # /main
+ ('O', 1), # /main/do_stuff1
+ ('O', 2), # /main/do_stuff1/execute
+ ('C', 2), # /main/do_stuff1
+ ('O', 3), # /main/do_stuff1/check
+ ('C', 3), # /main/do_stuff1
+ ('C', 1), # /main
+ ('C', 0), # /
+ ])
+ self.assertEqual(profile_combined['events'][0]['at'], 0.0)
+ self.assertEqual(profile_combined['events'][-1]['at'], 8.35)
+
+ def test_converts_profile_no_end(self):
+ profile = self.example_profile()
+ profile['result'].pop()
+
+ sp = Speedscope(init_stack_trace=profile['init_stack_trace'])
+ sp.add('profile', profile['result'])
+ sp.add_output(['profile'], complete=False)
+ res = sp.make()
+ profile_combined = res['profiles'][0]
+ events = [(e['type'], e['frame']) for e in profile_combined['events']]
+
+ self.assertEqual(events, [
+ ('O', 0), # /main
+ ('O', 1), # /main/do_stuff1
+ ('O', 2), # /main/do_stuff1/execute
+ ('C', 2), # /main/do_stuff1
+ ('O', 3), # /main/do_stuff1/check
+ ('C', 3), # /main/do_stuff1
+ ('C', 1), # /main
+ ('C', 0), # /
+ ])
+ self.assertEqual(profile_combined['events'][-1]['at'], 8)
+
+ def test_converts_init_stack_trace(self):
+ profile = self.example_profile()
+
+ sp = Speedscope(init_stack_trace=profile['init_stack_trace'])
+ sp.add('profile', profile['result'])
+ sp.add_output(['profile'], complete=True)
+ res = sp.make()
+
+ profile_combined = res['profiles'][0]
+ events = [(e['type'], e['frame']) for e in profile_combined['events']]
+
+ self.assertEqual(events, [
+ ('O', 4), # /__main__/
+ ('O', 0), # /__main__/main
+ ('O', 1), # /__main__/main/do_stuff1
+ ('O', 2), # /__main__/main/do_stuff1/execute
+ ('C', 2), # /__main__/main/do_stuff1
+ ('O', 3), # /__main__/main/do_stuff1/check
+ ('C', 3), # /__main__/main/do_stuff1
+ ('C', 1), # /__main__/main
+ ('C', 0), # /__main__/
+ ('C', 4), # /
+ ])
+ self.assertEqual(profile_combined['events'][-1]['at'], 8.35)
+
+ def test_end_priority(self):
+ """
+ If a sample as a time (usually a query) we expect to keep the complete frame
+ even if another concurent frame tics before the end of the current one:
+ frame duration should always be more reliable.
+ """
+
+ async_profile = self.example_profile()['result']
+ sql_profile = self.example_profile()['result']
+ # make sql_profile a single frame from 2.5 to 5.5
+ sql_profile = [sql_profile[1]]
+ sql_profile[0]['start'] = 2.5
+ sql_profile[0]['time'] = 3
+ sql_profile[0]['query'] = 'SELECT 1'
+ sql_profile[0]['full_query'] = 'SELECT 1'
+ # some check to ensure the take makes sence
+ self.assertEqual(async_profile[1]['start'], 3)
+ self.assertEqual(async_profile[2]['start'], 4)
+
+ self.assertNotIn('query', async_profile[1]['stack'])
+ self.assertNotIn('time', async_profile[1]['stack'])
+ self.assertEqual(async_profile[1]['stack'], async_profile[2]['stack'])
+ # this last assertion is not really usefull but ensure that the samples are consistent with the sql one, just missing que query
+
+ sp = Speedscope(init_stack_trace=[])
+ sp.add('sql', async_profile)
+ sp.add('traces', sql_profile)
+ sp.add_output(['sql', 'traces'], complete=False)
+ res = sp.make()
+ profile_combined = res['profiles'][0]
+ events = [(e['at']+2, e['type'], res['shared']['frames'][e['frame']]['name']) for e in profile_combined['events']]
+ self.assertEqual(events, [
+ (2.0, 'O', 'main'),
+ (2.0, 'O', 'do_stuff1'),
+ (2.5, 'O', 'execute'),
+ (2.5, 'O', "sql('SELECT 1')"),
+ (5.5, 'C', "sql('SELECT 1')"), # select ends at 5.5 as expected despite another concurent frame at 3 and 4
+ (5.5, 'C', 'execute'),
+ (6.0, 'O', 'check'),
+ (10.0, 'C', 'check'),
+ (10.35, 'C', 'do_stuff1'),
+ (10.35, 'C', 'main'),
+ ])
+
+
+@tagged('post_install', '-at_install', 'profiling')
+class TestProfiling(TransactionCase):
+
+ def test_default_values(self):
+ p = Profiler()
+ self.assertEqual(p.db, self.env.cr.dbname)
+
+ def test_env_profiler_database(self):
+ p = Profiler(collectors=[])
+ self.assertEqual(p.db, self.env.cr.dbname)
+
+ def test_env_profiler_description(self):
+ with Profiler(collectors=[], db=None) as p:
+ self.assertIn('test_env_profiler_description', p.description)
+
+ def test_execution_context_save(self):
+ with Profiler(db=None, collectors=['sql']) as p:
+ for letter in ('a', 'b'):
+ stack_level = profiler.stack_size()
+ with ExecutionContext(letter=letter):
+ self.env.cr.execute('SELECT 1')
+ stack_level = profiler.stack_size()
+ entries = p.collectors[0].entries
+ self.assertEqual(entries[0]['exec_context'][stack_level], {'letter': 'a'})
+ self.assertEqual(entries[1]['exec_context'][stack_level], {'letter': 'b'})
+
+ def test_sync_recorder(self):
+ def a():
+ b()
+ c()
+
+ def b():
+ pass
+
+ def c():
+ d()
+ d()
+
+ def d():
+ pass
+
+ with Profiler(description='test', collectors=['traces_sync'], db=None) as p:
+ a()
+
+ stacks = [r['stack'] for r in p.collectors[0].entries]
+
+ # map stack frames to their function name, and check
+ stacks_methods = [[frame[2] for frame in stack] for stack in stacks]
+ self.assertEqual(stacks_methods, [
+ ['a'],
+ ['a', 'b'],
+ ['a'],
+ ['a', 'c'],
+ ['a', 'c', 'd'],
+ ['a', 'c'],
+ ['a', 'c', 'd'],
+ ['a', 'c'],
+ ['a'],
+ [],
+ ['__exit__'],
+ ['__exit__', 'stop'] # could be removed by cleaning two last frames, or removing last frames only contained in profiler.py
+ ])
+
+ # map stack frames to their line number, and check
+ stacks_lines = [[frame[1] for frame in stack] for stack in stacks]
+ 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_default_recorders(self):
+ with Profiler(db=None) as p:
+ queries_start = self.env.cr.sql_log_count
+ for i in range(10):
+ self.env['res.partner'].create({'name': 'snail%s' % i})
+ self.env['res.partner'].flush()
+ total_queries = self.env.cr.sql_log_count - queries_start
+
+ rq = next(r for r in p.collectors if r.name == "sql").entries
+ self.assertEqual(p.init_stack_trace[-1][2], 'test_default_recorders')
+ self.assertEqual(p.init_stack_trace[-1][0].split('/')[-1], 'test_profiler.py')
+
+ self.assertEqual(len(rq), total_queries)
+ first_query = rq[0]
+ self.assertEqual(first_query['stack'][0][2], 'create')
+ #self.assertIn("self.env['res.partner'].create({", first_query['stack'][0][3])
+
+ self.assertGreater(first_query['time'], 0)
+ self.assertEqual(first_query['stack'][-1][2], 'execute')
+ self.assertEqual(first_query['stack'][-1][0].split('/')[-1], 'sql_db.py')
+
+
+def deep_call(func, depth):
+ """ Call the given function at the given call depth. """
+ if depth > 0:
+ deep_call(func, depth - 1)
+ else:
+ func()
+
+
+@tagged('-standard', 'profiling_performance')
+class TestPerformance(BaseCase):
+
+ def test_collector_max_frequency(self):
+ """
+ Check the creation time of an entry
+ """
+ collector = profiler.Collector()
+ p = Profiler(collectors=[collector], db=None)
+
+ def collect():
+ collector.add()
+
+ # collect on changing stack
+ with p:
+ start = time.time()
+ while start + 1 > time.time():
+ deep_call(collect, 20)
+
+ self.assertGreater(len(collector.entries), 20000) # ~40000
+
+ # collect on identical stack
+ collector = profiler.Collector()
+ p = Profiler(collectors=[collector], db=None)
+
+ def collect_1_s():
+ start = time.time()
+ while start + 1 > time.time():
+ collector.add()
+
+ with p:
+ deep_call(collect_1_s, 20)
+
+ self.assertGreater(len(collector.entries), 50000) # ~70000
+
+ def test_frequencies_1ms_sleep(self):
+ """
+ Check the number of entries generated in 1s at 1kHz
+ we need to artificially change the frame as often as possible to avoid
+ triggering the memory optimisation skipping identical frames
+ """
+ def sleep_1():
+ time.sleep(0.0001)
+
+ def sleep_2():
+ time.sleep(0.0001)
+
+ with Profiler(collectors=['traces_async'], db=None) as res:
+ start = time.time()
+ while start + 1 > time.time():
+ sleep_1()
+ sleep_2()
+
+ entry_count = len(res.collectors[0].entries)
+ self.assertGreater(entry_count, 700) # ~920
+
+ def test_traces_async_memory_optimisation(self):
+ """
+ Identical frames should be saved only once.
+ We should only have a few entries on a 1 second sleep.
+ """
+ with Profiler(collectors=['traces_async'], db=None) as res:
+ time.sleep(1)
+ entry_count = len(res.collectors[0].entries)
+ self.assertLess(entry_count, 5) # ~3
diff --git a/odoo/addons/base/views/ir_profile_views.xml b/odoo/addons/base/views/ir_profile_views.xml
new file mode 100644
index 00000000000..0d080066cbf
--- /dev/null
+++ b/odoo/addons/base/views/ir_profile_views.xml
@@ -0,0 +1,56 @@
+
+
+
+
+ IR Profile Search
+ ir.profile
+
+
+
+
+
+
+
+
+
+
+ IR Profile List
+ ir.profile
+
+
+
+
+
+
+
+
+
+
+
+ IR Profile Form
+ ir.profile
+
+
+
+
+
+
+
+
+
+
diff --git a/odoo/sql_db.py b/odoo/sql_db.py
index 5c1536c087f..bfd1f582035 100644
--- a/odoo/sql_db.py
+++ b/odoo/sql_db.py
@@ -284,6 +284,10 @@ class Cursor(BaseCursor):
_logger.warning(msg)
self._close(True)
+ def _format(self, query, params=None):
+ encoding = psycopg2.extensions.encodings[self.connection.encoding]
+ return self._obj.mogrify(query, params).decode(encoding, 'replace')
+
@check
def execute(self, query, params=None, log_exceptions=None):
if params and not isinstance(params, (tuple, list, dict)):
@@ -291,9 +295,8 @@ class Cursor(BaseCursor):
raise ValueError("SQL query parameters should be a tuple, list or dict; got %r" % (params,))
if self.sql_log:
- encoding = psycopg2.extensions.encodings[self.connection.encoding]
- _logger.debug("query: %s", self._obj.mogrify(query, params).decode(encoding, 'replace'))
- now = time.time()
+ _logger.debug("query: %s", self._format(query, params))
+ start = time.time()
try:
params = params or None
res = self._obj.execute(query, params)
@@ -304,10 +307,15 @@ class Cursor(BaseCursor):
# simple query count is always computed
self.sql_log_count += 1
- delay = (time.time() - now)
- if hasattr(threading.current_thread(), 'query_count'):
- threading.current_thread().query_count += 1
- threading.current_thread().query_time += delay
+ delay = (time.time() - start)
+ current_thread = threading.current_thread()
+ if hasattr(current_thread, 'query_count'):
+ current_thread.query_count += 1
+ current_thread.query_time += delay
+
+ # optional hooks for performance and tracing analysis
+ for hook in getattr(current_thread, 'query_hooks', ()):
+ hook(self, query, params, start, delay)
# advanced stats only if sql_log is enabled
if self.sql_log:
diff --git a/odoo/tests/common.py b/odoo/tests/common.py
index 7f9ae17b0ed..74e27421a97 100644
--- a/odoo/tests/common.py
+++ b/odoo/tests/common.py
@@ -47,7 +47,7 @@ from odoo.models import BaseModel
from odoo.osv.expression import normalize_domain, TRUE_LEAF, FALSE_LEAF
from odoo.service import security
from odoo.sql_db import Cursor
-from odoo.tools import float_compare, single_email_re
+from odoo.tools import float_compare, single_email_re, profiler
from odoo.tools.misc import find_in_path
from odoo.tools.safe_eval import safe_eval
@@ -657,6 +657,15 @@ class BaseCase(unittest.TestCase, metaclass=MetaCase):
def assertHTMLEqual(self, original, expected):
return self._assertXMLEqual(original, expected, 'html')
+ def profile(self, **kwargs):
+ test_method = getattr(self, '_testMethodName', 'Unknown test method')
+ if not hasattr(self, 'profile_session'):
+ self.profile_session = profiler.make_session(test_method)
+ return profiler.Profiler(
+ description='%s %s %s' % (test_method, self.env.user.name, 'warm' if self.warm else 'cold'),
+ db=self.env.cr.dbname,
+ profile_session=self.profile_session,
+ **kwargs)
savepoint_seq = itertools.count()
diff --git a/odoo/tools/profiler.py b/odoo/tools/profiler.py
index 85d4f00b633..f7b3d571295 100644
--- a/odoo/tools/profiler.py
+++ b/odoo/tools/profiler.py
@@ -1,197 +1,405 @@
# -*- coding: utf-8 -*-
-from decorator import decorator
-import inspect
+# Part of Odoo. See LICENSE file for full copyright and licensing details.
+
+import datetime
+import gc
+import json
import logging
+import os
import sys
import time
+import threading
+import re
+
+from psycopg2 import sql
+
+from odoo import tools
-import odoo
_logger = logging.getLogger(__name__)
-class _LogTracer(object):
- def __init__(self, whitelist=None, blacklist=None, files=None, deep=False):
- self.profiles = {}
- self.whitelist = whitelist
- self.blacklist = blacklist
- self.files = files
- self.deep = deep
- self.first_frame = None
+def _format_frame(frame):
+ code = frame.f_code
+ return (code.co_filename, frame.f_lineno, code.co_name, '')
- def tracer(self, frame, event, arg):
- if not self.first_frame:
- self.first_frame = frame.f_code
- if not self.deep and self.first_frame != frame.f_code:
- return self.tracer
- if frame.f_code.co_name in ['', '__getattr__', '__iter__', '__init__']:
- return
+def _format_stack(stack):
+ return [list(frame) for frame in stack]
- if 'self' not in frame.f_locals:
- return self.tracer
- if self.files and frame.f_code.co_filename not in self.files:
- return self.tracer
+def get_current_frame(thread=None):
+ if thread:
+ frame = sys._current_frames()[thread.ident]
+ else:
+ frame = sys._getframe()
+ while frame.f_code.co_filename == __file__:
+ frame = frame.f_back
+ return frame
- in_self = frame.f_locals['self']
- if not isinstance(in_self, odoo.models.BaseModel):
- return self.tracer
+def _get_stack_trace(frame, limit_frame=None):
+ stack = []
+ while frame is not None and frame != limit_frame:
+ stack.append(_format_frame(frame))
+ frame = frame.f_back
+ if frame is None and limit_frame:
+ _logger.error("Limit frame was not found")
+ return list(reversed(stack))
- model = getattr(in_self, '_name', None)
- if self.whitelist and model not in self.whitelist:
- return self.tracer
- if model in self.blacklist and self.first_frame != frame.f_code:
- return self.tracer
+def stack_size():
+ frame = get_current_frame()
+ size = 0
+ while frame:
+ size += 1
+ frame = frame.f_back
+ return size
- if frame.f_code not in self.profiles:
- try:
- lines, firstline = inspect.getsourcelines(frame)
- self.profiles[frame.f_code] = {
- 'model': model,
- 'filename': frame.f_code.co_filename,
- 'firstline': firstline,
- 'code': lines,
- 'calls': [],
- 'nb': 0,
- }
- except Exception:
- return
- codeProfile = self.profiles[frame.f_code]
- if not frame.f_lineno:
- codeProfile['nb'] += 1
+def make_session(name=''):
+ return f'{datetime.datetime.now():%Y-%m-%d %H:%M:%S} {name}'
- cr = getattr(in_self, '_cr', None)
- codeProfile['calls'].append({
- 'event': event,
- 'lineno': frame.f_lineno,
- 'queries': cr and cr.sql_log_count,
- 'time': time.time(),
- 'callno': codeProfile['nb'],
+
+class Collector:
+ """
+ Base class for objects that collect profiling data.
+
+ A collector object is used by a profiler to collect profiling data, most
+ likely a list of stack traces with time and some context information added
+ by ExecutionContext decorator on current thread.
+
+ This is a generic implementation of a basic collector, to be inherited.
+ It defines default behaviors for creating an entry in the collector.
+ """
+ name = None # symbolic name of the collector
+ _registry = {} # map collector names to their class
+
+ @classmethod
+ def __init_subclass__(cls):
+ if cls.name:
+ cls._registry[cls.name] = cls
+ cls._registry[cls.__name__] = cls
+
+ @classmethod
+ def make(cls, name, *args, **kwargs):
+ """ Instantiate a collector corresponding to the given name. """
+ return cls._registry[name](*args, **kwargs)
+
+ def __init__(self):
+ self._processed = False
+ self._entries = []
+ self.profiler = None
+
+ def start(self):
+ """ Start the collector. """
+
+ def stop(self):
+ """ Stop the collector. """
+
+ def add(self, entry=None, frame=None):
+ """ Add an entry (dict) to this collector. """
+ # todo add entry count limit
+ self._entries.append({
+ 'stack': self._get_stack_trace(frame),
+ # make a copy of the current context, because it will change
+ 'exec_context': dict(getattr(self.profiler.init_thread, 'exec_context', ())),
+ 'start': time.time(),
+ **(entry or {}),
})
- return self.tracer
+ def _get_stack_trace(self, frame=None):
+ """ Return the stack trace to be included in a given entry. """
+ frame = frame or get_current_frame(self.profiler.init_thread)
+ return _get_stack_trace(frame, self.profiler.init_frame)
-def profile(method=None, whitelist=None, blacklist=(None,), files=None,
- minimum_time=0, minimum_queries=0):
+ def post_process(self):
+ for entry in self._entries:
+ stack = entry.get('stack', [])
+ self.profiler._add_file_lines(stack)
+
+ @property
+ def entries(self):
+ """ Return the entries of the collector after postprocessing. """
+ if not self._processed:
+ self.post_process()
+ self._processed = True
+ return self._entries
+
+
+class SQLCollector(Collector):
"""
- Decorate an entry point method.
- If profile is used without params, log as shallow mode else, log
- all methods for all odoo models by applying the optional filters.
-
- :param whitelist: None or list of model names to display in the log
- (Default: None)
- :type whitelist: list or None
- :param files: None or list of filenames to display in the log
- (Default: None)
- :type files: list or None
- :param list blacklist: list model names to remove from the log
- (Default: remove non odoo model from the log: [None])
- :param int minimum_time: minimum time (ms) to display a method
- (Default: 0)
- :param int minimum_queries: minimum sql queries to display a method
- (Default: 0)
-
- .. code-block:: python
-
- from odoo.tools.profiler import profile
-
- class SaleOrder(models.Model):
- ...
-
- @api.model
- @profile # log only this create method
- def create(self, vals):
- ...
- @profile() # log all methods for all odoo models
- def unlink(self):
- ...
- @profile(whitelist=['sale.order', 'ir.model.data'])
- def action_quotation_send(self):
- ...
- @profile(files=['/home/openerp/odoo/odoo/addons/sale/models/sale.py'])
- def write(self):
- ...
-
- NB: The use of the profiler modifies the execution time
+ Saves all executed queries in the current thread with the call stack.
"""
+ name = 'sql'
- deep = not method
+ def start(self):
+ init_thread = self.profiler.init_thread
+ if not hasattr(init_thread, 'query_hooks'):
+ init_thread.query_hooks = []
+ init_thread.query_hooks.append(self.hook)
- def _odooProfile(method, *args, **kwargs):
- log_tracer = _LogTracer(whitelist=whitelist, blacklist=blacklist, files=files, deep=deep)
- sys.settrace(log_tracer.tracer)
+ def stop(self):
+ self.profiler.init_thread.query_hooks.remove(self.hook)
+
+ def hook(self, cr, query, params, query_start, query_time):
+ self.add({
+ 'query': str(query),
+ 'full_query': str(cr._format(query, params)),
+ 'start': query_start,
+ 'time': query_time,
+ })
+
+
+class PeriodicCollector(Collector):
+ """
+ Record execution frames asynchronously at most every `interval` seconds.
+
+ :param interval (float): time to wait in seconds between two samples.
+ """
+ name = 'traces_async'
+
+ def __init__(self, interval=0.01): # check duration. dynamic?
+ super().__init__()
+ self.active = False
+ self.frame_interval = interval
+ self.thread = threading.Thread(target=self.run)
+ self.last_frame = None
+
+ def run(self):
+ self.active = True
+ while self.active: # maybe add a check on parent_thread state?
+ self.add()
+ time.sleep(self.frame_interval)
+ self._entries.append({'stack': [], 'start': time.time()}) # add final end frame
+
+ def start(self):
+ interval = self.profiler.params.get('traces_async_interval')
+ if interval:
+ self.frame_interval = min(max(float(interval), 0.001), 1)
+ self.thread.start()
+
+ def stop(self):
+ self.active = False
+ self.thread.join()
+
+ def add(self, entry=None, frame=None):
+ """ Add an entry (dict) to this collector. """
+ frame = frame or get_current_frame(self.profiler.init_thread)
+ if frame == self.last_frame:
+ # don't save if the frame is exactly the same as the previous one.
+ # maybe modify the last entry to add a last seen?
+ return
+ self.last_frame = frame
+ super().add(entry=entry, frame=frame)
+
+
+class SyncCollector(Collector):
+ """
+ Record complete execution synchronously.
+ Note that --limit-memory-hard may need to be increased when launching Odoo.
+ """
+ name = 'traces_sync'
+
+ def start(self):
+ assert not self._processed, "You cannot start SyncCollector after accessing entries."
+ sys.settrace(self.hook) # todo test setprofile, but maybe not multithread safe
+
+ def stop(self):
+ sys.settrace(None)
+
+ def hook(self, _frame, event, _arg=None):
+ if event == 'line':
+ return
+ entry = {'event': event, 'frame': _format_frame(_frame)}
+ if event == 'call' and _frame.f_back:
+ # we need the parent frame to determine the line number of the call
+ entry['parent_frame'] = _format_frame(_frame.f_back)
+ self.add(entry, frame=_frame)
+ return self.hook
+
+ def _get_stack_trace(self, frame=None):
+ # Getting the full stack trace is slow, and not useful in this case.
+ # SyncCollector only saves the top frame and event at each call and
+ # recomputes the complete stack at the end.
+ return None
+
+ def post_process(self):
+ # Transform the evented traces to full stack traces. This processing
+ # could be avoided since speedscope will transform that back to
+ # evented anyway, but it is actually simpler to integrate into the
+ # current speedscope logic, especially when mixed with SQLCollector.
+ # We could improve it by saving as evented and manage it later.
+ stack = []
+ for entry in self._entries:
+ frame = entry.pop('frame')
+ event = entry.pop('event')
+ if event == 'call':
+ if stack:
+ stack[-1] = entry.pop('parent_frame')
+ stack.append(frame)
+ elif event == 'return':
+ stack.pop()
+ entry['stack'] = stack[:]
+ super().post_process()
+
+
+class ExecutionContext:
+ """
+ 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 information.
+ """
+ def __init__(self, **context):
+ self.context = context
+ self.stack_trace_level = None
+
+ def __enter__(self):
+ current_thread = threading.current_thread()
+ self.stack_trace_level = stack_size()
+ if not hasattr(current_thread, 'exec_context'):
+ current_thread.exec_context = {}
+ current_thread.exec_context[self.stack_trace_level] = self.context
+
+ def __exit__(self, *_args):
+ threading.current_thread().exec_context.pop(self.stack_trace_level)
+
+
+class Profiler:
+ """
+ Context manager to use to start the recording of some execution.
+ Will save sql and async stack trace by default.
+ """
+ def __init__(self, db=..., path=None, collectors=None, profile_session=None,
+ description=None, disable_gc=False, params=None):
+ """
+ :param db: database name to use to save results.
+ Will try to define database automatically by default.
+ Use value ``None`` to not save results in a database.
+ :param path: path to use to save result
+ :param collectors: list of string and Collector object Ex: ['sql', PeriodicCollector(interval=0.2)]. Use `None` for default collectors
+ :param profile_session: session description to use to reproup multiple profile. use make_session(name) for default format.
+ :param description: description of the current profiler Suggestion: (route name/test method/loading module, ...)
+ :param disable_gc: flag to disable gc durring profiling (usefull to avoid gc while profiling, especially during sql execution)
+ :param params: parameters usable by collectors (like frame interval)
+ """
+ self.path = path
+ self.start_time = 0
+ self.duration = 0
+ self.profile_session = profile_session or make_session()
+ self.description = description
+ self.init_frame = None
+ self.init_stack_trace = None
+ self.init_thread = None
+ self.disable_gc = disable_gc
+ self.filecache = {}
+ self.params = params or {} # custom parameters usable by collectors
+
+ if db is ...:
+ # determine database from current thread
+ db = getattr(threading.current_thread(), 'dbname', None)
+ if not db and not path:
+ # only raise if path is not given and db is not explicitely disabled
+ raise Exception('Database name cannot be defined automaticaly. \n Please provide a valid/falsy dbname or path parameter')
+ self.db = db
+
+ # collectors
+ if collectors is None:
+ collectors = ['sql', 'traces_async']
+ self.collectors = []
+ for collector in collectors:
+ if isinstance(collector, str):
+ try:
+ collector = Collector.make(collector)
+ except Exception:
+ _logger.error("Could not create collector with name %r", collector)
+ continue
+ collector.profiler = self
+ self.collectors.append(collector)
+
+ def __enter__(self):
+ self.init_thread = threading.current_thread()
+ self.init_frame = get_current_frame(self.init_thread)
+ if self.init_frame.f_code.co_name == 'enter_context':
+ self.init_frame = self.init_frame.f_back # profiler used in a ExitStack case
+ self.init_stack_trace = _get_stack_trace(self.init_frame)
+ if self.description is None:
+ frame = self.init_frame
+ code = frame.f_code
+ self.description = f"{frame.f_code.co_name} ({code.co_filename}:{frame.f_lineno})"
+ if self.disable_gc and gc.isenabled():
+ gc.disable()
+ self.start_time = time.time()
+ for collector in self.collectors:
+ collector.start()
+ return self
+
+ def __exit__(self, *args):
try:
- result = method(*args, **kwargs)
- finally:
- sys.settrace(None)
+ for collector in self.collectors:
+ collector.stop()
+ self.duration = time.time() - self.start_time
+ self._add_file_lines(self.init_stack_trace)
+ if self.path:
+ save_time = datetime.datetime.now().strftime("%Y%m%d-%H%M%S")
+ dirname = os.path.dirname(self.path)
+ os.makedirs(dirname, exist_ok=True)
+ for collector in self.collectors:
+ formatted_path = self.path.format(len=len(collector.entries), time=save_time)
+ row = collector.name
+ description = re.sub("[^0-9a-zA-Z-]+", "_", self.description)
+ path = f'{formatted_path}_{description}_{row}.json'
+ _logger.warning('saving to %s', path)
+ with open(path, 'w', encoding='utf-8') as f:
+ json.dump({
+ "name": self.description,
+ "session": self.profile_session,
+ "create_date": save_time,
+ "init_stack_trace": _format_stack(self.init_stack_trace),
+ "duration": self.duration,
+ 'result': collector.entries,
+ }, f, indent=4)
- log = ["\n%-10s%-10s%s\n" % ('calls', 'queries', 'ms')]
-
- for v in log_tracer.profiles.values():
- v['report'] = {}
- l = len(v['calls'])
- for k, call in enumerate(v['calls']):
- if k+1 >= l:
- continue
-
- if call['lineno'] not in v['report']:
- v['report'][call['lineno']] = {
- 'nb_queries': 0,
- 'delay': 0,
- 'nb': 0,
+ if self.db:
+ # pylint: disable=import-outside-toplevel
+ from odoo.sql_db import db_connect # only import from odoo if/when needed.
+ with db_connect(self.db).cursor() as cr:
+ values = {
+ "name": self.description,
+ "session": self.profile_session,
+ "create_date": datetime.datetime.now(),
+ "init_stack_trace": json.dumps(_format_stack(self.init_stack_trace)),
+ "duration": self.duration,
}
- v['report'][call['lineno']]['nb'] += 1
+ for collector in self.collectors:
+ if collector.entries:
+ values[collector.name] = json.dumps(collector.entries)
+ query = sql.SQL("INSERT INTO {}({}) VALUES %s RETURNING id").format(
+ sql.Identifier("ir_profile"),
+ sql.SQL(",").join(map(sql.Identifier, values)),
+ )
+ cr.execute(query, [tuple(values.values())])
+ profile_id = cr.fetchone()[0]
+ _logger.info('ir_profile %s (%s) created', profile_id, self.profile_session)
+ finally:
+ if self.disable_gc:
+ gc.enable()
- n = k+1
- while k+1 <= l and v['calls'][k+1]['callno'] != call['callno']:
- n += 1
- if n >= l:
- continue
- next_call = v['calls'][n]
- if next_call['queries'] is not None:
- v['report'][call['lineno']]['nb_queries'] += next_call['queries'] - call.get('queries', 0)
- v['report'][call['lineno']]['delay'] += next_call['time'] - call['time']
-
- queries = 0
- delay = 0
- for call in v['report'].values():
- queries += call['nb_queries']
- delay += call['delay']
-
- if minimum_time and minimum_time > delay*1000:
+ def _add_file_lines(self, stack):
+ for index, frame in enumerate(stack):
+ (filename, lineno, name, line) = frame
+ if line != '':
continue
- if minimum_queries and minimum_queries > queries:
- continue
-
- # todo: no color if output in a file
- log.append("\033[1;33m%s %s--------------------- %s, %s\033[1;0m\n\n" % (v['model'] or '', '-' * (15-len(v['model'] or '')), v['filename'], v['firstline']))
- for lineno, line in enumerate(v['code']):
- if (lineno + v['firstline']) in v['report']:
- data = v['report'][lineno + v['firstline']]
- log.append("%-10s%-10s%-10s%s" % (
- str(data['nb']) if 'nb_queries' in data else '.',
- str(data.get('nb_queries', '')),
- str(round(data['delay']*100000)/100) if 'delay' in data else '',
- line[:-1]))
- else:
- log.append(" " * 30)
- log.append(line[:-1])
- log.append('\n')
-
- log.append("\nTotal:\n%-10s%-10d%-10s\n\n" % (
- str(data['nb']),
- queries,
- str(round(delay*100000)/100)))
-
- _logger.info(''.join(log))
-
- return result
-
- if not method:
- return lambda method: decorator(_odooProfile, method)
-
- wrapper = decorator(_odooProfile, method)
- return wrapper
+ # retrieve file lines from the filecache
+ try:
+ filelines = self.filecache[filename]
+ except KeyError:
+ try:
+ with tools.file_open(filename, filter_ext=('.py',)) as f:
+ filelines = f.readlines()
+ except (ValueError, FileNotFoundError): # mainly for "filename"
+ filelines = None
+ self.filecache[filename] = filelines
+ # fill in the line
+ if filelines is not None:
+ line = filelines[lineno - 1]
+ stack[index] = (filename, lineno, name, line)
diff --git a/odoo/tools/speedscope.py b/odoo/tools/speedscope.py
new file mode 100644
index 00000000000..a1540426bdf
--- /dev/null
+++ b/odoo/tools/speedscope.py
@@ -0,0 +1,196 @@
+# -*- coding: utf-8 -*-
+# Part of Odoo. See LICENSE file for full copyright and licensing details.
+import reprlib
+
+shortener = reprlib.Repr()
+shortener.maxstring = 150
+shorten = shortener.repr
+
+
+class Speedscope:
+ def __init__(self, name='Speedscope', init_stack_trace=None):
+ self.init_stack_trace = init_stack_trace or []
+ self.init_stack_trace_level = len(self.init_stack_trace)
+ self.caller_frame = None
+ self.convert_stack(self.init_stack_trace)
+
+ self.init_caller_frame = None
+ if self.init_stack_trace:
+ self.init_caller_frame = self.init_stack_trace[-1]
+ self.profiles_raw = {}
+ self.name = name
+ self.frames_indexes = {}
+ self.frame_count = 0
+ self.profiles = []
+
+ def add(self, key, profile):
+ for entry in profile:
+ self.caller_frame = self.init_caller_frame
+ self.convert_stack(entry['stack'] or [])
+ if 'query' in entry:
+ query = entry['query']
+ full_query = entry['full_query']
+ entry['stack'].append((f'sql({shorten(query)})', full_query, None))
+ self.profiles_raw[key] = profile
+
+ def convert_stack(self, stack):
+ for index, frame in enumerate(stack):
+ method = frame[2]
+ line = ''
+ number = ''
+ if self.caller_frame and len(self.caller_frame) == 4:
+ line = f"called at {self.caller_frame[0]} ({self.caller_frame[3].strip()})"
+ number = self.caller_frame[1]
+ stack[index] = (method, line, number,)
+ self.caller_frame = frame
+
+ def add_output(self, names, complete=True, display_name=None, use_context=True, **params):
+ entries = []
+ display_name = display_name or ','.join(names)
+ for name in names:
+ entries += self.profiles_raw[name]
+ entries.sort(key=lambda e: e['start'])
+ result = self.process(entries, use_context=use_context, **params)
+ if not result:
+ return self
+ start = result[0]['at']
+ end = result[-1]['at']
+
+ if complete:
+ start_stack = []
+ end_stack = []
+ init_stack_trace_ids = self.stack_to_ids(self.init_stack_trace, use_context and entries[0].get('exec_context'))
+ for frame_id in init_stack_trace_ids:
+ start_stack.append({
+ "type": "O",
+ "frame": frame_id,
+ "at": start
+ })
+ for frame_id in reversed(init_stack_trace_ids):
+ end_stack.append({
+ "type": "C",
+ "frame": frame_id,
+ "at": end
+ })
+ result = start_stack + result + end_stack
+
+ self.profiles.append({
+ "name": display_name,
+ "type": "evented",
+ "unit": "seconds",
+ "startValue": 0,
+ "endValue": end - start,
+ "events": result
+ })
+ return self
+
+ def add_default(self):
+ if len(self.profiles_raw) > 1:
+ self.add_output(self.profiles_raw, display_name='Combined')
+ self.add_output(self.profiles_raw, display_name='Combined no context', use_context=False)
+ for key, profile in self.profiles_raw.items():
+ sql = profile and profile[0].get('query')
+ if sql:
+ self.add_output([key], hide_gaps=True, display_name=f'{key} (no gap)')
+ self.add_output([key], continuous=False, complete=False, display_name=f'{key} (density)')
+ else:
+ self.add_output([key], display_name=key)
+ return self
+
+ def make(self):
+ if not self.profiles:
+ self.add_default()
+ return {
+ "name": self.name,
+ "activeProfileIndex": 0,
+ "$schema": "https://www.speedscope.app/file-format-schema.json",
+ "shared": {
+ "frames": [{
+ "name": frame[0],
+ "file": frame[1],
+ "line": frame[2]
+ } for frame in self.frames_indexes]
+ },
+ "profiles": self.profiles,
+ }
+
+ def get_frame_id(self, frame):
+ if frame not in self.frames_indexes:
+ self.frames_indexes[frame] = self.frame_count
+ self.frame_count += 1
+ return self.frames_indexes[frame]
+
+ def stack_to_ids(self, stack, context, stack_offset=0):
+ stack_ids = []
+ for level, frame in enumerate(stack):
+ if context:
+ current_frame_level = stack_offset + level + 1
+ frame_context = context.get(str(current_frame_level)) or context.get(current_frame_level)
+ if frame_context:
+ context_frame = (', '.join('%s=%s' % item for item in frame_context.items()), '', '')
+ stack_ids.append(self.get_frame_id(context_frame))
+ stack_ids.append(self.get_frame_id(frame))
+ return stack_ids
+
+ def process(self, entries, continuous=True, hide_gaps=False, use_context=True):
+ entry_end = previous_end = None
+ if not entries:
+ return []
+ events = []
+ current_stack_ids = []
+ frames_start = entries[0]['start']
+
+ # add last closing entry if missing
+ last_entry = entries[-1]
+ if last_entry['stack']:
+ entries.append({'stack': [], 'start': last_entry['start'] + last_entry.get('time', 0)})
+
+ for entry in entries:
+ previous_end = entry_end
+
+ if hide_gaps and previous_end:
+ entry_start = previous_end
+ else:
+ entry_start = entry['start'] - frames_start
+
+ if previous_end and previous_end > entry_start:
+ # skip entry if entry starts after another entry end/
+ continue
+
+ if previous_end:
+ close_time = min(entry_start, previous_end)
+ else:
+ close_time = entry_start
+
+ entry_time = entry.get('time')
+ entry_end = None if entry_time is None else entry_start + entry_time
+ entry_stack_ids = self.stack_to_ids(
+ entry['stack'] or [],
+ use_context and entry.get('exec_context', {}),
+ self.init_stack_trace_level
+ )
+ level = 0
+ if continuous:
+ level = -1
+ for level, at_level in enumerate(zip(current_stack_ids, entry_stack_ids)):
+ current, new = at_level
+ if current != new:
+ break
+ else:
+ level += 1
+
+ for frame in reversed(current_stack_ids[level:]):
+ events.append({
+ "type": "C",
+ "frame": frame,
+ "at": close_time
+ })
+ for frame in entry_stack_ids[level:]:
+ events.append({
+ "type": "O",
+ "frame": frame,
+ "at": entry_start
+ })
+ current_stack_ids = entry_stack_ids
+
+ return events