Grokbase Groups Lucene dev July 2010
FAQ
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

Search Discussions

  • Karl Wright at Jul 27, 2010 at 3:57 pm
    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
  • Karl Wright at Jul 28, 2010 at 9:58 am
    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things). So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild. I am now committing every 1000 records, and I can make this happen utterly reliably. The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area. Perhaps this is related?

    If this guess is correct, then there are two bugs. First bug is that index corruption causes merge to spin indefinitely, rather than error out. Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption. I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49 AM


    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
  • Michael McCandless at Jul 29, 2010 at 3:57 pm
    Hi Karl,

    Can you post the original merge failure? A merge failure should not
    corrupt the index and shouldn't cause spinning.

    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?

    Your first thread dumps shows one thread waiting the for the commit to
    finish so it can add a doc, and another thread closing the IW for
    commit (aside: Solr seems to close the IW whenever it autoCommits? Is
    that true?) with the IW.close waiting for all outstanding merges to
    finish (though I see no actual merge thread running). Your 2nd
    [truncated] dump does show a merge thread actively running.

    Is it possible there's just a big merge running, and this is why Solr
    appears hung? (Ie because it closes the writer -- why not just call
    IW.commit instead?)

    Mike
    On Wed, Jul 28, 2010 at 5:57 AM, wrote:
    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things).  So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild.  I am now committing every 1000 records, and I can make this happen utterly reliably.  The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area.  Perhaps this is related?

    If this guess is correct, then there are two bugs.  First bug is that index corruption causes merge to spin indefinitely, rather than error out.  Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption.  I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49  AM


    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
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
  • Yonik Seeley at Jul 29, 2010 at 4:05 pm

    On Thu, Jul 29, 2010 at 11:56 AM, Michael McCandless wrote:
    (aside: Solr seems to close the IW whenever it autoCommits?  Is
    that true?)
    Yeah, the update handler logic is old, and predates the ability of IW
    to commit and handle more of it's own concurrency.

    We need to relax some of the locking that solr does, while adding
    access to NRT capabilities too.

    -Yonik
    http://www.lucidimagination.com

    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
  • Karl Wright at Aug 2, 2010 at 8:58 am
    >>>>>>
    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?
    <<<<<<

    Where can I find CheckIndex?
    Karl

    ________________________________________
    From: ext Michael McCandless [lucene@mikemccandless.com]
    Sent: Thursday, July 29, 2010 11:56 AM
    To: dev@lucene.apache.org
    Subject: Re: busywait hang using extracting update handler on trunk

    Hi Karl,

    Can you post the original merge failure? A merge failure should not
    corrupt the index and shouldn't cause spinning.

    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?

    Your first thread dumps shows one thread waiting the for the commit to
    finish so it can add a doc, and another thread closing the IW for
    commit (aside: Solr seems to close the IW whenever it autoCommits? Is
    that true?) with the IW.close waiting for all outstanding merges to
    finish (though I see no actual merge thread running). Your 2nd
    [truncated] dump does show a merge thread actively running.

    Is it possible there's just a big merge running, and this is why Solr
    appears hung? (Ie because it closes the writer -- why not just call
    IW.commit instead?)

    Mike
    On Wed, Jul 28, 2010 at 5:57 AM, wrote:
    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things). So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild. I am now committing every 1000 records, and I can make this happen utterly reliably. The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area. Perhaps this is related?

    If this guess is correct, then there are two bugs. First bug is that index corruption causes merge to spin indefinitely, rather than error out. Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption. I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49 AM


    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
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org


    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
  • Simon Willnauer at Aug 2, 2010 at 9:11 am

    On Mon, Aug 2, 2010 at 10:56 AM, wrote:
    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?
    <<<<<<

    Where can I find CheckIndex?
    you find it in your lucene JAR
    java -cp lucene.jar -ea:org.apache.lucene...
    org.apache.lucene.index.CheckIndex pathToIndex [-fix] [-segment X]
    [-segment Y]

    see http://lucene.apache.org/java/3_0_2/api/core/org/apache/lucene/index/CheckIndex.html#main%28java.lang.String[]%29
    for details....

    simon
    Karl

    ________________________________________
    From: ext Michael McCandless [lucene@mikemccandless.com]
    Sent: Thursday, July 29, 2010 11:56 AM
    To: dev@lucene.apache.org
    Subject: Re: busywait hang using extracting update handler on trunk

    Hi Karl,

    Can you post the original merge failure?  A merge failure should not
    corrupt the index and shouldn't cause spinning.

    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?

    Your first thread dumps shows one thread waiting the for the commit to
    finish so it can add a doc, and another thread closing the IW for
    commit (aside: Solr seems to close the IW whenever it autoCommits?  Is
    that true?) with the IW.close waiting for all outstanding merges to
    finish (though I see no actual merge thread running).  Your 2nd
    [truncated] dump does show a merge thread actively running.

    Is it possible there's just a big merge running, and this is why Solr
    appears hung?  (Ie because it closes the writer -- why not just call
    IW.commit instead?)

    Mike
    On Wed, Jul 28, 2010 at 5:57 AM,  wrote:
    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things).  So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild.  I am now committing every 1000 records, and I can make this happen utterly reliably.  The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area.  Perhaps this is related?

    If this guess is correct, then there are two bugs.  First bug is that index corruption causes merge to spin indefinitely, rather than error out.  Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption.  I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49  AM


    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
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org


    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
  • Karl Wright at Aug 2, 2010 at 10:00 am

    Thanks. And, for broader consumption, the AIOOB exception is as follows:
    The AIOOB from my reproducible case is as follows:
    SEVERE: java.lang.IndexOutOfBoundsException: Index: 124, Size: 5
    at java.util.ArrayList.RangeCheck(ArrayList.java:547)
    at java.util.ArrayList.get(ArrayList.java:322)
    at org.apache.lucene.index.FieldInfos.fieldInfo(FieldInfos.java:264)
    at org.apache.lucene.index.FieldsReader.doc(FieldsReader.java:204)
    at org.apache.lucene.index.SegmentReader.document(SegmentReader.java:828
    )
    at org.apache.lucene.index.DirectoryReader.document(DirectoryReader.java
    :588)
    at org.apache.lucene.index.IndexReader.document(IndexReader.java:755)
    at org.apache.solr.search.SolrIndexReader.document(SolrIndexReader.java:
    454)
    at org.apache.solr.search.SolrIndexSearcher.doc(SolrIndexSearcher.java:4
    27)
    at org.apache.solr.util.SolrPluginUtils.optimizePreFetchDocs(SolrPluginU
    tils.java:268)
    at org.apache.solr.handler.component.QueryComponent.doPrefetch(QueryComp
    onent.java:287)
    at org.apache.solr.handler.component.QueryComponent.process(QueryCompone
    nt.java:186)
    at org.apache.solr.handler.component.SearchHandler.handleRequestBody(Sea
    rchHandler.java:195)
    at org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandl
    erBase.java:131)
    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)
    <<<<<<

    Karl

    ________________________________________
    From: ext Simon Willnauer [simon.willnauer@googlemail.com]
    Sent: Monday, August 02, 2010 5:11 AM
    To: dev@lucene.apache.org
    Subject: Re: busywait hang using extracting update handler on trunk
    On Mon, Aug 2, 2010 at 10:56 AM, wrote:

    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?
    <<<<<<

    Where can I find CheckIndex?
    you find it in your lucene JAR
    java -cp lucene.jar -ea:org.apache.lucene...
    org.apache.lucene.index.CheckIndex pathToIndex [-fix] [-segment X]
    [-segment Y]

    see http://lucene.apache.org/java/3_0_2/api/core/org/apache/lucene/index/CheckIndex.html#main%28java.lang.String[]%29
    for details....

    simon
    Karl

    ________________________________________
    From: ext Michael McCandless [lucene@mikemccandless.com]
    Sent: Thursday, July 29, 2010 11:56 AM
    To: dev@lucene.apache.org
    Subject: Re: busywait hang using extracting update handler on trunk

    Hi Karl,

    Can you post the original merge failure? A merge failure should not
    corrupt the index and shouldn't cause spinning.

    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?

    Your first thread dumps shows one thread waiting the for the commit to
    finish so it can add a doc, and another thread closing the IW for
    commit (aside: Solr seems to close the IW whenever it autoCommits? Is
    that true?) with the IW.close waiting for all outstanding merges to
    finish (though I see no actual merge thread running). Your 2nd
    [truncated] dump does show a merge thread actively running.

    Is it possible there's just a big merge running, and this is why Solr
    appears hung? (Ie because it closes the writer -- why not just call
    IW.commit instead?)

    Mike
    On Wed, Jul 28, 2010 at 5:57 AM, wrote:
    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things). So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild. I am now committing every 1000 records, and I can make this happen utterly reliably. The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area. Perhaps this is related?

    If this guess is correct, then there are two bugs. First bug is that index corruption causes merge to spin indefinitely, rather than error out. Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption. I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49 AM


    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
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org


    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org


    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
  • Karl Wright at Aug 2, 2010 at 10:38 am

    The result of this run yields the following:
    C:\wip\solr\trunk\solr\example\solr>"c:\Program Files\Java\jdk1.6.0_19\bin\java"
    -cp \solr-dym\searcher\lib\lucene-core-4.0-dev.jar -ea:org.apache.lucene... org
    .apache.lucene.index.CheckIndex data\index

    Opening index @ data\index

    Segments file=segments_8x numSegments=5 version=FORMAT_4_0 [Lucene 4.0]
    1 of 5: name=_9q docCount=317
    codec=Standard
    compound=false
    hasProx=false
    numFiles=6
    size (MB)=0.031
    diagnostics = {optimize=false, mergeFactor=10, os.version=5.1, os=Windows XP
    , mergeDocStores=true, lucene.version=4.0-dev 979328 - 2010-07-26 14:02:52, sour
    ce=merge, os.arch=x86, java.version=1.6.0_19, java.vendor=Sun Microsystems Inc.}

    no deletions
    test: open reader.........OK
    test: fields..............OK [5 fields]
    test: field norms.........OK [5 fields]
    test: terms, freq, prox...OK [640 terms; 1268 terms/docs pairs; 1268 tokens]

    test: stored fields.......ERROR [Index: 103, Size: 5]
    java.lang.IndexOutOfBoundsException: Index: 103, Size: 5
    at java.util.ArrayList.RangeCheck(ArrayList.java:547)
    at java.util.ArrayList.get(ArrayList.java:322)
    at org.apache.lucene.index.FieldInfos.fieldInfo(FieldInfos.java:264)
    at org.apache.lucene.index.FieldsReader.doc(FieldsReader.java:204)
    at org.apache.lucene.index.SegmentReader.document(SegmentReader.java:828
    )
    at org.apache.lucene.index.IndexReader.document(IndexReader.java:755)
    at org.apache.lucene.index.CheckIndex.testStoredFields(CheckIndex.java:7
    39)
    at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:490)
    at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:288)
    at org.apache.lucene.index.CheckIndex.main(CheckIndex.java:934)
    test: term vectors........OK [0 total vector count; avg 0 term/freq vector f
    ields per doc]
    FAILED
    WARNING: fixIndex() would remove reference to this segment; full exception:
    java.lang.RuntimeException: Stored Field test failed
    at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:502)
    at org.apache.lucene.index.CheckIndex.checkIndex(CheckIndex.java:288)
    at org.apache.lucene.index.CheckIndex.main(CheckIndex.java:934)

    2 of 5: name=_9r docCount=1
    codec=Standard
    compound=false
    hasProx=false
    numFiles=7
    size (MB)=0.001
    diagnostics = {os.version=5.1, os=Windows XP, lucene.version=4.0-dev 979328
    - 2010-07-26 14:02:52, source=flush, os.arch=x86, java.version=1.6.0_19, java.ve
    ndor=Sun Microsystems Inc.}
    no deletions
    test: open reader.........OK
    test: fields..............OK [5 fields]
    test: field norms.........OK [5 fields]
    test: terms, freq, prox...OK [4 terms; 4 terms/docs pairs; 4 tokens]
    test: stored fields.......OK [4 total field count; avg 4 fields per doc]
    test: term vectors........OK [0 total vector count; avg 0 term/freq vector f
    ields per doc]

    3 of 5: name=_9s docCount=1
    codec=Standard
    compound=false
    hasProx=false
    numFiles=7
    size (MB)=0.001
    diagnostics = {os.version=5.1, os=Windows XP, lucene.version=4.0-dev 979328
    - 2010-07-26 14:02:52, source=flush, os.arch=x86, java.version=1.6.0_19, java.ve
    ndor=Sun Microsystems Inc.}
    no deletions
    test: open reader.........OK
    test: fields..............OK [5 fields]
    test: field norms.........OK [5 fields]
    test: terms, freq, prox...OK [4 terms; 4 terms/docs pairs; 4 tokens]
    test: stored fields.......OK [4 total field count; avg 4 fields per doc]
    test: term vectors........OK [0 total vector count; avg 0 term/freq vector f
    ields per doc]

    4 of 5: name=_9t docCount=1
    codec=Standard
    compound=false
    hasProx=false
    numFiles=7
    size (MB)=0.001
    diagnostics = {os.version=5.1, os=Windows XP, lucene.version=4.0-dev 979328
    - 2010-07-26 14:02:52, source=flush, os.arch=x86, java.version=1.6.0_19, java.ve
    ndor=Sun Microsystems Inc.}
    no deletions
    test: open reader.........OK
    test: fields..............OK [5 fields]
    test: field norms.........OK [5 fields]
    test: terms, freq, prox...OK [4 terms; 4 terms/docs pairs; 4 tokens]
    test: stored fields.......OK [4 total field count; avg 4 fields per doc]
    test: term vectors........OK [0 total vector count; avg 0 term/freq vector f
    ields per doc]

    5 of 5: name=_9u docCount=1
    codec=Standard
    compound=false
    hasProx=false
    numFiles=7
    size (MB)=0.001
    diagnostics = {os.version=5.1, os=Windows XP, lucene.version=4.0-dev 979328
    - 2010-07-26 14:02:52, source=flush, os.arch=x86, java.version=1.6.0_19, java.ve
    ndor=Sun Microsystems Inc.}
    no deletions
    test: open reader.........OK
    test: fields..............OK [5 fields]
    test: field norms.........OK [5 fields]
    test: terms, freq, prox...OK [4 terms; 4 terms/docs pairs; 4 tokens]
    test: stored fields.......OK [4 total field count; avg 4 fields per doc]
    test: term vectors........OK [0 total vector count; avg 0 term/freq vector f
    ields per doc]

    WARNING: 1 broken segments (containing 317 documents) detected
    WARNING: would write new segments file, and 317 documents would be lost, if -fix
    were specified
    <<<<<<

    Karl


    -----Original Message-----
    From: ext Simon Willnauer
    Sent: Monday, August 02, 2010 5:11 AM
    To: dev@lucene.apache.org
    Subject: Re: busywait hang using extracting update handler on trunk
    On Mon, Aug 2, 2010 at 10:56 AM, wrote:

    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?
    <<<<<<

    Where can I find CheckIndex?
    you find it in your lucene JAR
    java -cp lucene.jar -ea:org.apache.lucene...
    org.apache.lucene.index.CheckIndex pathToIndex [-fix] [-segment X]
    [-segment Y]

    see http://lucene.apache.org/java/3_0_2/api/core/org/apache/lucene/index/CheckIndex.html#main%28java.lang.String[]%29
    for details....

    simon
    Karl

    ________________________________________
    From: ext Michael McCandless [lucene@mikemccandless.com]
    Sent: Thursday, July 29, 2010 11:56 AM
    To: dev@lucene.apache.org
    Subject: Re: busywait hang using extracting update handler on trunk

    Hi Karl,

    Can you post the original merge failure? A merge failure should not
    corrupt the index and shouldn't cause spinning.

    And can you run CheckIndex and post that output, and also the AIOOBE
    you hit for certain searches?

    Your first thread dumps shows one thread waiting the for the commit to
    finish so it can add a doc, and another thread closing the IW for
    commit (aside: Solr seems to close the IW whenever it autoCommits? Is
    that true?) with the IW.close waiting for all outstanding merges to
    finish (though I see no actual merge thread running). Your 2nd
    [truncated] dump does show a merge thread actively running.

    Is it possible there's just a big merge running, and this is why Solr
    appears hung? (Ie because it closes the writer -- why not just call
    IW.commit instead?)

    Mike
    On Wed, Jul 28, 2010 at 5:57 AM, wrote:
    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things). So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild. I am now committing every 1000 records, and I can make this happen utterly reliably. The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area. Perhaps this is related?

    If this guess is correct, then there are two bugs. First bug is that index corruption causes merge to spin indefinitely, rather than error out. Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption. I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49 AM


    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
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org


    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
    ---------------------------------------------------------------------
    To unsubscribe, e-mail: dev-unsubscribe@lucene.apache.org
    For additional commands, e-mail: dev-help@lucene.apache.org
  • Karl Wright at Jul 28, 2010 at 11:55 am
    One of the characters that causes trouble is unicode character 243.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 28, 2010
    Time: 6:0:4 AM


    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things). So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild. I am now committing every 1000 records, and I can make this happen utterly reliably. The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area. Perhaps this is related?

    If this guess is correct, then there are two bugs. First bug is that index corruption causes merge to spin indefinitely, rather than error out. Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption. I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49 AM


    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
  • Karl Wright at Jul 29, 2010 at 2:52 pm
    Unfortunately, this theory goes out the window because I discovered other char 243's in the data prior to the one that apparently corrupts the index.

    I'd love to work with someone here who has better knowldge of indexreader and indexwriter classes. I could potentially post the data itself but that would require legal approval. So instead, please point me in the right direction. or should I just wait and see if other fixes resolve the problem?

    Karl


    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 28, 2010
    Time: 7:55:42 AM


    One of the characters that causes trouble is unicode character 243.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 28, 2010
    Time: 6:0:4 AM


    It appears that whenever I see a merge failure, I also apparently have a corrupt index (I get arrayindexoutofbounds exceptions when searching for certain things). So that may be the underlying cause of the merge infinite loop.

    I've blown away the indexes repeatedly and tried to rebuild. I am now committing every 1000 records, and I can make this happen utterly reliably. The data contains quite a lot of unicode, and I've noted recent posts about tests failing in this area. Perhaps this is related?

    If this guess is correct, then there are two bugs. First bug is that index corruption causes merge to spin indefinitely, rather than error out. Second bug is that certain characters cause index corruption.

    With a bit of work I should be able to isolate the record that is the proximate cause of the index corruption. I will post it when I have it.

    Karl

    --- original message ---
    From: "Wright Karl (Nokia-MS/Cambridge)" <karl.wright@nokia.com>
    Subject: RE: busywait hang using extracting update handler on trunk
    Date: July 27, 2010
    Time: 11:57:49 AM


    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

Related Discussions

Discussion Navigation
viewthread | post
Discussion Overview
groupdev @
categorieslucene
postedJul 27, '10 at 1:25p
activeAug 2, '10 at 10:38a
posts11
users4
websitelucene.apache.org

People

Translate

site design / logo © 2021 Grokbase