Lots of seaside objects not being GCed (need gemstone advise)

Mariano,

This looks familiar. I *think* it was Dario who encountered a similar problem. Check past message threads. If memory serves (and it usually doesn't), this was about 2-4 months ago.

I'm sure Dale will respond, but tomorrow is the 4th of July. So perhaps not as quickly as you would like.

Let us know whether you find that earlier exchange and if so whether it is the same issue.

Hi guys,

Sorry to bother but I started to find many instances of things I think I should not have.... I have a stone that nobody uses since a couple of hours (so I am sure all sessions should have been expired). I have run this code to clean:

ObjectLogEntry emptyLog.

WAGemStoneMaintenanceTask maintenanceTaskMarkForCollect performTask: 0.

WAGemStoneMaintenanceTask maintenanceTaskExpiration performTask: 0.

System beginTransaction. 

SystemRepository reclaimAll.

SystemRepository startNewLog.

System commitTransaction.

Then...I check some #allInstances size and I get this:

DpWebSession allInstances size 32

WACallbackRegistry allInstances size 217

JQueryClass allInstances size 16519

WACache  allInstances size 35

WAApplication allInstances size 3

WARenderVisitor allInstances size 217

WARenderContext allInstances size 217

WAHtmlCanvas allInstances size 909

.....

(just as some examples).

The good news is that ALL the sessions do look expired:

(DpWebSession allInstances select: [ :each | (each instVarNamed: 'parent') isNil ]) size 32

(expired sessions have a nil 'parent').

However...I cannot explain why I still have all that garbage above if all sessions are expired. Is that normal? I would expect to have nothing.

The worst is the WACallbackRegistry which then refer to closures and contexts of my callbacks, which could refer to large amount of temp data (like lots of XML objects...).

Is this normal? Any hint how can I get rid of those?

On Mon, Jul 6, 2015 at 2:33 PM, Dale Henrichs via Glass <[hidden email]> wrote:

Mariano,

I've read over your other messages and I guess you are still struggling to clean these guys up ... Rest of my comments in line.

Hi Dale.

Thanks, I answer inline. 

 

Dael

On 07/03/2015 08:22 PM, Mariano Martinez Peck via Glass wrote:

Then...I check some #allInstances size and I get this:

DpWebSession allInstances size 32

WACallbackRegistry allInstances size 217

JQueryClass allInstances size 16519

WACache  allInstances size 35

WAApplication allInstances size 3

WARenderVisitor allInstances size 217

WARenderContext allInstances size 217

WAHtmlCanvas allInstances size 909

.....

Right off the bat, my observation is that this doesn't seem like a  lot of uncollected objects, presumably you churn through a lot more sessions than this on a regular basis, so these objects appear to be the exception instead of the rule...

Of course. All those numbers are in a system which didn't receive a single request in a whole day. And this is the results after all the cleanings I could do. So this is why I expect to have zero instances of those (meaning .. no zero, but much less in the real system that what I have now),.

 

(just as some examples).

The good news is that ALL the sessions do look expired:

(DpWebSession allInstances select: [ :each | (each instVarNamed: 'parent') isNil ]) size 32

(expired sessions have a nil 'parent').

One of the interestings that came out of the Larry's "ordeal", is that we found a bug in WACache>>gemstoneReap, where an error while running this method can result in objects getting stuck in the WACache. Basically objects are marked as expired in the WARcLastAccessExpiryPolicy, but due to the error, they may not be removed from the objectsByKey and keysByObjects dictionaries ... thus keeping them alive "forever".

If you check your maintenance vm logs, you might find an error with WACache>>gemstoneReap (Almost Out of Memory is how we found the bug) in Larry's case.

I grep but I found no error in my maintenance logs. 

 

Since you have so few sessions, we can test whether the object  leak is due to this bug:

  | sessions |
  System abortTransaction.
  sessions := WASession allInstances
    select: [ :each | (each instVarNamed: 'parent') isNil ].
  System abortTransaction.
  WAApplication allInstances
    do: [ :app |
      | cache keysByObject |
      cache := app cache.
      keysByObject := cache instVarNamed: 'keysByObject'.
      sessions
        do: [ :session |
          (keysByObject includesKey: session)
            ifTrue: self halt ] ]

If you get a halt running the above, then you've been bitten by the bug and you you need to arrange to remove the session objects from both dicts. See WACache>>gemstoneReap for example code ...

I did not get a Halt in above code.

 

If the WASessions are not stuck in a WAApplication, then it's likely that you have some accidental reference to the WASession objects and you'll have to trace the reference path back to a persistent root using Repository>>findReferencePathToObject: .. this method only returns one reference path... In 3.2 we've created Repository>>findAllReferencePathsToObject: that finds and returns all of the reference paths (in a pinch you could upgrade your repository to 3.2.6 just to run the aalysis) ...

[1] https://github.com/GsDevKit/Seaside31/issues/68

Yes, in fact, earlier today I tried #findReferencePathToObject:  with (MySessionSubclass allInstances any) and guess what????

I get an array of only 2 entries, first element is target object and second element is false. Reading method comment says it means there is no path to that object. WTF!!!! so then why they do not go away??? As said, I do run MFC, I do run #reclaimAll... so..... in which scenario would I hold into instances (and in fact found via #allInstances), yet #findReferencePathToObject: would say there is no path?

 

However...I cannot explain why I still have all that garbage above if all sessions are expired. Is that normal? I would expect to have nothing.

It's not normal:)

That's cool to hear. So...even if those are little number of objects, this gives me a small scenario of the real system. If this stone has not received a single request in hours, then I should get ZERO instances of those :) Cool. 

 

On Mon, Jul 6, 2015 at 6:47 PM, Dale Henrichs <[hidden email]> wrote:

On 07/06/2015 12:28 PM, Mariano Martinez Peck wrote:

On Mon, Jul 6, 2015 at 2:33 PM, Dale Henrichs via Glass <[hidden email]> wrote:

Mariano,

I've read over your other messages and I guess you are still struggling to clean these guys up ... Rest of my comments in line.

Hi Dale.

Thanks, I answer inline. 

 

Dael

On 07/03/2015 08:22 PM, Mariano Martinez Peck via Glass wrote:

Then...I check some #allInstances size and I get this:

DpWebSession allInstances size 32

WACallbackRegistry allInstances size 217

JQueryClass allInstances size 16519

WACache  allInstances size 35

WAApplication allInstances size 3

WARenderVisitor allInstances size 217

WARenderContext allInstances size 217

WAHtmlCanvas allInstances size 909

.....

Right off the bat, my observation is that this doesn't seem like a  lot of uncollected objects, presumably you churn through a lot more sessions than this on a regular basis, so these objects appear to be the exception instead of the rule...

Of course. All those numbers are in a system which didn't receive a single request in a whole day. And this is the results after all the cleanings I could do. So this is why I expect to have zero instances of those (meaning .. no zero, but much less in the real system that what I have now),.

Okay, you didn't have a single request today, so these objects must be hanging around from a previous day. Did you have zero instances the day before?

Without any other information, it is possible that these objects got left behind because of a voting issue (i.e., reference left in the head of a vm) ... did you cycle all of the gems before running the mfc? What is your setting for GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE? If I'm not mistaken GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE does not guarantee that there aren't other references in the gems head to objects ... 

These instances did not appear out of thin air and there is a logical reason for them to be still hanging around ... This a complicated system with a number of moving parts and there is no way to rule out bugs either ...

Without a detailed accounting of the "starting point" and the gems, started and stopped between that point and now it is impossible to guess we cannot guess what might have happened ...

I would suggest that at some point you record the oops of the session objects so that we don't end up finding that every time we look we are looking at a different set of sessions ...

Good point. Thanks. I will remember it for next time: each time I am dealing with this kind of stuff: cycle all seaside gems first! 

Thanks. BTW, my GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE is 100% now to avoid having to cycle gems. 

I will continue with the tests with cycling/killing the gems... but.... continue reading below...

 

Since you have so few sessions, we can test whether the object  leak is due to this bug:

  | sessions |
  System abortTransaction.
  sessions := WASession allInstances
    select: [ :each | (each instVarNamed: 'parent') isNil ].
  System abortTransaction.
  WAApplication allInstances
    do: [ :app |
      | cache keysByObject |
      cache := app cache.
      keysByObject := cache instVarNamed: 'keysByObject'.
      sessions
        do: [ :session |
          (keysByObject includesKey: session)
            ifTrue: self halt ] ]

If you get a halt running the above, then you've been bitten by the bug and you you need to arrange to remove the session objects from both dicts. See WACache>>gemstoneReap for example code ...

I did not get a Halt in above code.

Did you replace `WASession allInstances` with DpWebSession?

hahahahaha how can I keep my respect after this? hahaha. Sorry. What another pair of eyes can do... Thanks Dale..Sorry. Having a 2 month baby is killing ahahah (perfect excuse!)

OK...so yeah, it halted. 

So if I understand correct, a possible fix is what you submitted to  https://github.com/GsDevKit/Seaside31/issues/68 ?

As to the workaround (to remove existing ones) I am not sure what I should do. I guess first step is to apply above fix. Then... A simple 

WACache allInstances do: [:each | each gemstoneReap]   would not do it? 

 

Ouch... no... It wasn't that..the Halt I got was simple because... the code you pasted says:

Dale,

I continue with the efforts and based on your comments I did a couple of things. First, kill all seaside gems. Stop stone. Start stone again (not seaside gems), and run:

((SystemRepository listInstances: { DpWebSession }) at: 1)    

gives me like 50 instances.. meaning there are 50 instances ON DISK. Then I tried to find a path for any of THOSE:

SystemRepository findReferencePathToObject: ((SystemRepository listInstances: { DpWebSession }) at: 1) first 

But still, #findReferencePathToObject: answers an empty path. 

If the path is empty, then "((SystemRepository listInstances: { DpWebSession }) at: 1)    " should give me zero. Correct? Because both are checking on disk...

So there is something I don't understand. 

Thanks in advance, 

On Mon, Jul 6, 2015 at 8:22 PM, Dale Henrichs <[hidden email]> wrote:

On 07/06/2015 03:31 PM, Mariano Martinez Peck wrote:

 

Since you have so few sessions, we can test whether the object  leak is due to this bug:

  | sessions |
  System abortTransaction.
  sessions := WASession allInstances
    select: [ :each | (each instVarNamed: 'parent') isNil ].
  System abortTransaction.
  WAApplication allInstances
    do: [ :app |
      | cache keysByObject |
      cache := app cache.
      keysByObject := cache instVarNamed: 'keysByObject'.
      sessions
        do: [ :session |
          (keysByObject includesKey: session)
            ifTrue: self halt ] ]

If you get a halt running the above, then you've been bitten by the bug and you you need to arrange to remove the session objects from both dicts. See WACache>>gemstoneReap for example code ...

I did not get a Halt in above code.

Did you replace `WASession allInstances` with DpWebSession?

hahahahaha how can I keep my respect after this? hahaha. Sorry. What another pair of eyes can do... Thanks Dale..Sorry. Having a 2 month baby is killing ahahah (perfect excuse!)

OK...so yeah, it halted. 

So if I understand correct, a possible fix is what you submitted to  https://github.com/GsDevKit/Seaside31/issues/68 ?

As to the workaround (to remove existing ones) I am not sure what I should do. I guess first step is to apply above fix. Then... A simple 

WACache allInstances do: [:each | each gemstoneReap]   would not do it? 

 

Ouch... no... It wasn't that..the Halt I got was simple because... the code you pasted says:

I guess we could have inferred that this was true, once the reference paths came back clean ...

Dale

--

Mariano
http://marianopeck.wordpress.com

Dale,

I have continue analyzing this in other stones and after some testing it is clear that some sessions (the size would depend on the system usage) are NOT GCed unless I shut all seaside gems down or cycle them. Originally I was having  GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE on 90% and I was cycling seaside gems once a day as part of GC. Then, I changed it to 100% and stop restarting gems. Now...it COULD have happened that I did not restarted all gems since I modified the GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE and so, the system was still running with 90% and yet I was not restarting seaside gems anymore.

That could explain why I hold onto some instances, right?  Another possibility is the "stale reference" you mention below. I continue answering below:

 

Good point. Thanks. I will remember it for next time: each time I am dealing with this kind of stuff: cycle all seaside gems first! 

Thanks. BTW, my GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE is 100% now to avoid having to cycle gems. 

I will continue with the tests with cycling/killing the gems... but.... continue reading below...

Do you also have the marksweep guy running?

The guy that every 30 minutes perform the "System _generationScavenge_vmMarkSweep."?  Then yes. Why you ask? how this guy could affect? He does not hold any seaside session as far as I know...i simply sends "System _generationScavenge_vmMarkSweep.". Could it be that the #wait: freezes the gem and therefore does not answer the the voting?

Mmmmm now I read in the sysadmin guide: "Gems do not vote until they complete their current transaction. If a Gem is sleeping or otherwise engaged in a long transaction, the vote cannot be

finalized and garbage collection pauses at this point. Commit records accumulate, garbage accumulates, and a variety of problems can ensue."

Uffff maybe since this guys practically sleeps all the time and yet does not do a commit nor abort in each iteration of the loop...maybe this guy is preventing the vote?

Even more......the sysadmin guide also says: "If a committed object in the pom area has been modified, it is copied to the old area if a scavenge occurs before the change is committed."

If it is not that ...maybe you asked because....if it happened that I modified the session (by any seaside request) and the _generationScavenge_vmMarkSweep happened before the request processing finished, then the session would have been moved to "old" space? But even in this case, when the request processing finishes, it would commit the "modified persistent object" (seaside session)...  

 

GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE only dumps the pomgen on the floor ... a stale direct reference to one of these in the the TOC can also keep these guys alive ... I think that was why I marveled in the earlier message about it only being 32 instances ... with the referencePath method not finding anything you should be able to declare a victory:)

What do you mean by a stale direct reference?  

 

On Tue, Jul 7, 2015 at 3:56 PM, Dale Henrichs <[hidden email]> wrote:

On 07/07/2015 05:49 AM, Mariano Martinez Peck wrote:

Dale,

I have continue analyzing this in other stones and after some testing it is clear that some sessions (the size would depend on the system usage) are NOT GCed unless I shut all seaside gems down or cycle them. Originally I was having  GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE on 90% and I was cycling seaside gems once a day as part of GC. Then, I changed it to 100% and stop restarting gems. Now...it COULD have happened that I did not restarted all gems since I modified the GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE and so, the system was still running with 90% and yet I was not restarting seaside gems anymore.

Yes. The meaning of GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE=100 is that all pomgen spaces are dropped ... this does not mean that all references to persistent objects in the vm are dropped ....

Indeed. That's why to be 100% sure to drop all references to persistent objects you likely need to recycle seaside gems (even with EM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE=100)

 

That could explain why I hold onto some instances, right?  Another possibility is the "stale reference" you mention below. I continue answering below:

 

Good point. Thanks. I will remember it for next time: each time I am dealing with this kind of stuff: cycle all seaside gems first! 

Thanks. BTW, my GEM_TEMPOBJ_POMGEN_PRUNE_ON_VOTE is 100% now to avoid having to cycle gems. 

I will continue with the tests with cycling/killing the gems... but.... continue reading below...

Do you also have the marksweep guy running?

The guy that every 30 minutes perform the "System _generationScavenge_vmMarkSweep."?  Then yes. Why you ask? how this guy could affect? He does not hold any seaside session as far as I know...i simply sends "System _generationScavenge_vmMarkSweep.". Could it be that the #wait: freezes the gem and therefore does not answer the the voting?

No if a gem is busy, the stone patiently waits for the gem to hit a transaction boundary - the vote happens on a transaction boundary.

Dale, with this comment, I do not understand why then the comment in the sys admin guide I pasted below "Gems do not vote until they complete their current transaction. If a Gem is sleeping or otherwise engaged in a long transaction, the vote cannot be finalized and garbage collection pauses at this point."

 

This is one of the factors that causes reclaimAll to be non-deterministic (our goal is for recalimAll to be deterministic, but the system _is_ a complex state machine). Gems can be busy doing a long running transaction or a a gem can be idle sitting in transaction - like an idle topaz or GemTools and unless the system triggers an event to cause the gem to wake up, like hitting the commit record limit thresholds, the system patiently waits for the Gem to finish it's "work".

Ok... so it will wait. Ok, I got that.

 

Mmmmm now I read in the sysadmin guide: "Gems do not vote until they complete their current transaction. If a Gem is sleeping or otherwise engaged in a long transaction, the vote cannot be

finalized and garbage collection pauses at this point. Commit records accumulate, garbage accumulates, and a variety of problems can ensue."

Uffff maybe since this guys practically sleeps all the time and yet does not do a commit nor abort in each iteration of the loop...maybe this guy is preventing the vote?

Recall the little process that you installed the vm marksweep code? This particular process is there so that a Seaside gem is guaranteed to have a Smalltalk process ready and available to respond to the SigAbort ... The SigAbort is sent by the stone, when commit records accumulate ...

Well. Here is where I have the last question. That little process we are talking about does this code:

 [

  | count minutesToForceGemGC |

  count := 0.

  minutesToForceGemGC := 30.

   [ true ] whileTrue: [

  (Delay forSeconds: 30) wait.

  count := count + 1.

  (count \\\ (minutesToForceGemGC * 2)) = 0 ifTrue: [

  System _generationScavenge_vmMarkSweep.

  count := 0.

  ].

  ].

 ] forkAt: Processor lowestPriority.

So my question is.... in that code you see I do NOT ever do a commit or abort. So I don't see how this code can enter what you describe as "the vote happens on a transaction boundary". I mean...that code is 99.9% time in a #wait doing no commit nor abort. So...wouldn't that make the voting process to wait for it forever?  Or the SigAbort is what would prevent that?