[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>

1 files changed, 22 insertions, 4 deletions

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)