mirror of
https://github.com/bringout/oca-ocb-core.git
synced 2026-04-21 13:52:07 +02:00
Initial commit: Core packages
This commit is contained in:
commit
12c29a983b
9512 changed files with 8379910 additions and 0 deletions
736
odoo-bringout-oca-ocb-base/odoo/tools/profiler.py
Normal file
736
odoo-bringout-oca-ocb-base/odoo/tools/profiler.py
Normal file
|
|
@ -0,0 +1,736 @@
|
|||
# -*- coding: utf-8 -*-
|
||||
# Part of Odoo. See LICENSE file for full copyright and licensing details.
|
||||
|
||||
from datetime import datetime
|
||||
import gc
|
||||
import json
|
||||
import logging
|
||||
import sys
|
||||
import time
|
||||
import threading
|
||||
import re
|
||||
import functools
|
||||
|
||||
from psycopg2 import sql
|
||||
|
||||
from odoo import tools
|
||||
|
||||
_logger = logging.getLogger(__name__)
|
||||
|
||||
# ensure we have a non patched time for profiling times when using freezegun
|
||||
real_datetime_now = datetime.now
|
||||
real_time = time.time.__call__
|
||||
|
||||
def _format_frame(frame):
|
||||
code = frame.f_code
|
||||
return (code.co_filename, frame.f_lineno, code.co_name, '')
|
||||
|
||||
|
||||
def _format_stack(stack):
|
||||
return [list(frame) for frame in stack]
|
||||
|
||||
|
||||
def get_current_frame(thread=None):
|
||||
if thread:
|
||||
frame = sys._current_frames()[thread.ident]
|
||||
else:
|
||||
frame = sys._getframe()
|
||||
while frame.f_code.co_filename == __file__:
|
||||
frame = frame.f_back
|
||||
return frame
|
||||
|
||||
|
||||
def _get_stack_trace(frame, limit_frame=None):
|
||||
stack = []
|
||||
while frame is not None and frame != limit_frame:
|
||||
stack.append(_format_frame(frame))
|
||||
frame = frame.f_back
|
||||
if frame is None and limit_frame:
|
||||
_logger.error("Limit frame was not found")
|
||||
return list(reversed(stack))
|
||||
|
||||
|
||||
def stack_size():
|
||||
frame = get_current_frame()
|
||||
size = 0
|
||||
while frame:
|
||||
size += 1
|
||||
frame = frame.f_back
|
||||
return size
|
||||
|
||||
|
||||
def make_session(name=''):
|
||||
return f'{real_datetime_now():%Y-%m-%d %H:%M:%S} {name}'
|
||||
|
||||
|
||||
def force_hook():
|
||||
"""
|
||||
Force periodic profiling collectors to generate some stack trace. This is
|
||||
useful before long calls that do not release the GIL, so that the time
|
||||
spent in those calls is attributed to a specific stack trace, instead of
|
||||
some arbitrary former frame.
|
||||
"""
|
||||
thread = threading.current_thread()
|
||||
for func in getattr(thread, 'profile_hooks', ()):
|
||||
func()
|
||||
|
||||
|
||||
class Collector:
|
||||
"""
|
||||
Base class for objects that collect profiling data.
|
||||
|
||||
A collector object is used by a profiler to collect profiling data, most
|
||||
likely a list of stack traces with time and some context information added
|
||||
by ExecutionContext decorator on current thread.
|
||||
|
||||
This is a generic implementation of a basic collector, to be inherited.
|
||||
It defines default behaviors for creating an entry in the collector.
|
||||
"""
|
||||
name = None # symbolic name of the collector
|
||||
_registry = {} # map collector names to their class
|
||||
|
||||
@classmethod
|
||||
def __init_subclass__(cls):
|
||||
if cls.name:
|
||||
cls._registry[cls.name] = cls
|
||||
cls._registry[cls.__name__] = cls
|
||||
|
||||
@classmethod
|
||||
def make(cls, name, *args, **kwargs):
|
||||
""" Instantiate a collector corresponding to the given name. """
|
||||
return cls._registry[name](*args, **kwargs)
|
||||
|
||||
def __init__(self):
|
||||
self._processed = False
|
||||
self._entries = []
|
||||
self.profiler = None
|
||||
|
||||
def start(self):
|
||||
""" Start the collector. """
|
||||
|
||||
def stop(self):
|
||||
""" Stop the collector. """
|
||||
|
||||
def add(self, entry=None, frame=None):
|
||||
""" Add an entry (dict) to this collector. """
|
||||
self._entries.append({
|
||||
'stack': self._get_stack_trace(frame),
|
||||
'exec_context': getattr(self.profiler.init_thread, 'exec_context', ()),
|
||||
'start': real_time(),
|
||||
**(entry or {}),
|
||||
})
|
||||
|
||||
def progress(self, entry=None, frame=None):
|
||||
""" Checks if the limits were met and add to the entries"""
|
||||
if self.profiler.entry_count_limit \
|
||||
and self.profiler.entry_count() >= self.profiler.entry_count_limit:
|
||||
self.profiler.end()
|
||||
|
||||
self.add(entry=entry, frame=frame)
|
||||
|
||||
def _get_stack_trace(self, frame=None):
|
||||
""" Return the stack trace to be included in a given entry. """
|
||||
frame = frame or get_current_frame(self.profiler.init_thread)
|
||||
return _get_stack_trace(frame, self.profiler.init_frame)
|
||||
|
||||
def post_process(self):
|
||||
for entry in self._entries:
|
||||
stack = entry.get('stack', [])
|
||||
self.profiler._add_file_lines(stack)
|
||||
|
||||
@property
|
||||
def entries(self):
|
||||
""" Return the entries of the collector after postprocessing. """
|
||||
if not self._processed:
|
||||
self.post_process()
|
||||
self._processed = True
|
||||
return self._entries
|
||||
|
||||
|
||||
class SQLCollector(Collector):
|
||||
"""
|
||||
Saves all executed queries in the current thread with the call stack.
|
||||
"""
|
||||
name = 'sql'
|
||||
|
||||
def start(self):
|
||||
init_thread = self.profiler.init_thread
|
||||
if not hasattr(init_thread, 'query_hooks'):
|
||||
init_thread.query_hooks = []
|
||||
init_thread.query_hooks.append(self.hook)
|
||||
|
||||
def stop(self):
|
||||
self.profiler.init_thread.query_hooks.remove(self.hook)
|
||||
|
||||
def hook(self, cr, query, params, query_start, query_time):
|
||||
self.progress({
|
||||
'query': str(query),
|
||||
'full_query': str(cr._format(query, params)),
|
||||
'start': query_start,
|
||||
'time': query_time,
|
||||
})
|
||||
|
||||
|
||||
class PeriodicCollector(Collector):
|
||||
"""
|
||||
Record execution frames asynchronously at most every `interval` seconds.
|
||||
|
||||
:param interval (float): time to wait in seconds between two samples.
|
||||
"""
|
||||
name = 'traces_async'
|
||||
|
||||
def __init__(self, interval=0.01): # check duration. dynamic?
|
||||
super().__init__()
|
||||
self.active = False
|
||||
self.frame_interval = interval
|
||||
self.__thread = threading.Thread(target=self.run)
|
||||
self.last_frame = None
|
||||
|
||||
def run(self):
|
||||
self.active = True
|
||||
last_time = real_time()
|
||||
while self.active: # maybe add a check on parent_thread state?
|
||||
duration = real_time() - last_time
|
||||
if duration > self.frame_interval * 10 and self.last_frame:
|
||||
# The profiler has unexpectedly slept for more than 10 frame intervals. This may
|
||||
# happen when calling a C library without releasing the GIL. In that case, the
|
||||
# last frame was taken before the call, and the next frame is after the call, and
|
||||
# the call itself does not appear in any of those frames: the duration of the call
|
||||
# is incorrectly attributed to the last frame.
|
||||
self._entries[-1]['stack'].append(('profiling', 0, '⚠ Profiler freezed for %s s' % duration, ''))
|
||||
self.last_frame = None # skip duplicate detection for the next frame.
|
||||
self.progress()
|
||||
last_time = real_time()
|
||||
time.sleep(self.frame_interval)
|
||||
|
||||
self._entries.append({'stack': [], 'start': real_time()}) # add final end frame
|
||||
|
||||
def start(self):
|
||||
interval = self.profiler.params.get('traces_async_interval')
|
||||
if interval:
|
||||
self.frame_interval = min(max(float(interval), 0.001), 1)
|
||||
|
||||
init_thread = self.profiler.init_thread
|
||||
if not hasattr(init_thread, 'profile_hooks'):
|
||||
init_thread.profile_hooks = []
|
||||
init_thread.profile_hooks.append(self.progress)
|
||||
|
||||
self.__thread.start()
|
||||
|
||||
def stop(self):
|
||||
self.active = False
|
||||
self.__thread.join()
|
||||
self.profiler.init_thread.profile_hooks.remove(self.progress)
|
||||
|
||||
def add(self, entry=None, frame=None):
|
||||
""" Add an entry (dict) to this collector. """
|
||||
frame = frame or get_current_frame(self.profiler.init_thread)
|
||||
if frame == self.last_frame:
|
||||
# don't save if the frame is exactly the same as the previous one.
|
||||
# maybe modify the last entry to add a last seen?
|
||||
return
|
||||
self.last_frame = frame
|
||||
super().add(entry=entry, frame=frame)
|
||||
|
||||
|
||||
class SyncCollector(Collector):
|
||||
"""
|
||||
Record complete execution synchronously.
|
||||
Note that --limit-memory-hard may need to be increased when launching Odoo.
|
||||
"""
|
||||
name = 'traces_sync'
|
||||
|
||||
def start(self):
|
||||
if sys.gettrace() is not None:
|
||||
_logger.error("Cannot start SyncCollector, settrace already set: %s", sys.gettrace())
|
||||
assert not self._processed, "You cannot start SyncCollector after accessing entries."
|
||||
sys.settrace(self.hook) # todo test setprofile, but maybe not multithread safe
|
||||
|
||||
def stop(self):
|
||||
sys.settrace(None)
|
||||
|
||||
def hook(self, _frame, event, _arg=None):
|
||||
if event == 'line':
|
||||
return
|
||||
entry = {'event': event, 'frame': _format_frame(_frame)}
|
||||
if event == 'call' and _frame.f_back:
|
||||
# we need the parent frame to determine the line number of the call
|
||||
entry['parent_frame'] = _format_frame(_frame.f_back)
|
||||
self.progress(entry, frame=_frame)
|
||||
return self.hook
|
||||
|
||||
def _get_stack_trace(self, frame=None):
|
||||
# Getting the full stack trace is slow, and not useful in this case.
|
||||
# SyncCollector only saves the top frame and event at each call and
|
||||
# recomputes the complete stack at the end.
|
||||
return None
|
||||
|
||||
def post_process(self):
|
||||
# Transform the evented traces to full stack traces. This processing
|
||||
# could be avoided since speedscope will transform that back to
|
||||
# evented anyway, but it is actually simpler to integrate into the
|
||||
# current speedscope logic, especially when mixed with SQLCollector.
|
||||
# We could improve it by saving as evented and manage it later.
|
||||
stack = []
|
||||
for entry in self._entries:
|
||||
frame = entry.pop('frame')
|
||||
event = entry.pop('event')
|
||||
if event == 'call':
|
||||
if stack:
|
||||
stack[-1] = entry.pop('parent_frame')
|
||||
stack.append(frame)
|
||||
elif event == 'return':
|
||||
stack.pop()
|
||||
entry['stack'] = stack[:]
|
||||
super().post_process()
|
||||
|
||||
|
||||
class QwebTracker():
|
||||
|
||||
@classmethod
|
||||
def wrap_render(cls, method_render):
|
||||
@functools.wraps(method_render)
|
||||
def _tracked_method_render(self, template, values=None, **options):
|
||||
current_thread = threading.current_thread()
|
||||
execution_context_enabled = getattr(current_thread, 'profiler_params', {}).get('execution_context_qweb')
|
||||
qweb_hooks = getattr(current_thread, 'qweb_hooks', ())
|
||||
if execution_context_enabled or qweb_hooks:
|
||||
# To have the new compilation cached because the generated code will change.
|
||||
# Therefore 'profile' is a key to the cache.
|
||||
options['profile'] = True
|
||||
return method_render(self, template, values, **options)
|
||||
return _tracked_method_render
|
||||
|
||||
@classmethod
|
||||
def wrap_compile(cls, method_compile):
|
||||
@functools.wraps(method_compile)
|
||||
def _tracked_compile(self, template):
|
||||
if not self.env.context.get('profile'):
|
||||
return method_compile(self, template)
|
||||
|
||||
template_functions, def_name = method_compile(self, template)
|
||||
render_template = template_functions[def_name]
|
||||
|
||||
def profiled_method_compile(self, values):
|
||||
options = template_functions['options']
|
||||
ref = options.get('ref')
|
||||
ref_xml = options.get('ref_xml')
|
||||
qweb_tracker = QwebTracker(ref, ref_xml, self.env.cr)
|
||||
self = self.with_context(qweb_tracker=qweb_tracker)
|
||||
if qweb_tracker.execution_context_enabled:
|
||||
with ExecutionContext(template=ref):
|
||||
return render_template(self, values)
|
||||
return render_template(self, values)
|
||||
template_functions[def_name] = profiled_method_compile
|
||||
|
||||
return (template_functions, def_name)
|
||||
return _tracked_compile
|
||||
|
||||
@classmethod
|
||||
def wrap_compile_directive(cls, method_compile_directive):
|
||||
@functools.wraps(method_compile_directive)
|
||||
def _tracked_compile_directive(self, el, options, directive, level):
|
||||
if not options.get('profile') or directive in ('inner-content', 'tag-open', 'tag-close'):
|
||||
return method_compile_directive(self, el, options, directive, level)
|
||||
enter = f"{' ' * 4 * level}self.env.context['qweb_tracker'].enter_directive({directive!r}, {el.attrib!r}, {options['_qweb_error_path_xml'][0]!r})"
|
||||
leave = f"{' ' * 4 * level}self.env.context['qweb_tracker'].leave_directive({directive!r}, {el.attrib!r}, {options['_qweb_error_path_xml'][0]!r})"
|
||||
code_directive = method_compile_directive(self, el, options, directive, level)
|
||||
return [enter, *code_directive, leave] if code_directive else []
|
||||
return _tracked_compile_directive
|
||||
|
||||
def __init__(self, view_id, arch, cr):
|
||||
current_thread = threading.current_thread() # don't store current_thread on self
|
||||
self.execution_context_enabled = getattr(current_thread, 'profiler_params', {}).get('execution_context_qweb')
|
||||
self.qweb_hooks = getattr(current_thread, 'qweb_hooks', ())
|
||||
self.context_stack = []
|
||||
self.cr = cr
|
||||
self.view_id = view_id
|
||||
for hook in self.qweb_hooks:
|
||||
hook('render', self.cr.sql_log_count, view_id=view_id, arch=arch)
|
||||
|
||||
def enter_directive(self, directive, attrib, xpath):
|
||||
execution_context = None
|
||||
if self.execution_context_enabled:
|
||||
directive_info = {}
|
||||
if ('t-' + directive) in attrib:
|
||||
directive_info['t-' + directive] = repr(attrib['t-' + directive])
|
||||
if directive == 'set':
|
||||
if 't-value' in attrib:
|
||||
directive_info['t-value'] = repr(attrib['t-value'])
|
||||
if 't-valuef' in attrib:
|
||||
directive_info['t-valuef'] = repr(attrib['t-valuef'])
|
||||
|
||||
for key in attrib:
|
||||
if key.startswith('t-set-') or key.startswith('t-setf-'):
|
||||
directive_info[key] = repr(attrib[key])
|
||||
elif directive == 'foreach':
|
||||
directive_info['t-as'] = repr(attrib['t-as'])
|
||||
elif directive == 'groups' and 'groups' in attrib and not directive_info.get('t-groups'):
|
||||
directive_info['t-groups'] = repr(attrib['groups'])
|
||||
elif directive == 'att':
|
||||
for key in attrib:
|
||||
if key.startswith('t-att-') or key.startswith('t-attf-'):
|
||||
directive_info[key] = repr(attrib[key])
|
||||
elif directive == 'options':
|
||||
for key in attrib:
|
||||
if key.startswith('t-options-'):
|
||||
directive_info[key] = repr(attrib[key])
|
||||
elif ('t-' + directive) not in attrib:
|
||||
directive_info['t-' + directive] = None
|
||||
|
||||
execution_context = tools.profiler.ExecutionContext(**directive_info, xpath=xpath)
|
||||
execution_context.__enter__()
|
||||
self.context_stack.append(execution_context)
|
||||
|
||||
for hook in self.qweb_hooks:
|
||||
hook('enter', self.cr.sql_log_count, view_id=self.view_id, xpath=xpath, directive=directive, attrib=attrib)
|
||||
|
||||
def leave_directive(self, directive, attrib, xpath):
|
||||
if self.execution_context_enabled:
|
||||
self.context_stack.pop().__exit__()
|
||||
|
||||
for hook in self.qweb_hooks:
|
||||
hook('leave', self.cr.sql_log_count, view_id=self.view_id, xpath=xpath, directive=directive, attrib=attrib)
|
||||
|
||||
|
||||
class QwebCollector(Collector):
|
||||
"""
|
||||
Record qweb execution with directive trace.
|
||||
"""
|
||||
name = 'qweb'
|
||||
|
||||
def __init__(self):
|
||||
super().__init__()
|
||||
self.events = []
|
||||
|
||||
def hook(event, sql_log_count, **kwargs):
|
||||
self.events.append((event, kwargs, sql_log_count, real_time()))
|
||||
self.hook = hook
|
||||
|
||||
def _get_directive_profiling_name(self, directive, attrib):
|
||||
expr = ''
|
||||
if directive == 'set':
|
||||
if 't-set' in attrib:
|
||||
expr = f"t-set={repr(attrib['t-set'])}"
|
||||
if 't-value' in attrib:
|
||||
expr += f" t-value={repr(attrib['t-value'])}"
|
||||
if 't-valuef' in attrib:
|
||||
expr += f" t-valuef={repr(attrib['t-valuef'])}"
|
||||
for key in attrib:
|
||||
if key.startswith('t-set-') or key.startswith('t-setf-'):
|
||||
if expr:
|
||||
expr += ' '
|
||||
expr += f"{key}={repr(attrib[key])}"
|
||||
elif directive == 'foreach':
|
||||
expr = f"t-foreach={repr(attrib['t-foreach'])} t-as={repr(attrib['t-as'])}"
|
||||
elif directive == 'options':
|
||||
if attrib.get('t-options'):
|
||||
expr = f"t-options={repr(attrib['t-options'])}"
|
||||
for key in attrib:
|
||||
if key.startswith('t-options-'):
|
||||
expr = f"{expr} {key}={repr(attrib[key])}"
|
||||
elif directive == 'att':
|
||||
for key in attrib:
|
||||
if key == 't-att' or key.startswith('t-att-') or key.startswith('t-attf-'):
|
||||
if expr:
|
||||
expr += ' '
|
||||
expr += f"{key}={repr(attrib[key])}"
|
||||
elif ('t-' + directive) in attrib:
|
||||
expr = f"t-{directive}={repr(attrib['t-' + directive])}"
|
||||
else:
|
||||
expr = f"t-{directive}"
|
||||
|
||||
return expr
|
||||
|
||||
def start(self):
|
||||
init_thread = self.profiler.init_thread
|
||||
if not hasattr(init_thread, 'qweb_hooks'):
|
||||
init_thread.qweb_hooks = []
|
||||
init_thread.qweb_hooks.append(self.hook)
|
||||
|
||||
def stop(self):
|
||||
self.profiler.init_thread.qweb_hooks.remove(self.hook)
|
||||
|
||||
def post_process(self):
|
||||
last_event_query = None
|
||||
last_event_time = None
|
||||
stack = []
|
||||
results = []
|
||||
archs = {}
|
||||
for event, kwargs, sql_count, time in self.events:
|
||||
if event == 'render':
|
||||
archs[kwargs['view_id']] = kwargs['arch']
|
||||
continue
|
||||
|
||||
# update the active directive with the elapsed time and queries
|
||||
if stack:
|
||||
top = stack[-1]
|
||||
top['delay'] += time - last_event_time
|
||||
top['query'] += sql_count - last_event_query
|
||||
last_event_time = time
|
||||
last_event_query = sql_count
|
||||
|
||||
directive = self._get_directive_profiling_name(kwargs['directive'], kwargs['attrib'])
|
||||
if directive:
|
||||
if event == 'enter':
|
||||
data = {
|
||||
'view_id': kwargs['view_id'],
|
||||
'xpath': kwargs['xpath'],
|
||||
'directive': directive,
|
||||
'delay': 0,
|
||||
'query': 0,
|
||||
}
|
||||
results.append(data)
|
||||
stack.append(data)
|
||||
else:
|
||||
assert event == "leave"
|
||||
data = stack.pop()
|
||||
|
||||
self.add({'results': {'archs': archs, 'data': results}})
|
||||
super().post_process()
|
||||
|
||||
|
||||
class ExecutionContext:
|
||||
"""
|
||||
Add some context on thread at current call stack level.
|
||||
This context stored by collector beside stack and is used by Speedscope
|
||||
to add a level to the stack with this information.
|
||||
"""
|
||||
def __init__(self, **context):
|
||||
self.context = context
|
||||
self.previous_context = None
|
||||
|
||||
def __enter__(self):
|
||||
current_thread = threading.current_thread()
|
||||
self.previous_context = getattr(current_thread, 'exec_context', ())
|
||||
current_thread.exec_context = self.previous_context + ((stack_size(), self.context),)
|
||||
|
||||
def __exit__(self, *_args):
|
||||
threading.current_thread().exec_context = self.previous_context
|
||||
|
||||
|
||||
class Profiler:
|
||||
"""
|
||||
Context manager to use to start the recording of some execution.
|
||||
Will save sql and async stack trace by default.
|
||||
"""
|
||||
def __init__(self, collectors=None, db=..., profile_session=None,
|
||||
description=None, disable_gc=False, params=None):
|
||||
"""
|
||||
:param db: database name to use to save results.
|
||||
Will try to define database automatically by default.
|
||||
Use value ``None`` to not save results in a database.
|
||||
:param collectors: list of string and Collector object Ex: ['sql', PeriodicCollector(interval=0.2)]. Use `None` for default collectors
|
||||
:param profile_session: session description to use to reproup multiple profile. use make_session(name) for default format.
|
||||
:param description: description of the current profiler Suggestion: (route name/test method/loading module, ...)
|
||||
:param disable_gc: flag to disable gc durring profiling (usefull to avoid gc while profiling, especially during sql execution)
|
||||
:param params: parameters usable by collectors (like frame interval)
|
||||
"""
|
||||
self.start_time = 0
|
||||
self.duration = 0
|
||||
self.profile_session = profile_session or make_session()
|
||||
self.description = description
|
||||
self.init_frame = None
|
||||
self.init_stack_trace = None
|
||||
self.init_thread = None
|
||||
self.disable_gc = disable_gc
|
||||
self.filecache = {}
|
||||
self.params = params or {} # custom parameters usable by collectors
|
||||
self.profile_id = None
|
||||
self.entry_count_limit = int(self.params.get("entry_count_limit", 0)) # the limit could be set using a smarter way
|
||||
self.done = False
|
||||
|
||||
if db is ...:
|
||||
# determine database from current thread
|
||||
db = getattr(threading.current_thread(), 'dbname', None)
|
||||
if not db:
|
||||
# only raise if path is not given and db is not explicitely disabled
|
||||
raise Exception('Database name cannot be defined automaticaly. \n Please provide a valid/falsy dbname or path parameter')
|
||||
self.db = db
|
||||
|
||||
# collectors
|
||||
if collectors is None:
|
||||
collectors = ['sql', 'traces_async']
|
||||
self.collectors = []
|
||||
for collector in collectors:
|
||||
if isinstance(collector, str):
|
||||
try:
|
||||
collector = Collector.make(collector)
|
||||
except Exception:
|
||||
_logger.error("Could not create collector with name %r", collector)
|
||||
continue
|
||||
collector.profiler = self
|
||||
self.collectors.append(collector)
|
||||
|
||||
def __enter__(self):
|
||||
self.init_thread = threading.current_thread()
|
||||
try:
|
||||
self.init_frame = get_current_frame(self.init_thread)
|
||||
self.init_stack_trace = _get_stack_trace(self.init_frame)
|
||||
except KeyError:
|
||||
# when using thread pools (gevent) the thread won't exist in the current_frames
|
||||
# this case is managed by http.py but will still fail when adding a profiler
|
||||
# inside a piece of code that may be called by a longpolling route.
|
||||
# in this case, avoid crashing the caller and disable all collectors
|
||||
self.init_frame = self.init_stack_trace = self.collectors = []
|
||||
self.db = self.params = None
|
||||
message = "Cannot start profiler, thread not found. Is the thread part of a thread pool?"
|
||||
if not self.description:
|
||||
self.description = message
|
||||
_logger.warning(message)
|
||||
|
||||
if self.description is None:
|
||||
frame = self.init_frame
|
||||
code = frame.f_code
|
||||
self.description = f"{frame.f_code.co_name} ({code.co_filename}:{frame.f_lineno})"
|
||||
if self.params:
|
||||
self.init_thread.profiler_params = self.params
|
||||
if self.disable_gc and gc.isenabled():
|
||||
gc.disable()
|
||||
self.start_time = real_time()
|
||||
for collector in self.collectors:
|
||||
collector.start()
|
||||
return self
|
||||
|
||||
def __exit__(self, *args):
|
||||
self.end()
|
||||
|
||||
def end(self):
|
||||
if self.done:
|
||||
return
|
||||
self.done = True
|
||||
try:
|
||||
for collector in self.collectors:
|
||||
collector.stop()
|
||||
self.duration = real_time() - self.start_time
|
||||
self._add_file_lines(self.init_stack_trace)
|
||||
|
||||
if self.db:
|
||||
# pylint: disable=import-outside-toplevel
|
||||
from odoo.sql_db import db_connect # only import from odoo if/when needed.
|
||||
with db_connect(self.db).cursor() as cr:
|
||||
values = {
|
||||
"name": self.description,
|
||||
"session": self.profile_session,
|
||||
"create_date": real_datetime_now(),
|
||||
"init_stack_trace": json.dumps(_format_stack(self.init_stack_trace)),
|
||||
"duration": self.duration,
|
||||
"entry_count": self.entry_count(),
|
||||
"sql_count": sum(len(collector.entries) for collector in self.collectors if collector.name == 'sql')
|
||||
}
|
||||
for collector in self.collectors:
|
||||
if collector.entries:
|
||||
values[collector.name] = json.dumps(collector.entries)
|
||||
query = sql.SQL("INSERT INTO {}({}) VALUES %s RETURNING id").format(
|
||||
sql.Identifier("ir_profile"),
|
||||
sql.SQL(",").join(map(sql.Identifier, values)),
|
||||
)
|
||||
cr.execute(query, [tuple(values.values())])
|
||||
self.profile_id = cr.fetchone()[0]
|
||||
_logger.info('ir_profile %s (%s) created', self.profile_id, self.profile_session)
|
||||
finally:
|
||||
if self.disable_gc:
|
||||
gc.enable()
|
||||
if self.params:
|
||||
del self.init_thread.profiler_params
|
||||
|
||||
def _get_cm_proxy(self):
|
||||
return _Nested(self)
|
||||
|
||||
def _add_file_lines(self, stack):
|
||||
for index, frame in enumerate(stack):
|
||||
(filename, lineno, name, line) = frame
|
||||
if line != '':
|
||||
continue
|
||||
# retrieve file lines from the filecache
|
||||
if not lineno:
|
||||
continue
|
||||
try:
|
||||
filelines = self.filecache[filename]
|
||||
except KeyError:
|
||||
try:
|
||||
with tools.file_open(filename, filter_ext=('.py',)) as f:
|
||||
filelines = f.readlines()
|
||||
except (ValueError, FileNotFoundError): # mainly for <decorator> "filename"
|
||||
filelines = None
|
||||
self.filecache[filename] = filelines
|
||||
# fill in the line
|
||||
if filelines is not None:
|
||||
line = filelines[lineno - 1]
|
||||
stack[index] = (filename, lineno, name, line)
|
||||
|
||||
def entry_count(self):
|
||||
""" Return the total number of entries collected in this profiler. """
|
||||
return sum(len(collector.entries) for collector in self.collectors)
|
||||
|
||||
def format_path(self, path):
|
||||
"""
|
||||
Utility function to format a path for this profiler.
|
||||
This is mainly useful to uniquify a path between executions.
|
||||
"""
|
||||
return path.format(
|
||||
time=real_datetime_now().strftime("%Y%m%d-%H%M%S"),
|
||||
len=self.entry_count(),
|
||||
desc=re.sub("[^0-9a-zA-Z-]+", "_", self.description)
|
||||
)
|
||||
|
||||
def json(self):
|
||||
"""
|
||||
Utility function to generate a json version of this profiler.
|
||||
This is useful to write profiling entries into a file, such as::
|
||||
|
||||
with Profiler(db=None) as profiler:
|
||||
do_stuff()
|
||||
|
||||
filename = p.format_path('/home/foo/{desc}_{len}.json')
|
||||
with open(filename, 'w') as f:
|
||||
f.write(profiler.json())
|
||||
"""
|
||||
return json.dumps({
|
||||
"name": self.description,
|
||||
"session": self.profile_session,
|
||||
"create_date": real_datetime_now().strftime("%Y%m%d-%H%M%S"),
|
||||
"init_stack_trace": _format_stack(self.init_stack_trace),
|
||||
"duration": self.duration,
|
||||
"collectors": {collector.name: collector.entries for collector in self.collectors},
|
||||
}, indent=4)
|
||||
|
||||
|
||||
class _Nested:
|
||||
__slots__ = ("__profiler",)
|
||||
|
||||
def __init__(self, profiler):
|
||||
self.__profiler = profiler
|
||||
|
||||
def __enter__(self):
|
||||
self.__profiler.__enter__()
|
||||
return self
|
||||
|
||||
def __exit__(self, *args):
|
||||
return self.__profiler.__exit__(*args)
|
||||
|
||||
|
||||
class Nested:
|
||||
"""
|
||||
Utility to nest another context manager inside a profiler.
|
||||
|
||||
The profiler should only be called directly in the "with" without nesting it
|
||||
with ExitStack. If not, the retrieval of the 'init_frame' may be incorrect
|
||||
and lead to an error "Limit frame was not found" when profiling. Since the
|
||||
stack will ignore all stack frames inside this file, the nested frames will
|
||||
be ignored, too. This is also why Nested() does not use
|
||||
contextlib.contextmanager.
|
||||
"""
|
||||
def __init__(self, profiler, context_manager):
|
||||
self.profiler = profiler
|
||||
self.context_manager = context_manager
|
||||
|
||||
def __enter__(self):
|
||||
self.profiler.__enter__()
|
||||
return self.context_manager.__enter__()
|
||||
|
||||
def __exit__(self, exc_type, exc_value, traceback):
|
||||
try:
|
||||
return self.context_manager.__exit__(exc_type, exc_value, traceback)
|
||||
finally:
|
||||
self.profiler.__exit__(exc_type, exc_value, traceback)
|
||||
Loading…
Add table
Add a link
Reference in a new issue