diff --git a/odoo/service/server.py b/odoo/service/server.py index 2abf542af47..8991bf33500 100644 --- a/odoo/service/server.py +++ b/odoo/service/server.py @@ -1271,6 +1271,7 @@ def preload_registries(dbnames): time.time() - t0, odoo.sql_db.sql_counter - t0_sql) + registry._assertion_report.log_stats() if not registry._assertion_report.wasSuccessful(): rc += 1 except Exception: diff --git a/odoo/sql_db.py b/odoo/sql_db.py index b651070cf95..3915268d34c 100644 --- a/odoo/sql_db.py +++ b/odoo/sql_db.py @@ -344,6 +344,7 @@ class Cursor(BaseCursor): return self._obj.mogrify(query, params).decode(encoding, 'replace') def execute(self, query, params=None, log_exceptions=None): + global sql_counter if params and not isinstance(params, (tuple, list, dict)): # psycopg2's TypeError is not clear if you mess up the params raise ValueError("SQL query parameters should be a tuple, list or dict; got %r" % (params,)) @@ -361,6 +362,8 @@ class Cursor(BaseCursor): # simple query count is always computed self.sql_log_count += 1 + sql_counter += 1 + delay = (real_time() - start) current_thread = threading.current_thread() if hasattr(current_thread, 'query_count'): @@ -437,16 +440,11 @@ class Cursor(BaseCursor): return self._close(False) def _close(self, leak=False): - global sql_counter - if not self._obj: return del self.cache - # simple query count is always computed - sql_counter += self.sql_log_count - # advanced stats only if sql_log is enabled self.print_log() diff --git a/odoo/tests/common.py b/odoo/tests/common.py index 734b9f3d2dd..0309ce2eee6 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -66,6 +66,7 @@ except ImportError: # chrome headless tests will be skipped websocket = None +from .runner import stats_logger _logger = logging.getLogger(__name__) @@ -188,9 +189,10 @@ class RecordCapturer: # ------------------------------------------------------------ # Main classes # ------------------------------------------------------------ -class OdooSuite(unittest.suite.TestSuite): - - if sys.version_info < (3, 8): +if sys.version_info >= (3, 8): + BackportSuite = unittest.suite.TestSuite +else: + class BackportSuite(unittest.suite.TestSuite): # Partial backport of bpo-24412, merged in CPython 3.8 def _handleClassSetUp(self, test, result): @@ -285,6 +287,37 @@ class OdooSuite(unittest.suite.TestSuite): className, info=exc) +class OdooSuite(BackportSuite): + def _handleClassSetUp(self, test, result): + previous_test_class = getattr(result, '_previousTestClass', None) + if not ( + previous_test_class != type(test) + and hasattr(result, 'stats') + and stats_logger.isEnabledFor(logging.INFO) + ): + super()._handleClassSetUp(test, result) + return + + test_class = type(test) + test_id = f'{test_class.__module__}.{test_class.__qualname__}.setUpClass' + with result.collectStats(test_id): + super()._handleClassSetUp(test, result) + + def _tearDownPreviousClass(self, test, result): + previous_test_class = getattr(result, '_previousTestClass', None) + if not ( + previous_test_class + and previous_test_class != type(test) + and hasattr(result, 'stats') + and stats_logger.isEnabledFor(logging.INFO) + ): + super()._tearDownPreviousClass(test, result) + return + + test_id = f'{previous_test_class.__module__}.{previous_test_class.__qualname__}.tearDownClass' + with result.collectStats(test_id): + super()._tearDownPreviousClass(test, result) + class MetaCase(type): """ Metaclass of test case classes to assign default 'test_tags': diff --git a/odoo/tests/runner.py b/odoo/tests/runner.py index d7db4327d16..7b80206cab5 100644 --- a/odoo/tests/runner.py +++ b/odoo/tests/runner.py @@ -1,12 +1,42 @@ +import collections import contextlib import logging +import re import time import unittest +from typing import NamedTuple from .. import sql_db +stats_logger = logging.getLogger('odoo.tests.stats') + +class Stat(NamedTuple): + time: float = 0.0 + queries: int = 0 + + def __add__(self, other: 'Stat') -> 'Stat': + if other == 0: + return self + + if not isinstance(other, Stat): + return NotImplemented + + return Stat( + self.time + other.time, + self.queries + other.queries, + ) _logger = logging.getLogger(__name__) +_TEST_ID = re.compile(r""" +^ +odoo\.addons\. +(?P[^.]+) +\.tests\. +(?P.+) +\. +(?P[^.]+) +$ +""", re.VERBOSE) class OdooTestResult(unittest.result.TestResult): """ This class in inspired from TextTestResult (https://github.com/python/cpython/blob/master/Lib/unittest/runner.py) @@ -21,6 +51,7 @@ class OdooTestResult(unittest.result.TestResult): self.queries_start = None self._soft_fail = False self.had_failure = False + self.stats = collections.defaultdict(Stat) def __str__(self): return f'{len(self.failures)} failed, {len(self.errors)} error(s) of {self.testsRun} tests' @@ -47,6 +78,7 @@ class OdooTestResult(unittest.result.TestResult): self.expectedFailures.extend(other.expectedFailures) self.unexpectedSuccesses.extend(other.unexpectedSuccesses) self.shouldStop = self.shouldStop or other.shouldStop + self.stats.update(other.stats) def log(self, level, msg, *args, test=None, exc_info=None, extra=None, stack_info=False, caller_infos=None): """ @@ -70,6 +102,37 @@ class OdooTestResult(unittest.result.TestResult): record = logger.makeRecord(logger.name, level, fn, lno, msg, args, exc_info, func, extra, sinfo) logger.handle(record) + def log_stats(self): + if not stats_logger.isEnabledFor(logging.INFO): + return + + details = stats_logger.isEnabledFor(logging.DEBUG) + stats_tree = collections.defaultdict(Stat) + counts = collections.Counter() + for test, stat in self.stats.items(): + r = _TEST_ID.match(test) + if not r: # upgrade has tests at weird paths, ignore them + continue + + stats_tree[r['module']] += stat + counts[r['module']] += 1 + if details: + stats_tree['%(module)s.%(class)s' % r] += stat + stats_tree['%(module)s.%(class)s.%(method)s' % r] += stat + + if details: + stats_logger.debug('Detailed Tests Report:\n%s', ''.join( + f'\t{test}: {stats.time:.2f}s {stats.queries} queries\n' + for test, stats in sorted(stats_tree.items()) + )) + else: + for module, stat in sorted(stats_tree.items()): + stats_logger.info( + "%s: %d tests %.2fs %d queries", + module, counts[module], + stat.time, stat.queries + ) + def getDescription(self, test): if isinstance(test, unittest.case._SubTest): return 'Subtest %s.%s %s' % (test.test_case.__class__.__qualname__, test.test_case._testMethodName, test._subDescription()) @@ -85,6 +148,26 @@ class OdooTestResult(unittest.result.TestResult): self.time_start = time.time() self.queries_start = sql_db.sql_counter + def stopTest(self, test): + if stats_logger.isEnabledFor(logging.INFO): + self.stats[test.id()] = Stat( + time=time.time() - self.time_start, + queries=sql_db.sql_counter - self.queries_start, + ) + super().stopTest(test) + + @contextlib.contextmanager + def collectStats(self, test_id): + queries_before = sql_db.sql_counter + time_start = time.time() + + yield + + self.stats[test_id] += Stat( + time=time.time() - time_start, + queries=sql_db.sql_counter - queries_before, + ) + def addError(self, test, err): if self._soft_fail: self.had_failure = True