Take a look again I've updated the change set and the readme file.

On 8-Jan-09, at 5:26 PM, Aidan Gauland wrote:

Igor Stasenko <siguctua <at> gmail.com> writes:

...

not sure, but i suspecting that such pauses can be caused by GC. I'd recomment to look over memory allocations during playback, and how often GC invoked.

That's kinda what I was thinking, but how do I monitor the garbage collector? I tried GCMonitor from here... ftp://ftp.smalltalkconsulting.com/squeakGarbage/ ...but running it raised a MessageNotUnderstood error, so I guess that's too old.

-- = = = ======================================================================== John M. McIntosh johnmci@smalltalkconsulting.com Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com = = = ========================================================================

Ok, well why don't you post the first 5 lines of the file and I'll explain them.

On 9-Jan-09, at 7:13 PM, Aidan Gauland wrote:

John M McIntosh <johnmci <at> smalltalkconsulting.com> writes:

...

Take a look again I've updated the change set and the readme file.

Wow, thanks! But I can't make any sense of the gcStats.txt file. I also tried MessageTally>>spyOn: which seems to indicate that the garbage collector ran many times while the audio file was played.

Which brings me to my next question: what control do I have over the garbage collector? Can I turn it off completely temporarily, or just tell it to relax a bit?

-Aidan

-- = = = ======================================================================== John M. McIntosh johnmci@smalltalkconsulting.com Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com = = = ========================================================================

Ok, the headings would be: statGCTime oldSpaceEnd youngSpaceEnd memoryEnd fullGCs fullGCTime incrGCs incrGCTime tenureCount statMarkCount statSweepCount statMkFwdCount statCompMoveCount statGrowMemory statShrinkMemory statRootTableCount statAllocationCount statSurvivorCount statSpecialMarkCount statIGCDeltaTime pendingFinalizationSignals

Most of this data comes from the primitiveVMParameter

0 args: return an Array of VM parameter values; 1 arg: return the indicated VM parameter; 2 args: set the VM indicated parameter. VM parameters are numbered as follows: 1 end of old-space (0-based, read-only) 2 end of young-space (read-only) 3 end of memory (read-only) 4 allocationCount (read-only) 5 allocations between GCs (read-write) 6 survivor count tenuring threshold (read-write) 7 full GCs since startup (read-only) 8 total milliseconds in full GCs since startup (read-only) 9 incremental GCs since startup (read-only) 10 total milliseconds in incremental GCs since startup (read-only) 11 tenures of surving objects since startup (read-only) 12-20 specific to the translating VM 21 root table size (read-only) 22 root table overflows since startup (read-only) 23 bytes of extra memory to reserve for VM buffers, plugins, etc. 24 memory threshold above which shrinking object memory (rw) 25 memory headroom when growing object memory (rw) 26 interruptChecksEveryNms - force an ioProcessEvents every N milliseconds, in case the image is not calling getNextEvent often (rw) 27 number of times mark loop iterated for current IGC/FGC (read- only) includes ALL marking 28 number of times sweep loop iterated for current IGC/FGC (read- only) 29 number of times make forward loop iterated for current IGC/FGC (read-only) 30 number of times compact move loop iterated for current IGC/FGC (read-only) 31 number of grow memory requests (read-only) 32 number of shrink memory requests (read-only) 33 number of root table entries used for current IGC/FGC (read-only) 34 number of allocations done before current IGC/FGC (read-only) 35 number of survivor objects after current IGC/FGC (read-only) 36 millisecond clock when current IGC/FGC completed (read-only) 37 number of marked objects for Roots of the world, not including Root Table entries for current IGC/FGC (read-only) 38 milliseconds taken by current IGC (read-only) 39 Number of finalization signals for Weak Objects pending when current IGC/FGC completed (read-only) 40 BytesPerWord for this image

Let's look at the values, so allow me to ramble...

statGCTime 123904

This is the millisecond clock time when the sample was taken. The SqueakVMMemoryPolicy will run in two modes, active or passive. In passive mode the SqueakVMMemoryPolicy process wakes up every N (5?) Seconds and takes a reading of the GC statistics. In active mode a semaphore is used to signal the SqueakVMMemoryPolicy process to collect data on every incremental GC event.

oldSpaceEnd 26725864

The byte offset of old space end. We don't have the start of memory here, it's a number elsewhere, but using that and this number we would know how many bytes oldspace uses, this boundary moves higher, or lower.

youngSpaceEnd 27365792 Memory is broken into old space, youngspace, free, forwarding block reserve. This is the end of allocated young space, the start of free space.

memoryEnd 30183488 This byte offset is the end of memory before the forwarding blocks, so let me talk about that space where since we have some other stats on forwarding blocks later.

Note: The amount of space reserved for forwarding blocks should be chosen to ensure that incremental compactions can usually be done in a single pass. However, there should be enough forwarding blocks so a full compaction can be done in a reasonable number of passes, say ten. (A full compaction requires N object-moving passes, where N = number of non-garbage objects / number of forwarding blocks). di 11/18/2000 Re totalObjectCount: Provide a margin of one byte per object to be used for forwarding pointers at GC time. Since fwd blocks are 8 bytes, this means an absolute worst case of 8 passes to compact memory. In most cases it will be adequate to do compaction in a single pass.

fullGCs 1

The number of full garbage collection count from zero at image startup, on a full GC we do a full GC against all objects in the image. Doing full GC frequently is a bad thing, but perhaps it cannot be avoid, depends on the app.

fullGCTime 224 The number of milliseconds accumulative from zero at image startup take in full GC work.

incrGCs 1561 Number of incremental garbage collection count from zero at image startup, on a incremental GC we scan objects in the root table and in the young space.

incrGCTime 1259 The number of milliseconds accumulative from zero at image startup take in incremental GC work, on machines today you'll note we can do some GC work in less than 1 milliscond, thus this count of 1,259 is less than the total taken, which is 1,561. In order to ensure events that are NEEDED to be triggered with millisecond accuracy we would like to complete a incremental GC (IGC) in 1 ms or less. If for example a IGC took say 25ms, then you would have a 25 error in average on a Delay termination.

tenureCount 12 By default we allocation 4,000 objects,then do a IGC, then see if the number of survivors is greater than the survivor count of 2000. If so then we tenure all the objects to old space by moving the oldSpaceEnd higher. This then ages the objects into oldspace and they are not looked at again when doing a IGC. The 4,000/2,000 numbers where picked in the 90's, 16Mhz machines. Some Squeakers report better GC behavior by making the allocation count & threashold count higher. How high is a number that requires some statistical calculations, again you want to ensure an IGC over N objects will take about 1 ms.

SqueakVMMemoryPolicy>>calculateGoals contains some sample not used code for consideration and experimentation. Also see SmalltalkImage current vmParameterAt: 5 put: 8000. "do an incremental GC after this many allocations" SmalltalkImage current vmParameterAt: 6 put: 4000. "tenure when more than this many objects survive the GC"

statMarkCount 13331

The Squeak GC algorithm uses a mark algorithm to mark which objects are accessible, then a sweep to mark objects that are free versus used, then a move and compacting event that consolidates the free space into one chunk at the end of young space.

In this case we know we reached the 4,000 limit of allocation by the statAllocationCount and using the root table and youngspace marked 13,331 as used.

statSweepCount 5579

At the end of the IGC we swept 5,579 object, which means 5,579 objects (free or allocated where in young space). The other data statSurvivorCount at 1,591 and the allocation count of 4,000 means on the last IGC there were 1,579 object alive, we allocated 4,000 more, and on the IGC only found 1,591 alive.

statMkFwdCount 109

This is a count of the number times thru the forwarding block loop.

statCompMoveCount 109 This is a count of the number times thru the compression move block loop.

statGrowMemory 1

memoryEnd is the limit of memory, but it might not be the limit of available memory, if so the memoryEnd can move by providing more memory. This counts the number times this happens. This happens when free memory becomes too low, or a large object cannot be allocated.

statShrinkMemory 1

When free space becomes too large, then we give some back to the operating system. This counts how many times this happens. The low memory and too much free memory thresholds are arbitrarily set values. 24 memory threshold above which shrinking object memory (rw) 25 memory headroom when growing object memory (rw)

Excessive statGrowMemory/statShrinkMemory incrrementing points to a problem where you are cycling between a high/low value exceeding the limits, this is expensive and the thresholds should be adjust to avoid thi. s

statRootTableCount 331 "Record that the given oop in the old object area points to an object in the young area. HeaderLoc is usually = oop, but may be an addr in a forwarding block."

This is the number of roots, the number of objects in oldspace (usually) that point to some object in young space. The IGC needs this information to determine which objects are live in young space. Other Smalltalk might call this the remember table.

Now a bit about Squeak's implementation, some other smalltalk record what the object is and what the slot is, this can require a lot of memory and require memory to be allocated when you can't allocate memory (crash). Squeak records the object, but now if this is a Collection then later when we mark we must visit ALL the slots in the object to determine which object is in young space. How this issue shows up in Squeak is stories about people allocating large collections then for some reason squeak becomes slow, but if they do a full GC, squeak becomes fast.

The SqueakVMMemoryPolicy>>calculateGoals attempts to solve this by doing:

| target |

... (statMarkCount ) > (statAllocationCount*2) ifTrue: [[Smalltalk forceTenure] on: Error do: [:ex | ]]. "Tenure if we think too much root table marking is going on"

If we think took much marking is going on because the root table counting is too high then we invoke Smalltalk forceTenure which tenures everything to oldspace, and hopefully removing the problem object from the root table. Although this seem excessive too much mark scanning means less CPU time for byte code interpretation.

statAllocationCount 4000 At the start of the IGC, this is the number of objects that were allocated, this helps determine if the IGC was done as a result of object allocation, or because some other allocation issue required the IGC to run to fix an issue, say a large object being allocated

statSurvivorCount 1591 At the end of the IGC this is the number of objects that still were alive, using the statAllocationCount, and statSurvivorCount you might be able to determine values that ensure a IGC doesn't tenure objects, yet finishes in about 1 ms.

statSpecialMarkCount 633 count the number of objects we mark which are accessible by the special objects, receiver, method, activecontext, message selector, method class, receiver class,etc, and the internal remapping objects array.

statIGCDeltaTime 1

For this IGC, it took 1 ms

pendingFinalizationSignals 0

This is the number of weak objects that have "died" in this GC cycle.

-------------------------------------------------------

Obviously figuring out what all this data means is a chore, so email me not the list of a sample file where you have the problem with playback. If you can determine the millisecond/second count where the problem occured at, it would be helpful.

-------------------------------------------------------

I'll note Squeak out of the box has a bias to compact memory, there is a condition that Squeak can enter into where when you allocate that next object memory is full, then you do a IGC and get back a reasonal number of bytes, you allocate the object, then fail on the next one, then a IGC, get back some bytes, allocate the object, fail on the next one... This then triggers 10 of thousands of IGC events a second, Squeak appears to hang.

The

[Smalltalk setGCBiasToGrowGCLimit: 8*1024*1024] on: Error do: [:ex | ^self]. [Smalltalk setGCBiasToGrow: 1] on: Error do: [:ex | ^self].

in SqueakVMMemoryPolicy startUp

Alters the allocation behaviour to grow memory versus doing just another IGC, so bias to grow memory. However we can't grow memory forever so the setGCBiasToGrowGCLimit to 8MB to indicate where a full GC should occur after 8MB of biased growth. This avoid the bug in the memory allocation logic.

On 10-Jan-09, at 3:24 PM, Aidan Gauland wrote:

John M McIntosh <johnmci <at> smalltalkconsulting.com> writes:

...

Ok, well why don't you post the first 5 lines of the file and I'll explain them.

Ok, here they are...

123904 26725864 27365792 30183488 1 224 1561 1259 12 13331 5579 109 109 1 1 331 4000 1591 633 1 0 129430 27191724 27961664 30183488 1 224 1567 1265 13 1530 4126 192 192 1 1 36 4000 142 351 2 0 133846 27191724 29113412 30183488 1 224 1572 1270 13 3441 4341 318 318 1 1 44 4000 370 350 2 0 139371 27191724 29181436 30183488 1 224 1578 1282 13 3793 4411 270 270 1 1 44 4000 418 350 2 0 143936 27191724 29757020 30183488 1 224 1583 1294 13 4263 4474 333 333 1 1 44 4000 479 314 2 0

Oh, and I had to do "SqueakVMMemoryPolicy new; collectStatistics: true; run" to make it create a file; just "SqueakVMMemoryPolicy run" didn't create a file.

-- = = = ======================================================================== John M. McIntosh johnmci@smalltalkconsulting.com Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com = = = ========================================================================

If you can point to a sound track, and the code you are using I can look further

On 13-Jan-09, at 2:03 PM, Aidan Gauland wrote:

John M McIntosh <johnmci <at> smalltalkconsulting.com> writes:

...

Obviously figuring out what all this data means is a chore, so email me not the list of a sample file where you have the problem with playback. If you can determine the millisecond/second count where the problem occured at, it would be helpful.

Thanks for the detailed reply!

It stutters with any long, CD-quality audio file; and it's not in the same places every time. I think that I should not try to use Squeak for playing CD rips, unless there's a way to disable garbage collection (or at least minimize it) while playing a file.

-Aidan

-- = = = ======================================================================== John M. McIntosh johnmci@smalltalkconsulting.com Corporate Smalltalk Consulting Ltd. http://www.smalltalkconsulting.com = = = ========================================================================