[IMP] core: reintroduce test stats
Uses a dedicated logger (for easier filtering / silencing) for results output, and provides rough (module-level) stats in INFO but detailed (test-level) in DEBUG. Also updates the global query counter (`odoo.sql_db.query_counter`) to update after each query rather than on close: with test cursors the actual underlying counter is only rarely flushed. closes odoo/odoo#95420 Signed-off-by: Xavier Morel (xmo) <xmo@odoo.com>
This commit is contained in:
Xavier Morel
@@ -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:
|
||||
|
||||
+3
-5
@@ -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()
|
||||
|
||||
|
||||
+36
-3
@@ -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':
|
||||
|
||||
@@ -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<module>[^.]+)
|
||||
\.tests\.
|
||||
(?P<class>.+)
|
||||
\.
|
||||
(?P<method>[^.]+)
|
||||
$
|
||||
""", 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
|
||||
|
||||
Reference in New Issue
Block a user