You are viewing a plain text version of this content. The canonical link for it is here.
Posted to dev@lucene.apache.org by ka...@nokia.com on 2010/07/27 15:24:30 UTC
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
RE: busywait hang using extracting update handler on trunk
Posted by ka...@nokia.com.
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