Solr Query taking 50 sec

[Manohar Sripada]

Hi,

We have Solr Cloud (version 4.7.2) setup on 64 shards spread across VMs. I
see my queries to Solr taking exactly 50 sec intermittently (as someone
said so :P). This happens once in 10 queries.
I have enabled log level to TRACE on all the solr nodes. I didn't find any
issue with the query time on any given shard (max QTime observed on a shard
is 10 ms). We ran all the tests related to network and everything looks
fine there.

Whenever the query took 50 sec, I am seeing the below log statements
for org.eclipse.jetty component. Is this some issue with Jetty?? I could
see this logs being printed every 11 seconds(*2015-07-24 07:06:00, **2015-07-24
07:06:11, ...)* for 4 times. Attached the complete logs during that
duration. Can someone please help me here??


*DEBUG - 2015-07-24 07:06:00.126; org.eclipse.jetty.http.HttpParser; filled
707/707*
*DEBUG - 2015-07-24 07:06:00.127; org.eclipse.jetty.server.Server; REQUEST
/solr/admin/info/logging on
***@7a5f39b0,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=209,c=0},r=43*
*DEBUG - 2015-07-24 07:06:00.127;
org.eclipse.jetty.server.handler.ContextHandler; scope
null||/solr/admin/info/logging @
o.e.j.w.WebAppContext{/solr,file:/u01/work/app/install_solr/daas_node/solr-webapp/webapp/},/u01/work/app/install_solr/daas_node/webapps/solr.war*
*DEBUG - 2015-07-24 07:06:00.127;
org.eclipse.jetty.server.handler.ContextHandler;
context=/solr||/admin/info/logging @
o.e.j.w.WebAppContext{/solr,file:/u01/work/app/install_solr/daas_node/solr-webapp/webapp/},/u01/work/app/install_solr/daas_node/webapps/solr.war*
*DEBUG - 2015-07-24 07:06:00.127;
org.eclipse.jetty.server.session.SessionHandler; Got Session ID
vZScVxfQ528bXYGHJw16N3vTLJ4t3L41bSkHNmyTywQKGGzZFC8p!-348395136!NONE from
cookie*
*DEBUG - 2015-07-24 07:06:00.127;
org.eclipse.jetty.server.session.SessionHandler;
sessionManager=***@1c49094*
*DEBUG - 2015-07-24 07:06:00.127;
org.eclipse.jetty.server.session.SessionHandler; session=null*
*DEBUG - 2015-07-24 07:06:00.128; org.eclipse.jetty.servlet.ServletHandler;
servlet /solr|/admin/info/logging|null -> default*
*DEBUG - 2015-07-24 07:06:00.128; org.eclipse.jetty.servlet.ServletHandler;
chain=SolrRequestFilter->default*
*DEBUG - 2015-07-24 07:06:00.128;
org.eclipse.jetty.servlet.ServletHandler$CachedChain; call filter
SolrRequestFilter*
*INFO - 2015-07-24 07:06:00.128;
org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null
path=/admin/info/logging
params={_=1437736005493&since=1437734905469&wt=json} status=0 QTime=0 *
*DEBUG - 2015-07-24 07:06:00.128;
org.apache.solr.servlet.SolrDispatchFilter; Closing out SolrRequest:
{_=1437736005493&since=1437734905469&wt=json}*
*DEBUG - 2015-07-24 07:06:00.129; org.eclipse.jetty.server.Server; RESPONSE
/solr/admin/info/logging 200 handled=true*
*DEBUG - 2015-07-24 07:06:06.327;
org.apache.zookeeper.ClientCnxn$SendThread; Got ping response for
sessionid: 0x14eaf8f79530460 after 0ms*
*DEBUG - 2015-07-24 07:06:11.118; org.eclipse.jetty.http.HttpParser; filled
707/707*
*DEBUG - 2015-07-24 07:06:11.119; org.eclipse.jetty.server.Server; REQUEST
/solr/admin/info/logging on
***@7a5f39b0,g=HttpGenerator{s=0,h=-1,b=-1,c=-1},p=HttpParser{s=-5,l=209,c=0},r=44*
*DEBUG - 2015-07-24 07:06:11.119;
org.eclipse.jetty.server.handler.ContextHandler; scope
null||/solr/admin/info/logging @
o.e.j.w.WebAppContext{/solr,file:/u01/work/app/install_solr/daas_node/solr-webapp/webapp/},/u01/work/app/install_solr/daas_node/webapps/solr.war*
*DEBUG - 2015-07-24 07:06:11.119;
org.eclipse.jetty.server.handler.ContextHandler;
context=/solr||/admin/info/logging @
o.e.j.w.WebAppContext{/solr,file:/u01/work/app/install_solr/daas_node/solr-webapp/webapp/},/u01/work/app/install_solr/daas_node/webapps/solr.war*
*DEBUG - 2015-07-24 07:06:11.119;
org.eclipse.jetty.server.session.SessionHandler; Got Session ID
vZScVxfQ528bXYGHJw16N3vTLJ4t3L41bSkHNmyTywQKGGzZFC8p!-348395136!NONE from
cookie*
*DEBUG - 2015-07-24 07:06:11.119;
org.eclipse.jetty.server.session.SessionHandler;
sessionManager=***@1c49094*
*DEBUG - 2015-07-24 07:06:11.119;
org.eclipse.jetty.server.session.SessionHandler; session=null*
*DEBUG - 2015-07-24 07:06:11.120; org.eclipse.jetty.servlet.ServletHandler;
servlet /solr|/admin/info/logging|null -> default*
*DEBUG - 2015-07-24 07:06:11.120; org.eclipse.jetty.servlet.ServletHandler;
chain=SolrRequestFilter->default*
*DEBUG - 2015-07-24 07:06:11.120;
org.eclipse.jetty.servlet.ServletHandler$CachedChain; call filter
SolrRequestFilter*
*INFO - 2015-07-24 07:06:11.120;
org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null
path=/admin/info/logging
params={_=1437736016484&since=1437734905469&wt=json} status=0 QTime=0 *
*DEBUG - 2015-07-24 07:06:11.120;
org.apache.solr.servlet.SolrDispatchFilter; Closing out SolrRequest:
{_=1437736016484&since=1437734905469&wt=json}*
*DEBUG - 2015-07-24 07:06:11.121; org.eclipse.jetty.server.Server; RESPONSE
/solr/admin/info/logging 200 handled=true*


Thanks,
Manohar

[Shawn Heisey]

Post by Manohar Sripada
We have Solr Cloud (version 4.7.2) setup on 64 shards spread across VMs.
I see my queries to Solr taking exactly 50 sec intermittently (as
someone said so :P). This happens once in 10 queries.
I have enabled log level to TRACE on all the solr nodes. I didn't find
any issue with the query time on any given shard (max QTime observed on
a shard is 10 ms). We ran all the tests related to network and
everything looks fine there.
Whenever the query took 50 sec, I am seeing the below log statements
for org.eclipse.jetty component. Is this some issue with Jetty?? I could
see this logs being printed every 11 seconds(/2015-07-24
07:06:00, //2015-07-24 07:06:11, ...)/ for 4 times. Attached the
complete logs during that duration. Can someone please help me here??

<snip>

Post by Manohar Sripada
/INFO - 2015-07-24 07:06:00.128;
org.apache.solr.servlet.SolrDispatchFilter; [admin] webapp=null
path=/admin/info/logging
params={_=1437736005493&since=1437734905469&wt=json} status=0 QTime=0

Those logs appear to be caused by someone watching the Logging tab in
the admin UI. This admin UI page refreshes every ten seconds. No queries
are happening during the log you included, only the requests for logging
info. These requests are normally very fast, and in your log, they show
a qtime of zero milliseconds.

64 shards is quite a bit, and as soon as someone talks about a very
large install on virtual machines that is having performance problems, I
suspect that they probably do not have enough resources (memory in
particular) for what they are asking the system to do.

Now it's time for some light reading:

http://wiki.apache.org/solr/SolrPerformanceProblems

Next there are questions. These first bunch of questions are about the
virtual machines themselves, not the host hardware for the virtual machines.

Are you using the jetty (start.jar) included with Solr, or have you
installed Solr into a different jetty?

On the dashboard of the admin UI, in the JVM section, there is an "Args"
parameter, which may have multiple lines. What all is there?

If you add up all the shard replicas on a single virtual machine, how
many docs are there and how much disk space is used by the index data?
Include all replicas in those numbers, even if they duplicate data
that's on another virtual machine.

How much memory does the virtual machine have, and how much of that
memory is allocated to the java heap?

Are all of the virtual machines similar as far as memory config and how
much Solr data they contain?

If you are using a virtual machine platform that you host yourself, then
I need to know how many of these virtual machines are loaded onto each
physical machine, and how much memory that physical machine has. If
you're using AWS, then this question is irrelevant. The allocation of
CPU resources might be important, but it's not as important as memory.

Thanks,
Shawn