From f4d0c728160e2e2c503c871329ed24cf5086c54c Mon Sep 17 00:00:00 2001 From: Xavier-Do Date: Wed, 18 Aug 2021 10:02:35 +0000 Subject: [PATCH] [FIX] profiling: manage long calls with the GIL Sometimes the profiler provides confusing information. This happens when calling a C library without releasing the GIL (Python's global interpreter lock). The time spent in the call will be attributed by the profiler to the former stack trace, because the collector cannot run during the call. This commit adds information on the frame when a given stack frame has lasted for too long. X-original-commit: 5e193c5dbcdfbdbab38309ed292131ae1f5d3026 --- odoo/tools/profiler.py | 12 ++++++++++++ 1 file changed, 12 insertions(+) diff --git a/odoo/tools/profiler.py b/odoo/tools/profiler.py index 61e611a3e9f..a0a0bfe035b 100644 --- a/odoo/tools/profiler.py +++ b/odoo/tools/profiler.py @@ -166,9 +166,21 @@ class PeriodicCollector(Collector): def run(self): self.active = True + last_time = time.time() while self.active: # maybe add a check on parent_thread state? + duration = time.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.add() + last_time = time.time() time.sleep(self.frame_interval) + self._entries.append({'stack': [], 'start': time.time()}) # add final end frame def start(self):