From b2b36524c27ddd8a892fe740a5eec874e06f8cf8 Mon Sep 17 00:00:00 2001 From: Xavier-Do Date: Wed, 4 Mar 2020 11:00:38 +0000 Subject: [PATCH] [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) --- addons/l10n_ar/models/res_partner.py | 4 ++-- addons/web/tests/test_click_everywhere.py | 4 ++-- addons/web/tests/test_serving_base.py | 6 +++--- addons/website/tests/test_crawl.py | 6 +++--- odoo/modules/loading.py | 26 +++++++++++++++++++---- odoo/modules/module.py | 13 +++++------- odoo/netsvc.py | 8 ++++++- odoo/tests/common.py | 6 +++--- odoo/tools/config.py | 2 +- 9 files changed, 48 insertions(+), 27 deletions(-) diff --git a/addons/l10n_ar/models/res_partner.py b/addons/l10n_ar/models/res_partner.py index d79552f3583..dd4d7aee514 100644 --- a/addons/l10n_ar/models/res_partner.py +++ b/addons/l10n_ar/models/res_partner.py @@ -41,7 +41,7 @@ class ResPartner(models.Model): rec.l10n_ar_formatted_vat = stdnum.ar.cuit.format(rec.l10n_ar_vat) except Exception as error: rec.l10n_ar_formatted_vat = rec.l10n_ar_vat - _logger.log(25, "Argentinian VAT was not formatted: %s", repr(error)) + _logger.runbot("Argentinian VAT was not formatted: %s", repr(error)) remaining = self - recs_ar_vat remaining.l10n_ar_formatted_vat = False @@ -96,7 +96,7 @@ class ResPartner(models.Model): module = rec._get_validation_module() except Exception as error: module = False - _logger.log(25, "Argentinian document was not validated: %s", repr(error)) + _logger.runbot("Argentinian document was not validated: %s", repr(error)) if not module: continue diff --git a/addons/web/tests/test_click_everywhere.py b/addons/web/tests/test_click_everywhere.py index 7f2d16d75d6..18c7431339e 100644 --- a/addons/web/tests/test_click_everywhere.py +++ b/addons/web/tests/test_click_everywhere.py @@ -13,7 +13,7 @@ class TestMenusAdmin(odoo.tests.HttpCase): menus = self.env['ir.ui.menu'].load_menus(False) for app in menus['children']: with self.subTest(app=app['name']): - _logger.log(25, 'Testing %s', app['name']) + _logger.runbot('Testing %s', app['name']) self.browser_js("/web", "odoo.__DEBUG__.services['web.clickEverywhere'](%d);" % app['id'], "odoo.isReady === true", login="admin", timeout=300) self.terminate_browser() @@ -25,7 +25,7 @@ class TestMenusDemo(odoo.tests.HttpCase): menus = self.env['ir.ui.menu'].load_menus(False) for app in menus['children']: with self.subTest(app=app['name']): - _logger.log(25, 'Testing %s', app['name']) + _logger.runbot('Testing %s', app['name']) self.browser_js("/web", "odoo.__DEBUG__.services['web.clickEverywhere'](%d);" % app['id'], "odoo.isReady === true", login="demo", timeout=300) self.terminate_browser() diff --git a/addons/web/tests/test_serving_base.py b/addons/web/tests/test_serving_base.py index 09c52df3471..267388bda85 100644 --- a/addons/web/tests/test_serving_base.py +++ b/addons/web/tests/test_serving_base.py @@ -982,7 +982,7 @@ class TestStaticInheritancePerformance(TestStaticInheritanceCommon): contents = HomeStaticTemplateHelpers.get_qweb_templates(addons=self._get_module_names(), debug=True) after = datetime.now() delta2500 = after - before - _logger.log(25, 'Static Templates Inheritance: 2500 templates treated in %s seconds' % delta2500.total_seconds()) + _logger.runbot('Static Templates Inheritance: 2500 templates treated in %s seconds' % delta2500.total_seconds()) whole_tree = etree.fromstring(contents) self.assertEqual(len(whole_tree), nMod * nFilePerMod * nTemplatePerFile) @@ -997,6 +997,6 @@ class TestStaticInheritancePerformance(TestStaticInheritanceCommon): delta25000 = after - before time_ratio = delta25000.total_seconds() / delta2500.total_seconds() - _logger.log(25, 'Static Templates Inheritance: 25000 templates treated in %s seconds' % delta25000.total_seconds()) - _logger.log(25, 'Static Templates Inheritance: Computed linearity ratio: %s' % time_ratio) + _logger.runbot('Static Templates Inheritance: 25000 templates treated in %s seconds' % delta25000.total_seconds()) + _logger.runbot('Static Templates Inheritance: Computed linearity ratio: %s' % time_ratio) self.assertLessEqual(time_ratio, 10) diff --git a/addons/website/tests/test_crawl.py b/addons/website/tests/test_crawl.py index 62df28c0f38..648fa258ec2 100644 --- a/addons/website/tests/test_crawl.py +++ b/addons/website/tests/test_crawl.py @@ -85,7 +85,7 @@ class Crawler(HttpCaseWithUserDemo): count = len(seen) duration = time.time() - t0 sql = self.registry.test_cr.sql_log_count - t0_sql - _logger.log(25, "public crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request, ", count, duration, sql, duration / count, float(sql) / count) + _logger.runbot("public crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request, ", count, duration, sql, duration / count, float(sql) / count) def test_20_crawl_demo(self): t0 = time.time() @@ -95,7 +95,7 @@ class Crawler(HttpCaseWithUserDemo): count = len(seen) duration = time.time() - t0 sql = self.registry.test_cr.sql_log_count - t0_sql - _logger.log(25, "demo crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) + _logger.runbot("demo crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) def test_30_crawl_admin(self): t0 = time.time() @@ -105,4 +105,4 @@ class Crawler(HttpCaseWithUserDemo): count = len(seen) duration = time.time() - t0 sql = self.registry.test_cr.sql_log_count - t0_sql - _logger.log(25, "admin crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) + _logger.runbot("admin crawled %s urls in %.2fs %s queries, %.3fs %.2fq per request", count, duration, sql, duration / count, float(sql) / count) 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)) diff --git a/odoo/netsvc.py b/odoo/netsvc.py index a9c1a365986..8257dccdbcb 100644 --- a/odoo/netsvc.py +++ b/odoo/netsvc.py @@ -125,9 +125,14 @@ def init_logger(): return record logging.setLogRecordFactory(record_factory) - logging.addLevelName(25, "INFO") + logging.RUNBOT = 25 + logging.addLevelName(logging.RUNBOT, "INFO") # displayed as info in log logging.captureWarnings(True) + def runbot(self, message, *args, **kws): + self.log(logging.RUNBOT, message, *args, **kws) + logging.Logger.runbot = runbot + # enable deprecation warnings (disabled by default) warnings.filterwarnings('once', category=DeprecationWarning) # ignore deprecation warnings from invalid escape (there's a ton and it's @@ -228,6 +233,7 @@ PSEUDOCONFIG_MAPPER = { 'debug': ['odoo:DEBUG', 'odoo.sql_db:INFO'], 'debug_sql': ['odoo.sql_db:DEBUG'], 'info': [], + 'runbot': ['odoo:RUNBOT', 'werkzeug:WARNING'], 'warn': ['odoo:WARNING', 'werkzeug:WARNING'], 'error': ['odoo:ERROR', 'werkzeug:ERROR'], 'critical': ['odoo:CRITICAL', 'werkzeug:CRITICAL'], diff --git a/odoo/tests/common.py b/odoo/tests/common.py index a86f0cc8bcf..15bc0ce1cec 100644 --- a/odoo/tests/common.py +++ b/odoo/tests/common.py @@ -964,7 +964,7 @@ class ChromeBrowser(): full_path = os.path.join(self.screenshots_dir, fname) with open(full_path, 'wb') as f: f.write(decoded) - self._logger.log(25, 'Screenshot in: %s', full_path) + self._logger.runbot('Screenshot in: %s', full_path) def _save_screencast(self, prefix='failed'): # could be encododed with something like that @@ -993,11 +993,11 @@ class ChromeBrowser(): if ffmpeg_path: framerate = int(len(self.screencast_frames) / (self.screencast_frames[-1].get('timestamp') - self.screencast_frames[0].get('timestamp'))) r = subprocess.run([ffmpeg_path, '-framerate', str(framerate), '-i', '%s/frame_%%05d.png' % self.screencasts_dir, outfile]) - self._logger.log(25, 'Screencast in: %s', outfile) + self._logger.runbot('Screencast in: %s', outfile) else: outfile = outfile.strip('.mp4') shutil.move(self.screencasts_frames_dir, outfile) - self._logger.log(25, 'Screencast frames in: %s', outfile) + self._logger.runbot('Screencast frames in: %s', outfile) def start_screencast(self): if self.screencasts_dir: diff --git a/odoo/tools/config.py b/odoo/tools/config.py index 0ac8c40e31b..efcd71ccf57 100644 --- a/odoo/tools/config.py +++ b/odoo/tools/config.py @@ -198,7 +198,7 @@ class configmanager(object): # For backward-compatibility, map the old log levels to something # quite close. levels = [ - 'info', 'debug_rpc', 'warn', 'test', 'critical', + 'info', 'debug_rpc', 'warn', 'test', 'critical', 'runbot', 'debug_sql', 'error', 'debug', 'debug_rpc_answer', 'notset' ] group.add_option('--log-level', dest='log_level', type='choice',