You may want to start solr with following settings to enable logging GC
details. Here are some flags you might want to enable.
-Xloggc:<path_to_log_dir>/gc.log
-XX:+PrintGCDetails
-XX:+PrintGCDateStamps
-XX:+PrintGCTimeStamps
-XX:+PrintTenuringDistribution
-XX:+PrintGCApplicationStoppedTime
-XX:+PrintHeapAtGC
Once you have GC logs, look for string "Total time for which application
threads were stopped" to check if you have long pauses (you may get long
pauses even with young generation GC).
-- Pushkar Raste
On Wed, Oct 14, 2015 at 11:47 AM, Lorenzo Fundaró <
lorenzo.fund...@dawandamail.com> wrote:
> <<What do you see if you attach
> &debug=true to the query?>>
>
> "debug": { "rawquerystring": "*:*", "querystring": "*:*", "parsedquery":
> "(+MatchAllDocsQuery(*:*))/no_coord", "parsedquery_toString": "+*:*", "
> explain": { "Product:47047358": "\n1.0 = (MATCH) MatchAllDocsQuery, product
> of:\n 1.0 = queryNorm\n", "Product:32211113": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:30852121":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:35018929": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:31682082": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:31077677": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:22298365":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:41094514": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:13106166": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:19142249": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:38243373":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:20434065": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:25194801": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:885482": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:45356790":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:67719831": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:12843394": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:38126213": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:38798130":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:30292169": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:11535854": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:8443674": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:51012182":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:75780871": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:20227881": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:38093629": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:3142218":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:15295602": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:3375982": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:38276777": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:10726118":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:50827742": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n", "Product:5771722": "\n1.0 = (MATCH) MatchAllDocsQuery,
> product of:\n 1.0 = queryNorm\n", "Product:3245678": "\n1.0 = (MATCH)
> MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "Product:13702130":
> "\n1.0
> = (MATCH) MatchAllDocsQuery, product of:\n 1.0 = queryNorm\n", "
> Product:25679953": "\n1.0 = (MATCH) MatchAllDocsQuery, product of:\n 1.0 =
> queryNorm\n" }, "QParser": "ExtendedDismaxQParser", "altquerystring": null,
> "boost_queries": null, "parsed_boost_queries": [], "boostfuncs": null, "
> filter_queries": [ "{!cost=1 cache=true}type_s:Product AND
> is_valid_b:true",
> "{!cost=50 cache=true}in_languages_t:de", "{!cost=99
> cache=false}(shipping_country_codes_mt: (DE OR EURO OR EUR OR ALL)) AND
> (cents_ri: [* TO 3000])" ], "parsed_filter_queries": [ "+type_s:Product
> +is_valid_b:true", "in_languages_t:de", "{!cache=false
> cost=99}+(shipping_country_codes_mt:de shipping_country_codes_mt:euro
> shipping_country_codes_mt:eur shipping_country_codes_mt:all) +cents_ri:[*
> TO 3000]" ], "timing": { "time": 18, "prepare": { "time": 0, "query": { "
> time": 0 }, "facet": { "time": 0 }, "mlt": { "time": 0 }, "highlight": { "
> time": 0 }, "stats": { "time": 0 }, "expand": { "time": 0 }, "spellcheck":
> {
> "time": 0 }, "debug": { "time": 0 } }, "process": { "time": 18, "query": {
> "
> time": 0 }, "facet": { "time": 0 }, "mlt": { "time": 0 }, "highlight": { "
> time": 0 }, "stats": { "time": 0 }, "expand": { "time": 0 }, "spellcheck":
> {
> "time": 0 }, "debug": { "time": 18 } }
>
> I think this clause is wrong:
> (cents_ri: [* 3000])
>
> I think you mean
> (cents_ri: [* TO 3000])
>
> I think I made no difference. I tried both and they both worked.
>
> But are these slow queries constant or intermittent?
>
> They are definetly cached. The second time runs in no time.
>
> I gonna try adding them in the pre warmcache too. And see the results.
>
> The field that I used for sorting is indexed but not stored and it's not a
> DocValue. I tried the query without the sort and the performance didnt
> change significantly.
>
> By the time I saw that log, the server was getting around 7k updates per
> minute. The query information I don't have it now, but I think it will
> qualify as heavy load query.
>
> Thank you !
>
>
> On 14 October 2015 at 17:14, Erick Erickson <erickerick...@gmail.com>
> wrote:
>
> > A couple of things don't particularly make sense here:
> >
> > You specify edismax, q=*:* yet you specify qf=
> > You're searching across whatever you defined as the default
> > field in the request handler. What do you see if you attach
> > &debug=true to the query?
> >
> > I think this clause is wrong:
> > (cents_ri: [* 3000])
> >
> > I think you mean
> > (cents_ri: [* TO 3000])
> >
> > I'm not sure either of those is the problem, but are places I'd start.
> >
> > As far as the size of your filter cache goes, a hit ratio of .87 actually
> > isn't bad. Upping the size would add some marginal benefit, but it's
> > unlikely to be a magic bullet.
> >
> > But are these slow queries constant or intermittent? In other words,
> > are all queries of this general form slow or just the first few? In
> > particular
> > is the first query that mentions sorting on this field slow but
> subsequent
> > ones faster? In that case consider adding a query to the newSearcher
> > event in solrconfig.xml that mentions this sort, that would pre-warm
> > the sort values. Also, defining all fields that you sort on as
> > docValues="true"
> > is recommended at this point.
> >
> > What I'd try is removing clauses to see which one is the problem. On
> > the surface this is surprisingly slow. And how heavily loaded is the
> > server?
> > Your autocommit settings look fine, my question is more how much indexing
> > and querying is going on when you take these measurements.
> >
> > Best,
> > Erick
> >
> > On Wed, Oct 14, 2015 at 3:03 AM, Lorenzo Fundaró
> > <lorenzo.fund...@dawandamail.com> wrote:
> > > Hello,
> > >
> > > I have following conf for filters and commits :
> > >
> > > Concurrent LFU Cache(maxSize=64, initialSize=64, minSize=57,
> > > acceptableSize=60, cleanupThread=false, timeDecay=true,
> autowarmCount=8,
> > > regenerator=org.apache.solr.search.SolrIndexSearcher$2@169ee0fd)
> > >
> > > <autoCommit>
> > > <!-- Every 15 seconds -->
> > > <maxTime>${solr.autoCommit.maxTime:15000}</maxTime>
> > > <openSearcher>false</openSearcher>
> > > </autoCommit>
> > >
> > > <autoSoftCommit>
> > > <!-- Every 10 minutes -->
> > > <maxTime>${solr.autoSoftCommit.maxTime:600000}</maxTime>
> > > </autoSoftCommit>
> > >
> > > and the following stats for filters:
> > >
> > > lookups = 3602
> > > hits = 3148
> > > hit ratio = 0.87
> > > inserts = 455
> > > evictions = 400
> > > size = 63
> > > warmupTime = 770
> > >
> > > *Problem: *a lot of slow queries, for example:
> > >
> > > {q=*:*&tie=1.0&defType=edismax&qt=standard&json.nl
> > =map&qf=&fl=pk_i,score&start=0&sort=view_counter_i
> > > desc&fq={!cost=1 cache=true}type_s:Product AND
> > is_valid_b:true&fq={!cost=50
> > > cache=true}in_languages_t:de&fq={!cost=99
> > > cache=false}(shipping_country_codes_mt: (DE OR EURO OR EUR OR ALL)) AND
> > > (cents_ri: [* 3000])&rows=36&wt=json} hits=3768003 status=0 QTime=1378
> > >
> > > I could increase the size of the filter so I would decrease the amount
> of
> > > evictions, but it seems to me this would not be solving the root
> problem.
> > >
> > > Some ideas on where/how to start for optimisation ? Is it actually
> normal
> > > that this query takes this time ?
> > >
> > > We have an index of ~14 million docs. 4 replicas with two cores and 1
> > shard
> > > each.
> > >
> > > thank you.
> > >
> > >
> > > --
> > >
> > > --
> > > Lorenzo Fundaro
> > > Backend Engineer
> > > E-Mail: lorenzo.fund...@dawandamail.com
> > >
> > > Fax + 49 - (0)30 - 25 76 08 52
> > > Tel + 49 - (0)179 - 51 10 982
> > >
> > > DaWanda GmbH
> > > Windscheidstraße 18
> > > 10627 Berlin
> > >
> > > Geschäftsführer: Claudia Helming, Michael Pütz
> > > Amtsgericht Charlottenburg HRB 104695 B
> >
>
>
>
> --
>
> --
> Lorenzo Fundaro
> Backend Engineer
> E-Mail: lorenzo.fund...@dawandamail.com
>
> Fax + 49 - (0)30 - 25 76 08 52
> Tel + 49 - (0)179 - 51 10 982
>
> DaWanda GmbH
> Windscheidstraße 18
> 10627 Berlin
>
> Geschäftsführer: Claudia Helming, Michael Pütz
> Amtsgericht Charlottenburg HRB 104695 B
>
