1# -*- coding: utf-8 -*- 2from decorator import decorator 3import inspect 4import logging 5import sys 6import time 7 8import odoo 9_logger = logging.getLogger(__name__) 10 11 12class _LogTracer(object): 13 def __init__(self, whitelist=None, blacklist=None, files=None, deep=False): 14 self.profiles = {} 15 self.whitelist = whitelist 16 self.blacklist = blacklist 17 self.files = files 18 self.deep = deep 19 self.first_frame = None 20 21 def tracer(self, frame, event, arg): 22 if not self.first_frame: 23 self.first_frame = frame.f_code 24 if not self.deep and self.first_frame != frame.f_code: 25 return self.tracer 26 27 if frame.f_code.co_name in ['<genexpr>', '__getattr__', '__iter__', '__init__']: 28 return 29 30 if 'self' not in frame.f_locals: 31 return self.tracer 32 33 if self.files and frame.f_code.co_filename not in self.files: 34 return self.tracer 35 36 in_self = frame.f_locals['self'] 37 38 if not isinstance(in_self, odoo.models.BaseModel): 39 return self.tracer 40 41 model = getattr(in_self, '_name', None) 42 43 if self.whitelist and model not in self.whitelist: 44 return self.tracer 45 if model in self.blacklist and self.first_frame != frame.f_code: 46 return self.tracer 47 48 if frame.f_code not in self.profiles: 49 try: 50 lines, firstline = inspect.getsourcelines(frame) 51 self.profiles[frame.f_code] = { 52 'model': model, 53 'filename': frame.f_code.co_filename, 54 'firstline': firstline, 55 'code': lines, 56 'calls': [], 57 'nb': 0, 58 } 59 except Exception: 60 return 61 codeProfile = self.profiles[frame.f_code] 62 63 if not frame.f_lineno: 64 codeProfile['nb'] += 1 65 66 cr = getattr(in_self, '_cr', None) 67 codeProfile['calls'].append({ 68 'event': event, 69 'lineno': frame.f_lineno, 70 'queries': cr and cr.sql_log_count, 71 'time': time.time(), 72 'callno': codeProfile['nb'], 73 }) 74 75 return self.tracer 76 77def profile(method=None, whitelist=None, blacklist=(None,), files=None, 78 minimum_time=0, minimum_queries=0): 79 """ 80 Decorate an entry point method. 81 If profile is used without params, log as shallow mode else, log 82 all methods for all odoo models by applying the optional filters. 83 84 :param whitelist: None or list of model names to display in the log 85 (Default: None) 86 :type whitelist: list or None 87 :param files: None or list of filenames to display in the log 88 (Default: None) 89 :type files: list or None 90 :param list blacklist: list model names to remove from the log 91 (Default: remove non odoo model from the log: [None]) 92 :param int minimum_time: minimum time (ms) to display a method 93 (Default: 0) 94 :param int minimum_queries: minimum sql queries to display a method 95 (Default: 0) 96 97 .. code-block:: python 98 99 from odoo.tools.profiler import profile 100 101 class SaleOrder(models.Model): 102 ... 103 104 @api.model 105 @profile # log only this create method 106 def create(self, vals): 107 ... 108 @profile() # log all methods for all odoo models 109 def unlink(self): 110 ... 111 @profile(whitelist=['sale.order', 'ir.model.data']) 112 def action_quotation_send(self): 113 ... 114 @profile(files=['/home/openerp/odoo/odoo/addons/sale/models/sale.py']) 115 def write(self): 116 ... 117 118 NB: The use of the profiler modifies the execution time 119 """ 120 121 deep = not method 122 123 def _odooProfile(method, *args, **kwargs): 124 log_tracer = _LogTracer(whitelist=whitelist, blacklist=blacklist, files=files, deep=deep) 125 sys.settrace(log_tracer.tracer) 126 try: 127 result = method(*args, **kwargs) 128 finally: 129 sys.settrace(None) 130 131 log = ["\n%-10s%-10s%s\n" % ('calls', 'queries', 'ms')] 132 133 for v in log_tracer.profiles.values(): 134 v['report'] = {} 135 l = len(v['calls']) 136 for k, call in enumerate(v['calls']): 137 if k+1 >= l: 138 continue 139 140 if call['lineno'] not in v['report']: 141 v['report'][call['lineno']] = { 142 'nb_queries': 0, 143 'delay': 0, 144 'nb': 0, 145 } 146 v['report'][call['lineno']]['nb'] += 1 147 148 n = k+1 149 while k+1 <= l and v['calls'][k+1]['callno'] != call['callno']: 150 n += 1 151 if n >= l: 152 continue 153 next_call = v['calls'][n] 154 if next_call['queries'] is not None: 155 v['report'][call['lineno']]['nb_queries'] += next_call['queries'] - call.get('queries', 0) 156 v['report'][call['lineno']]['delay'] += next_call['time'] - call['time'] 157 158 queries = 0 159 delay = 0 160 for call in v['report'].values(): 161 queries += call['nb_queries'] 162 delay += call['delay'] 163 164 if minimum_time and minimum_time > delay*1000: 165 continue 166 if minimum_queries and minimum_queries > queries: 167 continue 168 169 # todo: no color if output in a file 170 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'])) 171 for lineno, line in enumerate(v['code']): 172 if (lineno + v['firstline']) in v['report']: 173 data = v['report'][lineno + v['firstline']] 174 log.append("%-10s%-10s%-10s%s" % ( 175 str(data['nb']) if 'nb_queries' in data else '.', 176 str(data.get('nb_queries', '')), 177 str(round(data['delay']*100000)/100) if 'delay' in data else '', 178 line[:-1])) 179 else: 180 log.append(" " * 30) 181 log.append(line[:-1]) 182 log.append('\n') 183 184 log.append("\nTotal:\n%-10s%-10d%-10s\n\n" % ( 185 str(data['nb']), 186 queries, 187 str(round(delay*100000)/100))) 188 189 _logger.info(''.join(log)) 190 191 return result 192 193 if not method: 194 return lambda method: decorator(_odooProfile, method) 195 196 wrapper = decorator(_odooProfile, method) 197 return wrapper 198