Sling
  1. Sling
  2. SLING-943

deadlock when a single thread is adding users

    Details

    • Type: Bug Bug
    • Status: Resolved
    • Priority: Major Major
    • Resolution: Fixed
    • Affects Version/s: Servlets Get 2.0.4, Launchpad App 5, JCR Jackrabbit Server 2.0.4
    • Fix Version/s: None
    • Component/s: JCR, Launchpad
    • Labels:
      None
    • Environment:

      Description

      I have a script that tests adding users.
      When running this as a single thread, after about 7K users, Sling stops dead with the following deadlock.
      I have previously done runs adding 12K users.

      Will try and investigate, still have the JVM up with profiler connected

      Stack traces of all running threads

      11655167@qtp-12248553-1 - Acceptor0 Ajp13SocketConnector@0.0.0.0:8009 [RUNNABLE]
      java.net.PlainSocketImpl.socketAccept(native method)
      java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
      java.net.ServerSocket.implAccept(ServerSocket.java:450)
      java.net.ServerSocket.accept(ServerSocket.java:421)
      org.mortbay.jetty.bio.SocketConnector.accept(SocketConnector.java:99)
      org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:707)
      org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)

      127.0.0.1 [1240657176563] POST /system/userManager/user.create.html HTTP/1.1 [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      EDU.oswego.cs.dl.util.concurrent.SynchronousChannel.put(unknown source)
      EDU.oswego.cs.dl.util.concurrent.PooledExecutor$WaitWhenBlocked.blockedAction(unknown source)
      EDU.oswego.cs.dl.util.concurrent.PooledExecutor.execute(unknown source)
      org.apache.jackrabbit.core.query.lucene.DynamicPooledExecutor.executeAndWait(DynamicPooledExecutor.java:114)
      org.apache.jackrabbit.core.query.lucene.AbstractIndex.addDocuments(AbstractIndex.java:195)
      org.apache.jackrabbit.core.query.lucene.VolatileIndex.commitPending(VolatileIndex.java:162)
      org.apache.jackrabbit.core.query.lucene.VolatileIndex.getIndexReader(VolatileIndex.java:129)
      org.apache.jackrabbit.core.query.lucene.AbstractIndex.getReadOnlyIndexReader(AbstractIndex.java:265)
      org.apache.jackrabbit.core.query.lucene.MultiIndex.getIndexReader(MultiIndex.java:721)
      org.apache.jackrabbit.core.query.lucene.SearchIndex.getIndexReader(SearchIndex.java:862)
      org.apache.jackrabbit.core.query.lucene.SearchIndex.executeQuery(SearchIndex.java:702)
      org.apache.jackrabbit.core.query.lucene.QueryResultImpl.executeQuery(QueryResultImpl.java:242)
      org.apache.jackrabbit.core.query.lucene.QueryResultImpl.getResults(QueryResultImpl.java:292)
      org.apache.jackrabbit.core.query.lucene.QueryResultImpl.<init>(QueryResultImpl.java:191)
      org.apache.jackrabbit.core.query.lucene.QueryImpl.execute(QueryImpl.java:130)
      org.apache.jackrabbit.core.query.QueryImpl.execute(QueryImpl.java:177)
      org.apache.jackrabbit.core.security.user.IndexNodeResolver.findNode(IndexNodeResolver.java:63)
      org.apache.jackrabbit.core.security.user.UserManagerImpl.getUserNode(UserManagerImpl.java:401)
      org.apache.jackrabbit.core.security.user.UserManagerImpl.getAuthorizable(UserManagerImpl.java:96)
      org.apache.sling.jackrabbit.usermanager.resource.AuthorizableResourceProvider.getResource(AuthorizableResourceProvider.java:107)
      org.apache.sling.jcr.resource.internal.helper.ResourceProviderEntry.getResource(ResourceProviderEntry.java:376)
      org.apache.sling.jcr.resource.internal.helper.ResourceProviderEntry.getResource(ResourceProviderEntry.java:367)
      org.apache.sling.jcr.resource.internal.helper.ResourceProviderEntry.getResource(ResourceProviderEntry.java:122)
      org.apache.sling.jcr.resource.internal.JcrResourceResolver2.getResourceInternal(JcrResourceResolver2.java:686)
      org.apache.sling.jcr.resource.internal.JcrResourceResolver2.resolveInternal(JcrResourceResolver2.java:580)
      org.apache.sling.jcr.resource.internal.JcrResourceResolver2.map(JcrResourceResolver2.java:276)
      org.apache.sling.jcr.resource.internal.JcrResourceResolver2.map(JcrResourceResolver2.java:247)
      org.apache.sling.jackrabbit.usermanager.post.AbstractAuthorizablePostServlet.externalizePath(AbstractAuthorizablePostServlet.java:682)
      org.apache.sling.jackrabbit.usermanager.post.CreateUserServlet.handleOperation(CreateUserServlet.java:177)
      org.apache.sling.jackrabbit.usermanager.post.AbstractAuthorizablePostServlet.doPost(AbstractAuthorizablePostServlet.java:140)
      org.apache.sling.api.servlets.SlingAllMethodsServlet.mayService(SlingAllMethodsServlet.java:143)
      org.apache.sling.api.servlets.SlingSafeMethodsServlet.service(SlingSafeMethodsServlet.java:338)
      org.apache.sling.api.servlets.SlingSafeMethodsServlet.service(SlingSafeMethodsServlet.java:369)
      org.apache.sling.engine.impl.request.RequestData.service(RequestData.java:520)
      org.apache.sling.engine.impl.SlingMainServlet.processRequest(SlingMainServlet.java:409)
      org.apache.sling.engine.impl.filter.RequestSlingFilterChain.render(RequestSlingFilterChain.java:48)
      org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:59)
      org.apache.sling.engine.impl.debug.RequestProgressTrackerLogFilter.doFilter(RequestProgressTrackerLogFilter.java:59)
      org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:57)
      org.sakaiproject.kernel.webapp.filter.SakaiRequestFilter.doFilter(SakaiRequestFilter.java:122)
      org.apache.sling.engine.impl.filter.AbstractSlingFilterChain.doFilter(AbstractSlingFilterChain.java:57)
      org.apache.sling.engine.impl.SlingMainServlet.service(SlingMainServlet.java:296)
      org.apache.sling.engine.impl.SlingMainServlet.service(SlingMainServlet.java:183)
      org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:502)
      org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:389)
      org.ops4j.pax.web.service.internal.HttpServiceServletHandler.handle(HttpServiceServletHandler.java:64)
      org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:181)
      org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:765)
      org.ops4j.pax.web.service.internal.HttpServiceContext.handle(HttpServiceContext.java:111)
      org.ops4j.pax.web.service.internal.JettyServerHandlerCollection.handle(JettyServerHandlerCollection.java:64)
      org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
      org.mortbay.jetty.Server.handle(Server.java:324)
      org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:535)
      org.mortbay.jetty.HttpConnection$RequestHandler.content(HttpConnection.java:880)
      org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:747)
      org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
      org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
      org.mortbay.io.nio.SelectChannelEndPoint.run(SelectChannelEndPoint.java:409)
      org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)

      4998187@qtp-12248553-0 - Acceptor0 NIOSocketConnectorWrapper@0.0.0.0:8080 [RUNNABLE]
      sun.nio.ch.KQueueArrayWrapper.kevent0(native method)
      sun.nio.ch.KQueueArrayWrapper.poll(KQueueArrayWrapper.java:136)
      sun.nio.ch.KQueueSelectorImpl.doSelect(KQueueSelectorImpl.java:69)
      sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:69)
      sun.nio.ch.SelectorImpl.select(SelectorImpl.java:80)
      org.mortbay.io.nio.SelectorManager$SelectSet.doSelect(SelectorManager.java:432)
      org.mortbay.io.nio.SelectorManager.doSelect(SelectorManager.java:185)
      org.mortbay.jetty.nio.SelectChannelConnector.accept(SelectChannelConnector.java:124)
      org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:707)
      org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:520)

      Configuration Updater [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.felix.cm.impl.UpdateThread.run(UpdateThread.java:67)

      DestroyJavaVM [RUNNABLE]
      Stack trace is not available

      FelixDispatchQueue [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.felix.framework.util.EventDispatcher.run(EventDispatcher.java:875)
      org.apache.felix.framework.util.EventDispatcher.access$000(EventDispatcher.java:50)
      org.apache.felix.framework.util.EventDispatcher$1.run(EventDispatcher.java:102)
      java.lang.Thread.run(Thread.java:613)

      FelixPackageAdmin [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.felix.framework.PackageAdminImpl.run(PackageAdminImpl.java:314)
      java.lang.Thread.run(Thread.java:613)

      FelixStartLevel [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.felix.framework.StartLevelImpl.run(StartLevelImpl.java:241)
      java.lang.Thread.run(Thread.java:613)

      File Reaper [WAITING]
      java.lang.Object.wait(native method)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
      org.apache.commons.io.FileCleaningTracker$Reaper.run(FileCleaningTracker.java:205)

      FinalizableReferenceQueue [WAITING]
      java.lang.Object.wait(native method)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
      com.google.inject.util.FinalizableReferenceQueue$1.run(FinalizableReferenceQueue.java:53)

      Finalizer [WAITING]
      java.lang.Object.wait(native method)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
      java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

      GC Daemon [TIMED WAITING]
      java.lang.Object.wait(native method)
      sun.misc.GC$Daemon.run(GC.java:100)

      IndexMerger [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.commons.collections.buffer.BlockingBuffer.remove(BlockingBuffer.java:192)
      org.apache.jackrabbit.core.query.lucene.IndexMerger.run(IndexMerger.java:263)

      IndexMerger [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.commons.collections.buffer.BlockingBuffer.remove(BlockingBuffer.java:192)
      org.apache.jackrabbit.core.query.lucene.IndexMerger.run(IndexMerger.java:263)

      IndexMerger [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.commons.collections.buffer.BlockingBuffer.remove(BlockingBuffer.java:192)
      org.apache.jackrabbit.core.query.lucene.IndexMerger.run(IndexMerger.java:263)

      LogEntry Dispatcher [WAITING]
      sun.misc.Unsafe.park(native method)
      java.util.concurrent.locks.LockSupport.park(LockSupport.java:118)
      java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:1841)
      java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:359)
      org.apache.sling.commons.log.internal.LogSupport$LogEntryDispatcher.dequeueLogEntry(LogSupport.java:536)
      org.apache.sling.commons.log.internal.LogSupport$LogEntryDispatcher.run(LogSupport.java:560)

      ObservationManager [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.commons.collections.buffer.BlockingBuffer.remove(BlockingBuffer.java:192)
      org.apache.jackrabbit.core.observation.ObservationDispatcher.run(ObservationDispatcher.java:138)
      java.lang.Thread.run(Thread.java:613)

      ObservationManager [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.commons.collections.buffer.BlockingBuffer.remove(BlockingBuffer.java:192)
      org.apache.jackrabbit.core.observation.ObservationDispatcher.run(ObservationDispatcher.java:138)
      java.lang.Thread.run(Thread.java:613)

      RMI Reaper [WAITING]
      java.lang.Object.wait(native method)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:120)
      java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:136)
      sun.rmi.transport.ObjectTable$Reaper.run(ObjectTable.java:336)
      java.lang.Thread.run(Thread.java:613)

      RMI TCP Accept-0 [RUNNABLE]
      java.net.PlainSocketImpl.socketAccept(native method)
      java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
      java.net.ServerSocket.implAccept(ServerSocket.java:450)
      java.net.ServerSocket.accept(ServerSocket.java:421)
      sun.management.jmxremote.LocalRMIServerSocketFactory$1.accept(LocalRMIServerSocketFactory.java:31)
      sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
      java.lang.Thread.run(Thread.java:613)

      RMI TCP Accept-0 [RUNNABLE]
      java.net.PlainSocketImpl.socketAccept(native method)
      java.net.PlainSocketImpl.accept(PlainSocketImpl.java:384)
      java.net.ServerSocket.implAccept(ServerSocket.java:450)
      java.net.ServerSocket.accept(ServerSocket.java:421)
      sun.rmi.transport.tcp.TCPTransport.run(TCPTransport.java:340)
      java.lang.Thread.run(Thread.java:613)

      Reference Handler [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)

      Repository Pinger [TIMED WAITING]
      java.lang.Object.wait(native method)
      org.apache.sling.jcr.base.AbstractSlingRepository.run(AbstractSlingRepository.java:922)
      java.lang.Thread.run(Thread.java:613)

      SCR Component Actor [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.felix.scr.impl.ComponentActorThread.run(ComponentActorThread.java:63)

      Signal Dispatcher [RUNNABLE]
      Stack trace is not available

      Thread-11 [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.felix.eventadmin.impl.dispatch.TaskHandler.next(TaskHandler.java:143)
      org.apache.felix.eventadmin.impl.tasks.DispatchTask.run(DispatchTask.java:147)
      org.apache.felix.eventadmin.impl.dispatch.CacheThreadPool$PooledThread.run(CacheThreadPool.java:265)

      Thread-24 [TIMED WAITING]
      java.lang.Thread.sleep(native method)
      org.apache.geronimo.transaction.manager.TransactionTimer$CurrentTime.run(TransactionTimer.java:38)

      Thread-9 [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.felix.eventadmin.impl.dispatch.TaskHandler.next(TaskHandler.java:143)
      org.apache.felix.eventadmin.impl.tasks.DispatchTask.run(DispatchTask.java:147)
      org.apache.felix.eventadmin.impl.dispatch.CacheThreadPool$PooledThread.run(CacheThreadPool.java:265)

      Timer-0 [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      java.util.TimerThread.mainLoop(Timer.java:483)
      java.util.TimerThread.run(Timer.java:462)

      Timer-3 [TIMED WAITING]
      java.lang.Object.wait(native method)
      java.util.TimerThread.mainLoop(Timer.java:509)
      java.util.TimerThread.run(Timer.java:462)

      Timer-4 [TIMED WAITING]
      java.lang.Object.wait(native method)
      java.util.TimerThread.mainLoop(Timer.java:509)
      java.util.TimerThread.run(Timer.java:462)

      Timer-5 [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      java.util.TimerThread.mainLoop(Timer.java:483)
      java.util.TimerThread.run(Timer.java:462)

      Timer-6 [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      java.util.TimerThread.mainLoop(Timer.java:483)
      java.util.TimerThread.run(Timer.java:462)

      Timer-7 [BLOCKED; waiting to lock java.lang.Object@1081c1]
      org.apache.jackrabbit.core.query.lucene.MultiIndex.checkFlush(MultiIndex.java:1156)
      org.apache.jackrabbit.core.query.lucene.MultiIndex.access$100(MultiIndex.java:80)
      org.apache.jackrabbit.core.query.lucene.MultiIndex$1.run(MultiIndex.java:335)
      java.util.TimerThread.mainLoop(Timer.java:512)
      java.util.TimerThread.run(Timer.java:462)

      Timer-8 [TIMED WAITING]
      java.lang.Object.wait(native method)
      java.util.TimerThread.mainLoop(Timer.java:509)
      java.util.TimerThread.run(Timer.java:462)

      Timer-9 [TIMED WAITING]
      java.lang.Object.wait(native method)
      java.util.TimerThread.mainLoop(Timer.java:509)
      java.util.TimerThread.run(Timer.java:462)

      YJPAgent-RequestListener [RUNNABLE]
      Stack trace is not available

      YJPAgent-Telemetry [TIMED WAITING]
      Stack trace is not available

      derby.antiGC [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.derby.impl.services.monitor.AntiGC.run(unknown source)
      java.lang.Thread.run(Thread.java:613)

      derby.antiGC [WAITING]
      java.lang.Object.wait(native method)
      java.lang.Object.wait(Object.java:474)
      org.apache.derby.impl.services.monitor.AntiGC.run(unknown source)
      java.lang.Thread.run(Thread.java:613)

      derby.rawStoreDaemon [TIMED WAITING]
      java.lang.Object.wait(native method)
      org.apache.derby.impl.services.daemon.BasicDaemon.rest(unknown source)
      org.apache.derby.impl.services.daemon.BasicDaemon.run(unknown source)
      java.lang.Thread.run(Thread.java:613)

      derby.rawStoreDaemon [TIMED WAITING]
      java.lang.Object.wait(native method)
      org.apache.derby.impl.services.daemon.BasicDaemon.rest(unknown source)
      org.apache.derby.impl.services.daemon.BasicDaemon.run(unknown source)
      java.lang.Thread.run(Thread.java:613)

      derby.rawStoreDaemon [TIMED WAITING]
      java.lang.Object.wait(native method)
      org.apache.derby.impl.services.daemon.BasicDaemon.rest(unknown source)
      org.apache.derby.impl.services.daemon.BasicDaemon.run(unknown source)
      java.lang.Thread.run(Thread.java:613)

      derby.rawStoreDaemon [TIMED WAITING]
      java.lang.Object.wait(native method)
      org.apache.derby.impl.services.daemon.BasicDaemon.rest(unknown source)
      org.apache.derby.impl.services.daemon.BasicDaemon.run(unknown source)
      java.lang.Thread.run(Thread.java:613)

        Activity

        Gavin made changes -
        Workflow re-open possible,doc-test-required [ 12789705 ] no-reopen-closed,doc-test-required [ 12792696 ]
        Gavin made changes -
        Workflow no-reopen-closed,doc-test-required [ 12767211 ] re-open possible,doc-test-required [ 12789705 ]
        Ian Boston made changes -
        Status Open [ 1 ] Resolved [ 5 ]
        Resolution Fixed [ 1 ]
        Gavin made changes -
        Workflow Copy of no-reopen-closed,doc-test-required [ 12763772 ] no-reopen-closed,doc-test-required [ 12767211 ]
        Gavin made changes -
        Workflow no-reopen-closed,doc-test-required [ 12476161 ] Copy of no-reopen-closed,doc-test-required [ 12763772 ]
        Carsten Ziegeler made changes -
        Component/s JCR [ 12311946 ]
        Component/s Launchpad [ 12312146 ]
        Felix Meschberger made changes -
        Field Original Value New Value
        Workflow jira [ 12461730 ] no-reopen-closed,doc-test-required [ 12476161 ]
        Ian Boston created issue -

          People

          • Assignee:
            Unassigned
            Reporter:
            Ian Boston
          • Votes:
            0 Vote for this issue
            Watchers:
            1 Start watching this issue

            Dates

            • Created:
              Updated:
              Resolved:

              Development