[SLING-943] deadlock when a single thread is adding users

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

Environment

Sling Trunk at r768397 with 1 patch SLING-940, OSX 10.5, JDK 1.5, JMX, and Debug ports open.

• Assignee: Unassigned
• Reporter: Ian Boston
• Created: 25/Apr/09 11:10
• Updated: 25/Feb/13 00:16
• Resolved: 25/Feb/13 00:16

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)