Quick scan, but probably this: INFO o.a.solr.spelling.suggest.Suggester - build()
The suggester build process can easily take many minutes, there's some explanation here: https://lucidworks.com/blog/2015/03/04/solr-suggester/ the short form is that depending on how it's defined, it may have to read _all_ the documents in your entire corpus to build the suggester structures. And you apparently have buildOnCommit set to true. Note particularly the caveats there about the Solr version required so that buildOnStartup=false is honored. Best, Erick On Wed, Dec 16, 2015 at 2:34 AM, Vincenzo D'Amore <v.dam...@gmail.com> wrote: > Hi, > > an update. Hope you can help me. > > I have stopped all the other working collections, in order to have a clean > log file. > > at 11:01:16 an hard commit has been issued > > 2015-12-16 11:01:49,839 [http-bio-8080-exec-824] INFO > org.apache.solr.update.UpdateHandler - start > commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} > > at 11:11:31,344 the commit has been completed. > > The commit was ended logging this line, I suppose 615021 is the wait time > (roughly 10 minutes) : > > 2015-12-16 11:11:31,343 [http-bio-8080-exec-991] INFO > o.a.s.u.processor.LogUpdateProcessor - [catalogo_shard2_replica3] > webapp=/solr path=/update > params={waitSearcher=true&commit=true&softCommit=false&wt=javabin&version=2} > {commit=} 0 615021 > > During this 10 minutes, the server logged "only" thes lines, looking at > them I don't see anything of strange: > > 2015-12-16 11:01:50,705 [http-bio-8080-exec-824] INFO > o.a.solr.search.SolrIndexSearcher - Opening > Searcher@6d5c31e2[catalogo_shard1_replica2] > main > 2015-12-16 11:01:50,724 [http-bio-8080-exec-824] INFO > org.apache.solr.update.UpdateHandler - end_commit_flush > 2015-12-16 11:02:20,722 [searcherExecutor-108-thread-1] INFO > o.a.solr.spelling.suggest.Suggester - build() > 2015-12-16 11:02:21,846 [http-bio-8080-exec-824] INFO > o.a.s.u.processor.LogUpdateProcessor - [catalogo_shard1_replica2] > webapp=/solr path=/update > params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from= > http://192.168.101.118:8080/solr/catalogo_shard2_replica3/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false} > {commit=} 0 32007 > 2015-12-16 11:05:47,162 [http-bio-8080-exec-1037] INFO > org.apache.solr.update.UpdateHandler - start > commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} > 2015-12-16 11:05:47,970 [http-bio-8080-exec-1037] INFO > o.a.solr.search.SolrIndexSearcher - Opening > Searcher@4ede7ac5[catalogo_shard2_replica3] > main > 2015-12-16 11:05:47,989 [http-bio-8080-exec-1037] INFO > org.apache.solr.update.UpdateHandler - end_commit_flush > 2015-12-16 11:06:03,063 [commitScheduler-115-thread-1] INFO > org.apache.solr.update.UpdateHandler - start > commit{,optimize=false,openSearcher=false,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} > 2015-12-16 11:06:03,896 [commitScheduler-115-thread-1] INFO > o.a.solr.search.SolrIndexSearcher - Opening > Searcher@2bf4fd3a[catalogo_shard3_replica1] > realtime > 2015-12-16 11:06:03,913 [commitScheduler-115-thread-1] INFO > org.apache.solr.update.UpdateHandler - end_commit_flush > 2015-12-16 11:06:19,435 [searcherExecutor-111-thread-1] INFO > o.a.solr.spelling.suggest.Suggester - build() > 2015-12-16 11:06:20,589 [http-bio-8080-exec-1037] INFO > o.a.s.u.processor.LogUpdateProcessor - [catalogo_shard2_replica3] > webapp=/solr path=/update > params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from= > http://192.168.101.118:8080/solr/catalogo_shard2_replica3/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false} > {commit=} 0 33427 > 2015-12-16 11:08:07,076 [http-bio-8080-exec-1037] INFO > org.apache.solr.update.UpdateHandler - start > commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=false,prepareCommit=false} > 2015-12-16 11:08:07,076 [http-bio-8080-exec-1037] INFO > org.apache.solr.update.UpdateHandler - No uncommitted changes. Skipping > IW.commit. > 2015-12-16 11:08:07,076 [http-bio-8080-exec-1037] INFO > o.a.solr.search.SolrIndexSearcher - Opening > Searcher@75b2727f[catalogo_shard3_replica1] > main > 2015-12-16 11:08:07,084 [http-bio-8080-exec-1037] INFO > org.apache.solr.update.UpdateHandler - end_commit_flush > 2015-12-16 11:08:39,040 [searcherExecutor-114-thread-1] INFO > o.a.solr.spelling.suggest.Suggester - build() > 2015-12-16 11:08:40,286 [http-bio-8080-exec-1037] INFO > o.a.s.u.processor.LogUpdateProcessor - [catalogo_shard3_replica1] > webapp=/solr path=/update > params={update.distrib=FROMLEADER&waitSearcher=true&openSearcher=true&commit=true&softCommit=false&distrib.from= > http://192.168.101.118:8080/solr/catalogo_shard2_replica3/&commit_end_point=true&wt=javabin&version=2&expungeDeletes=false} > {commit=} 0 33211 > > Could some component be the cause of this wait? Something like a suggester > or a spellchecker cache? > But if yes, I should see the activity in log file, isn't it? > > Best regards, > Vincenzo > > > On Sat, Dec 12, 2015 at 7:50 PM, Erick Erickson <erickerick...@gmail.com> > wrote: > >> Autowarm times will only happen when the commit has openSearcher=true >> or on a soft commit. But maybe your log levels aren't at INFO for the right >> code... >> >> That said, your autowarm counts at 0 probably means that you're not seeing >> any autowarming really, so that might be a red herring. Your newSearcher >> event in solrconfig.xml will still be fired, but may be commented out. >> >> This is still something of a puzzle. With an index this size, your hard >> commits should never take more than a second or two unless you're >> in some very strange state. Stack traces would be in order if lengthening >> the commit interval doesn't work. >> >> Best, >> Erick >> >> On Fri, Dec 11, 2015 at 5:58 PM, Vincenzo D'Amore <v.dam...@gmail.com> >> wrote: >> > Hi All, >> > >> > an update, I have switched logging from WARN to INFO for all except for >> > those two: >> > >> > - org.apache.solr.core >> > - org.apache.solr.handler.component.SpellCheckComponent >> > >> > Well, looking at log file I'm unable to find any autowarm log line, even >> > after few updates and commits. >> > >> > Looking at solrconfig.xml I see most autowarmCount parameters are set to >> 0 >> > >> > <filterCache class="solr.FastLRUCache" size="1500" initialSize="1000" >> > autowarmCount="0" /> >> > <queryResultCache class="solr.LRUCache" size="8096" initialSize="1024" >> > autowarmCount="0" /> >> > <documentCache class="solr.FastLRUCache" size="10240" initialSize="4096" >> > autowarmCount="0" /> >> > <cache name="perSegFilter" class="solr.search.LRUCache" >> size >> > ="10" initialSize="0" autowarmCount="10" >> regenerator="solr.NoOpRegenerator" >> > /> >> > >> > Not sure what this means... >> > >> > On Sat, Dec 12, 2015 at 1:13 AM, Vincenzo D'Amore <v.dam...@gmail.com> >> > wrote: >> > >> >> Thanks Erick, Mark, >> >> >> >> I'll raise maxTime asap. >> >> Just to be sure understand, given that I have openSearcher=false, I >> >> suppose it shouldn't trigger autowarming at least until a commit is >> >> executed, shouldn't it? >> >> >> >> Anyway, I don't understand, given that maxTime is very aggressive, why >> >> hard commit takes so long. >> >> >> >> Thanks again for your answers. >> >> Vincenzo >> >> >> >> >> >> On Fri, Dec 11, 2015 at 7:22 PM, Erick Erickson < >> erickerick...@gmail.com> >> >> wrote: >> >> >> >>> First of all, your autocommit settings are _very_ aggressive. >> Committing >> >>> every second is far to frequent IMO. >> >>> >> >>> As an aside, I generally prefer to omit the maxDocs as it's not all >> >>> that predictable, >> >>> but that's a personal preference and really doesn't bear on your >> problem.. >> >>> >> >>> My _guess_ is that you are doing a lot of autowarming. The number of >> docs >> >>> doesn't really matter if your autowarming is taking forever, your Solr >> >>> logs >> >>> should report the autowarm times at INFO level, have you checked those? >> >>> >> >>> The commit settings shouldn't be a problem in terms of your server >> dying, >> >>> the indexing process flushes docs to the tlog independent of >> committing so >> >>> upon restart they should be recovered. Here's a blog on the subject: >> >>> >> >>> >> >>> >> https://lucidworks.com/blog/2013/08/23/understanding-transaction-logs-softcommit-and-commit-in-sorlcloud/ >> >>> >> >>> Best, >> >>> Erick >> >>> >> >>> On Fri, Dec 11, 2015 at 8:24 AM, Vincenzo D'Amore <v.dam...@gmail.com> >> >>> wrote: >> >>> > Hi all, >> >>> > >> >>> > I have a SolrCloud cluster with a collection (2.5M docs) with 3 >> shards >> >>> and >> >>> > 15 replicas. >> >>> > There is a solrj application that feeds the collection, updating few >> >>> > documents every hour, I don't understand why, at end of process, the >> >>> hard >> >>> > commit takes about 8/10 minutes. >> >>> > >> >>> > Even if there are only few hundreds of documents. >> >>> > >> >>> > This is the autocommit configuration: >> >>> > >> >>> > <autoCommit> >> >>> > <maxDocs>10000</maxDocs> >> >>> > <maxTime>1000</maxTime> >> >>> > <openSearcher>false</openSearcher> >> >>> > </autoCommit> >> >>> > >> >>> > In your experience why hard commit takes so long even for so few >> >>> documents? >> >>> > >> >>> > Now I'm changing the code to softcommit, calling commit (waitFlush = >> >>> > false, waitSearcher >> >>> > = false, softCommit = true); >> >>> > >> >>> > solrServer.commit(false, false, true);. >> >>> > >> >>> > I have configured NRTCachingDirectoryFactory, but I'm a little bit >> >>> worried >> >>> > if a server goes down (something like: kill -9, SolrCloud crashes, >> out >> >>> of >> >>> > memory, etc.), and if, using this strategy >> >>> softcommit+NRTCachingDirectory, >> >>> > SolrCloud instance could not recover a replica. >> >>> > >> >>> > Should I worry about this new configuration? I was thinking to take a >> >>> > snapshot of everything every day, in order to recover immediately the >> >>> > index. Could this be considered a best practice? >> >>> > >> >>> > Thanks in advance for your time, >> >>> > Vincenzo >> >>> > >> >>> > -- >> >>> > Vincenzo D'Amore >> >>> > email: v.dam...@gmail.com >> >>> > skype: free.dev >> >>> > mobile: +39 349 8513251 >> >>> >> >> >> >> >> >> >> >> -- >> >> Vincenzo D'Amore >> >> email: v.dam...@gmail.com >> >> skype: free.dev >> >> mobile: +39 349 8513251 >> >> >> > >> > >> > >> > -- >> > Vincenzo D'Amore >> > email: v.dam...@gmail.com >> > skype: free.dev >> > mobile: +39 349 8513251 >> > > > > -- > Vincenzo D'Amore > email: v.dam...@gmail.com > skype: free.dev > mobile: +39 349 8513251
