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
