deadlock when a single thread is adding users ---------------------------------------------
Key: SLING-943 URL: https://issues.apache.org/jira/browse/SLING-943 Project: Sling Issue Type: Bug Affects Versions: Launchpad App 4, Servlets Get 2.0.4, JCR Jackrabbit Server 2.0.4 Environment: Sling Trunk at r768397 with 1 patch SLING-940, OSX 10.5, JDK 1.5, JMX, and Debug ports open. Reporter: Ian Boston 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 11655...@qtp-12248553-1 - Acceptor0 ajp13socketconnec...@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) 4998...@qtp-12248553-0 - Acceptor0 niosocketconnectorwrap...@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.obj...@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) -- This message is automatically generated by JIRA. - You can reply to this email to add a comment to the issue online.