This issue tracker has been migrated to GitHub, and is currently read-only.
For more information, see the GitHub FAQs in the Python's Developer Guide.

classification
Title: Python-Profiler bug: Bad call
Type: performance Stage:
Components: Interpreter Core Versions: Python 2.7
process
Status: closed Resolution: out of date
Dependencies: Superseder:
Assigned To: Nosy List: Terje.Wiesener, dmaurer, glyf, nnorwitz, rhettinger
Priority: normal Keywords:

Created on 2003-05-28 11:02 by dmaurer, last changed 2022-04-10 16:08 by admin. This issue is now closed.

Files
File name Uploaded Description Edit
prof2.py dmaurer, 2003-05-28 11:02 Run through Python interpreter to reproduce the bug
profile.pat dmaurer, 2003-06-06 08:23 Patch to "profile.py" preventing the bug
Messages (6)
msg16182 - (view) Author: Dieter Maurer (dmaurer) Date: 2003-05-28 11:02
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).
msg16183 - (view) Author: Neal Norwitz (nnorwitz) * (Python committer) Date: 2003-05-29 00:01
Logged In: YES 
user_id=33168

The good news is that this has been fixed in Python 2.2.x
and beyond.
msg16184 - (view) Author: Dieter Maurer (dmaurer) Date: 2003-06-06 08:23
Logged In: YES 
user_id=265829

Apparently, a colleague observed the bug also in Python 2.2.2.
msg16185 - (view) Author: Raymond Hettinger (rhettinger) * (Python committer) Date: 2003-06-25 15:27
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.
msg16186 - (view) Author: Glyph Lefkowitz (glyf) Date: 2004-01-16 16:33
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.
msg190402 - (view) Author: Terje Wiesener (Terje.Wiesener) Date: 2013-05-31 11:52
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)
History
Date User Action Args
2022-04-10 16:08:55adminsetgithub: 38559
2013-05-31 11:52:30Terje.Wiesenersetversions: + Python 2.7
nosy: + Terje.Wiesener

messages: + msg190402

type: performance
2003-05-28 11:02:00dmaurercreate