[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) <moc@odoo.com>

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',