diff --git a/openerp/modules/loading.py b/openerp/modules/loading.py index b9b421a20ca..d81461d6a77 100644 --- a/openerp/modules/loading.py +++ b/openerp/modules/loading.py @@ -138,7 +138,8 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules= registry.fields_by_model.setdefault(field['model'], []).append(field) # register, instantiate and initialize models for each modules - ta0 = time.time() + t0 = time.time() + t0_sql = openerp.sql_db.sql_counter for index, package in enumerate(graph): module_name = package.name @@ -147,8 +148,6 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules= if skip_modules and module_name in skip_modules: continue - tm0 = time.time() - migrations.migrate_module(package, 'pre') load_openerp_module(package.name) @@ -226,12 +225,10 @@ def load_module_graph(cr, graph, status=None, perform_checks=True, skip_modules= if hasattr(package, kind): delattr(package, kind) - #_logger.log(25, "%s loaded in %.2fs", package.name, time.time() - tm0) - registry._init_modules.add(package.name) cr.commit() - _logger.log(25, "%s modules loaded in %.2fs", len(graph), time.time() - ta0) + _logger.log(25, "%s modules loaded in %.2fs, %s queries", len(graph), time.time() - t0, openerp.sql_db.sql_counter - t0_sql) # The query won't be valid for models created later (i.e. custom model # created after the registry has been loaded), so empty its result. @@ -460,12 +457,13 @@ def load_modules(db, force_demo=False, status=None, update_module=False): # STEP 9: Run the post-install tests cr.commit() - ta0 = time.time() + t0 = time.time() + t0_sql = openerp.sql_db.sql_counter if openerp.tools.config['test_enable']: cr.execute("SELECT name FROM ir_module_module WHERE state='installed'") for module_name in cr.fetchall(): report.record_result(openerp.modules.module.run_unit_tests(module_name[0], cr.dbname, position=runs_post_install)) - _logger.log(25, "All post-tested in %.2fs", time.time() - ta0) + _logger.log(25, "All post-tested in %.2fs, %s queries", time.time() - t0, openerp.sql_db.sql_counter - t0_sql) finally: cr.close() diff --git a/openerp/modules/module.py b/openerp/modules/module.py index 66119ce31f1..0dd93629830 100644 --- a/openerp/modules/module.py +++ b/openerp/modules/module.py @@ -425,11 +425,12 @@ def run_unit_tests(module_name, dbname, position=runs_at_install): suite = unittest2.TestSuite(itertools.ifilter(position, tests)) if suite.countTestCases(): - tm0 = time.time() + t0 = time.time() + t0_sql = openerp.sql_db.sql_counter _logger.info('%s running tests.', m.__name__) result = unittest2.TextTestRunner(verbosity=2, stream=TestStream(m.__name__)).run(suite) - if time.time() - tm0 > 5: - _logger.log(25, "%s tested in %.2fs", m.__name__, time.time() - tm0) + if time.time() - t0 > 5: + _logger.log(25, "%s tested in %.2fs, %s queries", m.__name__, time.time() - t0, openerp.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/openerp/sql_db.py b/openerp/sql_db.py index add6cc9655a..be6c02f9fe3 100644 --- a/openerp/sql_db.py +++ b/openerp/sql_db.py @@ -237,12 +237,15 @@ class Cursor(object): _logger.exception("bad query: %s", self._obj.query or query) raise + # simple query count is always computed + self.sql_log_count += 1 + + # advanced stats only if sql_log is enabled if self.sql_log: delay = mdt.now() - now delay = delay.seconds * 1E6 + delay.microseconds _logger.debug("query: %s", self._obj.query) - self.sql_log_count+=1 res_from = re_from.match(query.lower()) if res_from: self.sql_from_log.setdefault(res_from.group(1), [0, 0]) @@ -263,7 +266,7 @@ class Cursor(object): def print_log(self): global sql_counter - sql_counter += self.sql_log_count + if not self.sql_log: return def process(type): @@ -294,6 +297,8 @@ class Cursor(object): return self._close(False) def _close(self, leak=False): + global sql_counter + if not self._obj: return @@ -301,6 +306,11 @@ class Cursor(object): if self.sql_log: self.__closer = frame_codeinfo(currentframe(),3) + + # simple query count is always computed + sql_counter += self.sql_log_count + + # advanced stats only if sql_log is enabled self.print_log() self._obj.close()