You are viewing a plain text version of this content. The canonical link for it is here.

Posted to solr-user@lucene.apache.org by "mav.peri@holidaylettings.co.uk" <ma...@holidaylettings.co.uk> on 2012/04/28 02:23:08 UTC

commit fail

Hi again,

This is the only log entry I can find, regarding the failed commits…

Still timing out as far as the client is concerned and there is actually nothing happening on the server in terms of load (staging environment).

1 CPU core seems busy constantly with solr but unsure what is happening.

<record>
  <date>2012-04-28T01:19:53</date>
  <millis>1335572393793</millis>
  <sequence>388</sequence>
  <logger>org.apache.solr.core.SolrCore</logger>
  <level>INFO</level>
  <class>org.apache.solr.core.SolrDeletionPolicy</class>
  <method>onInit</method>
  <thread>15</thread>
  <message>SolrDeletionPolicy.onInit: commits:num=1
commit{dir=/usr/local/apache-solr-3.5.0/example/solr/data/index,segFN=segments_1r,version=1335435169804,generation=63,filenames=[_bl.nrm, _bd.prx, _bi.prx, _bc.fnm, _9x.nrm, _9c.tii, _bf.prx, _be.frq, _6u.tii, _as.fnm, _6u.tis, _bd.nrm, _9m.prx, _bl.fdt, _9t.fnm, _9c.tis, _bl.fdx, _b1.nrm, _a7.fdt, _9c.frq, _b9.tii, _9c.fdx, _bi.nrm, _bf.tii, _9m.nrm, _a7.fdx, _9c.fdt, _b9.tis, _ah.tii, _6u.frq, _bi.fdt, _bl.prx, _ba.tii, _b9.nrm, _c2.tii, _bi.frq, _b0.tis, _bi.fdx, _bb.tis, _9c.nrm, _bf.tis, _c2.tis, _9c.prx, _bd.fdx, _b0.tii, _ba.tis, _9m.frq, _ah.tis, _bb.tii, _92.prx, _bd.fdt, _c2.fdt, _bc.prx, _c2.fdx, _b9.frq, _bf.nrm, _c2.prx, _ba.nrm, _bb.prx, _9m.tis, _be.fdx, _b0.prx, _ah.frq, _be.fdt, _9t.fdt, _92.fdx, _c2.nrm, _ba.prx, _a7.fnm, _9t.fdx, _92.fdt, _92.fnm, _b0.nrm, _bl.frq, _bc.tii, _9m.tii, _bf.fnm, _bd.frq, _bc.tis, _9x.prx, _9x.fdt, _9t.tii, _b1.frq, _ba.fdt, _9x.fnm, _ba.fdx, _bb.fnm, _9t.tis, segments_1r, _9x.fdx, _as.tis, _bc.nrm, _9x.tis, _as.frq, _b9.fdt, _b1.prx, _c2.fnm, _9x.tii, _as_1.del, _be.tis, _9t.frq, _9c.fnm, _be.tii, _bb.nrm, _bc.frq, _a7.nrm, _ba.fnm, _bb.fdt, _6u.fnm, _9t.nrm, _bd.tii, _a7.frq, _bb.fdx, _as.tii, _b1.fdx, _bd.tis, _9m.fdx, _be.prx, _b0.fnm, _9m.fnm, _9m.fdt, _be.fnm, _a7.tis, _a7.prx, _b1.fdt, _b9.fnm, _a7.tii, _bc.fdx, _b9.prx, _bi.fnm, _bc.fdt, _c2.frq, _ah.prx, _b0.frq, _92.nrm, _ah.fnm, _92.tis, _6u.nrm, _9t.prx, _be.nrm, _as.nrm, _6u.fdt, _b1.tis, _bi.tis, _bf.frq, _bd.fnm, _ah.fdx, _92.frq, _92.tii, _b1.tii, _bl.fnm, _as.prx, _9x.frq, _bl.tii, _6u.fdx, _ah.nrm, _bb.frq, _b0.fdt, _as.fdt, _as.fdx, _6u_4.del, _ah.fdt, _b1.fnm, _bl.tis, _bf.fdx, _6u.prx, _ba.frq, _bf.fdt, _b0.fdx, _bi.tii, _b9.fdx]</message>
</record>
<record>
  <date>2012-04-28T01:19:53</date>
  <millis>1335572393806</millis>
  <sequence>389</sequence>
  <logger>org.apache.solr.core.SolrCore</logger>
  <level>INFO</level>
  <class>org.apache.solr.core.SolrDeletionPolicy</class>
  <method>updateCommits</method>
  <thread>15</thread>
  <message>newest commit = 1335435169804</message>
</record>

Re: commit fail

Posted by Erick Erickson <er...@gmail.com>.

In the 3.6 world, LukeRequestHandler does some...er...really expensive
things when you click into the admin/schema browser. This is _much_
better in trunk BTW.

So, as Yonik says, LukeRequestHandler probably accounts for
one of the threads.

Does this occur when nobody is playing around with the admin
handler?

Erick

On Sat, Apr 28, 2012 at 10:03 AM, Yonik Seeley
<yo...@lucidimagination.com> wrote:
> On Sat, Apr 28, 2012 at 7:02 AM, mav.peri@holidaylettings.co.uk
> <ma...@holidaylettings.co.uk> wrote:
>> Hi,
>>
>> This is what the thread dump looks like.
>>
>> Any ideas?
>
> Looks like the thread taking up CPU is in LukeRequestHandler
>
>> 1062730578@qtp-1535043768-5' Id=16, RUNNABLE on lock=, total cpu
>> time=16156160.0000ms user time=16153110.0000msat
>> org.apache.solr.handler.admin.LukeRequestHandler.getIndexedFieldsInfo(LukeR
>> equestHandler.java:320)
>
> That probably accounts for the 1 CPU doing things... but it's not
> clear at all why commits are failing.
>
> Perhaps the commit is succeeding, but the client is just not waiting
> long enough for it to complete?
>
> -Yonik
> lucenerevolution.com - Lucene/Solr Open Source Search Conference.
> Boston May 7-10

Re: commit fail

Posted by Yonik Seeley <yo...@lucidimagination.com>.

On Sat, Apr 28, 2012 at 7:02 AM, mav.peri@holidaylettings.co.uk
<ma...@holidaylettings.co.uk> wrote:
> Hi,
>
> This is what the thread dump looks like.
>
> Any ideas?

Looks like the thread taking up CPU is in LukeRequestHandler

> 1062730578@qtp-1535043768-5' Id=16, RUNNABLE on lock=, total cpu
> time=16156160.0000ms user time=16153110.0000msat
> org.apache.solr.handler.admin.LukeRequestHandler.getIndexedFieldsInfo(LukeR
> equestHandler.java:320)

That probably accounts for the 1 CPU doing things... but it's not
clear at all why commits are failing.

Perhaps the commit is succeeding, but the client is just not waiting
long enough for it to complete?

-Yonik
lucenerevolution.com - Lucene/Solr Open Source Search Conference.
Boston May 7-10

Re: commit fail

Posted by "mav.peri@holidaylettings.co.uk" <ma...@holidaylettings.co.uk>.

Hi,

This is what the thread dump looks like.

Any ideas?

Mav

Java HotSpot(TM) 64-Bit Server VM20.1-b02Thread Count: current=19,
peak=20, daemon=6'DestroyJavaVM' Id=26, RUNNABLE on lock=, total cpu
time=198450.0000ms user time=196890.0000ms'Timer-2' Id=25, TIMED_WAITING
on lock=java.util.TaskQueue@33799a1e, total cpu time=0.0000ms user
time=0.0000msat java.lang.Object.wait(Native Method)
at java.util.TimerThread.mainLoop(Timer.java:509)
at java.util.TimerThread.run(Timer.java:462)
'pool-3-thread-1' Id=24, WAITING on
lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@
747541f8, total cpu time=0.0000ms user time=0.0000msat
sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at 
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await
(AbstractQueuedSynchronizer.java:1987)
at 
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399)
 
at 
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947
) 
at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:
907) 
at java.lang.Thread.run(Thread.java:662)
'pool-1-thread-1' Id=23, WAITING on
lock=java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@
3e3e3c83, total cpu time=480.0000ms user time=460.0000msat
sun.misc.Unsafe.park(Native Method)
at java.util.concurrent.locks.LockSupport.park(LockSupport.java:158)
at 
java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await
(AbstractQueuedSynchronizer.java:1987)
at 
java.util.concurrent.LinkedBlockingQueue.take(LinkedBlockingQueue.java:399)
 
at 
java.util.concurrent.ThreadPoolExecutor.getTask(ThreadPoolExecutor.java:947
) 
at 
java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:
907) 
at java.lang.Thread.run(Thread.java:662)
'Timer-1' Id=21, TIMED_WAITING on lock=java.util.TaskQueue@67f6dc61, total
cpu time=180.0000ms user time=120.0000msat java.lang.Object.wait(Native
Method) 
at java.util.TimerThread.mainLoop(Timer.java:509)
at java.util.TimerThread.run(Timer.java:462)
'2021372560@qtp-1535043768-9 - Acceptor0 SocketConnector@0.0.0.0:8983'
Id=20, RUNNABLE on lock=, total cpu time=60.0000ms user time=60.0000msat
java.net.PlainSocketImpl.socketAccept(Native Method)
at java.net.PlainSocketImpl.accept(PlainSocketImpl.java:408)
at java.net.ServerSocket.implAccept(ServerSocket.java:462)
at java.net.ServerSocket.accept(ServerSocket.java:430)
at org.mortbay.jetty.bio.SocketConnector.accept(SocketConnector.java:99)
at 
org.mortbay.jetty.AbstractConnector$Acceptor.run(AbstractConnector.java:708
) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:58
2) 
'1384828782@qtp-1535043768-8' Id=19, TIMED_WAITING on
lock=org.mortbay.thread.QueuedThreadPool$PoolThread@528acf6e, total cpu
time=274160.0000ms user time=273060.0000msat java.lang.Object.wait(Native
Method) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:62
6) 
'1715374531@qtp-1535043768-7' Id=18, RUNNABLE on lock=, total cpu
time=15725890.0000ms user time=15723380.0000msat
sun.management.ThreadImpl.getThreadInfo1(Native Method)
at sun.management.ThreadImpl.getThreadInfo(ThreadImpl.java:154)
at 
org.apache.jsp.admin.threaddump_jsp._jspService(org.apache.jsp.admin.thread
dump_jsp:264) 
at org.apache.jasper.runtime.HttpJspBase.service(HttpJspBase.java:109)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
at 
org.apache.jasper.servlet.JspServletWrapper.service(JspServletWrapper.java:
389) 
at 
org.apache.jasper.servlet.JspServlet.serviceJspFile(JspServlet.java:486)
at org.apache.jasper.servlet.JspServlet.service(JspServlet.java:380)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:820)
at org.mortbay.jetty.servlet.ServletHolder.handle(ServletHolder.java:511)
at 
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:401)
at 
org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
 
at 
org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
at 
org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:450)
at org.mortbay.jetty.servlet.Dispatcher.forward(Dispatcher.java:327)
at org.mortbay.jetty.servlet.Dispatcher.forward(Dispatcher.java:126)
at 
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java
:275) 
at 
org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandle
r.java:1212) 
at 
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:399)
at 
org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
 
at 
org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
at 
org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:450)
at 
org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCol
lection.java:230) 
at 
org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:1
14) 
at 
org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
at org.mortbay.jetty.Server.handle(Server.java:326)
at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
at 
org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnecti
on.java:928) 
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:549)
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:2
28) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:58
2) 
'1336225759@qtp-1535043768-6' Id=17, TIMED_WAITING on
lock=org.mortbay.thread.QueuedThreadPool$PoolThread@4fa52fdf, total cpu
time=16570.0000ms user time=16550.0000msat java.lang.Object.wait(Native
Method) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:62
6) 
'1062730578@qtp-1535043768-5' Id=16, RUNNABLE on lock=, total cpu
time=16156160.0000ms user time=16153110.0000msat
org.apache.solr.handler.admin.LukeRequestHandler.getIndexedFieldsInfo(LukeR
equestHandler.java:320)
at 
org.apache.solr.handler.admin.LukeRequestHandler.handleRequestBody(LukeRequ
estHandler.java:146)
at 
org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase
.java:129) 
at org.apache.solr.core.SolrCore.execute(SolrCore.java:1372)
at 
org.apache.solr.servlet.SolrDispatchFilter.execute(SolrDispatchFilter.java:
356) 
at 
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java
:252) 
at 
org.mortbay.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandle
r.java:1212) 
at 
org.mortbay.jetty.servlet.ServletHandler.handle(ServletHandler.java:399)
at 
org.mortbay.jetty.security.SecurityHandler.handle(SecurityHandler.java:216)
 
at 
org.mortbay.jetty.servlet.SessionHandler.handle(SessionHandler.java:182)
at 
org.mortbay.jetty.handler.ContextHandler.handle(ContextHandler.java:766)
at org.mortbay.jetty.webapp.WebAppContext.handle(WebAppContext.java:450)
at 
org.mortbay.jetty.handler.ContextHandlerCollection.handle(ContextHandlerCol
lection.java:230) 
at 
org.mortbay.jetty.handler.HandlerCollection.handle(HandlerCollection.java:1
14) 
at 
org.mortbay.jetty.handler.HandlerWrapper.handle(HandlerWrapper.java:152)
at org.mortbay.jetty.Server.handle(Server.java:326)
at org.mortbay.jetty.HttpConnection.handleRequest(HttpConnection.java:542)
at 
org.mortbay.jetty.HttpConnection$RequestHandler.headerComplete(HttpConnecti
on.java:928) 
at org.mortbay.jetty.HttpParser.parseNext(HttpParser.java:549)
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:2
28) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:58
2) 
'1133736492@qtp-1535043768-4' Id=15, TIMED_WAITING on
lock=org.mortbay.thread.QueuedThreadPool$PoolThread@4393722c, total cpu
time=310470.0000ms user time=309850.0000msat java.lang.Object.wait(Native
Method) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:62
6) 
'906199566@qtp-1535043768-3' Id=14, TIMED_WAITING on
lock=org.mortbay.thread.QueuedThreadPool$PoolThread@3603820e, total cpu
time=16530.0000ms user time=16490.0000msat java.lang.Object.wait(Native
Method) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:62
6) 
'1355362812@qtp-1535043768-2' Id=13, TIMED_WAITING on
lock=org.mortbay.thread.QueuedThreadPool$PoolThread@50c931fc, total cpu
time=390.0000ms user time=390.0000msat java.lang.Object.wait(Native
Method) 
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:62
6) 
'1829923591@qtp-1535043768-1' Id=12, TIMED_WAITING on
lock=org.mortbay.thread.QueuedThreadPool$PoolThread@6d126b07, total cpu
time=50.0000ms user time=50.0000msat java.lang.Object.wait(Native Method)
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:62
6) 
'2136368034@qtp-1535043768-0' Id=11, TIMED_WAITING on
lock=org.mortbay.thread.QueuedThreadPool$PoolThread@7f5663a2, total cpu
time=50.0000ms user time=40.0000msat java.lang.Object.wait(Native Method)
at 
org.mortbay.thread.QueuedThreadPool$PoolThread.run(QueuedThreadPool.java:62
6) 
'Timer-0' Id=10, TIMED_WAITING on lock=java.util.TaskQueue@7ffe9999, total
cpu time=2050.0000ms user time=1910.0000msat java.lang.Object.wait(Native
Method) 
at java.util.TimerThread.mainLoop(Timer.java:509)
at java.util.TimerThread.run(Timer.java:462)
'Signal Dispatcher' Id=4, RUNNABLE on lock=, total cpu time=0.0000ms user
time=0.0000ms'Finalizer' Id=3, WAITING on
lock=java.lang.ref.ReferenceQueue$Lock@24164d75, total cpu time=0.0000ms
user time=0.0000msat java.lang.Object.wait(Native Method)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:118)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:134)
at java.lang.ref.Finalizer$FinalizerThread.run(Finalizer.java:159)
'Reference Handler' Id=2, WAITING on
lock=java.lang.ref.Reference$Lock@34374ed5, total cpu time=0.0000ms user
time=0.0000msat java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:485)
at java.lang.ref.Reference$ReferenceHandler.run(Reference.java:116)






On 28/04/2012 02:32, "Yonik Seeley" <yo...@lucidimagination.com> wrote:

>On Fri, Apr 27, 2012 at 8:23 PM, mav.peri@holidaylettings.co.uk
><ma...@holidaylettings.co.uk> wrote:
>> Hi again,
>>
>> This is the only log entry I can find, regarding the failed commitsŠ
>>
>> Still timing out as far as the client is concerned and there is
>>actually nothing happening on the server in terms of load (staging
>>environment).
>>
>> 1 CPU core seems busy constantly with solr but unsure what is happening.
>
>You can get a thread dump to see what the various threads are doing
>(use the solr admin, or kill -3).  Sounds like it could just be either
>merging in progress or a commit in progress.
>
>-Yonik
>lucenerevolution.com - Lucene/Solr Open Source Search Conference.
>Boston May 7-10

Re: commit fail

Posted by Yonik Seeley <yo...@lucidimagination.com>.

On Fri, Apr 27, 2012 at 8:23 PM, mav.peri@holidaylettings.co.uk
<ma...@holidaylettings.co.uk> wrote:
> Hi again,
>
> This is the only log entry I can find, regarding the failed commits…
>
> Still timing out as far as the client is concerned and there is actually nothing happening on the server in terms of load (staging environment).
>
> 1 CPU core seems busy constantly with solr but unsure what is happening.

You can get a thread dump to see what the various threads are doing
(use the solr admin, or kill -3).  Sounds like it could just be either
merging in progress or a commit in progress.

-Yonik
lucenerevolution.com - Lucene/Solr Open Source Search Conference.
Boston May 7-10