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