lucene-dev mailing list archives

Site index · List index
Message view « Date » · « Thread »
Top « Date » · « Thread »
From <karl.wri...@nokia.com>
Subject RE: busywait hang using extracting update handler on trunk
Date Tue, 27 Jul 2010 15:56:49 GMT
Happened again.  The thing that caused it seems to have been an autocommit.  Here's part of
the first thread dump:

        at java.lang.Object.wait(Native Method)
        - waiting on <0x29642f00> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
        - locked <0x29642f00> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"25615188@qtp-20051738-9 - Acceptor0 SocketConnector@0.0.0.0:8983" prio=6 tid=0x
03076800 nid=0x19ac runnable [0x034df000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
        - locked <0x29770448> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:453)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at org.mortbay.jetty.bio.SocketConnector.accept(SocketConnector.java:99)

        at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.ja
va:707)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:582)

"11245030@qtp-20051738-8" prio=6 tid=0x03075000 nid=0x10b4 waiting on condition
[0x0348e000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x2970bad8> (a java.util.concurrent.locks.Reentr
antReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInt
errupt(AbstractQueuedSynchronizer.java:747)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared
(AbstractQueuedSynchronizer.java:877)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.acquireShared(A
bstractQueuedSynchronizer.java:1197)
        at java.util.concurrent.locks.ReentrantReadWriteLock$ReadLock.lock(Reent
rantReadWriteLock.java:594)
        at org.apache.solr.update.DirectUpdateHandler2.addDoc(DirectUpdateHandle
r2.java:211)
        at org.apache.solr.update.processor.RunUpdateProcessor.processAdd(RunUpd
ateProcessorFactory.java:61)
        at org.apache.solr.handler.extraction.ExtractingDocumentLoader.doAdd(Ext
ractingDocumentLoader.java:120)
        at org.apache.solr.handler.extraction.ExtractingDocumentLoader.addDoc(Ex
tractingDocumentLoader.java:125)
        at org.apache.solr.handler.extraction.ExtractingDocumentLoader.load(Extr
actingDocumentLoader.java:195)
        at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(Co
ntentStreamHandlerBase.java:54)
        at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandl
erBase.java:131)
        at org.apache.solr.core.RequestHandlers$LazyRequestHandlerWrapper.handle
Request(RequestHandlers.java:237)
        at org.apache.solr.core.SolrCore.execute(SolrCore.java:1323)
        at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter
.java:337)
        at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilte
r.java:240)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(Servlet
Handler.java:1157)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:3
88)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.jav
a:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:1
82)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:7
65)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)

        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHand
lerCollection.java:230)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.
java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:1
52)
        at org.mortbay.jetty.Server.handle(Server.java:326)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:54
2)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpCo
nnection.java:923)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:547)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
        at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.
java:228)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:582)

"25377109@qtp-20051738-7" prio=6 tid=0x03073800 nid=0x11c0 in Object.wait() [0x0
343e000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x2c802ee0> (a org.apache.solr.update.SolrIndexWriter)
        at org.apache.lucene.index.IndexWriter.doWait(IndexWriter.java:4270)
        - locked <0x2c802ee0> (a org.apache.solr.update.SolrIndexWriter)
        at org.apache.lucene.index.IndexWriter.waitForMerges(IndexWriter.java:27
81)
        - locked <0x2c802ee0> (a org.apache.solr.update.SolrIndexWriter)
        at org.apache.lucene.index.IndexWriter.finishMerges(IndexWriter.java:276
9)
        - locked <0x2c802ee0> (a org.apache.solr.update.SolrIndexWriter)
        at org.apache.lucene.index.IndexWriter.closeInternal(IndexWriter.java:17
42)
        at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1695)
        at org.apache.lucene.index.IndexWriter.close(IndexWriter.java:1659)
        at org.apache.solr.update.SolrIndexWriter.close(SolrIndexWriter.java:231
)
        at org.apache.solr.update.DirectUpdateHandler2.closeWriter(DirectUpdateH
andler2.java:181)
        at org.apache.solr.update.DirectUpdateHandler2.commit(DirectUpdateHandle
r2.java:409)
        at org.apache.solr.update.processor.RunUpdateProcessor.processCommit(Run
UpdateProcessorFactory.java:85)
        at org.apache.solr.handler.RequestHandlerUtils.handleCommit(RequestHandl
erUtils.java:107)
        at org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(Co
ntentStreamHandlerBase.java:48)
        at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandl
erBase.java:131)
        at org.apache.solr.core.RequestHandlers$LazyRequestHandlerWrapper.handle
Request(RequestHandlers.java:237)
        at org.apache.solr.core.SolrCore.execute(SolrCore.java:1323)
        at org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter
.java:337)
        at org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilte
r.java:240)
        at org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(Servlet
Handler.java:1157)
        at org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:3
88)
        at org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.jav
a:216)
        at org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:1
82)
        at org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:7
65)
        at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:418)

        at org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHand
lerCollection.java:230)
        at org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.
java:114)
        at org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:1
52)
        at org.mortbay.jetty.Server.handle(Server.java:326)
        at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:54
2)
        at org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpCo
nnection.java:923)
        at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:547)
        at org.mortbay.jetty.HttpParser.parseAvailable(HttpParser.java:212)
        at org.mortbay.jetty.HttpConnection.handle(HttpConnection.java:404)
        at org.mortbay.jetty.bio.SocketConnector$Connection.run(SocketConnector.
java:228)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:582)

"15232416@qtp-20051738-6" prio=6 tid=0x0309ac00 nid=0x1458 in Object.wait() [0x0
33ef000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ece00> (a org.mortbay.thread.QueuedThreadPool$PoolThr
ead)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:625)
        - locked <0x295ece00> (a org.mortbay.thread.QueuedThreadPool$PoolThread)


"381299@qtp-20051738-5" prio=6 tid=0x03099800 nid=0x19ec in Object.wait() [0x033
9f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ece70> (a org.mortbay.thread.QueuedThreadPool$PoolThr
ead)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:625)
        - locked <0x295ece70> (a org.mortbay.thread.QueuedThreadPool$PoolThread)


"2583282@qtp-20051738-4" prio=6 tid=0x03095800 nid=0x18dc in Object.wait() [0x03
34f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ecee0> (a org.mortbay.thread.QueuedThreadPool$PoolThr
ead)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:625)
        - locked <0x295ecee0> (a org.mortbay.thread.QueuedThreadPool$PoolThread)


"31289430@qtp-20051738-3" prio=6 tid=0x030a2800 nid=0x10c4 in Object.wait() [0x0
32ff000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ecf50> (a org.mortbay.thread.QueuedThreadPool$PoolThr
ead)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:625)
        - locked <0x295ecf50> (a org.mortbay.thread.QueuedThreadPool$PoolThread)


"9004539@qtp-20051738-2" prio=6 tid=0x03077400 nid=0x1a38 in Object.wait() [0x03
2af000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ecfc0> (a org.mortbay.thread.QueuedThreadPool$PoolThr
ead)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:625)
        - locked <0x295ecfc0> (a org.mortbay.thread.QueuedThreadPool$PoolThread)


"30971263@qtp-20051738-1" prio=6 tid=0x0308f800 nid=0x1ae0 in Object.wait() [0x0
325f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ed030> (a org.mortbay.thread.QueuedThreadPool$PoolThr
ead)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:625)
        - locked <0x295ed030> (a org.mortbay.thread.QueuedThreadPool$PoolThread)


"17758476@qtp-20051738-0" prio=6 tid=0x03094800 nid=0x1d58 in Object.wait() [0x0
320f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ed0a0> (a org.mortbay.thread.QueuedThreadPool$PoolThr
ead)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:625)
        - locked <0x295ed0a0> (a org.mortbay.thread.QueuedThreadPool$PoolThread)


"Timer-0" daemon prio=6 tid=0x0308a400 nid=0x1d68 in Object.wait() [0x031bf000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295ed180> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
        - locked <0x295ed180> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"Low Memory Detector" daemon prio=6 tid=0x02c1d400 nid=0x122c runnable [0x000000
00]
   java.lang.Thread.State: RUNNABLE

"CompilerThread0" daemon prio=10 tid=0x02c17400 nid=0x1f94 waiting on condition
[0x00000000]
   java.lang.Thread.State: RUNNABLE

"Attach Listener" daemon prio=10 tid=0x02c15c00 nid=0x11b8 runnable [0x00000000]

   java.lang.Thread.State: RUNNABLE

"Signal Dispatcher" daemon prio=10 tid=0x02c14800 nid=0xf38 waiting on condition
 [0x00000000]
   java.lang.Thread.State: RUNNABLE

"Finalizer" daemon prio=8 tid=0x02c0cc00 nid=0x1408 in Object.wait() [0x02ddf000
]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x29590468> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
        - locked <0x29590468> (a java.lang.ref.ReferenceQueue$Lock)
        at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
        at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)

"Reference Handler" daemon prio=10 tid=0x02c0b400 nid=0x1614 in Object.wait() [0
x02d8f000]
   java.lang.Thread.State: WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x295904f0> (a java.lang.ref.Reference$Lock)
        at java.lang.Object.wait(Object.java:485)
        at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)
        - locked <0x295904f0> (a java.lang.ref.Reference$Lock)

"VM Thread" prio=10 tid=0x02c09c00 nid=0x1cc8 runnable

"VM Periodic Task Thread" prio=10 tid=0x02c20000 nid=0x90c waiting on condition


JNI global references: 1236

Heap
 def new generation   total 44992K, used 20928K [0x24040000, 0x27110000, 0x29590
000)
  eden space 40000K,  52% used [0x24040000, 0x254b0278, 0x26750000)
  from space 4992K,   0% used [0x26c30000, 0x26c30038, 0x27110000)
  to   space 4992K,   0% used [0x26750000, 0x26750000, 0x26c30000)
 tenured generation   total 99780K, used 74989K [0x29590000, 0x2f701000, 0x34040
000)
   the space 99780K,  75% used [0x29590000, 0x2decb7a8, 0x2decb800, 0x2f701000)
 compacting perm gen  total 12288K, used 8833K [0x34040000, 0x34c40000, 0x380400
00)
   the space 12288K,  71% used [0x34040000, 0x348e0758, 0x348e0800, 0x34c40000)
    ro space 10240K,  54% used [0x38040000, 0x385bb760, 0x385bb800, 0x38a40000)
    rw space 12288K,  55% used [0x38a40000, 0x390df798, 0x390df800, 0x39640000)



Here's the top part of a second thread dump (it doesn't all fit in one screen buffer, unfortunately):

JNI global references: 1236

Heap
 def new generation   total 44992K, used 20928K [0x24040000, 0x27110000, 0x29590
000)
  eden space 40000K,  52% used [0x24040000, 0x254b0278, 0x26750000)
  from space 4992K,   0% used [0x26c30000, 0x26c30038, 0x27110000)
  to   space 4992K,   0% used [0x26750000, 0x26750000, 0x26c30000)
 tenured generation   total 99780K, used 74989K [0x29590000, 0x2f701000, 0x34040
000)
   the space 99780K,  75% used [0x29590000, 0x2decb7a8, 0x2decb800, 0x2f701000)
 compacting perm gen  total 12288K, used 8833K [0x34040000, 0x34c40000, 0x380400
00)
   the space 12288K,  71% used [0x34040000, 0x348e0758, 0x348e0800, 0x34c40000)
    ro space 10240K,  54% used [0x38040000, 0x385bb760, 0x385bb800, 0x38a40000)
    rw space 12288K,  55% used [0x38a40000, 0x390df798, 0x390df800, 0x39640000)

2010-07-27 11:55:19
Full thread dump Java HotSpot(TM) Client VM (16.2-b04 mixed mode, sharing):

"Lucene Merge Thread #0" daemon prio=6 tid=0x02ffc400 nid=0xba0 runnable [0x042e
f000]
   java.lang.Thread.State: RUNNABLE
        at sun.nio.ch.FileChannelImpl.size0(Native Method)
        at sun.nio.ch.FileChannelImpl.size(FileChannelImpl.java:309)
        - locked <0x2de616d8> (a java.lang.Object)
        at sun.nio.ch.FileChannelImpl.transferFrom(FileChannelImpl.java:597)
        at org.apache.lucene.store.FSDirectory.copy(FSDirectory.java:476)
        at org.apache.lucene.store.FSDirectory$FSIndexOutput.copyBytes(FSDirecto
ry.java:513)
        at org.apache.lucene.index.FieldsWriter.addRawDocuments(FieldsWriter.jav
a:210)
        at org.apache.lucene.index.SegmentMerger.copyFieldsWithDeletions(Segment
Merger.java:392)
        at org.apache.lucene.index.SegmentMerger.mergeFields(SegmentMerger.java:
329)
        at org.apache.lucene.index.SegmentMerger.merge(SegmentMerger.java:153)
        at org.apache.lucene.index.IndexWriter.mergeMiddle(IndexWriter.java:4024
)
        at org.apache.lucene.index.IndexWriter.merge(IndexWriter.java:3618)
        at org.apache.lucene.index.ConcurrentMergeScheduler.doMerge(ConcurrentMe
rgeScheduler.java:339)
        at org.apache.lucene.index.ConcurrentMergeScheduler$MergeThread.run(Conc
urrentMergeScheduler.java:407)

"DestroyJavaVM" prio=6 tid=0x003b6800 nid=0x1e34 waiting on condition [0x0000000
0]
   java.lang.Thread.State: RUNNABLE

"Timer-2" daemon prio=6 tid=0x0363b400 nid=0x1e2c in Object.wait() [0x03a9f000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x297703f0> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
        - locked <0x297703f0> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"pool-1-thread-1" prio=6 tid=0x02cb1400 nid=0x1760 waiting on condition [0x03a3f
000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x296acc88> (a java.util.concurrent.locks.Abstra
ctQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject
.await(AbstractQueuedSynchronizer.java:1925)
        at java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.jav
a:399)
        at java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.ja
va:947)
        at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor
.java:907)
        at java.lang.Thread.run(Thread.java:619)

"Timer-1" daemon prio=6 tid=0x036de000 nid=0x1130 in Object.wait() [0x039df000]
   java.lang.Thread.State: TIMED_WAITING (on object monitor)
        at java.lang.Object.wait(Native Method)
        - waiting on <0x29642f00> (a java.util.TaskQueue)
        at java.util.TimerThread.mainLoop(Timer.java:509)
        - locked <0x29642f00> (a java.util.TaskQueue)
        at java.util.TimerThread.run(Timer.java:462)

"25615188@qtp-20051738-9 - Acceptor0 SocketConnector@0.0.0.0:8983" prio=6 tid=0x
03076800 nid=0x19ac runnable [0x034df000]
   java.lang.Thread.State: RUNNABLE
        at java.net.PlainSocketImpl.socketAccept(Native Method)
        at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:390)
        - locked <0x29770448> (a java.net.SocksSocketImpl)
        at java.net.ServerSocket.implAccept(ServerSocket.java:453)
        at java.net.ServerSocket.accept(ServerSocket.java:421)
        at org.mortbay.jetty.bio.SocketConnector.accept(SocketConnector.java:99)

        at org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.ja
va:707)
        at org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.j
ava:582)

"11245030@qtp-20051738-8" prio=6 tid=0x03075000 nid=0x10b4 waiting on condition
[0x0348e000]
   java.lang.Thread.State: WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x2970bad8> (a java.util.concurrent.locks.Reentr
antReadWriteLock$NonfairSync)
        at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.parkAndCheckInt
errupt(AbstractQueuedSynchronizer.java:747)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer.doAcquireShared
(AbstractQueuedSynchronizer.java:877)
...

Karl


-----Original Message-----
From: Wright Karl (Nokia-MS/Cambridge)
Sent: Tuesday, July 27, 2010 9:25 AM
To: dev@lucene.apache.org
Subject: busywait hang using extracting update handler on trunk

Hi,
While using extracting update request handler on trunk to index some 20 million records, about
1/3 theway through solr just hung, using 100% cpu.  the same post code had been successfully
used with the last release solr version, so this may be a regrssion.  If it happens again
I cantry to get a thread dump.  Any thoughts?

Karl

Mime
View raw message