Is this a bug? Python intermittently stops dead for seconds

[charlie strauss]

Below is a simple program that will cause python to intermittently
stop executing for a few seconds. it's 100% reproducible on my machine.

I'd be tempted to say this is a nasty garbage collection performance
issue except that there is no major memory to be garbage collected in
this script. I'd be tempted to say it was a unix virtual memory
issue except this is occuring at around 1/5th of my physical memory
size. So something else unexplained is going on

Class Foo instances create and hold a list of size nfoo of integers.
(nfoo =10)

Class Bar instances create and hold a list of size nbar of Foo
objects. (nbar =100)

When the code runs it starts creating and storing Bar objects in a
list while watching for real-time glitches in how long it takes to
create the next Foo object. If this is longer than 1/2 of a second
then it reports it.

On my computer after creating 1500 Bar objects, the rate of
creation of new Foo suddenly has a periodic glitch. This glitch re-
occurs about every 300 Bar Objects, and the duration of the glitch
keeps getting longer--growing to many seconds!!!!

Platform: 800Mhz powermac g 4 1Gb of memory
python: python 2.4.2

Note: since I an using absolute time threshold for reporting the
glitches, the first one may take more iterations before it occurs on
a fast computer. You may need to increase nbar or nfoo.

import sys
from time import time


class Foo(object):
def __init__(me,nfoo):
me.memory = [1]*nfoo

class Bar(object):
def __init__(me,nbar,nfoo):
tgx.set_tag("Bar") # timer

b = [None]*nbar
for i in xrange(nbar):
b=Foo(nfoo) # make a foo, add it to list
tgx.jump("Bar"+`i`) #timer

me.b = b #store the list in my instance memory




# just a utility class to time things.
class gtime:
def __init__(me,f=sys.stderr):
me.last = time()
me.f=f
me.tag = ""
me.ticks = 0

def set_tag(me,tag):
me.tag = tag
me.ticks = 0

def reset(me):
me.ticks = 0

def jump(me,tag="NONE",allowed_gap=0.5):
me.t = time()
me.ticks +=1
if me.t-me.last>allowed_gap:
print >>me.f,"Big Gap:",me.t-me.last,"seconds
",me.tag,tag,me.ticks
me.last = time()

tgx = gtime() # instance of the timer


# main loop
nbar = 100
nfoo = 10

ad_nauseum = 20000
final = [None]*ad_nauseum

for i in xrange(ad_nauseum ):
if i%100 == 0 rint >>sys.stderr,"Bars Made: ",i
final = Bar(nbar,nfoo)



sample Output:

Bars Made: 0
Bars Made: 100
Bars Made: 200
Bars Made: 300
Bars Made: 400
Bars Made: 500
Bars Made: 600
Bars Made: 700
Bars Made: 800
Bars Made: 900
Bars Made: 1000
Bars Made: 1100
Bars Made: 1200
Bars Made: 1300
Bars Made: 1400
Bars Made: 1500
Big Gap: 0.618862867355 seconds Bar Bar5 6
Bars Made: 1600
Bars Made: 1700
Bars Made: 1800
Big Gap: 0.748915195465 seconds Bar Bar76 77
Bars Made: 1900
Bars Made: 2000
Bars Made: 2100
Big Gap: 0.809149980545 seconds Bar Bar45 46
Bars Made: 2200
Bars Made: 2300
Bars Made: 2400
Big Gap: 0.898494958878 seconds Bar Bar15 16
Bars Made: 2500
Bars Made: 2600
Bars Made: 2700
Big Gap: 1.01110696793 seconds Bar Bar86 87
Bars Made: 2800
Bars Made: 2900
Bars Made: 3000
Big Gap: 1.12396192551 seconds Bar Bar55 56
Bars Made: 3100
Bars Made: 3200
Bars Made: 3300
Big Gap: 1.39006495476 seconds Bar Bar25 26
Bars Made: 3400
Bars Made: 3500
Bars Made: 3600
Big Gap: 1.55699706078 seconds Bar Bar96 97
Bars Made: 3700
Bars Made: 3800
Bars Made: 3900
Big Gap: 1.49929594994 seconds Bar Bar65 66
Bars Made: 4000
Bars Made: 4100
Bars Made: 4200
Big Gap: 1.64840602875 seconds Bar Bar35 36
Bars Made: 4300
Bars Made: 4400
Bars Made: 4500
Big Gap: 1.728484869 seconds Bar Bar5 6
Bars Made: 4600
Bars Made: 4700
Bars Made: 4800

 

[Giovanni Bajo]

Below is a simple program that will cause python to intermittently
stop executing for a few seconds. it's 100% reproducible on my
machine.

Confirmed with Python 2.4.2 on Windows.

gc.disable() fixes it, so it looks like you found an inefficiency in the
Python's GC. I have no idea whether this would be considered a bug by Python's
developer, but you can try opening a bugreport...

 

[John Machin]

Confirmed with Python 2.4.2 on Windows.

gc.disable() fixes it, so it looks like you found an inefficiency in the
Python's GC. I have no idea whether this would be considered a bug by Python's
developer, but you can try opening a bugreport...

Reproduced on 2.4.3 and 2.5 on Windows.
Disabling GC fixes the speed problem as Giovanni said, but doesn't
reduce the amount of memory taken (measured by increase in "page file
used" display in Task Manager). At about 520 Mb, this seems rather too
high to me.

Definitely worth reporting, even if the outcome is only(!) a timbottian
dissertation of why it's not a problem -- at least we'd learn something


Cheers,
John

 

[Daniel Nogradi]

Below is a simple program that will cause python to intermittently

Reproduced on 2.4.3 and 2.5 on Windows.
Disabling GC fixes the speed problem as Giovanni said, but doesn't
reduce the amount of memory taken (measured by increase in "page file
used" display in Task Manager). At about 520 Mb, this seems rather too
high to me.

Definitely worth reporting, even if the outcome is only(!) a timbottian
dissertation of why it's not a problem -- at least we'd learn something

This is because the OP violated the Style Guide (PEP 8) and used 'me'
instead of 'self' as the first argument of instance methods, the
couple of seconds delay in runtime is the revenge of the vicious
interpreter

 

[Jorgen Grahn]

Confirmed with Python 2.4.2 on Windows.

And Python 2.3.5 on Linux, amd64. In fact, it causes heavy swapping so it
will disrupt other processes, too.

I didn't read the code, stupid as I am, but I trust that the behavior
doesn't match what the code actually tries to do.

/Jorgen

 

[Tim Peters]

[charlie strauss]
[Giovanni Bajo]
[Jorgen Grahn]

And Python 2.3.5 on Linux, amd64. In fact, it causes heavy swapping so it
will disrupt other processes, too.

I didn't read the code, stupid as I am, but I trust that the behavior
doesn't match what the code actually tries to do.

No, that's what it does: as it goes on, it creates an ever-increasing
and unbounded number of immortal objects and lists. The "time burps"
merely reflect that the more live containers and objects you have, the
longer it takes for cyclic gc to determine that they're not trash.