From b2b36524c27ddd8a892fe740a5eec874e06f8cf8 Mon Sep 17 00:00:00 2001 From: Xavier-Do Date: Wed, 4 Mar 2020 11:00:38 +0000 Subject: [IMP] core: improve module loading logs Performances from a general point of view can be difficult to track. This commit proposes to improve logs in two ways: The current logs only use the sql_counter, wich will only be updated when a cursor is closed. In a test-enable install, this counter is actually the queries of the tests wince the install cursor is open untill the end. The first fix is to use bot sql_counter and sql_log_count to have total queries untill now on closed cursor, but also the current number of queries of the current cursor. This means that the new log format will be {nb} modules loaded in {time}, {loading_querie} (+{test_cr_queries}) queries instead of {nb} modules loaded in {time}, {tests_cr__queries}queries Nothe that in the current version, {nb} is actually the total number of loaded modules until now. This commit also add an equivalent end log by module and change the loglevel of module start on install (mainly usefull if an error occurs before anything else is logged hidding the module causing this error.) A cleaner runbot logger is also added, in order to be abble to call _logger.runbot( instead of _logger.log(25. This will clarify the purpose of such a log level. closes odoo/odoo#47283 Signed-off-by: Christophe Monniez (moc) --- odoo/modules/loading.py | 26 ++++++++++++++++++++++---- odoo/modules/module.py | 13 +++++-------- 2 files changed, 27 insertions(+), 12 deletions(-) (limited to 'odoo/modules') diff --git a/odoo/modules/loading.py b/odoo/modules/loading.py index 117bd0a4f90..8cb50e68438 100644 --- a/odoo/modules/loading.py +++ b/odoo/modules/loading.py @@ -153,7 +153,8 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, # register, instantiate and initialize models for each modules t0 = time.time() - t0_sql = odoo.sql_db.sql_counter + loading_extra_query_count = odoo.sql_db.sql_counter + loading_cursor_query_count = cr.sql_log_count models_updated = set() @@ -164,13 +165,20 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, if skip_modules and module_name in skip_modules: continue - _logger.debug('loading module %s (%d/%d)', module_name, index, module_count) + module_t0 = time.time() + module_cursor_query_count = cr.sql_log_count + module_extra_query_count = odoo.sql_db.sql_counter needs_update = ( hasattr(package, "init") or hasattr(package, "update") or package.state in ("to install", "to upgrade") ) + module_log_level = logging.DEBUG + if needs_update: + module_log_level = logging.INFO + _logger.log(module_log_level, 'Loading module %s (%d/%d)', module_name, index, module_count) + if needs_update: if package.name != 'base': registry.setup_models(cr) @@ -276,7 +284,17 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, if package.name is not None: registry._init_modules.add(package.name) - _logger.log(25, "%s modules loaded in %.2fs, %s queries", len(graph), time.time() - t0, odoo.sql_db.sql_counter - t0_sql) + _logger.log(module_log_level, "Module %s loaded in %.2fs, %s queries (+%s extra)", + module_name, + time.time() - module_t0, + cr.sql_log_count - module_cursor_query_count, + odoo.sql_db.sql_counter - module_extra_query_count) # extra queries: testes, notify, any other closed cursor + + _logger.runbot("%s modules loaded in %.2fs, %s queries (+%s extra)", + len(graph), + time.time() - t0, + cr.sql_log_count - loading_cursor_query_count, + odoo.sql_db.sql_counter - loading_extra_query_count) # extra queries: testes, notify, any other closed cursor return loaded_modules, processed_modules @@ -459,7 +477,7 @@ def load_modules(db, force_demo=False, status=None, update_module=False): if model in registry: env[model]._check_removed_columns(log=True) elif _logger.isEnabledFor(logging.INFO): # more an info that a warning... - _logger.log(25, "Model %s is declared but cannot be loaded! (Perhaps a module was partially removed or renamed)", model) + _logger.runbot("Model %s is declared but cannot be loaded! (Perhaps a module was partially removed or renamed)", model) # Cleanup orphan records env['ir.model.data']._process_end(processed_modules) diff --git a/odoo/modules/module.py b/odoo/modules/module.py index b5a513e19fc..88d96949b74 100644 --- a/odoo/modules/module.py +++ b/odoo/modules/module.py @@ -495,18 +495,13 @@ class OdooTestResult(unittest.result.TestResult): class OdooTestRunner(object): - """A test runner class that displays results in in logger. - Simplified verison of TextTestRunner( + """A test runner class that displays results in in logger using OdooTestResult. + Simplified verison of TextTestRunner """ def run(self, test): result = OdooTestResult() - - start_time = time.perf_counter() test(result) - time_taken = time.perf_counter() - start_time - run = result.testsRun - _logger.info("Ran %d test%s in %.3fs", run, run != 1 and "s" or "", time_taken) return result current_test = None @@ -535,8 +530,10 @@ def run_unit_tests(module_name, position='at_install'): t0_sql = odoo.sql_db.sql_counter _logger.info('%s running tests.', m.__name__) result = OdooTestRunner().run(suite) + log_level = logging.INFO if time.time() - t0 > 5: - _logger.log(25, "%s tested in %.2fs, %s queries", m.__name__, time.time() - t0, odoo.sql_db.sql_counter - t0_sql) + log_level = logging.RUNBOT + _logger.log(log_level, "%s ran %s tests in %.2fs, %s queries", m.__name__, result.testsRun, time.time() - t0, odoo.sql_db.sql_counter - t0_sql) if not result.wasSuccessful(): r = False _logger.error("Module %s: %d failures, %d errors", module_name, len(result.failures), len(result.errors)) -- cgit v1.2.3