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[i]=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
charlie strauss wrote: > 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... -- 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...
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 :-)
> > > 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...
> 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 :)
I want to clarify that, on my computer, the first instance of the gap occurs way before the memory if filled. (at about 20% of physical ram). Additionally the process monitor shows no page faults.
Yes if you let the as-written demo program run to completetion (all 20,000 iterations) then on many computers it would not be surprising that your computer eventually goes into forced page swapping at some point. That would be expected and is not the issue than the one I am concerned with.
in my case starts glicthing at around iteration 1000.
1000(bars) x 100(foos)x(10 integers in array)
is nominally 100,000 class objects and 1,000,000 array elements.
(note that the array if filled as [1]*10, so there is actually only one "integer", but 10 array elements refering to it, per foo class.)
However steve may have put his finger on the reason why the duration grows with time. Here is my current hypothesis. The design of the program does not have and points where significant amounts of memory are released: all objects have held references till the end. But prehaps there are some implicitly created objects of the same size created along the way??? For example when I write
me.memory = [1]*nfoo
perhaps internally, python is allocating an array of size foo and then __copying__ it into me.memory??? Since there is no reference to the intermediate it would then marked for future garbage collection.
If that were true then the memory would have interleaved entities of things to GC and things with references held in me.memory.
Then to remove these would require GC to scan the entire set of existing objects, which is growing.
Turning off GC would prevent this.
In any case I don't think what I'm doing is very unusual. The original program that trigger my investigation of the bug was doing this:
foo was an election ballot holding 10 outcomes, and bar was a set of 100 ballots from 100 voting machines, and the total array was holding the ballot sets from a few thousand voting machines.
Almost any inventory program is likely to have such a simmilar set of nested array, so it hardly seems unusual.
By the way if you are on a fast computer, and an OS whose time.time() function can resolve less than 0.5 seconds then you can see this problem on your machine at lower memory utilizations by changing the value of the default "allowed_gap" in the gtime class from 0.5 seconds down to say 0.1 second. This is the threshold for which the computer program flags the time it takes to create a "foo" object. on a fast computer it should take much less than 0.1 sec.
-----Original Message----- >From: charlie strauss <c...@earthlink.net> >Sent: Oct 1, 2006 10:33 AM >To: Steve Holden <st...@holdenweb.com>, python-l...@python.org >Subject: Re: Is this a bug? Python intermittently stops dead for seconds
>Steve and other good folks who replied:
>I want to clarify that, on my computer, the first instance of the gap occurs way before the memory if filled. (at about 20% of physical ram). Additionally the process monitor shows no page faults.
> Yes if you let the as-written demo program run to completetion (all 20,000 iterations) then on many computers it would not be surprising that your computer eventually goes into forced page swapping at some point. That would be expected and is not the issue than the one I am concerned with.
>in my case starts glicthing at around iteration 1000.
>1000(bars) x 100(foos)x(10 integers in array)
>is nominally >100,000 class objects and >1,000,000 array elements.
>(note that the array if filled as [1]*10, so there is actually only one "integer", but 10 array elements refering to it, per foo class.)
>However steve may have put his finger on the reason why the duration grows with time. Here is my current hypothesis. The design of the program does not have and points where significant amounts of memory are released: all objects have held references till the end. But prehaps there are some implicitly created objects of the same size created along the way??? For example when I write
>me.memory = [1]*nfoo
>perhaps internally, python is allocating an array of size foo and then __copying__ it into me.memory??? Since there is no reference to the intermediate it would then marked for future garbage collection.
>If that were true then the memory would have interleaved entities of things to GC and things with references held in me.memory.
>Then to remove these would require GC to scan the entire set of existing objects, which is growing.
>Turning off GC would prevent this.
>In any case I don't think what I'm doing is very unusual. The original program that trigger my investigation of the bug was doing this:
>foo was an election ballot holding 10 outcomes, and bar was a set of 100 ballots from 100 voting machines, and the total array was holding the ballot sets from a few thousand voting machines.
>Almost any inventory program is likely to have such a simmilar set of nested array, so it hardly seems unusual.
charlie strauss wrote: > Steve and other good folks who replied:
> I want to clarify that, on my computer, the first instance of the gap occurs way before the memory if filled. (at about 20% of physical ram). Additionally the process monitor shows no page faults.
> Yes if you let the as-written demo program run to completetion (all 20,000 iterations) then on many computers it would not be surprising that your computer eventually goes into forced page swapping at some point. That would be expected and is not the issue than the one I am concerned with.
> in my case starts glicthing at around iteration 1000.
> 1000(bars) x 100(foos)x(10 integers in array)
> is nominally > 100,000 class objects and > 1,000,000 array elements.
> (note that the array if filled as [1]*10, so there is actually only one "integer", but 10 array elements refering to it, per foo class.)
> However steve may have put his finger on the reason why the duration grows with time. Here is my current hypothesis. The design of the program does not have and points where significant amounts of memory are released: all objects have held references till the end. But prehaps there are some implicitly created objects of the same size created along the way??? For example when I write
> me.memory = [1]*nfoo
> perhaps internally, python is allocating an array of size foo and then __copying__ it into me.memory??? Since there is no reference to the intermediate it would then marked for future garbage collection.
> If that were true then the memory would have interleaved entities of things to GC and things with references held in me.memory.
> Then to remove these would require GC to scan the entire set of existing objects, which is growing.
> Turning off GC would prevent this.
> In any case I don't think what I'm doing is very unusual. The original program that trigger my investigation of the bug was doing this:
> foo was an election ballot holding 10 outcomes, and bar was a set of 100 ballots from 100 voting machines, and the total array was holding the ballot sets from a few thousand voting machines.
> Almost any inventory program is likely to have such a simmilar set of nested array, so it hardly seems unusual.
I think the point you are missing is that the garbage collector is triggered from time to time to ensure that no cyclical garbage remains uncollected, IIRC. The more data that's been allocated, the longer it takes the collector to scan all of memory to do its job.
If you can find a way to avoid the behaviour I'm sure the development team would be interested to hear it :-)
I think you'll find that most programs that eat through memory in this way will exhibit pretty much the same behaviour. If you *know* your program isn't creating data cycles, just turn the GC off and rely on reference counting. That won't save you from paging when you eventually exhaust physical memory. Nothing can.
>I think the point you are missing is that the garbage collector is >triggered from time to time to ensure that no cyclical garbage remains >uncollected, IIRC. The more data that's been allocated, the longer it >takes the collector to scan all of memory to do its job.
>If you can find a way to avoid the behaviour I'm sure the development >team would be interested to hear it :-)
>I think you'll find that most programs that eat through memory in this >way will exhibit pretty much the same behaviour. If you *know* your >program isn't creating data cycles, just turn the GC off and rely on >reference counting. That won't save you from paging when you eventually >exhaust physical memory. Nothing can.
Could you clarify that for me. GC really has three components two it: 1) finding and freeing unrefernced memory by refer counts 2) cycle removal and 3) defragementing the storage stack. If I turn off GC, don't I lose all of these?
>From a user perspective, turning off GC and then managing it yourself is unappealing. What would be preferrable would be to be able to simply turn down it's threshold. That is, what I really want is to tell GC it can hold off and checks other than reference counts until X% of the memory is filled. At some point I want it to kick in, and I don't want to have to programatically manage that, but simply specify a simple tolerance.
Even better , I'd like to keep 1 and 3 and turn off just 2 and just use weak reference in the few cases I really need them.
Steve, digging into the gc docs a bit more, I think the behaviour I am seeing is still not expected. Namely, the program I offered has no obvious place where objects are deallocated. The way GC is supposed to work is thate there are three levels of objects
level0: newly created objects level1: objects that survived 1 round of garbage collection level2: objects that survivied 2+ rounds of gargbage collection
Since all of my numerous objects are level2 objects, and none of them are every deallocated, then I should never trip the GC for these.
Your explanation would require this to be tripped so I can't explain it. For your explanation to be correct then there as to be some non-obvious step in the program that is deallocating level2 items in sufficient numbers to trip the GC.
charlie strauss wrote: > Could you clarify that for me. GC really has three components
> two it: 1) finding and freeing unrefernced memory by refer > refer counts 2) cycle removal and 3) defragementing the > storage stack. If I turn off GC, don't I lose all of these?
CPython always does (1), only does (2) if cycle-breaking GC isn't disabled, and never does (3).
in your case, it's (2) that takes more and more time, simply because you're creating tons of non-trivial objects. to see what's going on in there, add
import gc gc.set_debug(gc.DEBUG_STATS)
to the top of your program, and look at the status messages that appear just before each "Big Gap" message.
charlie strauss wrote: > level0: newly created objects > level1: objects that survived 1 round of garbage collection > level2: objects that survivied 2+ rounds of gargbage collection
> Since all of my numerous objects are level2 objects, and none of
> them are every deallocated, then I should never trip the GC for > these.
your understanding of generational GC is a bit fuzzy, it seems. that an object is promoted to a higher level means that it's not inspected quite as often as lower-level objects, not that it's never inspected at all.
charlie strauss wrote: > Steve, digging into the gc docs a bit more, I think the behaviour I am seeing is still not expected. Namely, the program I offered has no obvious place where objects are deallocated. The way GC is supposed to work is thate there are three levels of objects
> level0: newly created objects > level1: objects that survived 1 round of garbage collection > level2: objects that survivied 2+ rounds of gargbage collection
> Since all of my numerous objects are level2 objects, and none of them are every deallocated, then I should never trip the GC for these.
> Your explanation would require this to be tripped so I can't explain it. For your explanation to be correct then there as to be some non-obvious step in the program that is deallocating level2 items in sufficient numbers to trip the GC.
So perhaps you can explain why switching garbage collection off changes program behaviour? If you read the documentation more carefully you will see that the collector merely scans generations 1 and 2 less frequently that generation 0.
>> level0: newly created objects >> level1: objects that survived 1 round of garbage collection >> level2: objects that survivied 2+ rounds of gargbage collection
>> Since all of my numerous objects are level2 objects, and none of >> them are every deallocated, then I should never trip the GC for >> these.
> your understanding of generational GC is a bit fuzzy, it seems. > that an > object is promoted to a higher level means that it's not inspected > quite > as often as lower-level objects, not that it's never inspected at all.
As I understand it, level2 (and level1) objects only undergo gc when more than 10 of them is deallocated. Since I never deallocate, this should not be tripped right?
In any case regarding your other comments:
>> Could you clarify that for me. GC really has three components >> two it: 1) finding and freeing unrefernced memory by refer >> refer counts 2) cycle removal and 3) defragementing the >> storage stack. If I turn off GC, don't I lose all of these?
> CPython always does (1), only does (2) if cycle-breaking GC isn't > disabled, and never does (3).
Never does 3? then how does it compact it's memory allocation area? Surely it does not rely on the OS to manage every small object as a separate memory allocation.
And just to be clear: are you saying that when I do a gc.disable this only turns off 2 and not 1? The docs don't say that as far as I can tell.
> in your case, it's (2) that takes more and more time, simply because > you're creating tons of non-trivial objects. to see what's going > on in > there, add
> import gc > gc.set_debug(gc.DEBUG_STATS)
> to the top of your program, and look at the status messages that > appear > just before each "Big Gap" message.
Could you be a bit more explicit. I'm new to the gc module. Sorry to be slow but I don't know what "looking at the status message" means.
> On Oct 1, 2006, at 9:48 AM, Fredrik Lundh wrote: >> charlie strauss wrote: >>> Could you clarify that for me. GC really has three components >>> two it: 1) finding and freeing unrefernced memory by refer >>> refer counts 2) cycle removal and 3) defragementing the >>> storage stack. If I turn off GC, don't I lose all of these?
>> CPython always does (1), only does (2) if cycle-breaking GC isn't >> disabled, and never does (3).
[snip] > And just to be clear: are you saying that when I do a gc.disable this > only turns off 2 and not 1? The docs don't say that as far as I can > tell.
AFAIK Python always does reference counting, and the garbage collector is used only for more difficult cases. As the gc module docs say: "Since the collector supplements the reference counting already used in Python, you can disable the collector if you are sure your program does not create reference cycles."
I don't know if that's only true for CPython or also for the other implementations.
-- If I have been able to see further, it was only because I stood on the shoulders of giants. -- Isaac Newton
>>On Oct 1, 2006, at 9:48 AM, Fredrik Lundh wrote:
>>>charlie strauss wrote:
>>>>Could you clarify that for me. GC really has three components >>>>two it: 1) finding and freeing unrefernced memory by refer >>>>refer counts 2) cycle removal and 3) defragementing the >>>>storage stack. If I turn off GC, don't I lose all of these?
>>>CPython always does (1), only does (2) if cycle-breaking GC isn't >>>disabled, and never does (3).
> [snip]
>>And just to be clear: are you saying that when I do a gc.disable this >>only turns off 2 and not 1? The docs don't say that as far as I can >>tell.
> AFAIK Python always does reference counting, and the garbage collector > is used only for more difficult cases. As the gc module docs say: > "Since the collector supplements the reference counting already used in > Python, you can disable the collector if you are sure your program does > not create reference cycles."
> I don't know if that's only true for CPython or also for the other > implementations.
Read the documentation: the garbage collector is called regularly in CPython.
Roel Schroeven wrote: > AFAIK Python always does reference counting, and the garbage collector > is used only for more difficult cases. As the gc module docs say: > "Since the collector supplements the reference counting already used in > Python, you can disable the collector if you are sure your program does > not create reference cycles."
> I don't know if that's only true for CPython or also for the other > implementations.
CPython always uses reference counting, but that's not guaranteed by the language specification:
"Objects are never explicitly destroyed; however, when they become unreachable they may be garbage-collected. An implementation is allowed to postpone garbage collection or omit it altogether -- it is a matter of implementation quality how garbage collection is implemented, as long as no objects are collected that are still reachable."
Steve Holden wrote: > I think you'll find that most programs that eat through memory in this > way will exhibit pretty much the same behaviour. If you *know* your > program isn't creating data cycles, just turn the GC off and rely on > reference counting. That won't save you from paging when you > eventually exhaust physical memory. Nothing can.
Even better, if you know that you're *creating* tons of objects without creating many *discardable* cycles at the same, it's better to turn off GC collection during loading, and only do a single pass (gc.collect()) when you are done with the allocations. -- 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.
Any program that creates a great many long-lived container objects will behave similarly during the creation phase. Others have explained why. Here's a simpler example:
from time import time xs = [] i = 0 while 1: i += 1 s = time() xs.append([[1, 2] for dummy in xrange(1000)]) f = time() if f-s > 0.25: print "time", f-s, "on try", i if i % 100 == 0: print "xs made:", i
>>> Below is a simple program that will cause python to intermittently >>> stop executing for a few seconds. it's 100% reproducible on my >>> machine.
[Giovanni Bajo]
>> Confirmed with Python 2.4.2 on Windows.
[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.
[Steve Holden, "pins the blame" for pauses on periodic cyclic gc]
> ... > So basically what you have here is a pathological example of why it's > sometimes wise to disable garbage collection. Tim, did I miss anything?
> I want to clarify that, on my computer, the first instance of the gap occurs way > before the memory if filled. (at about 20% of physical ram). Additionally the > process monitor shows no page faults.
Python has no idea of how much RAM you have, or even of how much RAM it's using. See the `gc` module docs, function set_threshold(), for a description of when Python decides to run a cyclic gc pass. That's all about the current excess (if any) of the number of container allocations over the number of container deallocations since the last time cyclic gc ran.
> ... > (note that the array if filled as [1]*10, so there is actually only one "integer", > but 10 array elements refering to it, per foo class.)
Nevertheless cyclic gc has to examine all 10 array elements each time the list is scanned.
> ... > For example when I write
> me.memory = [1]*nfoo
> perhaps internally, python is allocating an array of size foo and then __copying__ it > into me.memory???
No. Assignments in Python never copy anything.
> Since there is no reference to the intermediate it would then marked for future > garbage collection.
Nothing in Python is "marked for future garbage collection". From time to time /all/ container objects are scanned to determine whether any have become cyclic trash. This takes time proportional to the total number of containees across all container objects.
...
> foo was an election ballot holding 10 outcomes, and bar was a set of 100 ballots > from 100 voting machines, and the total array was holding the ballot sets from a few > thousand voting machines.
> Almost any inventory program is likely to have such a simmilar set of nested array, > so it hardly seems unusual.
For memory-consumption reasons alone, a serious <wink> such program is likely to use array.array objects at leaf level instead. array.array objects hold raw bits, not Python objects. Since they don't hold Python objects, they can't possibly be part of a cycle, so cyclic gc doesn't need to scan array.array contents either.
> Steve, digging into the gc docs a bit more, I think the behaviour I am seeing is still > not expected. Namely, the program I offered has no obvious place where objects > are deallocated. The way GC is supposed to work is thate there are three levels of > objects
> level0: newly created objects > level1: objects that survived 1 round of garbage collection > level2: objects that survivied 2+ rounds of gargbage collection
Yes.
> Since all of my numerous objects are level2 objects,
No. All newly created objects start in level0. Over time, most (but never all) of your objects end up in level 2.
> and none of them are every deallocated, then I should never trip the GC for these.
Cyclic gc scans /all/ container objects at or under level N, whenever cyclic gc runs. N varies from run to run of cyclic gc, according to the scheme described in the docs for the gc.set_threshold() function. N=2 is certainly a possible value. There is never a time when a live container object becomes exempt from all future runs of cyclic gc. If a live container object survives two rounds of cyclic gc, it ends up lin level2. That doesn't mean it's never looked at again, it just means it's not looked at during level0 or level1 (N=0 or N=1) runs of cyclic gc. It will still be looked at during all level2 (N=2) runs of cyclic gc.
> Your explanation would require this to be tripped so I can't explain it. For your > explanation to be correct then there as to be some non-obvious step in the program > that is deallocating level2 items in sufficient numbers to trip the GC.
Deallocations never trigger cyclic gc. As the docs say, cyclic gc is triggered by an /excess/ of allocations /over/ deallocations. So, e.g., if you delete container objects just as fast as you create them, cyclic gc will never run. But that's not what you're doing. Instead you're allocating new objects but never deallocating them. That makes cyclic gc run as frequently as it's possible for it to run.
>>> level0: newly created objects >>> level1: objects that survived 1 round of garbage collection >>> level2: objects that survivied 2+ rounds of gargbage collection
>>> Since all of my numerous objects are level2 objects, and none of >>> them are every deallocated, then I should never trip the GC for >>> these.
[Fredrik Lundh]
>> your understanding of generational GC is a bit fuzzy, it seems. >> that an object is promoted to a higher level means that it's >> not inspected quite as often as lower-level objects, not that it's >> never inspected at all.
[Charlie]
> As I understand it, level2 (and level1) objects only undergo gc when > more than 10 of them is deallocated. Since I never deallocate, this > should not be tripped right?
No. Cyclic gc is triggered by an excess of allocations over deallocations.
> In any case regarding your other comments: >>> Could you clarify that for me. GC really has three components >>> two it: 1) finding and freeing unrefernced memory by refer >>> refer counts 2) cycle removal and 3) defragementing the >>> storage stack. If I turn off GC, don't I lose all of these? >> CPython always does (1), only does (2) if cycle-breaking GC isn't >> disabled, and never does (3). > Never does 3?
Correct.
> then how does it compact it's memory allocation area?
It doesn't.
> Surely it does not rely on the OS to manage every small object as a > separate memory allocation.
It doesn't do that either. Python has its own small-object allocator, carving up 256KB chunks obtained from the system malloc(). It's based on size-segregated "pools" with extremely low bookkeeping overhead, and external fragmentation in small-object memory is essentially non-existent because of that (although it's possible to concoct pathological programs that exhibit it).
> And just to be clear: are you saying that when I do a gc.disable this > only turns off 2 and not 1?
Right. Refcounting (#1) can never be disabled, and cyclic GC (#2) is used only for trash objects that can't be reclaimed by #1 (meaning container objects in cycles).
|
