8 Replies Latest reply on Apr 3, 2014 11:30 AM by mashama

    Periodic garbage collection NPE

    mashama

      I am seeing a NPE every five minutes during a scheduled LockGarbageCollectionTask.  I have placed the stack trace below.  What could be the cause of this issue?  I am utilizing locks in my application code, however I am not explicitly unlocking them.  It is my understanding that if the locks are session scoped they will expire when Session.logout is explicitly called. 

      14:49:55,859 ERROR [org.modeshape.jcr.JcrRepository] (modeshape-gc-6-thread-1) Error during background garbage collection: null: java.lang.NullPointerException

              at org.modeshape.jcr.SystemContent.first(SystemContent.java:647) [modeshape-jcr-3.7.1.Final.jar:3.7.1.Final]

              at org.modeshape.jcr.SystemContent.first(SystemContent.java:641) [modeshape-jcr-3.7.1.Final.jar:3.7.1.Final]

              at org.modeshape.jcr.SystemContent.cleanUpLocks(SystemContent.java:818) [modeshape-jcr-3.7.1.Final.jar:3.7.1.Final]

              at org.modeshape.jcr.JcrRepository$RunningState.cleanUpLocks(JcrRepository.java:1790) [modeshape-jcr-3.7.1.Final.jar:3.7.1.Final]

              at org.modeshape.jcr.JcrRepository$LockGarbageCollectionTask.doRun(JcrRepository.java:2125) [modeshape-jcr-3.7.1.Final.jar:3.7.1.Final]

              at org.modeshape.jcr.JcrRepository$BackgroundRepositoryTask.run(JcrRepository.java:2095) [modeshape-jcr-3.7.1.Final.jar:3.7.1.Final]

              at java.util.concurrent.Executors$RunnableAdapter.call(Executors.java:441) [rt.jar:1.6.0_27]

              at java.util.concurrent.FutureTask$Sync.innerRunAndReset(FutureTask.java:317) [rt.jar:1.6.0_27]

              at java.util.concurrent.FutureTask.runAndReset(FutureTask.java:150) [rt.jar:1.6.0_27]

              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.access$101(ScheduledThreadPoolExecutor.java:98) [rt.jar:1.6.0_27]

              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.runPeriodic(ScheduledThreadPoolExecutor.java:180) [rt.jar:1.6.0_27]

              at java.util.concurrent.ScheduledThreadPoolExecutor$ScheduledFutureTask.run(ScheduledThreadPoolExecutor.java:204) [rt.jar:1.6.0_27]

              at java.util.concurrent.ThreadPoolExecutor$Worker.runTask(ThreadPoolExecutor.java:886) [rt.jar:1.6.0_27]

              at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:908) [rt.jar:1.6.0_27]

              at java.lang.Thread.run(Thread.java:662) [rt.jar:1.6.0_27]

      As always your help is greatly appreciated!

       

      Environment:

      ModeShape 3.7.1.Final (ModeShape subsystem for EAP 6.1.0.GA)

      JBoss EAP 6.1.0.GA

        • 1. Re: Periodic garbage collection NPE
          rhauch

          From the stack trace, it looks like the CachedNode instance held in the 'locks' variable on line 817 of SystemContent is actually null and thus causing the NullPointerException. Since the key (identifier) for this node was obtained as being one of the children of the "/jcr:system/mode:locks" parent node, my guess is that some concurrent operations are removing locks that otherwise attempt to get cleaned up in this LockGarbageCollectionTask. Essentially, a lock is removed after the set of children (e.g., locks) has been obtained but before all locks have been processed.

           

          Can you log an issue in our JIRA to check for the null CacheNode reference? That will catch most of these concurrent cases. Thanks!

           

          If your application *always* cleans up its locks, then you could decrease the frequency of this garbage collection process. After all, this background process is only attempting to clean up locks that were not cleaned up properly.

          • 2. Re: Periodic garbage collection NPE
            mashama

            Thanks for the prompt response Randall.  I think your implication is that my application may not *always* be cleaning up locks.  This may very well the case, aside from retrieving the locks from the lock manager my application does nothing else explicitly with them.  The assumption here is that they will be unlocked when the Session expires.  My next question how can I see what locks my application is not cleaning up properly? I tried hoing to http://host:port/modeshape-rest/repository/workspace/items/jcr%3asystem/mode%3alocks but it yielded an exceptional result:

            {"stacktrace": "java.util.NoSuchElementExceptionntat org.modeshape.common.collection.LinkedListMultimap.isValid(LinkedListMultimap.java:668)ntat org.modeshape.common.collection.LinkedListMultimap$EntryIterator.next(LinkedListMultimap.java:700)ntat org.modeshape.common.collection.LinkedListMultimap$4$1.next(LinkedListMultimap.java:391)ntat org.modeshape.jcr.JcrChildNodeIterator.nextNode(JcrChildNodeIterator.java:112)ntat org.modeshape.web.jcr.rest.handler.AbstractHandler.createRestNode(AbstractHandler.java:294)ntat org.modeshape.web.jcr.rest.handler.AbstractHandler.createRestItem(AbstractHandler.java:226)ntat org.modeshape.web.jcr.rest.handler.RestItemHandler.item(RestItemHandler.java:76)ntat org.modeshape.web.jcr.rest.ModeShapeRestService.getItem(ModeShapeRestService.java:312)ntat sun.reflect.GeneratedMethodAccessor679.invoke(Unknown Source)ntat sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:25)ntat java.lang.reflect.Method.invoke(Method.java:597)ntat org.jboss.resteasy.core.MethodInjectorImpl.invoke(MethodInjectorImpl.java:167)ntat org.jboss.resteasy.core.ResourceMethod.invokeOnTarget(ResourceMethod.java:269)ntat org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:227)ntat org.jboss.resteasy.core.ResourceMethod.invoke(ResourceMethod.java:216)ntat org.jboss.resteasy.core.SynchronousDispatcher.getResponse(SynchronousDispatcher.java:542)ntat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:524)ntat org.jboss.resteasy.core.SynchronousDispatcher.invoke(SynchronousDispatcher.java:126)ntat org.jboss.resteasy.plugins.server.servlet.ServletContainerDispatcher.service(ServletContainerDispatcher.java:208)ntat org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:55)ntat org.jboss.resteasy.plugins.server.servlet.HttpServletDispatcher.service(HttpServletDispatcher.java:50)ntat javax.servlet.http.HttpServlet.service(HttpServlet.java:847)ntat org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:295)ntat org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:214)ntat org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:230)ntat org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:149)ntat org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:481)ntat org.jboss.as.web.security.SecurityContextAssociationValve.invoke(SecurityContextAssociationValve.java:169)ntat org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:145)ntat org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:97)ntat org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:102)ntat org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:336)ntat org.apache.coyote.http11.Http11Processor.process(Http11Processor.java:856)ntat org.apache.coyote.http11.Http11Protocol$Http11ConnectionHandler.process(Http11Protocol.java:653)ntat org.apache.tomcat.util.net.JIoEndpoint$Worker.run(JIoEndpoint.java:920)ntat java.lang.Thread.run(Thread.java:662)n"}

             

            Looking forward to ModeShape 4.0 ... =P

            • 3. Re: Periodic garbage collection NPE
              rhauch

              No, I wasn't insinuating that your application is not properly cleaning up locks. Apologies if that's how you interpreted by comment.

               

              When the lock garbage collection thread runs, it will see all current locks and will attempt to see if they're candidates for garbage collection. The NPE happens when one of the locks it found was suddenly not available because it was properly cleaned up by the session. So that's what we have to fix, and that's what I asked you log an issue about.

               

              When a session logs out, it will automatically release any session-scoped locks. Of course, your application can manually release any locks by calling LockManager.unlock(...) with the path of the locked node. Andy if your application acquires any open-scoped locks (that is, releases the token for a lock that was previously session-scoped), then those really should be released explicitly. The garbage collector is simply a background process that will catch any locks that happen to fall through the cracks; really, this only happens with open-scoped locks that your application might forget to release, or if your JVM crashes while a session has session-scoped locks.

               

              So if you're just using session-scoped locks, you can continue doing what you're doing, though I'd suggestion decreasing the frequency of the lock garbage collection thread, which is adding very little in the case of session-scoped locks. I would venture to say that every 5 minutes is too frequent.

               

              As for your latest exception, I think this is caused by the same situation as your original problem: the underlying node is being removed from the repository while the iterator is in the middle of iterating over the children of the parent node. Please add both exceptions to the issue.

              • 4. Re: Periodic garbage collection NPE
                mashama

                No need for an apology.  I guess it was just wishful thinking that I am doing something wrong I can fix.  So here is what I am concluding from this discussion.  First, the error is benign to the applications running on top of the ModeShape instance.  Second, the error happens at the frequency of the lock garbage collection thread because the error prevent the garbage collection from succeeding thereby leaving the lock for subsequent garbage collections.  Third, lock garbage collecting ever 5 minutes doesn't make sense in the case of session-scoped locks. 

                 

                I will add a JIRA issue pertaining to these two exceptions shortly.

                • 5. Re: Periodic garbage collection NPE
                  rhauch

                  First, the error is benign to the applications running on top of the ModeShape instance.

                  Yes, that is correct IMO.

                   

                  Second, the error happens at the frequency of the lock garbage collection thread because the error prevent the garbage collection from succeeding thereby leaving the lock for subsequent garbage collections.

                  Well, not quite. If you're using session-scoped locks (and no open-scoped locks) then when you close your session all session-scoped locks will get cleaned up even if the lock garbage collection were to never run. Therefore, the error does not prevent the garbage collection from succeeding, because really the garbage collection (if it were allowed to continue) would discover there are no locks that it can clean up. (The garbage collection process looks at all the locks, and attempts to clean up only open-scoped locks and session-scoped that are "old". Since none of your locks will be "old enough", the garbage collection process really is just trying to read the lock information and having trouble doing that since the locks are routinely disappearing part way through the process' loop.)

                   

                  Third, lock garbage collecting ever 5 minutes doesn't make sense in the case of session-scoped locks.

                  Correct, assuming your JVM and ModeShape both stay in working order. For example, if a session obtains a session-scoped lock and the JVM crashes at that point (before the session logs out and releases the lock), then this lock will remain forever. That's why the garbage collection process also looks at session-scoped locks and cleans them up after they are "old" enough. So the lock garbage collection process still is useful, even when using only session-scoped locks, but only to clean up after a catastrophic event like the JVM crashing.

                   

                  So, I would configure the lock garbage collection process to run, but just far less frequently. If you are indeed properly using sessions-scoped locks, you could run it perhaps just once per day during a time period where you might routinely have less load. The garbage collection process is not really that intensive of an operation, but it'd make sense to run any housecleaning processes like this during off-peak times.

                  • 6. Re: Periodic garbage collection NPE
                    rhauch

                    Thanks for logging MODE-2190.

                    • 7. Re: Periodic garbage collection NPE
                      mashama

                      You are welcome!  Thanks for your superb stewardship of the ModeShape project.  Looking forward to ModeShape 4.x ...

                      • 8. Re: Periodic garbage collection NPE
                        mashama

                        Just out of curiosity can I update the garbage collection frequency through CLI?  Reading the resource through CLI seems to report inconsistent information regarding the garbage collection interval:

                         

                        [standalone@chp-jbsdev01:10099 /] /subsystem=modeshape/repository=salesapp:read-resource

                        {

                            "outcome" => "success",

                            "result" => {

                        ....

                                "garbage-collection-initial-time" => "00:00",

                                "garbage-collection-interval" => 24,

                                "garbage-collection-thread-pool" => "modeshape-gc",

                         

                        ....

                        I believe this is reporting a 24 hour garbage collection frequency.  However the errors I saw seem to suggest the interval is 5 minutes ... and I never explicitly configured it to be that way.