pengyuthon/odoo_source
1
0
Fork 0
Code Issues Pull Requests Actions Packages Projects Releases Wiki Activity

[IMP] core: improve module loading logs

Browse Source 
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>
This commit is contained in:
Xavier-Do
2020-03-16 13:21:57 +00:00
parent a12479aaa8
commit b2b36524c2
9 changed files with 48 additions and 27 deletions
Download Patch File Download Diff File Expand all files Collapse all files
addons/l10n_ar/models/res_partner.py
+2 -2
View File
@@ -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
addons/web/tests/test_click_everywhere.py
+2 -2
View File
@@ -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()
addons/web/tests/test_serving_base.py
+3 -3
View File
@@ -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)
addons/website/tests/test_crawl.py
+3 -3
View File
@@ -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)
odoo/modules/loading.py
+22 -4
View File
@@ -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)
odoo/modules/module.py
+5 -8
View File
@@ -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))
odoo/netsvc.py
+7 -1
View File
@@ -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'],
odoo/tests/common.py
+3 -3
View File
@@ -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:
odoo/tools/config.py
+1 -1
View File
@@ -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',