From b04bf31e29b68ad8761c63bf852058c86ceba598 Mon Sep 17 00:00:00 2001 From: Christophe Matthieu Date: Wed, 9 Aug 2017 10:42:53 +0200 Subject: [PATCH] [FIX] odoo profiler: Calculation error for loops The previous line in a loop calculates the number of queries made until the end of the loop. This causes the number of queries to be counted twice. Don't blacklist the entry point method. Check the methods called from a blacklisted method. --- odoo/tools/profiler.py | 100 +++++++++++++++++------------------------ 1 file changed, 40 insertions(+), 60 deletions(-) diff --git a/odoo/tools/profiler.py b/odoo/tools/profiler.py index f159cf978ca..dce9f98fb44 100644 --- a/odoo/tools/profiler.py +++ b/odoo/tools/profiler.py @@ -12,7 +12,6 @@ _logger = logging.getLogger(__name__) class _LogTracer(object): def __init__(self, whitelist=None, blacklist=None, files=None, deep=False): self.profiles = {} - self.lines = [] self.whitelist = whitelist self.blacklist = blacklist self.files = files @@ -32,19 +31,19 @@ class _LogTracer(object): return self.tracer if self.files and frame.f_code.co_filename not in self.files: - return + return self.tracer in_self = frame.f_locals['self'] if isinstance(in_self, (odoo.sql_db.Cursor, odoo.sql_db.TestCursor, odoo.sql_db.LazyCursor)): - return + return self.tracer model = getattr(in_self, '_name', None) if self.whitelist and model not in self.whitelist: - return - if model in self.blacklist: - return + return self.tracer + if model in self.blacklist and self.first_frame != frame.f_code: + return self.tracer if frame.f_code not in self.profiles: try: @@ -54,7 +53,7 @@ class _LogTracer(object): 'filename': frame.f_code.co_filename, 'firstline': firstline, 'code': lines, - 'lines': {}, + 'calls': [], 'nb': 0, } except Exception: @@ -64,27 +63,14 @@ class _LogTracer(object): if not frame.f_lineno: codeProfile['nb'] += 1 - lineno = frame.f_lineno - if event == 'return': - lineno += 0.5 - - if lineno not in codeProfile['lines']: - codeProfile['lines'][lineno] = { - 'code': codeProfile, - 'infos': {}, - 'nb': 0, - 'event': event - } - lineProfile = codeProfile['lines'][lineno] - lineProfile['nb'] += 1 - cr = getattr(in_self, '_cr', None) - lineProfile['infos'][codeProfile['nb']] = { + codeProfile['calls'].append({ + 'event': event, + 'lineno': frame.f_lineno, 'queries': cr and cr.sql_log_count, - 'time': time.time() - } - - self.lines.append(lineProfile) + 'time': time.time(), + 'callno': codeProfile['nb'], + }) return self.tracer @@ -146,41 +132,35 @@ def profile(method=None, whitelist=None, blacklist=(None,), files=None, log = ["\n%-10s%-10s%s\n" % ('calls', 'queries', 'ms')] for v in log_tracer.profiles.values(): - sort_by_calls = {} - for lineno in v['lines']: - line = v['lines'][lineno] - for n in line['infos']: - if n not in sort_by_calls: - sort_by_calls[n] = {} - sort_by_calls[n][lineno] = { - 'queries': line['infos'][n]['queries'], - 'time': line['infos'][n]['time'], - 'line': line, - } - line.pop('infos') - line['nb_queries'] = 0 - line['delay'] = 0 + v['report'] = {} + l = len(v['calls']) + for k, call in enumerate(v['calls']): + if k+1 >= l: + continue - for n in sort_by_calls: - linenos = sorted(sort_by_calls[n]) - for k, lineno in enumerate(linenos): - if k+1 < len(linenos): - line = sort_by_calls[n][lineno] - next_line = sort_by_calls[n][linenos[k+1]] - if 'nb_queries' in line['line'] and next_line['time'] - line['time'] > 0: - line['line']['nb_queries'] += next_line['queries'] - line['queries'] - line['line']['delay'] += next_line['time'] - line['time'] - else: - line['line'].pop('nb_queries') - line['line'].pop('delay') + if call['lineno'] not in v['report']: + v['report'][call['lineno']] = { + 'nb_queries': 0, + 'delay': 0, + 'nb': 0, + } + v['report'][call['lineno']]['nb'] += 1 + + n = k+1 + while k+1 <= l and v['calls'][k+1]['callno'] != call['callno']: + n += 1 + if n >= l: + continue + next_call = v['calls'][n] + if next_call['queries'] is not None: + v['report'][call['lineno']]['nb_queries'] += next_call['queries'] - call.get('queries', 0) + v['report'][call['lineno']]['delay'] += next_call['time'] - call['time'] queries = 0 delay = 0 - v['nb_queries'] = 0 - v['delay'] = 0 - for line in v['lines'].values(): - queries += line.get('nb_queries', 0) - delay += line.get('delay', 0) + for call in v['report'].values(): + queries += call['nb_queries'] + delay += call['delay'] if minimum_time and minimum_time > delay*1000: continue @@ -190,8 +170,8 @@ def profile(method=None, whitelist=None, blacklist=(None,), files=None, # todo: no color if output in a file log.append("\033[1;33m%s %s--------------------- %s, %s\033[1;0m\n\n" % (v['model'] or '', '-' * (15-len(v['model'] or '')), v['filename'], v['firstline'])) for lineno, line in enumerate(v['code']): - if (lineno + v['firstline']) in v['lines']: - data = v['lines'][lineno + v['firstline']] + if (lineno + v['firstline']) in v['report']: + data = v['report'][lineno + v['firstline']] log.append("%-10s%-10s%-10s%s" % ( str(data['nb']) if 'nb_queries' in data else '.', str(data.get('nb_queries', '')), @@ -202,7 +182,7 @@ def profile(method=None, whitelist=None, blacklist=(None,), files=None, log.append(line[:-1]) log.append('\n') - log.append("%-10s%-10d%-10s\n\n" % ( + log.append("\nTotal:\n%-10s%-10d%-10s\n\n" % ( str(data['nb']), queries, str(round(delay*100000)/100)))