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 Jeff Newburn <jn...@zappos.com> on 2009/07/22 00:52:34 UTC
Random Slowness
We are experiencing random slowness on certain queries. I have been unable
to diagnose what the issue is. We are using SOLR 1.4 and 99.99% of queries
return in under 250 ms. The remaining queries are returning in 2-5 seconds
for no apparent reason. There does not seem to be any commonality between
the queries. This problem also includes admin system queries. Any help or
direction would be much appreciated.
Specs:
Solr 1.4
Tomcat Server
4 cores
Largest core 155,000 documents.
Logs:
INFO: [zeta-main] webapp=null path=null params={command=details} status=0
QTime=1276
INFO: [zeta-main] webapp=null path=null params={command=details} status=0
QTime=1144
INFO: [zeta-main] webapp=null path=null params={command=details} status=0
QTime=1285
INFO: [zeta-main] webapp=/solr path=/select
params={facet=true&facet.mincount=1&facet.limit=-1&wt=javabin&rows=0&facet.s
ort=true&start=0&q=shoes&facet.field=colorFacet&facet.field=brandNameFacet&f
acet.field=heelHeight&facet.field=attrFacet_Style&qt=dismax&fq=productTypeFa
cet:Shoes&fq=gender:Womens&fq=categoryFacet:Sandals&fq=width:EE&fq=size:10.5
&fq=priceFacet:"$100.00+and+Under"&fq=personalityFacet:Sexy} hits=19
status=0 QTime=3689
INFO: [zeta-main] webapp=/solr path=/select
params={wt=javabin&rows=100&facet.sort=true&start=0&q=shoes&qt=dismax&fq=pro
ductTypeFacet:Shoes&fq=gender:Womens&fq=size:8&fq=width:D&fq=brandNameFacet:
Dansko} hits=8 status=0 QTime=3566
INFO: [zeta-main] webapp=/solr path=/select
params={wt=javabin&rows=100&facet.sort=true&start=0&q=shoes&qt=dismax&fq=gen
der:Womens&fq=productTypeFacet:Shoes&fq=subCategoryFacet:Heels&fq=categoryFa
cet:Shoes&fq=size:10} hits=5409 status=0 QTime=3348
INFO: [zeta-main] webapp=/solr path=/select
params={wt=javabin&rows=100&facet.sort=true&start=100&q=shoes&qt=dismax&fq=p
roductTypeFacet:Shoes&fq=gender:Womens&fq=personalityFacet:Dress&fq=category
Facet:Shoes&fq=size:10&fq=heelHeight:"Medium+(1+3/8in+-+2+1/2in)"} hits=1129
status=0 QTime=3285
INFO: [zeta-main] webapp=/solr path=/select
params={wt=javabin&rows=100&facet.sort=true&start=200&q=shoes&qt=dismax&fq=p
roductTypeFacet:Shoes&fq=gender:Womens&fq=categoryFacet:Shoes&fq=subCategory
Facet:Heels&fq=personalityFacet:Dress&fq=attrFacet_Style:Pump&fq=size:5}
hits=644 status=0 QTime=3750
INFO: [6pm-main] webapp=/solr path=/select
params={wt=javabin&rows=100&facet.sort=true&start=0&q=shoes&qt=dismax&fq=exp
andedGender:Kids&fq=productTypeFacet:Shoes&fq=gender:girls&fq=brandNameFacet
:"UGG+Kids"} hits=17 status=0 QTime=3789
--
Jeff Newburn
Software Engineer, Zappos.com
jnewburn@zappos.com - 702-943-7562
Re: Random Slowness
Posted by Otis Gospodnetic <ot...@yahoo.com>.
Or simply attach to the JVM with Jconsole and watch the GC from there. You'd have to watch things (logs and jconsole) closely though, and correlate the slow query periods with a GC spike.
Otis
--
Sematext -- http://sematext.com/ -- Lucene - Solr - Nutch
----- Original Message ----
> From: Ed Summers <eh...@pobox.com>
> To: solr-user@lucene.apache.org
> Sent: Wednesday, July 22, 2009 11:03:08 AM
> Subject: Re: Random Slowness
>
> On Wed, Jul 22, 2009 at 10:44 AM, Jeff Newburnwrote:
> > How do I go about enabling the gc logging for solr?
>
> It depends how you are running solr. You basically want to make sure
> that when the JVM is started up with the java command, that it gets
> some additional arguments [1]. So for example if you are running solr
> using jetty you would:
>
> java -verbose:gc -Xloggc:solr_gc.log -jar start.jar
>
> And then poke around in the log looking for garbage collection events
> that take as long as the pauses you are seeing in your app. I think
> there are tools that will help you analyze the log files if you need
> them. If there is a correlation you'll probably want to tune your solr
> memory usage with -xMx and -xMs.
>
> Hope this helps.
>
> //Ed
>
> [1] http://java.sun.com/javase/7/docs/technotes/tools/windows/java.html
Re: Random Slowness
Posted by Ed Summers <eh...@pobox.com>.
On Wed, Jul 22, 2009 at 10:44 AM, Jeff Newburn<jn...@zappos.com> wrote:
> How do I go about enabling the gc logging for solr?
It depends how you are running solr. You basically want to make sure
that when the JVM is started up with the java command, that it gets
some additional arguments [1]. So for example if you are running solr
using jetty you would:
java -verbose:gc -Xloggc:solr_gc.log -jar start.jar
And then poke around in the log looking for garbage collection events
that take as long as the pauses you are seeing in your app. I think
there are tools that will help you analyze the log files if you need
them. If there is a correlation you'll probably want to tune your solr
memory usage with -xMx and -xMs.
Hope this helps.
//Ed
[1] http://java.sun.com/javase/7/docs/technotes/tools/windows/java.html
Re: Random Slowness
Posted by Jeff Newburn <jn...@zappos.com>.
Ed,
How do I go about enabling the gc logging for solr?
--
Jeff Newburn
Software Engineer, Zappos.com
jnewburn@zappos.com - 702-943-7562
> From: Ed Summers <eh...@pobox.com>
> Reply-To: <so...@lucene.apache.org>
> Date: Wed, 22 Jul 2009 10:39:03 -0400
> To: <so...@lucene.apache.org>
> Subject: Re: Random Slowness
>
> I haven't read this whole thread, so maybe it's already come up. Have
> you turned on the garbage collection logging to see if the jvm is busy
> cleaning up when you are seeing the slowness? Maybe the jvm is
> struggling to keep the heap size within a particular limit?
>
> //Ed
>
> On Wed, Jul 22, 2009 at 10:22 AM, Jeff Newburn<jn...@zappos.com> wrote:
>> We can never reproduce the slowness with the same query. As soon as we try
>> to run them again they are fine. I have even tried running the same query
>> the next day and it is fine.
>>
>> All of our requests go through our dismax handler which is part of why it is
>> so weird. Most queries are fine, however just occasionally they aren't.
>> Additionally, why would the command=details command also go slow? That
>> seems like a server issue.
>>
>> It appears that for FieldValueCache and FilterCache we have no evictions,
>> but for queryResultCache and DocumentCache there are a good number of
>> evictions. How would I help lower the evictions to see if that is the
>> problem?
>>
>> Dismax Config below:
>> <requestHandler name="dismax" class="solr.DisMaxRequestHandler"
>> default="true">
>> ?
>> <lst name="defaults">
>> <str name="echoParams">explicit</str>
>> <float name="tie">0.5</float>
>> ?
>> <str name="qf">
>>
>> productId^10.0
>>
>> personality^8.0
>> subCategory^8.0
>> category^6.0
>> productType^5.0
>>
>> brandName^1.0
>> realBrandName^1.0
>> productNameSearch^1.0
>>
>> size^1.2
>> width^1.0
>> heelHeight^1.0
>>
>> productDescription^1.0
>> color^10.0
>> price^1.0
>> attrs^5.0
>>
>> expandedGender^0.5
>>
>> </str>
>> ?
>> <str name="pf">
>>
>> attrs^3 brandName^10.0 productNameSearch^8.0
>> productDescription^2.0 personality^4.0 subCategory^12.0 category^10.0
>> productType^8.0
>>
>> </str>
>> ?
>> <str name="fl">
>>
>> productId, productName, price, originalPrice,
>> brandNameFacet, productRating, imageUrl, productUrl, isNew, onSale, styleId
>>
>> </str>
>> <str name="mm">100%</str>
>> <int name="ps">1</int>
>> <int name="qs">5</int>
>> <str name="q.alt">*:*</str>
>> <!-- More like this search parameters -->
>> ?
>> <str name="mlt.fl">
>> brandNameFacet,productTypeFacet,productName,categoryFacet,subCategoryFacet,p
>> ersonalityFacet,colorFacet,heelHeight,expandedGender
>> </str>
>> <int name="mlt.mindf">1</int>
>> <int name="mlt.mintf">1</int>
>> </lst>
>> ?
>> <arr name="last-components">
>> <str>spellcheck</str>
>> </arr>
>> </requestHandler>
>>
>> --
>> Jeff Newburn
>> Software Engineer, Zappos.com
>> jnewburn@zappos.com - 702-943-7562
>>
>>
>>> From: Erik Hatcher <er...@ehatchersolutions.com>
>>> Reply-To: <so...@lucene.apache.org>
>>> Date: Wed, 22 Jul 2009 00:36:30 -0400
>>> To: <so...@lucene.apache.org>
>>> Subject: Re: Random Slowness
>>>
>>>
>>> On Jul 21, 2009, at 6:52 PM, Jeff Newburn wrote:
>>>
>>>> We are experiencing random slowness on certain queries. I have been
>>>> unable
>>>> to diagnose what the issue is. We are using SOLR 1.4 and 99.99% of
>>>> queries
>>>> return in under 250 ms. The remaining queries are returning in 2-5
>>>> seconds
>>>> for no apparent reason. There does not seem to be any commonality
>>>> between
>>>> the queries. This problem also includes admin system queries. Any
>>>> help or
>>>> direction would be much appreciated.
>>>
>>> Do you experience the same slow speeds when you manually issue those
>>> queries? In other words, is it repeatable? If so, try
>>> &debugQuery=true and see the component timings and where the time is
>>> going.
>>>
>>> What's the query parsing too? Anything unusually large due to synonym
>>> lists or something like that?
>>>
>>> What about your filter cache - how's it looking when these slow
>>> queries take place? evictions > 0?
>>>
>>>> params
>>>> ={facet=true&facet.mincount=1&facet.limit=-1&wt=javabin&rows=0&facet.s
>>>> ort
>>>> =
>>>> true
>>>> &start=0&q=shoes&facet.field=colorFacet&facet.field=brandNameFacet&f
>>>> acet
>>>> .field
>>>> =heelHeight&facet.field=attrFacet_Style&qt=dismax&fq=productTypeFa
>>>> cet:Shoes
>>>> &fq=gender:Womens&fq=categoryFacet:Sandals&fq=width:EE&fq=size:10.5
>>>> &fq=priceFacet:"$100.00+and+Under"&fq=personalityFacet:Sexy} hits=19
>>>> status=0 QTime=3689
>>>
>>> What's the config of your dismax handler look like?
>>>
>>> Erik
>>>
>>
>>
Re: Random Slowness
Posted by Ed Summers <eh...@pobox.com>.
I haven't read this whole thread, so maybe it's already come up. Have
you turned on the garbage collection logging to see if the jvm is busy
cleaning up when you are seeing the slowness? Maybe the jvm is
struggling to keep the heap size within a particular limit?
//Ed
On Wed, Jul 22, 2009 at 10:22 AM, Jeff Newburn<jn...@zappos.com> wrote:
> We can never reproduce the slowness with the same query. As soon as we try
> to run them again they are fine. I have even tried running the same query
> the next day and it is fine.
>
> All of our requests go through our dismax handler which is part of why it is
> so weird. Most queries are fine, however just occasionally they aren't.
> Additionally, why would the command=details command also go slow? That
> seems like a server issue.
>
> It appears that for FieldValueCache and FilterCache we have no evictions,
> but for queryResultCache and DocumentCache there are a good number of
> evictions. How would I help lower the evictions to see if that is the
> problem?
>
> Dismax Config below:
> <requestHandler name="dismax" class="solr.DisMaxRequestHandler"
> default="true">
> ?
> <lst name="defaults">
> <str name="echoParams">explicit</str>
> <float name="tie">0.5</float>
> ?
> <str name="qf">
>
> productId^10.0
>
> personality^8.0
> subCategory^8.0
> category^6.0
> productType^5.0
>
> brandName^1.0
> realBrandName^1.0
> productNameSearch^1.0
>
> size^1.2
> width^1.0
> heelHeight^1.0
>
> productDescription^1.0
> color^10.0
> price^1.0
> attrs^5.0
>
> expandedGender^0.5
>
> </str>
> ?
> <str name="pf">
>
> attrs^3 brandName^10.0 productNameSearch^8.0
> productDescription^2.0 personality^4.0 subCategory^12.0 category^10.0
> productType^8.0
>
> </str>
> ?
> <str name="fl">
>
> productId, productName, price, originalPrice,
> brandNameFacet, productRating, imageUrl, productUrl, isNew, onSale, styleId
>
> </str>
> <str name="mm">100%</str>
> <int name="ps">1</int>
> <int name="qs">5</int>
> <str name="q.alt">*:*</str>
> <!-- More like this search parameters -->
> ?
> <str name="mlt.fl">
> brandNameFacet,productTypeFacet,productName,categoryFacet,subCategoryFacet,p
> ersonalityFacet,colorFacet,heelHeight,expandedGender
> </str>
> <int name="mlt.mindf">1</int>
> <int name="mlt.mintf">1</int>
> </lst>
> ?
> <arr name="last-components">
> <str>spellcheck</str>
> </arr>
> </requestHandler>
>
> --
> Jeff Newburn
> Software Engineer, Zappos.com
> jnewburn@zappos.com - 702-943-7562
>
>
>> From: Erik Hatcher <er...@ehatchersolutions.com>
>> Reply-To: <so...@lucene.apache.org>
>> Date: Wed, 22 Jul 2009 00:36:30 -0400
>> To: <so...@lucene.apache.org>
>> Subject: Re: Random Slowness
>>
>>
>> On Jul 21, 2009, at 6:52 PM, Jeff Newburn wrote:
>>
>>> We are experiencing random slowness on certain queries. I have been
>>> unable
>>> to diagnose what the issue is. We are using SOLR 1.4 and 99.99% of
>>> queries
>>> return in under 250 ms. The remaining queries are returning in 2-5
>>> seconds
>>> for no apparent reason. There does not seem to be any commonality
>>> between
>>> the queries. This problem also includes admin system queries. Any
>>> help or
>>> direction would be much appreciated.
>>
>> Do you experience the same slow speeds when you manually issue those
>> queries? In other words, is it repeatable? If so, try
>> &debugQuery=true and see the component timings and where the time is
>> going.
>>
>> What's the query parsing too? Anything unusually large due to synonym
>> lists or something like that?
>>
>> What about your filter cache - how's it looking when these slow
>> queries take place? evictions > 0?
>>
>>> params
>>> ={facet=true&facet.mincount=1&facet.limit=-1&wt=javabin&rows=0&facet.s
>>> ort
>>> =
>>> true
>>> &start=0&q=shoes&facet.field=colorFacet&facet.field=brandNameFacet&f
>>> acet
>>> .field
>>> =heelHeight&facet.field=attrFacet_Style&qt=dismax&fq=productTypeFa
>>> cet:Shoes
>>> &fq=gender:Womens&fq=categoryFacet:Sandals&fq=width:EE&fq=size:10.5
>>> &fq=priceFacet:"$100.00+and+Under"&fq=personalityFacet:Sexy} hits=19
>>> status=0 QTime=3689
>>
>> What's the config of your dismax handler look like?
>>
>> Erik
>>
>
>
Re: Random Slowness
Posted by Jeff Newburn <jn...@zappos.com>.
We can never reproduce the slowness with the same query. As soon as we try
to run them again they are fine. I have even tried running the same query
the next day and it is fine.
All of our requests go through our dismax handler which is part of why it is
so weird. Most queries are fine, however just occasionally they aren't.
Additionally, why would the command=details command also go slow? That
seems like a server issue.
It appears that for FieldValueCache and FilterCache we have no evictions,
but for queryResultCache and DocumentCache there are a good number of
evictions. How would I help lower the evictions to see if that is the
problem?
Dismax Config below:
<requestHandler name="dismax" class="solr.DisMaxRequestHandler"
default="true">
?
<lst name="defaults">
<str name="echoParams">explicit</str>
<float name="tie">0.5</float>
?
<str name="qf">
productId^10.0
personality^8.0
subCategory^8.0
category^6.0
productType^5.0
brandName^1.0
realBrandName^1.0
productNameSearch^1.0
size^1.2
width^1.0
heelHeight^1.0
productDescription^1.0
color^10.0
price^1.0
attrs^5.0
expandedGender^0.5
</str>
?
<str name="pf">
attrs^3 brandName^10.0 productNameSearch^8.0
productDescription^2.0 personality^4.0 subCategory^12.0 category^10.0
productType^8.0
</str>
?
<str name="fl">
productId, productName, price, originalPrice,
brandNameFacet, productRating, imageUrl, productUrl, isNew, onSale, styleId
</str>
<str name="mm">100%</str>
<int name="ps">1</int>
<int name="qs">5</int>
<str name="q.alt">*:*</str>
<!-- More like this search parameters -->
?
<str name="mlt.fl">
brandNameFacet,productTypeFacet,productName,categoryFacet,subCategoryFacet,p
ersonalityFacet,colorFacet,heelHeight,expandedGender
</str>
<int name="mlt.mindf">1</int>
<int name="mlt.mintf">1</int>
</lst>
?
<arr name="last-components">
<str>spellcheck</str>
</arr>
</requestHandler>
--
Jeff Newburn
Software Engineer, Zappos.com
jnewburn@zappos.com - 702-943-7562
> From: Erik Hatcher <er...@ehatchersolutions.com>
> Reply-To: <so...@lucene.apache.org>
> Date: Wed, 22 Jul 2009 00:36:30 -0400
> To: <so...@lucene.apache.org>
> Subject: Re: Random Slowness
>
>
> On Jul 21, 2009, at 6:52 PM, Jeff Newburn wrote:
>
>> We are experiencing random slowness on certain queries. I have been
>> unable
>> to diagnose what the issue is. We are using SOLR 1.4 and 99.99% of
>> queries
>> return in under 250 ms. The remaining queries are returning in 2-5
>> seconds
>> for no apparent reason. There does not seem to be any commonality
>> between
>> the queries. This problem also includes admin system queries. Any
>> help or
>> direction would be much appreciated.
>
> Do you experience the same slow speeds when you manually issue those
> queries? In other words, is it repeatable? If so, try
> &debugQuery=true and see the component timings and where the time is
> going.
>
> What's the query parsing too? Anything unusually large due to synonym
> lists or something like that?
>
> What about your filter cache - how's it looking when these slow
> queries take place? evictions > 0?
>
>> params
>> ={facet=true&facet.mincount=1&facet.limit=-1&wt=javabin&rows=0&facet.s
>> ort
>> =
>> true
>> &start=0&q=shoes&facet.field=colorFacet&facet.field=brandNameFacet&f
>> acet
>> .field
>> =heelHeight&facet.field=attrFacet_Style&qt=dismax&fq=productTypeFa
>> cet:Shoes
>> &fq=gender:Womens&fq=categoryFacet:Sandals&fq=width:EE&fq=size:10.5
>> &fq=priceFacet:"$100.00+and+Under"&fq=personalityFacet:Sexy} hits=19
>> status=0 QTime=3689
>
> What's the config of your dismax handler look like?
>
> Erik
>
Re: Random Slowness
Posted by Erik Hatcher <er...@ehatchersolutions.com>.
On Jul 21, 2009, at 6:52 PM, Jeff Newburn wrote:
> We are experiencing random slowness on certain queries. I have been
> unable
> to diagnose what the issue is. We are using SOLR 1.4 and 99.99% of
> queries
> return in under 250 ms. The remaining queries are returning in 2-5
> seconds
> for no apparent reason. There does not seem to be any commonality
> between
> the queries. This problem also includes admin system queries. Any
> help or
> direction would be much appreciated.
Do you experience the same slow speeds when you manually issue those
queries? In other words, is it repeatable? If so, try
&debugQuery=true and see the component timings and where the time is
going.
What's the query parsing too? Anything unusually large due to synonym
lists or something like that?
What about your filter cache - how's it looking when these slow
queries take place? evictions > 0?
> params
> ={facet=true&facet.mincount=1&facet.limit=-1&wt=javabin&rows=0&facet.s
> ort
> =
> true
> &start=0&q=shoes&facet.field=colorFacet&facet.field=brandNameFacet&f
> acet
> .field
> =heelHeight&facet.field=attrFacet_Style&qt=dismax&fq=productTypeFa
> cet:Shoes
> &fq=gender:Womens&fq=categoryFacet:Sandals&fq=width:EE&fq=size:10.5
> &fq=priceFacet:"$100.00+and+Under"&fq=personalityFacet:Sexy} hits=19
> status=0 QTime=3689
What's the config of your dismax handler look like?
Erik