You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@solr.apache.org by Ronen Nussbaum <ro...@gmail.com> on 2021/04/27 17:07:18 UTC

Too Many Searcher Opening Events

Hi Everyone,

I have a cluster of seven servers, running Solr 8.3.0
Collection is divided into 64 shards, each shard has a replica.
Total number of documents: ~700M, but most are nested (childs) so an
effective number is 20M parents.
Ingestion is quite heavy.
Auto commit is configured like this:
     <autoCommit>
       <!-- every minute -->
       <maxTime>${solr.autoCommit.maxTime:60000}</maxTime>
       <maxDocs>${solr.autoCommit.maxDocs:50000}</maxDocs>
       <openSearcher>*false*</openSearcher>
     </autoCommit>

     <autoSoftCommit>
       <!-- every 5 minutes -->
       <maxTime>${solr.autoSoftCommit.maxTime:300000}</maxTime>
     </autoSoftCommit>

I'm trying to understand why there are so many "SolrIndexSearcher Opening"
events in the log e.g.
[2021-04-19T14:45:27.019] INFO [qtp1686100174-260205]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@3fae69f8[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:45:27.061] INFO [qtp1686100174-258896]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@2a47a89c[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:45:37.193] INFO [qtp1686100174-256821]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@3bf060ea[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:45:41.284] INFO [qtp1686100174-258269]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@2b18321b[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:46:02.238] INFO [qtp1686100174-258858]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@76f4935f[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:46:07.248] INFO [qtp1686100174-256407]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@f086b3a[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:46:16.609] INFO [qtp1686100174-257476]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@15b79751[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:46:29.856] INFO [qtp1686100174-259689]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@bf0a783[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:46:56.211] INFO [qtp1686100174-257346]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@43d22ad5[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:47:06.972] INFO [qtp1686100174-256721]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@1779ccd1[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:47:21.089] INFO [qtp1686100174-259395]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@368b2cfb[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:47:44.583] INFO [qtp1686100174-256722]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@11afa0d8[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:47:54.912] INFO [qtp1686100174-256157]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@38cb7e42[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:48:14.520] INFO [qtp1686100174-258515]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@479d4204[1602350_shard46_replica_n182]
realtime]
[2021-04-19T14:48:18.961] INFO [qtp1686100174-253862]
org.apache.solr.search.SolrIndexSearcher Opening
[Searcher@164a03a6[1602350_shard46_replica_n182]
realtime]

Between 00:00 and 17:00 (17 hours) I have ~1500 lines like the above, and
~800 lines "registered new searcher".
This time period is ~1000 minutes so I was expecting 1000/5=200 events
(soft commit each 5 minutes).
This doesn't look good to me.
Could it be affected by clients submitting a commit request?
Should I use a different configuration?

Thanks in advance,
Ronen.

Re: Too Many Searcher Opening Events

Posted by Emir Arnautović <em...@sematext.com>.
Hi Ronen,
If you think that it is unintentional explicit commit that is causing this, you can disable explicit commit with IgnoreCommitOptimizeUpdateProcessorFactory.

HTH,
Emir
--
Monitoring - Log Management - Alerting - Anomaly Detection
Solr & Elasticsearch Consulting Support Training - http://sematext.com/



> On 27 Apr 2021, at 19:07, Ronen Nussbaum <ro...@gmail.com> wrote:
> 
> Hi Everyone,
> 
> I have a cluster of seven servers, running Solr 8.3.0
> Collection is divided into 64 shards, each shard has a replica.
> Total number of documents: ~700M, but most are nested (childs) so an
> effective number is 20M parents.
> Ingestion is quite heavy.
> Auto commit is configured like this:
>     <autoCommit>
>       <!-- every minute -->
>       <maxTime>${solr.autoCommit.maxTime:60000}</maxTime>
>       <maxDocs>${solr.autoCommit.maxDocs:50000}</maxDocs>
>       <openSearcher>*false*</openSearcher>
>     </autoCommit>
> 
>     <autoSoftCommit>
>       <!-- every 5 minutes -->
>       <maxTime>${solr.autoSoftCommit.maxTime:300000}</maxTime>
>     </autoSoftCommit>
> 
> I'm trying to understand why there are so many "SolrIndexSearcher Opening"
> events in the log e.g.
> [2021-04-19T14:45:27.019] INFO [qtp1686100174-260205]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@3fae69f8[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:45:27.061] INFO [qtp1686100174-258896]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@2a47a89c[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:45:37.193] INFO [qtp1686100174-256821]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@3bf060ea[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:45:41.284] INFO [qtp1686100174-258269]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@2b18321b[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:46:02.238] INFO [qtp1686100174-258858]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@76f4935f[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:46:07.248] INFO [qtp1686100174-256407]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@f086b3a[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:46:16.609] INFO [qtp1686100174-257476]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@15b79751[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:46:29.856] INFO [qtp1686100174-259689]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@bf0a783[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:46:56.211] INFO [qtp1686100174-257346]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@43d22ad5[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:47:06.972] INFO [qtp1686100174-256721]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@1779ccd1[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:47:21.089] INFO [qtp1686100174-259395]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@368b2cfb[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:47:44.583] INFO [qtp1686100174-256722]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@11afa0d8[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:47:54.912] INFO [qtp1686100174-256157]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@38cb7e42[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:48:14.520] INFO [qtp1686100174-258515]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@479d4204[1602350_shard46_replica_n182]
> realtime]
> [2021-04-19T14:48:18.961] INFO [qtp1686100174-253862]
> org.apache.solr.search.SolrIndexSearcher Opening
> [Searcher@164a03a6[1602350_shard46_replica_n182]
> realtime]
> 
> Between 00:00 and 17:00 (17 hours) I have ~1500 lines like the above, and
> ~800 lines "registered new searcher".
> This time period is ~1000 minutes so I was expecting 1000/5=200 events
> (soft commit each 5 minutes).
> This doesn't look good to me.
> Could it be affected by clients submitting a commit request?
> Should I use a different configuration?
> 
> Thanks in advance,
> Ronen.

RE: Too Many Searcher Opening Events

Posted by "Nussbaum, Ronen" <Ro...@verint.com>.
Thank you Shawn for your reply.
I didn't notice the "realtime", we do use it in our application workflow.
I tried to reproduce it in a similar environment but when used the /get handler I only saw this line in the log:
"org.apache.solr.handler.component.RealTimeGetComponent LOOKUP_SLICE:shard50=..."
Didn't see searcher opening events.
Since we experience high memory usage and overall performance slowness I thought it might be related.


-----Original Message-----
From: Shawn Heisey <ap...@elyograg.org>
Sent: יום ד 28 אפריל 2021 16:46
To: users@solr.apache.org
Subject: Re: Too Many Searcher Opening Events

On 2021-04-27 11:07, Ronen Nussbaum wrote:
> I'm trying to understand why there are so many "SolrIndexSearcher
> Opening"
> events in the log e.g.

Those events are all for the realtime searcher, which is normally found at the /get handler path.  I believe that handler is implicit, meaning you don't have to define it in solrconfig.xml for it to be created.

The realtime searcher allows you to query uncommitted documents by the value in the uniqueKey field.  I do not know whether there is anything available to control how often this searcher is replaced.  I don't think there is.  It is part of Solr's norm operation.

When you are looking in the log for for "real" searchers opening, you will need exclude any lines that say "realtime".

Thanks,
Shawn


This electronic message may contain proprietary and confidential information of Verint Systems Inc., its affiliates and/or subsidiaries. The information is intended to be for the use of the individual(s) or entity(ies) named above. If you are not the intended recipient (or authorized to receive this e-mail for the intended recipient), you may not use, copy, disclose or distribute to anyone this message or any information contained in this message. If you have received this electronic message in error, please notify us by replying to this e-mail.

Re: Too Many Searcher Opening Events

Posted by Shawn Heisey <ap...@elyograg.org>.
On 2021-04-27 11:07, Ronen Nussbaum wrote:
> I'm trying to understand why there are so many "SolrIndexSearcher 
> Opening"
> events in the log e.g.

Those events are all for the realtime searcher, which is normally found 
at the /get handler path.  I believe that handler is implicit, meaning 
you don't have to define it in solrconfig.xml for it to be created.

The realtime searcher allows you to query uncommitted documents by the 
value in the uniqueKey field.  I do not know whether there is anything 
available to control how often this searcher is replaced.  I don't think 
there is.  It is part of Solr's norm operation.

When you are looking in the log for for "real" searchers opening, you 
will need exclude any lines that say "realtime".

Thanks,
Shawn