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 Andy Lester <an...@petdance.com> on 2012/08/08 17:30:58 UTC

Solr makes long requests about once a minute

I'm having a problem with Solr under Tomcat unexpectedly taking a long time to respond to queries.  As part of some stress testing, I wrote a bot that just does random word searches on my Solr install, and my responses typically come back in 10-50 ms.  The queries are just 1-3 random words from /usr/share/dict/words, and I cap off the results at 2500 hits.  

The queries run just fine and I typically get responses up to 50ms for large result sets.  Here's an example of my log:

TIME     HITS   MS SEARCH WORDS
12:33:20    1    5 hoovey Aruru kwachas
12:33:20    8    5 blinis twyver
12:33:20 2500   34 prework burlily sunshine
12:33:20 1928   30 rendu Solly
12:33:20           unnethe
12:33:20           gadwell afterpeak
12:33:20  792   14 steen
12:33:20    4    7 blanchi repaving
12:33:20   32    6 torbanite Storz ungag
12:33:20    7    5 chemostat
12:33:20   15    6 Guauaenok Adao lakist
12:33:20    6    6 bechance viny
12:33:20   20    6 chagigah
12:33:22  532 2404 bonne
12:33:22  143    9 nonman Norrie
12:33:22   24    6 repealers
12:33:22           Pfosi laniard locutory
12:33:22   51    6 sexipolar wordsmith enshield
12:33:22           loggiest Aryanise koels
12:33:22           fogyish unforcing
12:33:22    4    5 Millvale chokies
12:33:22    5    6 Melfa ripal Olva
12:33:22   15    6 apio Heraea latimeria
12:33:22    4    5 nonnitric parleying

See that one line where it 2404ms to return?  I get those about once a minute, but not at a regular interval.  I ran this for two hours and got 122 spikes in 120 minutes.  I ran it overnight and came in to work to find that there were 1283 spikes in 1260 minutes.  So that one-a-minute is a pattern.

As I write this, I'm in IRC with Chris Hostetter and he says:

--snip--
Probably need to tweak your garbage collector settings to something that doesn't involve "stop the world" ... the specifics of the changes largely depend on what JVM you are using, what options you already have set, etc.  markrmiller wrote a good blog about this a little while back: http://searchhub.org/dev/2011/03/27/garbage-collection-bootcamp-1-0/  There's also some notes here in the LucidWorks Solr Ref Guide: http://lucidworks.lucidimagination.com/display/solr/JVM+Settings
--snip--

GC certainly sounds like a reasonable suspect.  Any other suggestions?  Any hints on Solr-specific GC tuning?  I'm currently scouring Google.

Thanks,
xoa

--
Andy Lester => andy@petdance.com => www.petdance.com => AIM:petdance


Re: Solr makes long requests about once a minute

Posted by Jack Krupansky <ja...@basetechnology.com>.
Check the Solr log file and see if something is happening at those slow 
queries. Maybe an auto-commit?

-- Jack Krupansky

-----Original Message----- 
From: Andy Lester
Sent: Wednesday, August 08, 2012 11:30 AM
To: solr-user@lucene.apache.org
Subject: Solr makes long requests about once a minute

I'm having a problem with Solr under Tomcat unexpectedly taking a long time 
to respond to queries.  As part of some stress testing, I wrote a bot that 
just does random word searches on my Solr install, and my responses 
typically come back in 10-50 ms.  The queries are just 1-3 random words from 
/usr/share/dict/words, and I cap off the results at 2500 hits.

The queries run just fine and I typically get responses up to 50ms for large 
result sets.  Here's an example of my log:

TIME     HITS   MS SEARCH WORDS
12:33:20    1    5 hoovey Aruru kwachas
12:33:20    8    5 blinis twyver
12:33:20 2500   34 prework burlily sunshine
12:33:20 1928   30 rendu Solly
12:33:20           unnethe
12:33:20           gadwell afterpeak
12:33:20  792   14 steen
12:33:20    4    7 blanchi repaving
12:33:20   32    6 torbanite Storz ungag
12:33:20    7    5 chemostat
12:33:20   15    6 Guauaenok Adao lakist
12:33:20    6    6 bechance viny
12:33:20   20    6 chagigah
12:33:22  532 2404 bonne
12:33:22  143    9 nonman Norrie
12:33:22   24    6 repealers
12:33:22           Pfosi laniard locutory
12:33:22   51    6 sexipolar wordsmith enshield
12:33:22           loggiest Aryanise koels
12:33:22           fogyish unforcing
12:33:22    4    5 Millvale chokies
12:33:22    5    6 Melfa ripal Olva
12:33:22   15    6 apio Heraea latimeria
12:33:22    4    5 nonnitric parleying

See that one line where it 2404ms to return?  I get those about once a 
minute, but not at a regular interval.  I ran this for two hours and got 122 
spikes in 120 minutes.  I ran it overnight and came in to work to find that 
there were 1283 spikes in 1260 minutes.  So that one-a-minute is a pattern.

As I write this, I'm in IRC with Chris Hostetter and he says:

--snip--
Probably need to tweak your garbage collector settings to something that 
doesn't involve "stop the world" ... the specifics of the changes largely 
depend on what JVM you are using, what options you already have set, etc. 
markrmiller wrote a good blog about this a little while back: 
http://searchhub.org/dev/2011/03/27/garbage-collection-bootcamp-1-0/ 
There's also some notes here in the LucidWorks Solr Ref Guide: 
http://lucidworks.lucidimagination.com/display/solr/JVM+Settings
--snip--

GC certainly sounds like a reasonable suspect.  Any other suggestions?  Any 
hints on Solr-specific GC tuning?  I'm currently scouring Google.

Thanks,
xoa

--
Andy Lester => andy@petdance.com => www.petdance.com => AIM:petdance 


Re: Solr makes long requests about once a minute

Posted by Michael Della Bitta <mi...@appinions.com>.
StandardDirectoryFactory gets us partway there, but that's actually a
class that chooses an appropriate implementation at runtime based on
the parameters of the system it's being run on.

If you go to the status page off of the admin page and do a find on
"readerDir", I'm guessing you'll see
"org.apache.lucene.store.MMapDirectory"

So you have that 16GB to yourself, that's good. Have you told Tomcat
how much heap it can have? It's usually done with a setting like
-Xmx4g, but where that goes depends on how you installed Tomcat.

Have you watched Tomcat's RSIZE in 'top'? You should see it peak out
when your query pauses and then suddenly drop a significant amount.

Michael Della Bitta

------------------------------------------------
Appinions | 18 East 41st St., Suite 1806 | New York, NY 10017
www.appinions.com
Where Influence Isn’t a Game


On Wed, Aug 8, 2012 at 12:05 PM, Andy Lester <an...@petdance.com> wrote:
>
> On Aug 8, 2012, at 10:53 AM, Michael Della Bitta wrote:
>
>> What version of Solr are you running and what Directory implementation
>> are you using? How much RAM does your system have, and how much is
>> available for use by Solr?
>
> Solr 3.6.0
>
> I don't know what "directory implementation" means.  Are you asking about <directoryFactory>?  All I have in my solrconfig.xml is
>
>     <directoryFactory name="DirectoryFactory"
>         class="${solr.directoryFactory:solr.StandardDirectoryFactory}"/>
>
> The box has 16GB in it and currently has literally nothing else running on it.  As to the "how much is available for use by Solr", is there somewhere that I'm setting that in a config file?
>
> Clearly, I'm entirely new to the whole JVM ecosystem. I'm coming from the world of Perl.
>
> Thanks,
> xoa
>
> --
> Andy Lester => andy@petdance.com => www.petdance.com => AIM:petdance
>

Re: Solr makes long requests about once a minute

Posted by Andy Lester <an...@petdance.com>.
On Aug 8, 2012, at 10:53 AM, Michael Della Bitta wrote:

> What version of Solr are you running and what Directory implementation
> are you using? How much RAM does your system have, and how much is
> available for use by Solr?

Solr 3.6.0

I don't know what "directory implementation" means.  Are you asking about <directoryFactory>?  All I have in my solrconfig.xml is

    <directoryFactory name="DirectoryFactory"
        class="${solr.directoryFactory:solr.StandardDirectoryFactory}"/>

The box has 16GB in it and currently has literally nothing else running on it.  As to the "how much is available for use by Solr", is there somewhere that I'm setting that in a config file?

Clearly, I'm entirely new to the whole JVM ecosystem. I'm coming from the world of Perl.

Thanks,
xoa

--
Andy Lester => andy@petdance.com => www.petdance.com => AIM:petdance


Re: Solr makes long requests about once a minute

Posted by Michael Della Bitta <mi...@appinions.com>.
Hi, Andy,

What version of Solr are you running and what Directory implementation
are you using? How much RAM does your system have, and how much is
available for use by Solr?

Michael Della Bitta

------------------------------------------------
Appinions | 18 East 41st St., Suite 1806 | New York, NY 10017
www.appinions.com
Where Influence Isn’t a Game


On Wed, Aug 8, 2012 at 11:30 AM, Andy Lester <an...@petdance.com> wrote:
> I'm having a problem with Solr under Tomcat unexpectedly taking a long time to respond to queries.  As part of some stress testing, I wrote a bot that just does random word searches on my Solr install, and my responses typically come back in 10-50 ms.  The queries are just 1-3 random words from /usr/share/dict/words, and I cap off the results at 2500 hits.
>
> The queries run just fine and I typically get responses up to 50ms for large result sets.  Here's an example of my log:
>
> TIME     HITS   MS SEARCH WORDS
> 12:33:20    1    5 hoovey Aruru kwachas
> 12:33:20    8    5 blinis twyver
> 12:33:20 2500   34 prework burlily sunshine
> 12:33:20 1928   30 rendu Solly
> 12:33:20           unnethe
> 12:33:20           gadwell afterpeak
> 12:33:20  792   14 steen
> 12:33:20    4    7 blanchi repaving
> 12:33:20   32    6 torbanite Storz ungag
> 12:33:20    7    5 chemostat
> 12:33:20   15    6 Guauaenok Adao lakist
> 12:33:20    6    6 bechance viny
> 12:33:20   20    6 chagigah
> 12:33:22  532 2404 bonne
> 12:33:22  143    9 nonman Norrie
> 12:33:22   24    6 repealers
> 12:33:22           Pfosi laniard locutory
> 12:33:22   51    6 sexipolar wordsmith enshield
> 12:33:22           loggiest Aryanise koels
> 12:33:22           fogyish unforcing
> 12:33:22    4    5 Millvale chokies
> 12:33:22    5    6 Melfa ripal Olva
> 12:33:22   15    6 apio Heraea latimeria
> 12:33:22    4    5 nonnitric parleying
>
> See that one line where it 2404ms to return?  I get those about once a minute, but not at a regular interval.  I ran this for two hours and got 122 spikes in 120 minutes.  I ran it overnight and came in to work to find that there were 1283 spikes in 1260 minutes.  So that one-a-minute is a pattern.
>
> As I write this, I'm in IRC with Chris Hostetter and he says:
>
> --snip--
> Probably need to tweak your garbage collector settings to something that doesn't involve "stop the world" ... the specifics of the changes largely depend on what JVM you are using, what options you already have set, etc.  markrmiller wrote a good blog about this a little while back: http://searchhub.org/dev/2011/03/27/garbage-collection-bootcamp-1-0/  There's also some notes here in the LucidWorks Solr Ref Guide: http://lucidworks.lucidimagination.com/display/solr/JVM+Settings
> --snip--
>
> GC certainly sounds like a reasonable suspect.  Any other suggestions?  Any hints on Solr-specific GC tuning?  I'm currently scouring Google.
>
> Thanks,
> xoa
>
> --
> Andy Lester => andy@petdance.com => www.petdance.com => AIM:petdance
>