[Glass] Explanation to "too many failed pom_gen scavenges" in this context??
Dale Henrichs via Glass
glass at lists.gemtalksystems.com
Tue Mar 8 13:38:22 PST 2016
Okay .. given your stack, OrderedCollection>>at: is probably not going
to be causing you to run out of memory in and of itself. ...
The error `too many failed pom_gen scavenges` is indicating that you are
running into trouble in POM gen and by extension OLD gen ...
From your memory dump, you've got 250K OrderedCollection instances
taking up 500MB and another 1M Strings taking up 300MB ...
Objects are held in POM gen and OLD gen if they've been modified or if
they are directly referenced from temp objects or the stack and the
error specifically means that you've filled both OLD Gen and POM gen ...
it is interesting that you are able to reference so many strings and
ordered collections from the stack and/or temp objects ...
First we want to know what the setting for
GEM_TEMPOBJ_AGGRESSIVE_STUBBING (perhaps you could send us the banner
that gets dumped when topaz starts up, so we can get more info about
what's happening). If GEM_TEMPOBJ_AGGRESSIVE_STUBBING is FALSE, then
that could be the source of your problem the default for
GEM_TEMPOBJ_AGGRESSIVE_STUBBING is TRUE ... but seeing the banner will
help us nonetheless...
We took a 3.2.9 topaz and started it with a 700MB temp obj cache and
this memory space info was printed out by topaz:
(vmGc spaceSizes: eden init 2048K max 134400K , survivor init 384K max
22400K,
vmGc old max 537600K, code max 143360K, perm max 71680K, pom 10 *
59776K = 597760K,
vmGc remSet 13828K, meSpace max 685324K oopMapSize 4194304 max
footprint 2229M)
Giving you a pom gen size of ~600M and old gem of ~500M
In order to get additional information we want you to reduce the size of
POM gen to 300M (which will in turn cause OLD gen to be increased in
size) with the following settings in your system.conf:
GEM_TEMPOBJ_AGGRESSIVE_STUBBING = TRUE;
GEM_TEMPOBJ_POMGEN_SIZE = 300MB;
GEM_TEMPOBJ_CACHE_SIZE = 700MB;
This may shift the problem to a different point but at least we will
learn more info ... especially getting the startup banner from topaz...
Dale
On 03/08/2016 10:57 AM, Mariano Martinez Peck wrote:
>
>
> On Tue, Mar 8, 2016 at 3:13 PM, Dale Henrichs
> <dale.henrichs at gemtalksystems.com
> <mailto:dale.henrichs at gemtalksystems.com>> wrote:
>
>
>
> On 03/08/2016 09:50 AM, Mariano Martinez Peck wrote:
>> Hi guys,
>>
>> First of all, thanks to Richard for the suggestion. Adding the
>> env var did write the useful info in the gem log.
>>
>> Problem is that even if I tried to fix it (in my code), I still
>> failed :( I attach the whole log in case someone wants to take
>> a look.
>>
>> However, I think there is something strange in
>> #installAlmostOutOfMemoryStaticHandler:. I added some logging to
>> this method to see what was going on (in bold the important parts):
>>
>>
>> /installAlmostOutOfMemoryStaticHandler: initialCommitThreshold/
>> / | handler commitThreshold used |/
>> / commitThreshold := initialCommitThreshold./
>> / handler := AlmostOutOfMemory/
>> / addDefaultHandler: [ :ex | /
>> / "Exception caught, do a commit."/
>> / Transcript/
>> / show: 'exception handled: ' , ex printString;/
>> / cr./
>> / System commitTransaction/
>> / ifFalse: [ /
>> / Transcript/
>> / show: 'AutoCommit failed';/
>> / cr./
>> / nil error: 'AutoCommit failed' ]./
>> / System _vmMarkSweep./
>> /*Transcript*/
>> */ show: 'commit threshold value: ' , commitThreshold
>> printString;/*
>> */ cr./*
>> */ used := System _tempObjSpacePercentUsedLastMark./*
>> */ Transcript/*
>> */ show: 'percent used ' , used printString;/*
>> */ cr./*
>> */ used < commitThreshold/*
>> / ifTrue: [ /
>> / "We dropped below the threshold, reenable the signal"/
>> /*Transcript*/
>> */ show: 're-enable the signal ';/*
>> */ cr./*
>> / System enableAlmostOutOfMemoryError ]/
>> / ifFalse: [ /
>> / "commit and mark sweep did drop us below threshold.
>> cut threshold in half /
>> / and try again. Record an entry in the object log "/
>> / commitThreshold := (100 - commitThreshold) // 2 +
>> commitThreshold./
>> / Transcript/
>> / show: 'commit threshold value: ' , commitThreshold
>> printString;/
>> / cr./
>> / commitThreshold < 98/
>> / ifTrue: [ /
>> / Transcript/
>> / show: 'signalAlmostOutOfMemoryThreshold: ';/
>> / cr./
>> / System signalAlmostOutOfMemoryThreshold:
>> commitThreshold ]/
>> / ifFalse: [ /
>> / "we're with 10% of out of memory, commit instance
>> counts structure /
>> / into objectlog for posterity."/
>> / Transcript/
>> / show: '10% out of memory... record in the object
>> log ';/
>> / cr./
>> / (ObjectLogEntry/
>> / trace: 'almost out of memory: ' ,
>> commitThreshold printString/
>> / object: (System _vmInstanceCountsReport: 3))
>> addToLog./
>> / System commitTransaction/
>> / ifFalse: [ /
>> / Transcript/
>> / show: 'Last AutoCommit failed ';/
>> / cr./
>> / nil error: 'AutoCommit failed' ] ] ]./
>> / ex resume ]./
>> / SessionTemps current/
>> / at: #'CommitOnAlmostOutOfMemoryStaticException'/
>> / put: handler./
>> / System signalAlmostOutOfMemoryThreshold: commitThreshold/
>>
>>
>>
>> Now...if I check the gem log, I get this:
>>
>> /--transcript--'exception handled: a AlmostOutOfMemory occurred
>> (notification 6013), Session''s temporary object memory is almost
>> full'/
>> /--transcript--'commit threshold value: 10'/
>> /--transcript--'percent used 0'/
>> /--transcript--'re-enable the signal '/
>>
>> And that 4 lines repeated several times, until it starts with the:
>>
>>
>> /*********** Fatal error 4067 OutOfMemory *****/
>> /
>> /
>> /Printing Smalltalk stack because of OutOfMemory:/
>> /Smalltalk stack: printing to topaz .out file at [03/08/2016
>> 12:36:11.827 EST]/
>>
>>
>>
>> And this is what I don't understand...from the transcript, it
>> seems that "*/System _tempObjSpacePercentUsedLastMark"/ *always
>> answered 0, hence we are below threshold (no problem!). But then
>> I get the OutOfMemory anyway... so... how can I run out of
>> memory if #_tempObjSpacePercentUsedLastMark answered 0 each time?
>>
>
> Okay the `--transcript--'re-enable the signal '` simply means that
> the AlmostOfMemory signal was re-enabled - the handler is armed -
> it does not guarantee that you won't run out of memory.
>
> The `*********** Fatal error 4067 OutOfMemory *****` means that
> you ran out of memory without triggering an AlmostOutOfMemory
> exception ... for the reasons I mentioned earlier: most likely you
> ran out of memory during a primitive call BEFORE the deferred
> exception could be signaled ..
>
>
> OK, I got it, and that would explain it. OK.
>
> BTW, I tried looking at the selector in my 3.2.9 and didn't see
> symbols, so I don't know what methods are actually being called
> in the first couple of frames, so I can't guess about what might
> be consuming memory ...
>
>
> OK.. I did some analysis. The most complicated part that I didn't know
> how to debug was the "blocks" entries in the stack. Until some time I
> figured out I could use:
>
> (Object _objectForOop: XXX) _sourceStringForBlock
>
> where XXX is the OOP of the GsNMethod printed at the END of the line,
> not the homeMethod printing at the beginning.
>
>
> This is the resulting, translated analysis. Please, start reading from
> the bottom to the top.
>
>
> Thanks!!
>
>
>
> 1 Object >> #'at:' (receiver is OrderedCollection)
>
>
> 2. The closure
>
> '[ :coDataRowDict | coDataRowDict row at: index ]'
>
>
> 3. SequenceableCollection >> #'collect:'
>
>
> 4. Looks to me the closure of #mapSelectedRows:
> inputListOfRowDictionaries toQuuveUsing:
> quuveKeysForZacksTableAccessor prependKeysWith: aPrefix , that is:
>
>
> [ :rowDict |
> | key tmp values dataType |
> ...
> values := aListOfRowDictionaries collect: [ :coDataRowDict |
> coDataRowDict row at: index ].
> ....
> ]
>
>
> 5. The closure of #doWithRowDictionaries: that is:
>
> [ :row | | t|
> t := self rowAsRowDictionary: row. "now the user can use symbolic
> references for testing in the aTestBlock"
> (aBlock value: t)
> ].
>
>
> 6. Collection >> do:
>
>
> 7. FaTableAccessor >> doWithRowDictionaries: aBlock
> self table
> do: [ :row |
> | t |
> t := self rowAsRowDictionary: row."now the user can use symbolic
> references for testing in the aTestBlock"
> aBlock value: t ]
> 8 FaQuandlZacksFundamentalsDataLoader >> mapSelectedRows:
> inputListOfRowDictionaries toQuuveUsing:
> quuveKeysForZacksTableAccessor prependKeysWith: aPrefix
>
> "some code here"
> ....
> quuveKeysForZacksTableAccessor doWithRowDictionaries: [ :rowDict |
> | key tmp values dataType |
> ...
> values := aListOfRowDictionaries collect: [ :coDataRowDict |
> coDataRowDict row at: index ].
> ....
> ]
>
>
>
>
>
>
>
> --
> Mariano
> http://marianopeck.wordpress.com
-------------- next part --------------
An HTML attachment was scrubbed...
URL: <http://lists.gemtalksystems.com/mailman/private/glass/attachments/20160308/ee96fbbe/attachment-0001.html>
More information about the Glass
mailing list