Issue 744841: Python-Profiler bug: Bad call (original) (raw)
Created on 2003-05-28 11:02 by dmaurer, last changed 2022-04-10 16:08 by admin. This issue is now closed.
Messages (6)
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).
Author: Neal Norwitz (nnorwitz) * 
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.
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.
Author: Raymond Hettinger (rhettinger) *
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.
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.
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 :1() 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:55
admin
set
github: 38559
2013-05-31 11:52:30
Terje.Wiesener
set
versions: + Python 2.7
nosy: + Terje.Wiesener
messages: +
type: performance
2003-05-28 11:02:00
dmaurer
create