Profiler called with wrong args by system callback

Jim Roskind (jar@infoseek.com)
Tue, 24 Jan 1995 19:41:13 -0800

Under Python 1.1.1 the profiler is sometimes called with the wrong
frame argument. This causes my profiler to report incorrect timing
stats, and call stats :-(. Does anyone have a patch that might help?
I have a patch to my profiler that detects the problem when it
happens, and even have a workaround (adjustment to my Python code)
that avoids the problem, but it is all a little painful.

This situation seems to happen in a construct like:

for i in list_instance:

where "list_instance" is an instance of a class with a __getitem__()
method. If I understand what going wrong, the __getitem__ method is
called sequentially until it raises an IndexError exception.
Unfortunately, although the Python interpreter keys on this exception
and terminates the iteration, it does not properly "pop" the
__getitem__ stack-frame.

For the record, the python work-around (when the profiler is giving
wacky results) is to do:

for i in list_instance[:]:

and then everything will be fine (assuming you have a __getslice__
method). Basically this patch gets away from user defined __getitem__
methods, and uses the builtin array access methods. It seems a little
painful to have to copy arrays all the time just to make it possible
to profile :-(. One hard part is to *find* the line of code that is
causing this problem, but I'll give the critical patch to help find
this stuff in a second.

If I'm not being clear enough, consider the following code:

cut here--------------------------------------------------------------
class array:
def __init__(self, val):
self.val = val

def __getitem__(self, i):
exec 'print "getting item", i'
return self.val[i]

a = array([37])

def iter_func():
for i in a:
print "i=", i
# break
simple()

def simple():
pass

import profile
p = profile.Profile().run("iter_func()")

import pstats
s = pstats.Stats(p).print_callers("simple")

cut here--------------------------------------------------------------

Notice how the function "simple" is called by iter_func. Surprisingly,
the output from the above program is:

cut here--------------------------------------------------------------

getting item 0
i= 37
getting item 1
Random listing order was used
List reduced from 8 to 1 due to restriction <'simple'>

Function was called by...
<stdin>:18(simple) <stdin>:5(__getitem__)(1) 0.000

cut here--------------------------------------------------------------

...which means that the profiler thinks that "simple()" was called by
"getitem()"!!! :-(

If you want the above program to work correctly, then uncomment the
"break" statement and you'll get:

cut here--------------------------------------------------------------
getting item 0
i= 37
Random listing order was used
List reduced from 7 to 1 due to restriction <'simple'>

Function was called by...
<stdin>:18(simple) <stdin>:12(iter_func)(1) 0.000
cut here--------------------------------------------------------------

which is correct (re: simple was called by iter_func).

If you want to detect this error in the profiler (in case your code is
getting bogus results in the profiler), then you should uncomment the
assertion in profile.py:

def trace_dispatch_return(self, frame, t):
# if not frame is self.cur[-2]: raise "Bad return", self.cur[3]
^

This line compares the profilers recollection of what the current
frame is, to the argument passed in by the system callback. When
iter_func() completes, the profiler will be told that __getitem__() is
returning, and it will raise the exception. :-( The traceback will
then identify the function containing the harmful iteration.

The question is: Where is the C code that handles iteration over
list-like classes? I found some stuff in compile.c ( com_for_stmt())
but am having a terrible time reading it. Is there any documentation
of what is going on in some file or other? Any gurus have the time to
read the "compiled" code and see what the issue is?

Thanks,

Jim

-- 
Jim Roskind
InfoSeek Corporation
voice: 408.982.4469
fax: 408.986.1889
jar@infoseek.com
----------------------------------------------------------------------------
PGP 2.6.1 Key fingerprint =  0E 2A B2 35 01 9B 5C 58  2D 52 05 9A 3D 9B 84 DB 
To get my PGP 2.6 Public Key, "finger -l jar@infoseek.com | pgp -kaf"