RE: Updates to index not available immediately as index scales, even with autoSoftCommit at 1 second
Thanks for the explanation. This makes a lot of sense to me... I'm wondering if there's a way to get the best of both worlds. Can throwing more hardware at the index give real time updates + a large LRU cache? Would we be CPU bound at this point? -- View this message in context: http://lucene.472066.n3.nabble.com/Updates-to-index-not-available-immediately-as-index-scales-even-with-autoSoftCommit-at-1-second-tp4152511p4152983.html Sent from the Solr - User mailing list archive at Nabble.com.
Re: Updates to index not available immediately as index scales, even with autoSoftCommit at 1 second
Oh, what a lovely anti-pattern! Every second, you're throwing away your filterCache. And then firing up to 4096 autowarm queries at your index on the filterCache. And this doesn't even consider the other caches! And this will get worse with time after restarts if my scenario is accurate. Having extremely fast autocommit times is fundamentally incompatible with having large caches. More hardware simply won't help unless you have so much hardware that you're storing a tiny number of docs on each shard, which is a ridiculous solution. IMO your only choices are to 1 drastically reduce your autowarm counts (which, btw, means that you can also drastically reduce their size) or 2 drastically increase your commit interval and live with 15 minute warmup times. I've never seen autowarm counts that high really do much good anyway. For that matter, the raw size of your caches is also far too large IMO. If you're really generating that many unique filter queries, I'd argue you've got something pathological in your setup. What you are _not_ going to be able to do is have autowarm counts that high and 1 second commits. Here's the long form. I don't know how many entries are in your various caches, but I bet it's a lot. Note that it picks on filterCache, but the same logic applies to your other caches, i.e. queryResultCache in particular. Your new searcher isn't serving any queries until up to 4096 autowarm queries are executed. Which you're then immediately throwing away due to your soft commit interval. I rather suspect you'll be seeing log messages about too many on deck searchers or some such due to this setting in solrconfig.xml: maxWarmingSearchers2/maxWarmingSearchers Do not think you can up this number and cure your problem, you'll hit OOMs I predict if you do. Now, here's the kicker. Your filterCache is going to accumulate entries _because_ of autowarming! Imagine that every second you're adding 10 new fq clauses that are unique. Now, when the first soft commit happens, your filterCache has 10 entries in it. The autowarm kicks in and puts those same 10 in your filterCache and the searcher opens for business. A second later, another 10 fq clauses have come in and been put in your filterCache. And another searcher is opened. And now there are 20 entries. All of which are autowarmed and put back in the filterCache. A second later there are 30 entries in your filterCache. A second after that 40. And so on. If this guess is correct, then if you restart all your servers your interval between when you index a doc and can search it will start out OK, but then increase. Eventually you get to the situation you have now, a huge number of autowarming queries that take minutes to warm before you can see any of your recently added documents. Places to look to see what's happening: admin/plugins-stats/core. you should see warmupTime near the bottom. admin/plugins-stats/cache/filter cache. You should see warmupTime there too. /document cache etc. While you're at the filter cache stats page, take a look at your hit ratio, I suspect it's very small. If so, it's not doing you much good anyway. BTW, one way of adding completely useless (but unique) fq clauses is to follow another anti-pattern like: fq=timestamp:[NOW/DAY to NOW] http://searchhub.org/2012/02/23/date-math-now-and-filter-queries/ On Thu, Aug 14, 2014 at 7:21 AM, cwhit cwhi...@solinkcorp.com wrote: Thanks for the explanation. This makes a lot of sense to me... I'm wondering if there's a way to get the best of both worlds. Can throwing more hardware at the index give real time updates + a large LRU cache? Would we be CPU bound at this point? -- View this message in context: http://lucene.472066.n3.nabble.com/Updates-to-index-not-available-immediately-as-index-scales-even-with-autoSoftCommit-at-1-second-tp4152511p4152983.html Sent from the Solr - User mailing list archive at Nabble.com.
Re: Updates to index not available immediately as index scales, even with autoSoftCommit at 1 second
You havne't given us a lot of information to go on (ie: full solrconfig.xml, log messages arround the tim of your update, etc...) but my best guess would be that you are seeing a delay between the time the new searcher is opened and the time the newSearcher is made available to requests due to cache warming. the specifics of your cache configs and newSearcher event listeners would impact this ... and of course, you'd see log messages about opening hte searcher, the cache warming, etc : Date: Tue, 12 Aug 2014 07:18:20 -0700 (PDT) : From: cwhit cwhi...@solinkcorp.com : Reply-To: solr-user@lucene.apache.org : To: solr-user@lucene.apache.org : Subject: Updates to index not available immediately as index scales, : even with autoSoftCommit at 1 second : : I've been trying to debug through this but I'm stumped. I have a Solr index : with ~40 million documents indexed currently sitting idle. I update an : existing document through the web interface (collection1 - Documents - : /update) and the web request returns successfully. At this point, I expect : the document to be updated on future searches within 1 second, but that's : not the case. The document can sometimes not be updated to future searches : for several minutes. What could be causing this, and how can it be : remedied? : : Within my solrconfig.xml, I have the following commit properties set: : : autoSoftCommit : maxTime1000/maxTime : /autoSoftCommit : : autoCommit : maxTime30/maxTime : openSearcherfalse/openSearcher : /autoCommit : : Running an identical Solr configuration but with thousands of documents : (rather than tens of millions), the updates are available immediately. : : : : : -- : View this message in context: http://lucene.472066.n3.nabble.com/Updates-to-index-not-available-immediately-as-index-scales-even-with-autoSoftCommit-at-1-second-tp4152511.html : Sent from the Solr - User mailing list archive at Nabble.com. : -Hoss http://www.lucidworks.com/
Re: Updates to index not available immediately as index scales, even with autoSoftCommit at 1 second
I'm not seeing any messages in the log with respect to cache warming at the time, but I will investigate that possibility. Thank you. In case it is helpful, I pasted the entire solrconfig.xml at http://pastebin.com/C0iQ7E9a -- View this message in context: http://lucene.472066.n3.nabble.com/Updates-to-index-not-available-immediately-as-index-scales-even-with-autoSoftCommit-at-1-second-tp4152511p4152545.html Sent from the Solr - User mailing list archive at Nabble.com.
Re: Updates to index not available immediately as index scales, even with autoSoftCommit at 1 second
: I'm not seeing any messages in the log with respect to cache warming at the : time, but I will investigate that possibility. Thank you. In case it is what logs *do* you see at the time you send the doc? w/o details, we can't help you. : helpful, I pasted the entire solrconfig.xml at http://pastebin.com/C0iQ7E9a -Hoss http://www.lucidworks.com/
Re: Updates to index not available immediately as index scales, even with autoSoftCommit at 1 second
Immediately after triggering the update, this is what is in the logs:
/2014-08-12 12:58:48,774 | [71] | 153414367 [qtp2038499066-4772] INFO
org.apache.solr.update.processor.LogUpdateProcessor – [collection1]
webapp=/solr path=/update params={wt=json} {add=[52627624
(1476251068652322816)]} 0 34
2014-08-12 12:58:49,773 | [71] | 153415369 [commitScheduler-7-thread-1] INFO
org.apache.solr.update.UpdateHandler – start
commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
2014-08-12 12:58:49,862 | [71] | 153415459 [commitScheduler-7-thread-1] INFO
org.apache.solr.search.SolrIndexSearcher – Opening Searcher@65c48c06 main
2014-08-12 12:58:49,874 | [71] | 153415472 [commitScheduler-7-thread-1] INFO
org.apache.solr.update.UpdateHandler – end_commit_flush/
The end_commit_flush leads me to believe that the soft commit has completed,
but perhaps that thought is wrong. There are no other logs for a while,
until
/
2014-08-12 13:03:49,556 | [71] | 153715147 [commitScheduler-6-thread-1] INFO
org.apache.solr.update.UpdateHandler – start
commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
2014-08-12 13:03:49,805 | [71] | 153715402 [commitScheduler-6-thread-1] INFO
org.apache.solr.core.SolrCore – SolrDeletionPolicy.onCommit: commits: num=2
2014-08-12 13:03:49,805 | [71] |
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@E:\Program
Files (x86)\SolrLive\SolrFiles\Solr\service\solr\data\index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fac1a3c;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2we,generation=3758}
2014-08-12 13:03:49,805 | [71] |
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@E:\Program
Files (x86)\SolrLive\SolrFiles\Solr\service\solr\data\index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fac1a3c;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2wf,generation=3759}
2014-08-12 13:03:49,805 | [34] | 153715403 [commitScheduler-6-thread-1] INFO
org.apache.solr.core.SolrCore – newest commit generation = 3759
2014-08-12 13:03:49,818 | [34] | 153715415 [commitScheduler-6-thread-1] INFO
org.apache.solr.update.UpdateHandler – end_commit_flush
/
At this point, the update is still not present...
/2014-08-12 13:11:45,279 | [81] | 154190876 [searcherExecutor-4-thread-1]
INFO org.apache.solr.core.SolrCore – QuerySenderListener sending requests
to Searcher@65c48c06 main{StandardDirectoryReader(segments_2we:82217:nrt
_qkc(4.6):C8161558/879724:delGen=275 _sra(4.6):C2943436/247953:delGen=51
_r2w(4.6):C1149753/18376:delGen=55 _rgs(4.6):C1468449/648612:delGen=107
_tdl(4.6):C583431/7873:delGen=94 _svo(4.6):C197286/7:delGen=5
_t4d(4.6):C247031/2928:delGen=36 _tkf(4.6):C111429/761:delGen=23
_tch(4.6):C6014/81:delGen=22 _tk5(4.6):C3907/242:delGen=21
_tjv(4.6):C3492/119:delGen=13 _thd(4.6):C5014/241:delGen=24
_tdh(4.6):C5375/437:delGen=30 _tj1(4.6):C5989/15:delGen=6
_tkq(4.6):C1749/36:delGen=6 _tmj(4.6):C961/1:delGen=1
_tlm(4.6):C714/9:delGen=5 _tm6(4.6):C2616 _tlx(4.6):C1105/273:delGen=3
_tly(4.6):C5/2:delGen=1 _tm2(4.6):C1 _tm4(4.6):C1 _tmb(4.6):C1 _tmk(4.6):C5
_tml(4.6):C12 _tmm(4.6):C1 _tmn(4.6):C2/1:delGen=1 _tmo(4.6):C1 _tmp(4.6):C1
_tmr(4.6):C1 _tms(4.6):C1)}
2014-08-12 13:11:45,280 | [81] | 154190877 [searcherExecutor-4-thread-1]
INFO org.apache.solr.core.SolrCore – QuerySenderListener done.
2014-08-12 13:11:45,280 | [81] | 154190877 [searcherExecutor-4-thread-1]
INFO org.apache.solr.handler.component.SpellCheckComponent – Building
spell index for spell checker: suggest
2014-08-12 13:11:45,280 | [81] | 154190877 [searcherExecutor-4-thread-1]
INFO org.apache.solr.spelling.suggest.Suggester – build()/
Still no update...
/2014-08-12 13:12:58,424 | [81] | 154264021 [searcherExecutor-4-thread-1]
INFO org.apache.solr.core.SolrCore – [collection1] Registered new searcher
Searcher@65c48c06 main{StandardDirectoryReader(segments_2we:82217:nrt
_qkc(4.6):C8161558/879724:delGen=275 _sra(4.6):C2943436/247953:delGen=51
_r2w(4.6):C1149753/18376:delGen=55 _rgs(4.6):C1468449/648612:delGen=107
_tdl(4.6):C583431/7873:delGen=94 _svo(4.6):C197286/7:delGen=5
_t4d(4.6):C247031/2928:delGen=36 _tkf(4.6):C111429/761:delGen=23
_tch(4.6):C6014/81:delGen=22 _tk5(4.6):C3907/242:delGen=21
_tjv(4.6):C3492/119:delGen=13 _thd(4.6):C5014/241:delGen=24
_tdh(4.6):C5375/437:delGen=30 _tj1(4.6):C5989/15:delGen=6
_tkq(4.6):C1749/36:delGen=6 _tmj(4.6):C961/1:delGen=1
_tlm(4.6):C714/9:delGen=5 _tm6(4.6):C2616 _tlx(4.6):C1105/273:delGen=3
_tly(4.6):C5/2:delGen=1 _tm2(4.6):C1 _tm4(4.6):C1 _tmb(4.6):C1 _tmk(4.6):C5
_tml(4.6):C12 _tmm(4.6):C1 _tmn(4.6):C2/1:delGen=1 _tmo(4.6):C1 _tmp(4.6):C1
_tmr(4.6):C1 _tms(4.6):C1)}/
There we go! Finally an update! Almost 15 minutes after making the update,
it is visible to queries.
--
View this message in context:
RE: Updates to index not available immediately as index scales, even with autoSoftCommit at 1 second
Based on your solrconfig.xml settings for the filter and queryResult caches, I
believe Chris's initial guess is correct. After a commit, there is likely
plenty of time spent warming these caches due to the significantly high
autowarm counts.
filterCache class=solr.FastLRUCache
size=16384
initialSize=4096
autowarmCount=4096/
queryResultCache class=solr.FastLRUCache
size=8192
initialSize=8192
autowarmCount=2048/
Suggest you try setting the autowarmcount very low or to zero, and then testing
to confirm the problem.
You might want to monitor if any JVM garbage collections are occurring during
this time, and causing system pauses. With such large caches (nominally stored
in Old Gen) you may be setting yourself up for GCs that take a significant
amount of time and thus add to your delay.
Matt
-Original Message-
From: cwhit [mailto:cwhi...@solinkcorp.com]
Sent: Tuesday, August 12, 2014 11:18 AM
To: solr-user@lucene.apache.org
Subject: Re: Updates to index not available immediately as index scales, even
with autoSoftCommit at 1 second
Immediately after triggering the update, this is what is in the logs:
/2014-08-12 12:58:48,774 | [71] | 153414367 [qtp2038499066-4772] INFO
org.apache.solr.update.processor.LogUpdateProcessor – [collection1]
webapp=/solr path=/update params={wt=json} {add=[52627624
(1476251068652322816)]} 0 34
2014-08-12 12:58:49,773 | [71] | 153415369 [commitScheduler-7-thread-1] INFO
org.apache.solr.update.UpdateHandler – start
commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
2014-08-12 12:58:49,862 | [71] | 153415459 [commitScheduler-7-thread-1] INFO
org.apache.solr.search.SolrIndexSearcher – Opening Searcher@65c48c06 main
2014-08-12 12:58:49,874 | [71] | 153415472 [commitScheduler-7-thread-1] INFO
org.apache.solr.update.UpdateHandler – end_commit_flush/
The end_commit_flush leads me to believe that the soft commit has completed,
but perhaps that thought is wrong. There are no other logs for a while, until
/
2014-08-12 13:03:49,556 | [71] | 153715147 [commitScheduler-6-thread-1] INFO
org.apache.solr.update.UpdateHandler – start
commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false}
2014-08-12 13:03:49,805 | [71] | 153715402 [commitScheduler-6-thread-1] INFO
org.apache.solr.core.SolrCore – SolrDeletionPolicy.onCommit: commits: num=2
2014-08-12 13:03:49,805 | [71] |
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@E:\Program
Files (x86)\SolrLive\SolrFiles\Solr\service\solr\data\index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fac1a3c;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2we,generation=3758}
2014-08-12 13:03:49,805 | [71] |
commit{dir=NRTCachingDirectory(org.apache.lucene.store.MMapDirectory@E:\Program
Files (x86)\SolrLive\SolrFiles\Solr\service\solr\data\index
lockFactory=org.apache.lucene.store.NativeFSLockFactory@1fac1a3c;
maxCacheMB=48.0 maxMergeSizeMB=4.0),segFN=segments_2wf,generation=3759}
2014-08-12 13:03:49,805 | [34] | 153715403 [commitScheduler-6-thread-1] INFO
org.apache.solr.core.SolrCore – newest commit generation = 3759
2014-08-12 13:03:49,818 | [34] | 153715415 [commitScheduler-6-thread-1] INFO
org.apache.solr.update.UpdateHandler – end_commit_flush / At this point, the
update is still not present...
/2014-08-12 13:11:45,279 | [81] | 154190876 [searcherExecutor-4-thread-1]
INFO org.apache.solr.core.SolrCore – QuerySenderListener sending requests
to Searcher@65c48c06 main{StandardDirectoryReader(segments_2we:82217:nrt
_qkc(4.6):C8161558/879724:delGen=275 _sra(4.6):C2943436/247953:delGen=51
_r2w(4.6):C1149753/18376:delGen=55 _rgs(4.6):C1468449/648612:delGen=107
_tdl(4.6):C583431/7873:delGen=94 _svo(4.6):C197286/7:delGen=5
_t4d(4.6):C247031/2928:delGen=36 _tkf(4.6):C111429/761:delGen=23
_tch(4.6):C6014/81:delGen=22 _tk5(4.6):C3907/242:delGen=21
_tjv(4.6):C3492/119:delGen=13 _thd(4.6):C5014/241:delGen=24
_tdh(4.6):C5375/437:delGen=30 _tj1(4.6):C5989/15:delGen=6
_tkq(4.6):C1749/36:delGen=6 _tmj(4.6):C961/1:delGen=1
_tlm(4.6):C714/9:delGen=5 _tm6(4.6):C2616 _tlx(4.6):C1105/273:delGen=3
_tly(4.6):C5/2:delGen=1 _tm2(4.6):C1 _tm4(4.6):C1 _tmb(4.6):C1 _tmk(4.6):C5
_tml(4.6):C12 _tmm(4.6):C1 _tmn(4.6):C2/1:delGen=1 _tmo(4.6):C1 _tmp(4.6):C1
_tmr(4.6):C1 _tms(4.6):C1)}
2014-08-12 13:11:45,280 | [81] | 154190877 [searcherExecutor-4-thread-1]
INFO org.apache.solr.core.SolrCore – QuerySenderListener done.
2014-08-12 13:11:45,280 | [81] | 154190877 [searcherExecutor-4-thread-1]
INFO org.apache.solr.handler.component.SpellCheckComponent – Building
spell index for spell checker: suggest
2014-08-12 13:11:45,280 | [81] | 154190877 [searcherExecutor-4-thread-1]
INFO org.apache.solr.spelling.suggest.Suggester – build()/
Still no
