Re: newSearcher autowarming queries in solrconfig.xml run but does not appear to warm cache
Erick,
Thanks very much for your help so far with this one. I have captured the logs
from a commit which shows a commit and new searcher starting.
It appears a few ERROR's are amongst the logs and a few uninverting lines.
The query is a very basic query as shown below:
DataType_s:Product
WebSections_ms:house
VisibleOnline_ms:NAT
SS_Stage_ms:Live
0
20
INFO (qtp755840090-55) [ x:core1] o.a.s.c.SolrCore
SolrDeletionPolicy.onCommit: commits: num=2
commit{dir=NRTCachingDirectory(MMapDirectory@/var/solr/data/core1/data/index.20131212092900012
lockFactory=org.apache.lucene.store.NativeFSLockFactory@8815140;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_9kgw,generation=446432}
commit{dir=NRTCachingDirectory(MMapDirectory@/var/solr/data/core1/data/index.20131212092900012
lockFactory=org.apache.lucene.store.NativeFSLockFactory@8815140;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_9kgx,generation=446433}
INFO (qtp755840090-55) [ x:core1] o.a.s.c.SolrCore newest commit generation
= 446433
INFO (qtp755840090-55) [ x:core1] o.a.s.s.SolrIndexSearcher Opening
Searcher@63f1fac[core1] main
INFO (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
o.a.s.c.SolrCore QuerySenderListener sending requests to
Searcher@63f1fac[core1]
main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a3p4(5.3.1):C313761/58754:delGen=2073)
Uninverting(_a7bs(5.3.1):c22601/9516:delGen=608)
Uninverting(_a7np(5.3.1):C37794/14987:delGen=463)
Uninverting(_aa7h(5.3.1):c13906/163:delGen=57)
Uninverting(_a7u7(5.3.1):c5968/504:delGen=89)
Uninverting(_a7yt(5.3.1):c2643/426:delGen=39)
Uninverting(_aafw(5.3.1):c313/27:delGen=2)
Uninverting(_aajf(5.3.1):c355/14:delGen=3)
Uninverting(_aaqa(5.3.1):c195/1:delGen=1)
Uninverting(_aapg(5.3.1):c279/3:delGen=3)
Uninverting(_aahr(5.3.1):c262/5:delGen=1)
Uninverting(_aafa(5.3.1):c265/2:delGen=1)
Uninverting(_aap3(5.3.1):c252/2:delGen=2) Uninverting(_aaqb(5.3.1):C1)
Uninverting(_aaqd(5.3.1):C1) Uninverting(_aaqh(5.3.1):C1)
Uninverting(_aaqj(5.3.1):C1) Uninverting(_aaqm(5.3.1):C2/1:delGen=1)
Uninverting(_aaqo(5.3.1):C1) Uninverting(_aaqq(5.3.1):C1)
Uninverting(_aaqs(5.3.1):C1)))}
ERROR (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
o.a.s.c.SolrCore Previous SolrRequestInfo was not closed! req=wt=json
ERROR (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
o.a.s.c.SolrCore prev == info : false
INFO (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
o.a.s.c.S.Request [core1] webapp=null path=null
params={start=0&event=newSearcher&q=SS_Stage_ms:Live&distrib=false&fq=DataType_s:Product&fq=WebSections_ms:house&fq=VisibleOnline_ms:NAT&rows=20}
hits=2541 status=0 QTime=18
INFO (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
o.a.s.c.SolrCore QuerySenderListener done.
INFO (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
o.a.s.c.SolrCore [core1] Registered new searcher Searcher@63f1fac[core1]
main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a3p4(5.3.1):C313761/58754:delGen=2073)
Uninverting(_a7bs(5.3.1):c22601/9516:delGen=608)
Uninverting(_a7np(5.3.1):C37794/14987:delGen=463)
Uninverting(_aa7h(5.3.1):c13906/163:delGen=57)
Uninverting(_a7u7(5.3.1):c5968/504:delGen=89)
Uninverting(_a7yt(5.3.1):c2643/426:delGen=39)
Uninverting(_aafw(5.3.1):c313/27:delGen=2)
Uninverting(_aajf(5.3.1):c355/14:delGen=3)
Uninverting(_aaqa(5.3.1):c195/1:delGen=1)
Uninverting(_aapg(5.3.1):c279/3:delGen=3)
Uninverting(_aahr(5.3.1):c262/5:delGen=1)
Uninverting(_aafa(5.3.1):c265/2:delGen=1)
Uninverting(_aap3(5.3.1):c252/2:delGen=2) Uninverting(_aaqb(5.3.1):C1)
Uninverting(_aaqd(5.3.1):C1) Uninverting(_aaqh(5.3.1):C1)
Uninverting(_aaqj(5.3.1):C1) Uninverting(_aaqm(5.3.1):C2/1:delGen=1)
Uninverting(_aaqo(5.3.1):C1) Uninverting(_aaqq(5.3.1):C1)
Uninverting(_aaqs(5.3.1):C1)))}
INFO (qtp755840090-55) [ x:core1] o.a.s.u.UpdateHandler end_commit_flush
On Tuesday, 18 October 2016, 0:49, Erick Erickson
wrote:
Wow, wouldn't it be useful if the name of the field was dumped in the
message ;)...
You should see a query happen just before that message in the log
file. It won't quite be in the same format as a URL, but it's
reasonably easy to figure out.
Uninverting happens as a result of
> sorting
> faceting
> grouping
> ???
So the crude approach wold be to find the query(s) that precede this
then break it apart submitting one of the above operations from the
query in question at a time while tailing the logs.
And by "after the warming queries", I'm assuming that the searcher has
successfully opened (there'll be a message in the log).
BTW, DocValues fields are strongly recommended for any field that gets
uninverted.
Best,
Erick
On Sun, Oct 16, 2016 at 10:28 PM, Dalton Gooding
w
Re: newSearcher autowarming queries in solrconfig.xml run but does not appear to warm cache
Erick,
I think you might have nailed it.
After the three warming queries, I get the below when registering a new
searcher. How can I find out what I am missing in my warming queries?
Registered new searcher Searcher@15cdc368[core1]
main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_a3p4(5.3.1):C313761/57815:delGen=1722)
Uninverting(_a7bs(5.3.1):c22601/8393:delGen=464)
Uninverting(_a7np(5.3.1):C37794/13471:delGen=244)
Uninverting(_a7rp(5.3.1):c2490/760:delGen=77)
Uninverting(_a7u7(5.3.1):c5968/338:delGen=27)
Uninverting(_a7rz(5.3.1):c4306/1718:delGen=94)
Uninverting(_a806(5.3.1):c1734/7:delGen=6)
Uninverting(_a7tx(5.3.1):c1900/67:delGen=10)
Uninverting(_a7tn(5.3.1):c1900/24:delGen=9)
Uninverting(_a7yt(5.3.1):c2643/144:delGen=8)
Uninverting(_a7zn(5.3.1):c1595/2:delGen=2) Uninverting(_a82v(5.3.1):c31)
Uninverting(_a843(5.3.1):c23/3:delGen=1)
Uninverting(_a844(5.3.1):C3/1:delGen=1) Uninverting(_a846(5.3.1):C1)
Uninverting(_a848(5.3.1):C5/1:delGen=1) Uninverting(_a84a(5.3.1):C1)
Uninverting(_a84c(5.3.1):C1)))}
On Friday, 14 October 2016, 9:50, Erick Erickson
wrote:
Well, that's a puzzle, sorry I don't have a good answer.
The fact that your newSearcher event to be fired _should_ populate
the low-level caches. BTW, what's your autowarm count on filterCache and
queryResultCache? Have you tried setting them to non-zero values? Those
won't help when you first start Solr, but that should be rare.
Do note that your newSearcher events should mention a series of different values
from the fields in question.
Actually here's what I'd do. Look carefully in your Solr log after you
do a commit and
particularly when you fire your first query after the new searcher is
opened. Do you see
any suspicious messages like "Uninverting field" or the like? That
would indicate sorting
or faceting on a field that wasn't warmed by the newSearcher because
you didn't mention
sorting or faceting or whatever in your warming query.
Can we see the newSearcher entry and the query you say is "similar"
but slow. My _guess_
is that some innocent-seeming difference between the two is the issue.
Best,
Erick
On Sun, Oct 9, 2016 at 7:08 PM, Dalton Gooding
wrote:
> Erick,
>
> I have tried tuning the queries with some limited success. I still get
> drastic differences between the first time I fire my warming query (after
> newSearcher ran query) and the second time, or any variant of the query i.e.
> removing fields or changing parameters, it runs much faster.
>
> I am not sure what I am missing here, I put a query into the newSearcher
> section that runs fine, but the exact same query run after warming still
> takes the full time of a un-warmed query.
>
> Can you break it down to the most basic type of newSearcher query to try and
> shrink the gap between first query and subsequent queries sent?
>
> I cannot see why sending the same query after a newSearcher is slow, when
> subsequent queries run faster. I figured this was the idea of the
> newSearcher stanza's.
>
>
> On Friday, 7 October 2016, 14:45, Erick Erickson
> wrote:
>
>
> Replying on the public thread, somehow your mail was sent to me privately.
>
> Pasted your email to me below for others.
>
> You are still confusing documents and results. Forget about the rows
> parameter, for this discussion it's irrelevant.
>
> The QTime is the time spent searching. It is unaffected by whether a
> document is in the documentCache or not.
> It _solely_ measures the time that Solr/Lucene take to find the top N
> documents (where N is the rows param) and
> record their internal Lucene doc ID.
>
> Increasing the rows or the document cache won't change anything about
> the QTime. The documentCache is
> totally the wrong place to focus.
>
>
> The response when you re-submit the query suggests that getting the
> top N docs' internal Lucene ID is
> fetched from the queryResultCache. Changing the window size is also
> irrelevant to this discussion. If you
> vary the query even slightly you won't hit the queryResultCache. A
> very easy way to check this is the
> admin UI>>select core>>plugins/stats>>QueryHandler and then probably
> the "select" handler. If you see
> the hits go up after the fast query then you're getting the results
> from the querResultCache.
>
> What _is_ relevant is populating the low-level Lucene caches with
> values from the indexed terms. My
> contention is that this is not happening with match-all queries, i.e.
> field:* or field:[* TO *] because in
> those cases, a doc matches or doesn't based on whether it has anything
> in the field. There's no point
> in finding values since it doesn't matter anyway. And "finding values&quo
Re: newSearcher autowarming queries in solrconfig.xml run but does not appear to warm cache
Erick, I have tried tuning the queries with some limited success. I still get drastic differences between the first time I fire my warming query (after newSearcher ran query) and the second time, or any variant of the query i.e. removing fields or changing parameters, it runs much faster. I am not sure what I am missing here, I put a query into the newSearcher section that runs fine, but the exact same query run after warming still takes the full time of a un-warmed query. Can you break it down to the most basic type of newSearcher query to try and shrink the gap between first query and subsequent queries sent? I cannot see why sending the same query after a newSearcher is slow, when subsequent queries run faster. I figured this was the idea of the newSearcher stanza's. On Friday, 7 October 2016, 14:45, Erick Erickson wrote: Replying on the public thread, somehow your mail was sent to me privately. Pasted your email to me below for others. You are still confusing documents and results. Forget about the rows parameter, for this discussion it's irrelevant. The QTime is the time spent searching. It is unaffected by whether a document is in the documentCache or not. It _solely_ measures the time that Solr/Lucene take to find the top N documents (where N is the rows param) and record their internal Lucene doc ID. Increasing the rows or the document cache won't change anything about the QTime. The documentCache is totally the wrong place to focus. The response when you re-submit the query suggests that getting the top N docs' internal Lucene ID is fetched from the queryResultCache. Changing the window size is also irrelevant to this discussion. If you vary the query even slightly you won't hit the queryResultCache. A very easy way to check this is the admin UI>>select core>>plugins/stats>>QueryHandler and then probably the "select" handler. If you see the hits go up after the fast query then you're getting the results from the querResultCache. What _is_ relevant is populating the low-level Lucene caches with values from the indexed terms. My contention is that this is not happening with match-all queries, i.e. field:* or field:[* TO *] because in those cases, a doc matches or doesn't based on whether it has anything in the field. There's no point in finding values since it doesn't matter anyway. And "finding values" means reading indexed terms from disk into low-level Lucene caches. When I say "populate the low-level Lucene caches", what I'm really talking about is reading them from disk into your physical memory via MMapDirectory, see Uwe's excellent blog: http://blog.thetaphi.de/2012/07/use-lucenes-mmapdirectory-on-64bit.html So the suggestion is that you use real values from your index or possibly ranges is so that part or all of your disk files get read into MMapDirectorySpace via the first or new Searcher event. Please just give it a try. My bet is that you'll see your QTime values first time after autowarming go down. Significantly. Be sure to use a wide variety of different values for autowarming. BTW, the autowarmCounts in solrconfig.xml filterCache and queryResultCache are intended to warm by using the last N fq or q clauses on the theory that the most recent N are predictive of the next N. Best, Erick *** I believe the return time back to the command line from the curl command and the QTime as shown below time curl -v 'http:///solr/core1/select?fq=DataType_s%3AProduct&fq=WebSections_ms%3Ahouse&fq=%28VisibleOnline_ms%3ANAT+OR+VisibleOnline_ms%3A7%29&fq=%7B%21tag%3Dcurrent_group%7DGroupIds_ms%3A458&sort=SalesRank_f+desc&facet=true&facet.field=%7B%21ex%3Dcurrent_group%7Dattr_GroupLevel0&facet.field=BrandID_s&facet.field=%7B%21ex%3Dcurrent_group%7Dattr_GroupLevel2&facet.field=%7B%21ex%3Dcurrent_group%7Dattr_GroupLevel1&facet.field=SubBrandID_s&facet.field=ProductAttr_967_ms&facet.field=ProductAttr_NEG21_ms&facet.field=ProductAttr_1852_ms&facet.query=Price_7_f%3A%5B%2A+TO+%2A%5D&facet.query=Price_2_f%3A%5B%2A+TO+%2A%5D&facet.query=Price_3_f%3A%5B%2A+TO+%2A%5D&facet.query=Price_4_f%3A%5B%2A+TO+%2A%5D&facet.query=Price_5_f%3A%5B%2A+TO+%2A%5D&facet.query=Price_6_f%3A%5B%2A+TO+%2A%5D&facet.mincount=1&wt=json&json.nl=map&q=%28title%3A%2A+OR+text%3A%2A%29+AND+%28ms%3ALive%29&start=0&rows=24' real 0m1.436s user 0m0.001s sys 0m0.006s "QTime":1387 >From what you suggested, changing the rows value from 20 to something greater should add more documents to the cache. Injunction with tuning the queries to remove the * wild card, this should provide a better warming query? Should I also increase the queryResultWindowSize in the solrconfig.xml to help built out the cache? Cheers, Guy On Thu, Oct 6, 2016 at 4:43 PM, Dalt
Re: newSearcher autowarming queries in solrconfig.xml run but does not appear to warm cache
Erick,
Thanks for the response. After I run the initial query and get a long response
time, if I change the query to remove or add additional query statements, I
find the speed is good.
If I run the modified query after a new searcher has registered, the response
is slow but after the modified query has been completed, the warming query sent
from CuRl is much faster. I assume it is because the document cache has updated
with the documents from the modified query. A large number of our queries work
with the same document set, I am trying to get a warming query to populate the
document cache to be as big as feasible.
Should the firstSearcher and newSearcher warm the document cache?
On Friday, 7 October 2016, 9:31, Erick Erickson
wrote:
Submitting the exact same query twice will return results from the
queryResultCache. I'm not entirely
sure that the firstSearcher events get put into the cache.
So if you change the query even slighty my guess is that you'll see
response times very close to your
original ones of over a second.
Best,
Erick
On Thu, Oct 6, 2016 at 2:56 PM, Dalton Gooding
wrote:
> After setting a number of newSearcher and firstSearcher queries, I can see in
> the console logs that the queries are run, but when I run the same query
> against the new searcher (using CuRL), I get a slow response time for the
> first run.
>
> Config:
> name="queries"> DataType_s:Product
> WebSections_ms:house name="fq">{!tag=current_group}GroupIds_ms:*
> true name="facet.field">BrandID_s name="facet.query">Price_2_f:[* TO *] name="facet.query">Price_3_f:[* TO *] name="facet.query">Price_4_f:[* TO *] name="facet.query">Price_5_f:[* TO *] name="facet.query">Price_6_f:[* TO *] name="facet.query">Price_7_f:[* TO *] name="facet.query">Price_8_f:[* TO *] name="facet.mincount">1 fc
> json name="json.nl">map (title:* OR text:*)
> 0 20
>
>
> Console log:
> INFO (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
> o.a.s.c.S.Request [core1] webapp=null path=null
> params={facet=true&facet.mincount=1&start=0&facet.query=Price_2_f:[*+TO+*]&facet.query=Price_3_f:[*+TO+*]&facet.query=Price_4_f:[*+TO+*]&facet.query=Price_5_f:[*+TO+*]&facet.query=Price_6_f:[*+TO+*]&facet.query=Price_7_f:[*+TO+*]&facet.query=Price_8_f:[*+TO+*]&event=newSearcher&q=(title:*+OR+text:*)&distrib=false&json.nl=map&facet.field=BrandID_s&wt=json&facet.method=fc&fq=DataType_s:Product&fq=WebSections_ms:house&fq=VisibleOnline_ms:7&fq={!tag%3Dcurrent_group}GroupIds_ms:*&rows=20}
> hits=2549 status=0 QTime=1263
>
>
> If I run the same query after the index has registered I see a QTime of over
> a second, the second time I run the query I see around 80ms. This leads me to
> believe the warming did not occur or the query was not commited to cache on
> start up of the new searcher.
> Can someone please advise on how to use the newSearcher queries to
> effectively warm SolR caches. Should I see an improved response for the first
> time I run the query if the same query has been used as a newSearcher query?
> Cheers,
> Dalton
newSearcher autowarming queries in solrconfig.xml run but does not appear to warm cache
After setting a number of newSearcher and firstSearcher queries, I can see in
the console logs that the queries are run, but when I run the same query
against the new searcher (using CuRL), I get a slow response time for the first
run.
Config:
DataType_s:Product
WebSections_ms:house {!tag=current_group}GroupIds_ms:*
true BrandID_s Price_2_f:[* TO *] Price_3_f:[* TO *] Price_4_f:[* TO *] Price_5_f:[* TO *] Price_6_f:[* TO *] Price_7_f:[* TO *] Price_8_f:[* TO *] 1 fc
json map
(title:* OR text:*) 0 20
Console log:
INFO (searcherExecutor-7-thread-1-processing-x:core1) [ x:core1]
o.a.s.c.S.Request [core1] webapp=null path=null
params={facet=true&facet.mincount=1&start=0&facet.query=Price_2_f:[*+TO+*]&facet.query=Price_3_f:[*+TO+*]&facet.query=Price_4_f:[*+TO+*]&facet.query=Price_5_f:[*+TO+*]&facet.query=Price_6_f:[*+TO+*]&facet.query=Price_7_f:[*+TO+*]&facet.query=Price_8_f:[*+TO+*]&event=newSearcher&q=(title:*+OR+text:*)&distrib=false&json.nl=map&facet.field=BrandID_s&wt=json&facet.method=fc&fq=DataType_s:Product&fq=WebSections_ms:house&fq=VisibleOnline_ms:7&fq={!tag%3Dcurrent_group}GroupIds_ms:*&rows=20}
hits=2549 status=0 QTime=1263
If I run the same query after the index has registered I see a QTime of over a
second, the second time I run the query I see around 80ms. This leads me to
believe the warming did not occur or the query was not commited to cache on
start up of the new searcher.
Can someone please advise on how to use the newSearcher queries to effectively
warm SolR caches. Should I see an improved response for the first time I run
the query if the same query has been used as a newSearcher query?
Cheers,
Dalton
