Solrcloud (4.10) reports the end of soft commit before all shard replicas finished committing

[vsolakhian <vi...@zoominfo.com>]

We have a strange behavior of our Sorlcloud related code after upgrading from
from Solr 4.4 to Solr 4.10 (as part of upgrading from Cloudera CDH 4.6 to
Cloudera CDH 5.4.5).

We have a Solrcloud collection with three replicas of one shard.

Our code does batch indexing, then submits a soft commit request,using
SolrJ's

    org.apache.solr.client.solrj.impl.CloudSolrServer.commit(waitFlush,
waitSearcher, softCommit)

method with:

    waitFlush = true; waitSearcher = true; softCommit = true

After this synchronous commit invocation returns, we submit a query for the
newly indexed data.

Starting with Solr 4.10 we noticed that the query returns zero results
sometimes (about 70% of  tests).

In one of these cases logs (modified to make shorter) from our application
and from Solr servers show:

*1. Our application:*

  - 13:33:49:602 INFO Sending index commit request to CloudCollection
  - 13:35:49:752 INFO Finished index commit in 120110 millisecs
  - 13:35:50:349 INFO Sent query

*2. Solr server 1 (replica1):*

  - 13:33:49,612 INFO org.apache.solr.update.UpdateHandler: start commit ...
  - 13:34:23,486 INFO org.apache.solr.core.SolrCore: ===SolrEventListener
started warmup: event = newSearcher
  - 13:35:35,701 INFO org.apache.solr.core.SolrCore: ===SolrEventListener
done with newSearcher: totalTime = 72215  totalWarmupTime = 63349
  - 13:35:35,703 INFO org.apache.solr.core.SolrCore:
[CloudCollection_shard1_replica1] Registered new searcher
Searcher@4daaebbf[CloudCollection_shard1_replica1

*3. Solr server 2 (replica2):*

  - 13:33:49,604 INFO org.apache.solr.update.UpdateHandler: start commit ...
  - 13:35:49,163 INFO org.apache.solr.core.SolrCore: ===SolrEventListener
started warmup: event = newSearcher
  - 13:37:15,627 INFO org.apache.solr.core.SolrCore: ===SolrEventListener
done with newSearcher: totalTime = 86463  totalWarmupTime = 76713
  - 13:37:15,632 INFO org.apache.solr.core.SolrCore:
[CloudCollection_shard1_replica2] Registered new searcher
Searcher@57ddbc57[CloudCollection_shard1_replica2]

*4. Solr server 3 (replica3):*

  - 13:33:49,601 INFO org.apache.solr.update.UpdateHandler: start commit ...
  - 13:35:24,525 INFO org.apache.solr.core.SolrCore: ===SolrEventListener
started warmup: event = newSearcher

/--> QUERY IS RECEIVED HERE/

2015-10-21 13:35:50,416 INFO org.apache.solr.core.SolrCore.Request:
[CloudCollection_shard1_replica3] webapp=/solr path=/select
params={facet=true&fl=&facet.mincount=1&facet.query=<FACT
QUERY>&start=0&q=file_metadata_id:"123413"&wt=xml&qt=standard&fq=customer_company_id:"1010112"&fq=customer_account_id:"1185005"&version=2.2&rows=0}
hits=0 status=0 QTime=70

  - 13:36:43,535 INFO org.apache.solr.core.SolrCore: ===SolrEventListener
done with newSearcher: totalTime = 79009  totalWarmupTime = 69564
  - 13:36:43,537 INFO org.apache.solr.core.SolrCore:
[CloudCollection_shard1_replica3] Registered new searcher
Searcher@79d1be80[CloudCollection_shard1_replica3

*SUMMARY:*

    The application code returns from commit (which took about 2 minutes)
before replica2 and replica3 finished committing and opened a new searcher.
    At the time of sending the query only Solr server 1
(CloudCollection_shard1_replica1) has finished commit and is ready to return
the right result of the query.
    The query is received by the Solr server 3
(CloudCollection_shard1_replica3) when the commit is not finished and new
searcher is not opened yet, thus returning zero results.

I checked time on all hosts and they were all in sync.

Any opinions/explanations are appreciated.

Thanks,

Victor



--
View this message in context: http://lucene.472066.n3.nabble.com/Solrcloud-4-10-reports-the-end-of-soft-commit-before-all-shard-replicas-finished-committing-tp4235934.html
Sent from the Solr - User mailing list archive at Nabble.com.