5 Replies Latest reply on Dec 9, 2009 11:23 PM by Clebert Suconic

    Weird GC Behaviour on finalize...

    Clebert Suconic Master

      Say you close the session on this following block:


      
      try
      {
      }
      finally
      {
       session.close();
      }
      



      and say the connection failed while inside close...


      session.close() will happens as follows:

      first delegatingSession will call the clientSessionImpl::close.

      Here's a copy for reading convenience:

       try
       {
       producerCreditManager.close();
      
       closeChildren();
      
       inClose = true;
      
       channel.sendBlocking(new SessionCloseMessage());
       }
       catch (Throwable e)
       {
       // Session close should always return without exception
      
       // Note - we only log at trace
       ClientSessionImpl.log.trace("Failed to close session", e);
       }
      
       doCleanup(); // this will set closed as true
      


      The sendBlocking call will be released by failover... so the Failed to close session would happen.

      I have added logging after the failure.. and the cleanup will finish without any problem.

      But for some weird reason that I don't know why.. the DelegateSession is being GCEd while ClientSessionImpl::close still being executed.

      I have added debug logs on my workspace... and the clientSessionimpl::close will happen after the DelegatingSession is done.

      I set the currentThread on a variable on the ClientSession when close is being called and print the traces for that thread when closing, and I could confirm this behaviour.


      That's so weird but I can't control when the VM is going to release the object and call finalize.

      So, what I want to do as a fix is to add a boolean variable on DelegatingSession, so there are no dependencies between the GC of DelegatingSession and the closing on ClientSessionImpl.

      It would be possible to expose inClose on ClientsessionImpl, but I think just adding a property on DelegatingSession would make it clearer.


        • 1. Re: Weird GC Behaviour on finalize...
          Clebert Suconic Master

          So, basically the DelegatingSession is being released before the call to close is finished.

          That's weird I know... but we have no control over that.

          • 2. Re: Weird GC Behaviour on finalize...
            Clebert Suconic Master

            This was happening on MultiThreadRandomReattachTestBase::testB.

            The s.close() here was not on finalize but it was the lass call before s went out of scope.


            I said it was on finalize initially as I changed this locally on my computer but reverted it later. I saw the same behaviour with logs and everything on both scenarios.

            for (int i = 0; i < numSessions; i++)
             {
             SimpleString subName = new SimpleString(threadNum + "sub" + i);
            
             s.deleteQueue(subName);
             }
            
             s.close();
            
             long end = System.currentTimeMillis();
            
             log.info("duration " + (end - start));
            
             }
            


            • 3. Re: Weird GC Behaviour on finalize...
              Tim Fox Master

              I am extremely sceptical that you have found a bug in the garbage collector.

              Much more likely, in my opinion, is that the session is being closed from the garbage collection thread, but that's being called from the garbage collection of a *different object*

              • 4. Re: Weird GC Behaviour on finalize...
                Clebert Suconic Master

                I was also very confused... I added extra logs...


                The close happens in two steps... the first one will set in close.. if there is an exception, cleanup will be called and at that time the closed is set to true.

                Perhaps the closed couldn't be set?

                I added logging on that, and I couldn't find any exceptions.. but maybe I missed it.

                On the case of the exceptions during close.. the code I added into DelegatingSession would be enough to fix the issue.

                I don't think it's worth investing more time on it. The issue is not happening any more after your latest fixes. (I have done several tests on it) And even if it does.. (any exception aborting close), the code on delegatingSession will avoid the "didn't close session" exceptions for the sessions the user closed. (which would only happen rarely during a reattach while calling session.close(); i.e... never!)

                • 5. Re: Weird GC Behaviour on finalize...
                  Clebert Suconic Master

                  Actually.. I could just replicate the issue on my 32 bits laptop....


                  I was running on my laptop (64 bits), on my workstation (8 core, 64 bits).. and I could easily replicate it on my old laptop (32 bits).


                  First, I added the following hacks:

                  On ClientSessionImpl, I exposed inClose.. and I set the thread that is calling close.''


                  
                   private volatile Thread inCloseThread;
                  
                   public boolean isClosing()
                   {
                   return this.inClose;
                   }
                  
                   public void debug()
                   {
                   if (inCloseThread != null)
                   {
                   log.warn("Thread " + inCloseThread + " is at this place");
                   StackTraceElement[] stack = inCloseThread.getStackTrace();
                  
                   for (StackTraceElement el : stack)
                   {
                   log.warn(el.toString());
                   }
                   }
                   }
                  
                   public void close() throws HornetQException
                   {
                   if (closed)
                   {
                   return;
                   }
                  
                   this.inCloseThread = Thread.currentThread();
                  
                   try
                   {
                  
                   try
                   {
                   producerCreditManager.close();
                  
                   closeChildren();
                  
                   inClose = true;
                  
                   channel.sendBlocking(new SessionCloseMessage());
                   }
                   catch (Throwable e)
                   {
                   // Session close should always return without exception
                  
                   // Note - we only log at trace
                   ClientSessionImpl.log.warn("Failed to close session", e);
                   }
                  
                   try
                   {
                   doCleanup();
                   }
                   catch (Exception e)
                   {
                   log.warn("Couldn't complete cleanup", e);
                   }
                  
                   }
                   finally
                   {
                   this.inCloseThread = null;
                   }
                   }
                  
                  
                  


                  Notice that I set the inCloseThread on close.. and set it to null on a finally block.



                  On DelegatingSession, I have reverted my latest commit, and I've placed this on finalize:

                  @Override
                   protected void finalize() throws Throwable
                   {
                   if (!session.isClosed())
                   {
                   DelegatingSession.log.warn("I'm closing a core ClientSession you left open. Please make sure you close all ClientSessions explicitly " + "before letting them go out of scope! " +
                   System.identityHashCode(this));
                  
                   DelegatingSession.log.warn("The ClientSession you didn't close was created here:", creationStack);
                  
                   log.warn("finalize block being called here:", new Exception("trace"));
                  
                   if (((ClientSessionImpl)session).isClosing())
                   {
                   ((ClientSessionImpl)session).debug();
                   }
                  
                   close();
                   }
                  
                   super.finalize();
                   }
                  



                  When I run MultiThreadRandomReattachStress::testB... I see several of those messages on logs (after the hacks I added of course):


                  [Finalizer] 21:59:00,158 WARNING [org.hornetq.core.client.impl.DelegatingSession] The ClientSession you didn't close was created here:
                  java.lang.Exception
                   at org.hornetq.core.client.impl.DelegatingSession.<init>(DelegatingSession.java:95)
                   at org.hornetq.core.client.impl.FailoverManagerImpl.createSession(FailoverManagerImpl.java:433)
                   at org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSessionInternal(ClientSessionFactoryImpl.java:1120)
                   at org.hornetq.core.client.impl.ClientSessionFactoryImpl.createSession(ClientSessionFactoryImpl.java:885)
                   at org.hornetq.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase.doTestB(MultiThreadRandomReattachTestBase.java:426)
                   at org.hornetq.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase$2.run(MultiThreadRandomReattachTestBase.java:93)
                   at org.hornetq.tests.integration.cluster.reattach.MultiThreadReattachSupport$1Runner.run(MultiThreadReattachSupport.java:129)
                  [Finalizer] 21:59:00,181 WARNING [org.hornetq.core.client.impl.DelegatingSession] finalize block being called here:
                  java.lang.Exception: trace
                   at org.hornetq.core.client.impl.DelegatingSession.finalize(DelegatingSession.java:78)
                   at java.lang.ref.Finalizer.invokeFinalizeMethod(Native Method)
                   at java.lang.ref.Finalizer.runFinalizer(Finalizer.java:83)
                   at java.lang.ref.Finalizer.access$100(Finalizer.java:14)
                   at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:160)
                  [Finalizer] 21:59:00,182 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] Thread Thread[Thread-251,5,main] is at this place
                  [Finalizer] 21:59:00,190 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.FailoverManagerImpl.removeSession(FailoverManagerImpl.java:488)
                  [Finalizer] 21:59:00,190 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.ClientSessionImpl.doCleanup(ClientSessionImpl.java:1642)
                  [Finalizer] 21:59:00,191 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.ClientSessionImpl.close(ClientSessionImpl.java:838)
                  [Finalizer] 21:59:00,191 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.DelegatingSession.close(DelegatingSession.java:145)
                  [Finalizer] 21:59:00,192 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase.doTestB(MultiThreadRandomReattachTestBase.java:465)
                  [Finalizer] 21:59:00,192 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase$2.run(MultiThreadRandomReattachTestBase.java:93)
                  [Finalizer] 21:59:00,192 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.tests.integration.cluster.reattach.MultiThreadReattachSupport$1Runner.run(MultiThreadReattachSupport.java:129)
                  [
                  



                  If the call to close was finished... The finally block on ClientSessionImpl would set the inCloseThread back to null... what means.. it wouldn't print any stack traces...

                  In a summary, this shows that finalize is being called while this thread is still being executed:

                  [Finalizer] 21:59:00,182 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] Thread Thread[Thread-251,5,main] is at this place
                  [Finalizer] 21:59:00,190 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.FailoverManagerImpl.removeSession(FailoverManagerImpl.java:488)
                  [Finalizer] 21:59:00,190 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.ClientSessionImpl.doCleanup(ClientSessionImpl.java:1642)
                  [Finalizer] 21:59:00,191 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.ClientSessionImpl.close(ClientSessionImpl.java:838)
                  [Finalizer] 21:59:00,191 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.core.client.impl.DelegatingSession.close(DelegatingSession.java:145)
                  [Finalizer] 21:59:00,192 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase.doTestB(MultiThreadRandomReattachTestBase.java:465)
                  [Finalizer] 21:59:00,192 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.tests.integration.cluster.reattach.MultiThreadRandomReattachTestBase$2.run(MultiThreadRandomReattachTestBase.java:93)
                  [Finalizer] 21:59:00,192 WARNING [org.hornetq.core.client.impl.ClientSessionImpl] org.hornetq.tests.integration.cluster.reattach.MultiThreadReattachSupport$1Runner.run(MultiThreadReattachSupport.java:129)
                  [



                  This is all weird to me also.


                  @Tim: I don't know if you want to pursue this investigation. a simple fix is to add a property on the DelegatingSession like I did.

                  If you decide to pursue the investigation, I could then create a JIRA, attach the patch with my log/hacks.. and try to find out later what's going on. It's up to you.