Python-Profiler bug: Bad call

[d-maurer]

BPO	744841
Nosy	@rhettinger, @d-maurer
Files	prof2.py: Run through Python interpreter to reproduce the bug profile.pat: Patch to "profile.py" preventing the bug

^{Note: these values reflect the state of the issue at the time it was migrated and might not reflect the current state.}

Show more details

GitHub fields:

assignee = None
closed_at = <Date 2013-05-31.11:52:30.709>
created_at = <Date 2003-05-28.11:02:00.000>
labels = ['interpreter-core', 'performance']
title = 'Python-Profiler bug: Bad call'
updated_at = <Date 2013-05-31.11:52:30.709>
user = 'https://github.com/d-maurer'

bugs.python.org fields:

activity = <Date 2013-05-31.11:52:30.709>
actor = 'Terje.Wiesener'
assignee = 'none'
closed = True
closed_date = None
closer = None
components = ['Interpreter Core']
creation = <Date 2003-05-28.11:02:00.000>
creator = 'dmaurer'
dependencies = []
files = ['901', '902']
hgrepos = []
issue_num = 744841
keywords = []
message_count = 6.0
messages = ['16182', '16183', '16184', '16185', '16186', '190402']
nosy_count = 5.0
nosy_names = ['nnorwitz', 'rhettinger', 'dmaurer', 'glyf', 'Terje.Wiesener']
pr_nums = []
priority = 'normal'
resolution = 'out of date'
stage = None
status = 'closed'
superseder = None
type = 'performance'
url = 'https://bugs.python.org/issue744841'
versions = ['Python 2.7']

[d-maurer]

There is a timing problem between the call of
"call_trace(profile_func,...,'return',...)" and
"reset_exc_info" in Pythons main interpreter loop.

The main loop first calls "call_trace" (at the end of
function execution). With the
standard "profile.Profile" profiler this leads to a pop
of the current frame from the profiler stack while
the current frame is still on the interpreter stack.
Then "reset_exc_info" is called. When this call releases
an instance with a destructor ("__del__" method), the
"call_trace(profile_func,...'call',...)" for the destructor
observes the inconsistency between the profiler and the
interpreter stack and raises a "Bad call" exception. This
exception disables profiling effectively. However, the
exception is later ignored (as we are in a destructor) and
program execution continues. When the profiling is later
finished, all time after the exception is accounted for the
last function, that was on top of the profiler stack when
profiling was disabled. This can be extremely confusing.

The attached script reproduces the problem. Run it
through the Python interpreter. When you see an
"Exception Bad call ... ignored", the interpreter has the
described problem. We observed the problem in Python
2.1.3
(on Linux, Solaris and Windows).

[nnorwitz]

Logged In: YES
user_id=33168

The good news is that this has been fixed in Python 2.2.x
and beyond.

[d-maurer]

Logged In: YES
user_id=265829

Apparently, a colleague observed the bug also in Python 2.2.2.

[rhettinger]

Logged In: YES
user_id=80475

I've run your script on Py2.2.3 and 2.3b1+ and did not
observe "Exception Bad cad ... ignored".

Marking this one as already fixed.

[glyf]

Logged In: YES
user_id=226807

I believe this bug has cropped up again. On my Debian system:

glyph@kazekage:~% python -V ; python Downloads/prof2.py |
head -3
Python 2.3.3
Exception exceptions.AssertionError:
<exceptions.AssertionError instance at 0x403b270c> in <bound
method C.__del__ of <main.C instance at 0x403b26ec>> ignored
exceptions.ZeroDivisionError
5 function calls in 0.000 CPU seconds

This is not the same error as before, but it is just as
clearly wrong.

[TerjeWiesener]

This bug seems to have resurfaced in newer python versions.

I have tested the file attached in the original report (prof2.py) in python 2.6.6 and 2.7 (x86 versions) under Windows 7, and both give the same output:

c:\temp>c:\Python27\python.exe prof2.py
<type 'exceptions.ZeroDivisionError'>
Exception AssertionError: AssertionError('Bad call', ('prof2.py', 19, 'h'), <frame object at 0x023880E0>, <frame object at 0x00586E18>, <frame object at 0x02388518>, <frame object at 0x02388248>) in <
bound method C.__del__ of <main.C instance at 0x02342A80>> ignored
5 function calls in 0.007 CPU seconds

Ordered by: standard name

ncalls tottime percall cumtime percall filename:lineno(function)
1 0.000 0.000 0.007 0.007 <string>:1(<module>)
1 0.001 0.001 0.001 0.001 prof2.py:11(g)
1 0.006 0.006 0.007 0.007 prof2.py:19(h)
1 0.000 0.000 0.000 0.000 prof2.py:7(f)
1 0.000 0.000 0.007 0.007 profile:0(h())
0 0.000 0.000 profile:0(profiler)