solr reads whole index on startup

classic Classic list List threaded Threaded
11 messages Options
Reply | Threaded
Open this post in threaded view
|

solr reads whole index on startup

lstusr 5u93n4
Hi All,

We have a collection:
  - solr 7.5
  - 3 shards, replication factor 2 for a total of 6 NRT replicas
  - 3 servers, 16GB ram each
  - 2 billion documents
  - autoAddReplicas: false
  - 2.1 TB on-disk index size
  - index stored on hdfs on separate servers.

If we (gracefully) shut down solr on all 3 servers, when we re-launch solr
we notice that the nodes go into "Recovering" state for about 10-12 hours
before finally coming alive.

During this recovery time, we notice high network traffic outbound from our
HDFS servers to our solr servers. The sum total of which is roughly
equivalent to the index size on disk.

So it seems to us that on startup, solr has to re-read the entire index
before coming back alive.

1. is this assumption correct?
2. is there any way to mitigate this, so that solr can launch faster?

Thanks!

Kyle
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

Kevin Risden-3
Do you have logs right before the following?

"we notice that the nodes go into "Recovering" state for about 10-12 hours
before finally coming alive."

Is there a peersync failure or something else in the logs indicating why
there is a full recovery?

Kevin Risden


On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]> wrote:

> Hi All,
>
> We have a collection:
>   - solr 7.5
>   - 3 shards, replication factor 2 for a total of 6 NRT replicas
>   - 3 servers, 16GB ram each
>   - 2 billion documents
>   - autoAddReplicas: false
>   - 2.1 TB on-disk index size
>   - index stored on hdfs on separate servers.
>
> If we (gracefully) shut down solr on all 3 servers, when we re-launch solr
> we notice that the nodes go into "Recovering" state for about 10-12 hours
> before finally coming alive.
>
> During this recovery time, we notice high network traffic outbound from our
> HDFS servers to our solr servers. The sum total of which is roughly
> equivalent to the index size on disk.
>
> So it seems to us that on startup, solr has to re-read the entire index
> before coming back alive.
>
> 1. is this assumption correct?
> 2. is there any way to mitigate this, so that solr can launch faster?
>
> Thanks!
>
> Kyle
>
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

lstusr 5u93n4
Hi Kevin,

We do have logs. Grepping for peersync, I can see

solr               | 2018-12-05 03:31:41.301 INFO
(coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
[c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/]
nUpdates=100
solr               | 2018-12-05 03:31:41.307 INFO
(coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
[c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
versions.  sync failed.
solr               | 2018-12-05 03:31:44.007 INFO
(coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
[c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
http://solr.node4.metaonly01.eca.local:8983/solr/iglshistory_shard2_replica_n6/]
nUpdates=100
solr               | 2018-12-05 03:31:44.008 INFO
(coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
[c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
versions.  sync failed.
solr               | 2018-12-05 05:48:44.202 INFO
(coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
core=igls_shard1_replica_n1 url=
http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/]
nUpdates=100
solr               | 2018-12-05 05:48:44.646 WARN
(coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
core=igls_shard1_replica_n1 url=
http://solr.node2.metaonly01.eca.local:8983/solr  got a 503 from
http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/,
counting as success
solr               | 2018-12-05 05:48:44.682 INFO
(coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
core=igls_shard1_replica_n1 url=
http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync succeeded
solr               | 2018-12-05 05:51:18.369 INFO  (qtp2131952342-10232)
[c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
PeerSync: core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
nUpdates=100
solr               | 2018-12-05 06:01:18.496 WARN  (qtp2131952342-10232)
[c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
Replica did not return a fingerprint - possibly an older Solr version or
exception
solr               | 2018-12-05 06:01:31.126 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy Attempting
to PeerSync from [
http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/] -
recoveringAfterStartup=[true]
solr               | 2018-12-05 06:01:31.129 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
PeerSync: core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr START leader=
http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
nUpdates=100
solr               | 2018-12-05 06:11:18.535 WARN  (qtp2131952342-10232)
[c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
PeerSync: core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr  exception talking to
http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/,
failed
solr               | 2018-12-05 06:11:18.583 INFO  (qtp2131952342-10232)
[c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
PeerSync: core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
solr               |    at
org.apache.solr.update.PeerSyncWithLeader.request(PeerSyncWithLeader.java:321)
solr               |    at
org.apache.solr.update.PeerSyncWithLeader.alreadyInSync(PeerSyncWithLeader.java:341)
solr               |    at
org.apache.solr.update.PeerSyncWithLeader.sync(PeerSyncWithLeader.java:135)
solr               | 2018-12-05 09:21:31.831 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy Attempting
to PeerSync from [
http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/] -
recoveringAfterStartup=[true]
solr               | 2018-12-05 09:21:31.831 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
PeerSync: core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr START leader=
http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
nUpdates=100
solr               | 2018-12-05 12:28:26.698 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
Fingerprint comparison result: 1
solr               | 2018-12-05 12:28:26.698 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
fingerprint: {maxVersionSpecified=9223372036854775807,
maxVersionEncountered=1619003108526915584, maxInHash=1619003108526915584,
versionsHash=-2647181038600325382, numVersions=701868706,
numDocs=701868706, maxDoc=13478974}, Our fingerprint:
{maxVersionSpecified=9223372036854775807,
maxVersionEncountered=1618994939968880640, maxInHash=1618994939968880640,
versionsHash=-2861577316323569427, numVersions=701868706,
numDocs=701868706, maxDoc=13478974}
solr               | 2018-12-05 12:30:38.183 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
fingerprint {maxVersionSpecified=9223372036854775807,
maxVersionEncountered=1619014810634027008, maxInHash=1619014810634027008,
versionsHash=-5367247708654169186, numVersions=701868706,
numDocs=701868706, maxDoc=13478974}
solr               | 2018-12-05 12:30:38.183 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
PeerSync: core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr  Received 13 versions from
http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
solr               | 2018-12-05 12:30:38.184 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync PeerSync:
core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr  Our versions are too old.
ourHighThreshold=1618976334275411968 otherLowThreshold=1619012608476577792
ourHighest=1619014810634027008 otherHighest=1619014936356192256
solr               | 2018-12-05 12:30:38.185 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
PeerSync: core=igls_shard2_replica_n6 url=
http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
solr               | 2018-12-05 12:30:38.185 INFO
(recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy PeerSync
Recovery was not successful - trying replication.



Expanding one of them, we have:


solr               | 2018-12-05 03:31:39.421 INFO
(AutoscalingActionExecutor-8-thread-1) [   ] o.a.s.c.a.ExecutePlanAction No
operations to execute for event: {
solr               |   "id":"11402ae38efc8T1dr1vcl6ut11qh9fq6ncle94t",
solr               |   "source":".auto_add_replicas",
solr               |   "eventTime":303476722167752,
solr               |   "eventType":"NODELOST",
solr               |   "properties":{
solr               |     "eventTimes":[303476722167752],
solr               |     "preferredOperation":"movereplica",
solr               |     "_enqueue_time_":303959110445696,
solr               |
 "nodeNames":["solr.node4.metaonly01.eca.local:8983_solr"]}}
solr               | 2018-12-05 03:31:41.290 INFO
(coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
[c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu
e.
solr               | 2018-12-05 03:31:41.291 INFO
(coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
[c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an
d sync
solr               | 2018-12-05 03:31:41.291 INFO
(coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
[c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
o.a.s.c.SyncStrategy Sync replicas to http://solr.node2.metaonly01.
eca.local:8983/solr/iglshistory_shard3_replica_n10/
solr               | 2018-12-05 03:31:41.301 INFO
(coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
[c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/]
nUpdates=100
solr               | 2018-12-05 03:31:41.307 INFO
(coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
[c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
versions.  sync failed.


Not quite sure why it would be executing the auto-add-replicas trigger
since it's definitely set to false on the collection. (I checked).  Also,
this log comes from very early in the startup procedure, probably before
solr has been launched on the other servers.



Kyle

On Wed, 5 Dec 2018 at 12:58, Kevin Risden <[hidden email]> wrote:

> Do you have logs right before the following?
>
> "we notice that the nodes go into "Recovering" state for about 10-12 hours
> before finally coming alive."
>
> Is there a peersync failure or something else in the logs indicating why
> there is a full recovery?
>
> Kevin Risden
>
>
> On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]> wrote:
>
> > Hi All,
> >
> > We have a collection:
> >   - solr 7.5
> >   - 3 shards, replication factor 2 for a total of 6 NRT replicas
> >   - 3 servers, 16GB ram each
> >   - 2 billion documents
> >   - autoAddReplicas: false
> >   - 2.1 TB on-disk index size
> >   - index stored on hdfs on separate servers.
> >
> > If we (gracefully) shut down solr on all 3 servers, when we re-launch
> solr
> > we notice that the nodes go into "Recovering" state for about 10-12 hours
> > before finally coming alive.
> >
> > During this recovery time, we notice high network traffic outbound from
> our
> > HDFS servers to our solr servers. The sum total of which is roughly
> > equivalent to the index size on disk.
> >
> > So it seems to us that on startup, solr has to re-read the entire index
> > before coming back alive.
> >
> > 1. is this assumption correct?
> > 2. is there any way to mitigate this, so that solr can launch faster?
> >
> > Thanks!
> >
> > Kyle
> >
>
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

lstusr 5u93n4
I just repeated the procedure, same effect. I'm an hour in and it's still
recovering. Looked at the autoscaling API, but it's configured not to do
anything, which makes sense given the previous output.

One thing I did see, just now:

solr               | 2018-12-05 20:02:37.922 INFO  (qtp2131952342-5208) [
 x:igls_shard3_replica_n8] o.a.s.h.a.CoreAdminOperation It has been
requested that we recover: core=igls_shard3_replica_n8
solr               | 2018-12-05 20:02:37.923 ERROR (qtp2131952342-5208) [
 x:igls_shard3_replica_n8] o.a.s.h.RequestHandlerBase
org.apache.solr.common.SolrException: Unable to locate core
igls_shard3_replica_n8
solr               |    at
org.apache.solr.handler.admin.CoreAdminOperation.lambda$static$5(CoreAdminOperation.java:167)
solr               |    at
org.apache.solr.handler.admin.CoreAdminOperation.execute(CoreAdminOperation.java:360)
solr               |    at
org.apache.solr.handler.admin.CoreAdminHandler$CallInfo.call(CoreAdminHandler.java:395)
solr               |    at
org.apache.solr.handler.admin.CoreAdminHandler.handleRequestBody(CoreAdminHandler.java:180)
solr               |    at
org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:199)
solr               |    at
org.apache.solr.servlet.HttpSolrCall.handleAdmin(HttpSolrCall.java:734)
solr               |    at
org.apache.solr.servlet.HttpSolrCall.handleAdminRequest(HttpSolrCall.java:715)
solr               |    at
org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:496)
solr               |    at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:377)
solr               |    at
org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:323)
solr               |    at
org.eclipse.jetty.servlet.ServletHandler$CachedChain.doFilter(ServletHandler.java:1634)
solr               |    at
org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:533)
solr               |    at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:146)
solr               |    at
org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:548)
solr               |    at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
solr               |    at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:257)
solr               |    at
org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1595)
solr               |    at
org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:255)
solr               |    at
org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1317)
solr               |    at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:203)
solr               |    at
org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:473)
solr               |    at
org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1564)
solr               |    at
org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:201)
solr               |    at
org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1219)
solr               |    at
org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:144)
solr               |    at
org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:219)
solr               |    at
org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:126)
solr               |    at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
solr               |    at
org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:335)
solr               |    at
org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:132)
solr               |    at
org.eclipse.jetty.server.Server.handle(Server.java:531)
solr               |    at
org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:352)
solr               |    at
org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:260)
solr               |    at
org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:281)
solr               |    at
org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:102)
solr               |    at
org.eclipse.jetty.io.ChannelEndPoint$2.run(ChannelEndPoint.java:118)
solr               |    at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.runTask(EatWhatYouKill.java:333)
solr               |    at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.doProduce(EatWhatYouKill.java:310)
solr               |    at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.tryProduce(EatWhatYouKill.java:168)
solr               |    at
org.eclipse.jetty.util.thread.strategy.EatWhatYouKill.run(EatWhatYouKill.java:126)
solr               |    at
org.eclipse.jetty.util.thread.ReservedThreadExecutor$ReservedThread.run(ReservedThreadExecutor.java:366)
solr               |    at
org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:762)
solr               |    at
org.eclipse.jetty.util.thread.QueuedThreadPool$2.run(QueuedThreadPool.java:680)
solr               |    at java.lang.Thread.run(Thread.java:748)


But I'm not sure why it can't locate the core, because it's there in
${SOLR_HOME} and also exists on hdfs...

Thanks!

Kyle



On Wed, 5 Dec 2018 at 13:12, lstusr 5u93n4 <[hidden email]> wrote:

> Hi Kevin,
>
> We do have logs. Grepping for peersync, I can see
>
> solr               | 2018-12-05 03:31:41.301 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/]
> nUpdates=100
> solr               | 2018-12-05 03:31:41.307 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> versions.  sync failed.
> solr               | 2018-12-05 03:31:44.007 INFO
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node4.metaonly01.eca.local:8983/solr/iglshistory_shard2_replica_n6/]
> nUpdates=100
> solr               | 2018-12-05 03:31:44.008 INFO
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> versions.  sync failed.
> solr               | 2018-12-05 05:48:44.202 INFO
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> core=igls_shard1_replica_n1 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/]
> nUpdates=100
> solr               | 2018-12-05 05:48:44.646 WARN
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> core=igls_shard1_replica_n1 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  got a 503 from
> http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/,
> counting as success
> solr               | 2018-12-05 05:48:44.682 INFO
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> core=igls_shard1_replica_n1 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync succeeded
> solr               | 2018-12-05 05:51:18.369 INFO  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> nUpdates=100
> solr               | 2018-12-05 06:01:18.496 WARN  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> Replica did not return a fingerprint - possibly an older Solr version or
> exception
> solr               | 2018-12-05 06:01:31.126 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy Attempting
> to PeerSync from [
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> - recoveringAfterStartup=[true]
> solr               | 2018-12-05 06:01:31.129 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> nUpdates=100
> solr               | 2018-12-05 06:11:18.535 WARN  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  exception talking to
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/,
> failed
> solr               | 2018-12-05 06:11:18.583 INFO  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> solr               |    at
> org.apache.solr.update.PeerSyncWithLeader.request(PeerSyncWithLeader.java:321)
> solr               |    at
> org.apache.solr.update.PeerSyncWithLeader.alreadyInSync(PeerSyncWithLeader.java:341)
> solr               |    at
> org.apache.solr.update.PeerSyncWithLeader.sync(PeerSyncWithLeader.java:135)
> solr               | 2018-12-05 09:21:31.831 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy Attempting
> to PeerSync from [
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> - recoveringAfterStartup=[true]
> solr               | 2018-12-05 09:21:31.831 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> nUpdates=100
> solr               | 2018-12-05 12:28:26.698 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> Fingerprint comparison result: 1
> solr               | 2018-12-05 12:28:26.698 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> fingerprint: {maxVersionSpecified=9223372036854775807,
> maxVersionEncountered=1619003108526915584, maxInHash=1619003108526915584,
> versionsHash=-2647181038600325382, numVersions=701868706,
> numDocs=701868706, maxDoc=13478974}, Our fingerprint:
> {maxVersionSpecified=9223372036854775807,
> maxVersionEncountered=1618994939968880640, maxInHash=1618994939968880640,
> versionsHash=-2861577316323569427, numVersions=701868706,
> numDocs=701868706, maxDoc=13478974}
> solr               | 2018-12-05 12:30:38.183 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> fingerprint {maxVersionSpecified=9223372036854775807,
> maxVersionEncountered=1619014810634027008, maxInHash=1619014810634027008,
> versionsHash=-5367247708654169186, numVersions=701868706,
> numDocs=701868706, maxDoc=13478974}
> solr               | 2018-12-05 12:30:38.183 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  Received 13 versions
> from
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> solr               | 2018-12-05 12:30:38.184 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync PeerSync:
> core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  Our versions are too
> old. ourHighThreshold=1618976334275411968
> otherLowThreshold=1619012608476577792 ourHighest=1619014810634027008
> otherHighest=1619014936356192256
> solr               | 2018-12-05 12:30:38.185 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> solr               | 2018-12-05 12:30:38.185 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy PeerSync
> Recovery was not successful - trying replication.
>
>
>
> Expanding one of them, we have:
>
>
> solr               | 2018-12-05 03:31:39.421 INFO
> (AutoscalingActionExecutor-8-thread-1) [   ] o.a.s.c.a.ExecutePlanAction No
> operations to execute for event: {
> solr               |   "id":"11402ae38efc8T1dr1vcl6ut11qh9fq6ncle94t",
> solr               |   "source":".auto_add_replicas",
> solr               |   "eventTime":303476722167752,
> solr               |   "eventType":"NODELOST",
> solr               |   "properties":{
> solr               |     "eventTimes":[303476722167752],
> solr               |     "preferredOperation":"movereplica",
> solr               |     "_enqueue_time_":303959110445696,
> solr               |
>  "nodeNames":["solr.node4.metaonly01.eca.local:8983_solr"]}}
> solr               | 2018-12-05 03:31:41.290 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu
> e.
> solr               | 2018-12-05 03:31:41.291 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an
> d sync
> solr               | 2018-12-05 03:31:41.291 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.c.SyncStrategy Sync replicas to http://solr.node2.metaonly01.
> eca.local:8983/solr/iglshistory_shard3_replica_n10/
> solr               | 2018-12-05 03:31:41.301 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/]
> nUpdates=100
> solr               | 2018-12-05 03:31:41.307 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> versions.  sync failed.
>
>
> Not quite sure why it would be executing the auto-add-replicas trigger
> since it's definitely set to false on the collection. (I checked).  Also,
> this log comes from very early in the startup procedure, probably before
> solr has been launched on the other servers.
>
>
>
> Kyle
>
> On Wed, 5 Dec 2018 at 12:58, Kevin Risden <[hidden email]> wrote:
>
>> Do you have logs right before the following?
>>
>> "we notice that the nodes go into "Recovering" state for about 10-12 hours
>> before finally coming alive."
>>
>> Is there a peersync failure or something else in the logs indicating why
>> there is a full recovery?
>>
>> Kevin Risden
>>
>>
>> On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]>
>> wrote:
>>
>> > Hi All,
>> >
>> > We have a collection:
>> >   - solr 7.5
>> >   - 3 shards, replication factor 2 for a total of 6 NRT replicas
>> >   - 3 servers, 16GB ram each
>> >   - 2 billion documents
>> >   - autoAddReplicas: false
>> >   - 2.1 TB on-disk index size
>> >   - index stored on hdfs on separate servers.
>> >
>> > If we (gracefully) shut down solr on all 3 servers, when we re-launch
>> solr
>> > we notice that the nodes go into "Recovering" state for about 10-12
>> hours
>> > before finally coming alive.
>> >
>> > During this recovery time, we notice high network traffic outbound from
>> our
>> > HDFS servers to our solr servers. The sum total of which is roughly
>> > equivalent to the index size on disk.
>> >
>> > So it seems to us that on startup, solr has to re-read the entire index
>> > before coming back alive.
>> >
>> > 1. is this assumption correct?
>> > 2. is there any way to mitigate this, so that solr can launch faster?
>> >
>> > Thanks!
>> >
>> > Kyle
>> >
>>
>
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

Erick Erickson
In reply to this post by lstusr 5u93n4
Solr should _not_ have to replicate the index or go into peer sync on startup.

> are you stopping indexing before you shut your servers down?

> Be very sure you have passed your autocommit interval after you've stopped indexing and before you stop Solr.

> How are you shutting down? bin/solr stop is the proper way, and you should NOT be seeing any kind of message about force killing the Solr process. There are timeouts in solr.in.sh (unix) that you can lengthen if you are seeing any message about force killing.

> Bring all the nodes back up before you start indexing again.

With the above, you should not see peer sync on startup. Of course you
have to have all your Solr nodes in the "active" state before shutting
down.

 That said, some observations:

> your indexes are very large. Very very large  given your hardware. You have roughly 700M docs per replica,  I'm not quite sure whether your 2.1T is aggregate across all 6 replicas or not. Even if so (and that's the best case), each replica is roughly 350G in size.You have, at best, 700G per server trying to run with 16G of RAM. This is extremely undersized in my experience.

> I suspect you're hitting a lot of GC. What kind of GC observations have you made?

> I would turn off autoscaling, your index sizes and hardware are too small to even consider automatically moving that much data around.

In summary, this seems on the surface to be an extremely undersized
system, and unless and until you properly size it you'll have problems

Best,
Erick
On Wed, Dec 5, 2018 at 10:12 AM lstusr 5u93n4 <[hidden email]> wrote:

>
> Hi Kevin,
>
> We do have logs. Grepping for peersync, I can see
>
> solr               | 2018-12-05 03:31:41.301 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/]
> nUpdates=100
> solr               | 2018-12-05 03:31:41.307 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> versions.  sync failed.
> solr               | 2018-12-05 03:31:44.007 INFO
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node4.metaonly01.eca.local:8983/solr/iglshistory_shard2_replica_n6/]
> nUpdates=100
> solr               | 2018-12-05 03:31:44.008 INFO
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> versions.  sync failed.
> solr               | 2018-12-05 05:48:44.202 INFO
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> core=igls_shard1_replica_n1 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/]
> nUpdates=100
> solr               | 2018-12-05 05:48:44.646 WARN
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> core=igls_shard1_replica_n1 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  got a 503 from
> http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/,
> counting as success
> solr               | 2018-12-05 05:48:44.682 INFO
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> core=igls_shard1_replica_n1 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync succeeded
> solr               | 2018-12-05 05:51:18.369 INFO  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> nUpdates=100
> solr               | 2018-12-05 06:01:18.496 WARN  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> Replica did not return a fingerprint - possibly an older Solr version or
> exception
> solr               | 2018-12-05 06:01:31.126 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy Attempting
> to PeerSync from [
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/] -
> recoveringAfterStartup=[true]
> solr               | 2018-12-05 06:01:31.129 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> nUpdates=100
> solr               | 2018-12-05 06:11:18.535 WARN  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  exception talking to
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/,
> failed
> solr               | 2018-12-05 06:11:18.583 INFO  (qtp2131952342-10232)
> [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> solr               |    at
> org.apache.solr.update.PeerSyncWithLeader.request(PeerSyncWithLeader.java:321)
> solr               |    at
> org.apache.solr.update.PeerSyncWithLeader.alreadyInSync(PeerSyncWithLeader.java:341)
> solr               |    at
> org.apache.solr.update.PeerSyncWithLeader.sync(PeerSyncWithLeader.java:135)
> solr               | 2018-12-05 09:21:31.831 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy Attempting
> to PeerSync from [
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/] -
> recoveringAfterStartup=[true]
> solr               | 2018-12-05 09:21:31.831 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> nUpdates=100
> solr               | 2018-12-05 12:28:26.698 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> Fingerprint comparison result: 1
> solr               | 2018-12-05 12:28:26.698 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> fingerprint: {maxVersionSpecified=9223372036854775807,
> maxVersionEncountered=1619003108526915584, maxInHash=1619003108526915584,
> versionsHash=-2647181038600325382, numVersions=701868706,
> numDocs=701868706, maxDoc=13478974}, Our fingerprint:
> {maxVersionSpecified=9223372036854775807,
> maxVersionEncountered=1618994939968880640, maxInHash=1618994939968880640,
> versionsHash=-2861577316323569427, numVersions=701868706,
> numDocs=701868706, maxDoc=13478974}
> solr               | 2018-12-05 12:30:38.183 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> fingerprint {maxVersionSpecified=9223372036854775807,
> maxVersionEncountered=1619014810634027008, maxInHash=1619014810634027008,
> versionsHash=-5367247708654169186, numVersions=701868706,
> numDocs=701868706, maxDoc=13478974}
> solr               | 2018-12-05 12:30:38.183 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  Received 13 versions from
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> solr               | 2018-12-05 12:30:38.184 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync PeerSync:
> core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr  Our versions are too old.
> ourHighThreshold=1618976334275411968 otherLowThreshold=1619012608476577792
> ourHighest=1619014810634027008 otherHighest=1619014936356192256
> solr               | 2018-12-05 12:30:38.185 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> PeerSync: core=igls_shard2_replica_n6 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> solr               | 2018-12-05 12:30:38.185 INFO
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy PeerSync
> Recovery was not successful - trying replication.
>
>
>
> Expanding one of them, we have:
>
>
> solr               | 2018-12-05 03:31:39.421 INFO
> (AutoscalingActionExecutor-8-thread-1) [   ] o.a.s.c.a.ExecutePlanAction No
> operations to execute for event: {
> solr               |   "id":"11402ae38efc8T1dr1vcl6ut11qh9fq6ncle94t",
> solr               |   "source":".auto_add_replicas",
> solr               |   "eventTime":303476722167752,
> solr               |   "eventType":"NODELOST",
> solr               |   "properties":{
> solr               |     "eventTimes":[303476722167752],
> solr               |     "preferredOperation":"movereplica",
> solr               |     "_enqueue_time_":303959110445696,
> solr               |
>  "nodeNames":["solr.node4.metaonly01.eca.local:8983_solr"]}}
> solr               | 2018-12-05 03:31:41.290 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu
> e.
> solr               | 2018-12-05 03:31:41.291 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an
> d sync
> solr               | 2018-12-05 03:31:41.291 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.c.SyncStrategy Sync replicas to http://solr.node2.metaonly01.
> eca.local:8983/solr/iglshistory_shard3_replica_n10/
> solr               | 2018-12-05 03:31:41.301 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/]
> nUpdates=100
> solr               | 2018-12-05 03:31:41.307 INFO
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> versions.  sync failed.
>
>
> Not quite sure why it would be executing the auto-add-replicas trigger
> since it's definitely set to false on the collection. (I checked).  Also,
> this log comes from very early in the startup procedure, probably before
> solr has been launched on the other servers.
>
>
>
> Kyle
>
> On Wed, 5 Dec 2018 at 12:58, Kevin Risden <[hidden email]> wrote:
>
> > Do you have logs right before the following?
> >
> > "we notice that the nodes go into "Recovering" state for about 10-12 hours
> > before finally coming alive."
> >
> > Is there a peersync failure or something else in the logs indicating why
> > there is a full recovery?
> >
> > Kevin Risden
> >
> >
> > On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]> wrote:
> >
> > > Hi All,
> > >
> > > We have a collection:
> > >   - solr 7.5
> > >   - 3 shards, replication factor 2 for a total of 6 NRT replicas
> > >   - 3 servers, 16GB ram each
> > >   - 2 billion documents
> > >   - autoAddReplicas: false
> > >   - 2.1 TB on-disk index size
> > >   - index stored on hdfs on separate servers.
> > >
> > > If we (gracefully) shut down solr on all 3 servers, when we re-launch
> > solr
> > > we notice that the nodes go into "Recovering" state for about 10-12 hours
> > > before finally coming alive.
> > >
> > > During this recovery time, we notice high network traffic outbound from
> > our
> > > HDFS servers to our solr servers. The sum total of which is roughly
> > > equivalent to the index size on disk.
> > >
> > > So it seems to us that on startup, solr has to re-read the entire index
> > > before coming back alive.
> > >
> > > 1. is this assumption correct?
> > > 2. is there any way to mitigate this, so that solr can launch faster?
> > >
> > > Thanks!
> > >
> > > Kyle
> > >
> >
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

lstusr 5u93n4
Hey Erick,

Some thoughts:

Solr should _not_ have to replicate the index or go into peer sync on
> startup.
>

Okay, that's good to know! Tells us that this is a problem that can be
solved.


>
> > are you stopping indexing before you shut your servers down?
>

By indexing, you mean adding new entries to solr, right? We havent'
explicity stopped it, but it's very quiet (rate of 1 doc / minute).


>
> > Be very sure you have passed your autocommit interval after you've
> stopped indexing and before you stop Solr.
>

This we have not done... Autocommit is set fairly long on our system (5
mins) I'll do another test where I completely quiesce first.


>
> > How are you shutting down? bin/solr stop is the proper way, and you
> should NOT be seeing any kind of message about force killing the Solr
> process. There are timeouts in solr.in.sh (unix) that you can lengthen if
> you are seeing any message about force killing.
>

Nothing about force killing shows up in the logs, but I'll extend the
timeouts anyways and monitor the next shutdown (yes with bin/solr stop).
One thought: could it be that we're waiting TOO LONG between stopping the
solr processes on the different servers? Like by killing it on server 1,
we're causing servers 2 and 3 to go into a non-stable state? So they're not
perfectly "green" at the time of shutdown?


>
> > Bring all the nodes back up before you start indexing again.
>

if an entry were to trickle in before the last node were online, this could
cause the behaviour?  I'll block it anyways and see.


>
> With the above, you should not see peer sync on startup. Of course you
> have to have all your Solr nodes in the "active" state before shutting
> down.
>
>  That said, some observations:
>
> > your indexes are very large. Very very large  given your hardware. You
> have roughly 700M docs per replica,  I'm not quite sure whether your 2.1T
> is aggregate across all 6 replicas or not. Even if so (and that's the best
> case), each replica is roughly 350G in size.You have, at best, 700G per
> server trying to run with 16G of RAM. This is extremely undersized in my
> experience.
>

Your math is good. :D The replicas range between 337G and 355G in size.
That said, I'm curious as to why you say this is undersized. We're
optimized for index speed, not query speed. Based on the amount of data we
want to hold, we have to accept the fact that the full index will not fit
in RAM. (We're not going to provision 2-3T of RAM on the servers...) We
also have unpredictable query patterns, so we don't benefit much by
caching. Some data will have to be read from disk on nearly every query.
The queries on this system DO take a little bit long (like 10 seconds or
so, up to 100 seconds at the worst) but that's acceptable for our use
case.  Resource-wise, each server has 6GB allocated for solr's jvm, and
we're not pushing that beyond about 50% utilization (jvm memory usage
hovers around 3G, typically.) So, do we really gain anything by adding more
hardware?


>
> > I suspect you're hitting a lot of GC. What kind of GC observations have
> you made?
>

None, yet. Given that the jvm isn't pushing its limits, we haven't profiled
the GC. We will one day, certainly, to squeeze more performance out of the
system, but haven't gone down that road so far.


>
> > I would turn off autoscaling, your index sizes and hardware are too
> small to even consider automatically moving that much data around.
>

Yeah, absolutely. We explicity set autoAddReplicas to false on the
collection, and we have no other triggers setup.

Anyways, I'll report back with some findings, after the system comes back
online and I can kill it again. :D

Thanks for all your help!


>
> In summary, this seems on the surface to be an extremely undersized
> system, and unless and until you properly size it you'll have problems
>
> Best,
> Erick
> On Wed, Dec 5, 2018 at 10:12 AM lstusr 5u93n4 <[hidden email]> wrote:
> >
> > Hi Kevin,
> >
> > We do have logs. Grepping for peersync, I can see
> >
> > solr               | 2018-12-05 03:31:41.301 INFO
> >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> >
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> ]
> > nUpdates=100
> > solr               | 2018-12-05 03:31:41.307 INFO
> >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > versions.  sync failed.
> > solr               | 2018-12-05 03:31:44.007 INFO
> >
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> >
> http://solr.node4.metaonly01.eca.local:8983/solr/iglshistory_shard2_replica_n6/
> ]
> > nUpdates=100
> > solr               | 2018-12-05 03:31:44.008 INFO
> >
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > versions.  sync failed.
> > solr               | 2018-12-05 05:48:44.202 INFO
> >
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > core=igls_shard1_replica_n1 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> ]
> > nUpdates=100
> > solr               | 2018-12-05 05:48:44.646 WARN
> >
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > core=igls_shard1_replica_n1 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr  got a 503 from
> > http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> ,
> > counting as success
> > solr               | 2018-12-05 05:48:44.682 INFO
> >
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > core=igls_shard1_replica_n1 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync succeeded
> > solr               | 2018-12-05 05:51:18.369 INFO  (qtp2131952342-10232)
> > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > PeerSync: core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> ]
> > nUpdates=100
> > solr               | 2018-12-05 06:01:18.496 WARN  (qtp2131952342-10232)
> > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > Replica did not return a fingerprint - possibly an older Solr version or
> > exception
> > solr               | 2018-12-05 06:01:31.126 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> Attempting
> > to PeerSync from [
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> -
> > recoveringAfterStartup=[true]
> > solr               | 2018-12-05 06:01:31.129 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > PeerSync: core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > nUpdates=100
> > solr               | 2018-12-05 06:11:18.535 WARN  (qtp2131952342-10232)
> > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > PeerSync: core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr  exception talking to
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> ,
> > failed
> > solr               | 2018-12-05 06:11:18.583 INFO  (qtp2131952342-10232)
> > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > PeerSync: core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > solr               |    at
> >
> org.apache.solr.update.PeerSyncWithLeader.request(PeerSyncWithLeader.java:321)
> > solr               |    at
> >
> org.apache.solr.update.PeerSyncWithLeader.alreadyInSync(PeerSyncWithLeader.java:341)
> > solr               |    at
> >
> org.apache.solr.update.PeerSyncWithLeader.sync(PeerSyncWithLeader.java:135)
> > solr               | 2018-12-05 09:21:31.831 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> Attempting
> > to PeerSync from [
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> -
> > recoveringAfterStartup=[true]
> > solr               | 2018-12-05 09:21:31.831 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > PeerSync: core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > nUpdates=100
> > solr               | 2018-12-05 12:28:26.698 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > Fingerprint comparison result: 1
> > solr               | 2018-12-05 12:28:26.698 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> > fingerprint: {maxVersionSpecified=9223372036854775807,
> > maxVersionEncountered=1619003108526915584, maxInHash=1619003108526915584,
> > versionsHash=-2647181038600325382, numVersions=701868706,
> > numDocs=701868706, maxDoc=13478974}, Our fingerprint:
> > {maxVersionSpecified=9223372036854775807,
> > maxVersionEncountered=1618994939968880640, maxInHash=1618994939968880640,
> > versionsHash=-2861577316323569427, numVersions=701868706,
> > numDocs=701868706, maxDoc=13478974}
> > solr               | 2018-12-05 12:30:38.183 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> > fingerprint {maxVersionSpecified=9223372036854775807,
> > maxVersionEncountered=1619014810634027008, maxInHash=1619014810634027008,
> > versionsHash=-5367247708654169186, numVersions=701868706,
> > numDocs=701868706, maxDoc=13478974}
> > solr               | 2018-12-05 12:30:38.183 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > PeerSync: core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr  Received 13 versions
> from
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > solr               | 2018-12-05 12:30:38.184 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync PeerSync:
> > core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr  Our versions are too
> old.
> > ourHighThreshold=1618976334275411968
> otherLowThreshold=1619012608476577792
> > ourHighest=1619014810634027008 otherHighest=1619014936356192256
> > solr               | 2018-12-05 12:30:38.185 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > PeerSync: core=igls_shard2_replica_n6 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > solr               | 2018-12-05 12:30:38.185 INFO
> >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy PeerSync
> > Recovery was not successful - trying replication.
> >
> >
> >
> > Expanding one of them, we have:
> >
> >
> > solr               | 2018-12-05 03:31:39.421 INFO
> > (AutoscalingActionExecutor-8-thread-1) [   ] o.a.s.c.a.ExecutePlanAction
> No
> > operations to execute for event: {
> > solr               |   "id":"11402ae38efc8T1dr1vcl6ut11qh9fq6ncle94t",
> > solr               |   "source":".auto_add_replicas",
> > solr               |   "eventTime":303476722167752,
> > solr               |   "eventType":"NODELOST",
> > solr               |   "properties":{
> > solr               |     "eventTimes":[303476722167752],
> > solr               |     "preferredOperation":"movereplica",
> > solr               |     "_enqueue_time_":303959110445696,
> > solr               |
> >  "nodeNames":["solr.node4.metaonly01.eca.local:8983_solr"]}}
> > solr               | 2018-12-05 03:31:41.290 INFO
> >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu
> > e.
> > solr               | 2018-12-05 03:31:41.291 INFO
> >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an
> > d sync
> > solr               | 2018-12-05 03:31:41.291 INFO
> >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > o.a.s.c.SyncStrategy Sync replicas to http://solr.node2.metaonly01.
> > eca.local:8983/solr/iglshistory_shard3_replica_n10/
> > solr               | 2018-12-05 03:31:41.301 INFO
> >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> >
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> ]
> > nUpdates=100
> > solr               | 2018-12-05 03:31:41.307 INFO
> >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > versions.  sync failed.
> >
> >
> > Not quite sure why it would be executing the auto-add-replicas trigger
> > since it's definitely set to false on the collection. (I checked).  Also,
> > this log comes from very early in the startup procedure, probably before
> > solr has been launched on the other servers.
> >
> >
> >
> > Kyle
> >
> > On Wed, 5 Dec 2018 at 12:58, Kevin Risden <[hidden email]> wrote:
> >
> > > Do you have logs right before the following?
> > >
> > > "we notice that the nodes go into "Recovering" state for about 10-12
> hours
> > > before finally coming alive."
> > >
> > > Is there a peersync failure or something else in the logs indicating
> why
> > > there is a full recovery?
> > >
> > > Kevin Risden
> > >
> > >
> > > On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]>
> wrote:
> > >
> > > > Hi All,
> > > >
> > > > We have a collection:
> > > >   - solr 7.5
> > > >   - 3 shards, replication factor 2 for a total of 6 NRT replicas
> > > >   - 3 servers, 16GB ram each
> > > >   - 2 billion documents
> > > >   - autoAddReplicas: false
> > > >   - 2.1 TB on-disk index size
> > > >   - index stored on hdfs on separate servers.
> > > >
> > > > If we (gracefully) shut down solr on all 3 servers, when we re-launch
> > > solr
> > > > we notice that the nodes go into "Recovering" state for about 10-12
> hours
> > > > before finally coming alive.
> > > >
> > > > During this recovery time, we notice high network traffic outbound
> from
> > > our
> > > > HDFS servers to our solr servers. The sum total of which is roughly
> > > > equivalent to the index size on disk.
> > > >
> > > > So it seems to us that on startup, solr has to re-read the entire
> index
> > > > before coming back alive.
> > > >
> > > > 1. is this assumption correct?
> > > > 2. is there any way to mitigate this, so that solr can launch faster?
> > > >
> > > > Thanks!
> > > >
> > > > Kyle
> > > >
> > >
>
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

Erick Erickson
First, your indexing rate _probably_ isn't the culprit if it's as slow
as you indicate, although testing will tell.

bq. could it be that we're waiting TOO LONG between stopping the solr
processes on the different servers?
At your query rate this is probably not an issue. One thing you might
do is change the updatelog, see
numRecordsToKeep here:
https://lucene.apache.org/solr/guide/7_5/updatehandlers-in-solrconfig.html
This defines how many documents are kept in each replica's transaction
log. When told to recover,
Solr tries first to replay documents in the tlog and if it's not
possible/reasonable then  does the full
recovery (i.e. copies the index from the leader). The default number
is 100, making it 1,000 might help,
especially at your update rate.

I wouldn't bother changing your autocommit interval with an update
rate so low, it's pretty irrelevant.

bq. I'm curious as to why you say this is undersized

Solr is pretty sensitive to GC pauses when it comes to recoveries. One
scenario: ZooKeeper sends a keep-alive to each Solr instance, and when
the response exceeds the timeout, ZK says, in effect, "that node is
dead, when I see it again I'll tell it to recover". Actually, the
leader of that shard will fire a "Leader Initiated Recovery". A
stop-the-world GC pause will trigger this situation if it takes longer
than the timeout. With your index soooo much larger than your RAM, my
first guess would be exactly that. Collect the GC logs and use
something like GCViewer to see....

Another scenario is when the leader sends the doc to the follower, if
the request times out (again possibly due to a stop-the-world GC
pause) the leader, you guessed it, sends the follower into recovery.

You also say that you care most about indexing, now querying and that
querying is unpredictable. That'll drive a lot of swapping and/or GC
and/or....

And once a follower _does_ go into recovery, you'll have some
"interesting" times moving that much data around, contributing to GC
pressure, I/O waits, network saturation leading, possibly, to _more_
recoveries. The fact that it takes 10-12 hours to resync on startup
leads me to question whether your network is slow as well. Admittedly
it's a lot of data, but it's still just a copy operation.

All the above is just things that I've seen go wrong, by no means
exhaustive. I've seen a lot of Solr installations, and never seen  one
be stable with that much disparity  between index size and available
RAM so part of this is "the voice of experience". Whether that
experience is accurate or not is certainly debatable.

Best,
Erick
On Wed, Dec 5, 2018 at 2:02 PM lstusr 5u93n4 <[hidden email]> wrote:

>
> Hey Erick,
>
> Some thoughts:
>
> Solr should _not_ have to replicate the index or go into peer sync on
> > startup.
> >
>
> Okay, that's good to know! Tells us that this is a problem that can be
> solved.
>
>
> >
> > > are you stopping indexing before you shut your servers down?
> >
>
> By indexing, you mean adding new entries to solr, right? We havent'
> explicity stopped it, but it's very quiet (rate of 1 doc / minute).
>
>
> >
> > > Be very sure you have passed your autocommit interval after you've
> > stopped indexing and before you stop Solr.
> >
>
> This we have not done... Autocommit is set fairly long on our system (5
> mins) I'll do another test where I completely quiesce first.
>
>
> >
> > > How are you shutting down? bin/solr stop is the proper way, and you
> > should NOT be seeing any kind of message about force killing the Solr
> > process. There are timeouts in solr.in.sh (unix) that you can lengthen if
> > you are seeing any message about force killing.
> >
>
> Nothing about force killing shows up in the logs, but I'll extend the
> timeouts anyways and monitor the next shutdown (yes with bin/solr stop).
> One thought: could it be that we're waiting TOO LONG between stopping the
> solr processes on the different servers? Like by killing it on server 1,
> we're causing servers 2 and 3 to go into a non-stable state? So they're not
> perfectly "green" at the time of shutdown?
>
>
> >
> > > Bring all the nodes back up before you start indexing again.
> >
>
> if an entry were to trickle in before the last node were online, this could
> cause the behaviour?  I'll block it anyways and see.
>
>
> >
> > With the above, you should not see peer sync on startup. Of course you
> > have to have all your Solr nodes in the "active" state before shutting
> > down.
> >
> >  That said, some observations:
> >
> > > your indexes are very large. Very very large  given your hardware. You
> > have roughly 700M docs per replica,  I'm not quite sure whether your 2.1T
> > is aggregate across all 6 replicas or not. Even if so (and that's the best
> > case), each replica is roughly 350G in size.You have, at best, 700G per
> > server trying to run with 16G of RAM. This is extremely undersized in my
> > experience.
> >
>
> Your math is good. :D The replicas range between 337G and 355G in size.
> That said, I'm curious as to why you say this is undersized. We're
> optimized for index speed, not query speed. Based on the amount of data we
> want to hold, we have to accept the fact that the full index will not fit
> in RAM. (We're not going to provision 2-3T of RAM on the servers...) We
> also have unpredictable query patterns, so we don't benefit much by
> caching. Some data will have to be read from disk on nearly every query.
> The queries on this system DO take a little bit long (like 10 seconds or
> so, up to 100 seconds at the worst) but that's acceptable for our use
> case.  Resource-wise, each server has 6GB allocated for solr's jvm, and
> we're not pushing that beyond about 50% utilization (jvm memory usage
> hovers around 3G, typically.) So, do we really gain anything by adding more
> hardware?
>
>
> >
> > > I suspect you're hitting a lot of GC. What kind of GC observations have
> > you made?
> >
>
> None, yet. Given that the jvm isn't pushing its limits, we haven't profiled
> the GC. We will one day, certainly, to squeeze more performance out of the
> system, but haven't gone down that road so far.
>
>
> >
> > > I would turn off autoscaling, your index sizes and hardware are too
> > small to even consider automatically moving that much data around.
> >
>
> Yeah, absolutely. We explicity set autoAddReplicas to false on the
> collection, and we have no other triggers setup.
>
> Anyways, I'll report back with some findings, after the system comes back
> online and I can kill it again. :D
>
> Thanks for all your help!
>
>
> >
> > In summary, this seems on the surface to be an extremely undersized
> > system, and unless and until you properly size it you'll have problems
> >
> > Best,
> > Erick
> > On Wed, Dec 5, 2018 at 10:12 AM lstusr 5u93n4 <[hidden email]> wrote:
> > >
> > > Hi Kevin,
> > >
> > > We do have logs. Grepping for peersync, I can see
> > >
> > > solr               | 2018-12-05 03:31:41.301 INFO
> > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> > ]
> > > nUpdates=100
> > > solr               | 2018-12-05 03:31:41.307 INFO
> > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > versions.  sync failed.
> > > solr               | 2018-12-05 03:31:44.007 INFO
> > >
> > (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > >
> > http://solr.node4.metaonly01.eca.local:8983/solr/iglshistory_shard2_replica_n6/
> > ]
> > > nUpdates=100
> > > solr               | 2018-12-05 03:31:44.008 INFO
> > >
> > (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > versions.  sync failed.
> > > solr               | 2018-12-05 05:48:44.202 INFO
> > >
> > (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > core=igls_shard1_replica_n1 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> > ]
> > > nUpdates=100
> > > solr               | 2018-12-05 05:48:44.646 WARN
> > >
> > (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > core=igls_shard1_replica_n1 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr  got a 503 from
> > > http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> > ,
> > > counting as success
> > > solr               | 2018-12-05 05:48:44.682 INFO
> > >
> > (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls s:shard1
> > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > core=igls_shard1_replica_n1 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync succeeded
> > > solr               | 2018-12-05 05:51:18.369 INFO  (qtp2131952342-10232)
> > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > > PeerSync: core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > ]
> > > nUpdates=100
> > > solr               | 2018-12-05 06:01:18.496 WARN  (qtp2131952342-10232)
> > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > > Replica did not return a fingerprint - possibly an older Solr version or
> > > exception
> > > solr               | 2018-12-05 06:01:31.126 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> > Attempting
> > > to PeerSync from [
> > > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> > -
> > > recoveringAfterStartup=[true]
> > > solr               | 2018-12-05 06:01:31.129 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > PeerSync: core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > nUpdates=100
> > > solr               | 2018-12-05 06:11:18.535 WARN  (qtp2131952342-10232)
> > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > > PeerSync: core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr  exception talking to
> > > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > ,
> > > failed
> > > solr               | 2018-12-05 06:11:18.583 INFO  (qtp2131952342-10232)
> > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync
> > > PeerSync: core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > > solr               |    at
> > >
> > org.apache.solr.update.PeerSyncWithLeader.request(PeerSyncWithLeader.java:321)
> > > solr               |    at
> > >
> > org.apache.solr.update.PeerSyncWithLeader.alreadyInSync(PeerSyncWithLeader.java:341)
> > > solr               |    at
> > >
> > org.apache.solr.update.PeerSyncWithLeader.sync(PeerSyncWithLeader.java:135)
> > > solr               | 2018-12-05 09:21:31.831 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> > Attempting
> > > to PeerSync from [
> > > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> > -
> > > recoveringAfterStartup=[true]
> > > solr               | 2018-12-05 09:21:31.831 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > PeerSync: core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > nUpdates=100
> > > solr               | 2018-12-05 12:28:26.698 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > Fingerprint comparison result: 1
> > > solr               | 2018-12-05 12:28:26.698 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> > > fingerprint: {maxVersionSpecified=9223372036854775807,
> > > maxVersionEncountered=1619003108526915584, maxInHash=1619003108526915584,
> > > versionsHash=-2647181038600325382, numVersions=701868706,
> > > numDocs=701868706, maxDoc=13478974}, Our fingerprint:
> > > {maxVersionSpecified=9223372036854775807,
> > > maxVersionEncountered=1618994939968880640, maxInHash=1618994939968880640,
> > > versionsHash=-2861577316323569427, numVersions=701868706,
> > > numDocs=701868706, maxDoc=13478974}
> > > solr               | 2018-12-05 12:30:38.183 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader Leader
> > > fingerprint {maxVersionSpecified=9223372036854775807,
> > > maxVersionEncountered=1619014810634027008, maxInHash=1619014810634027008,
> > > versionsHash=-5367247708654169186, numVersions=701868706,
> > > numDocs=701868706, maxDoc=13478974}
> > > solr               | 2018-12-05 12:30:38.183 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > PeerSync: core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr  Received 13 versions
> > from
> > > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > solr               | 2018-12-05 12:30:38.184 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync PeerSync:
> > > core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr  Our versions are too
> > old.
> > > ourHighThreshold=1618976334275411968
> > otherLowThreshold=1619012608476577792
> > > ourHighest=1619014810634027008 otherHighest=1619014936356192256
> > > solr               | 2018-12-05 12:30:38.185 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > PeerSync: core=igls_shard2_replica_n6 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > > solr               | 2018-12-05 12:30:38.185 INFO
> > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls s:shard2
> > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy PeerSync
> > > Recovery was not successful - trying replication.
> > >
> > >
> > >
> > > Expanding one of them, we have:
> > >
> > >
> > > solr               | 2018-12-05 03:31:39.421 INFO
> > > (AutoscalingActionExecutor-8-thread-1) [   ] o.a.s.c.a.ExecutePlanAction
> > No
> > > operations to execute for event: {
> > > solr               |   "id":"11402ae38efc8T1dr1vcl6ut11qh9fq6ncle94t",
> > > solr               |   "source":".auto_add_replicas",
> > > solr               |   "eventTime":303476722167752,
> > > solr               |   "eventType":"NODELOST",
> > > solr               |   "properties":{
> > > solr               |     "eventTimes":[303476722167752],
> > > solr               |     "preferredOperation":"movereplica",
> > > solr               |     "_enqueue_time_":303959110445696,
> > > solr               |
> > >  "nodeNames":["solr.node4.metaonly01.eca.local:8983_solr"]}}
> > > solr               | 2018-12-05 03:31:41.290 INFO
> > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > > o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu
> > > e.
> > > solr               | 2018-12-05 03:31:41.291 INFO
> > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > > o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an
> > > d sync
> > > solr               | 2018-12-05 03:31:41.291 INFO
> > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > > o.a.s.c.SyncStrategy Sync replicas to http://solr.node2.metaonly01.
> > > eca.local:8983/solr/iglshistory_shard3_replica_n10/
> > > solr               | 2018-12-05 03:31:41.301 INFO
> > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> > ]
> > > nUpdates=100
> > > solr               | 2018-12-05 03:31:41.307 INFO
> > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > [c:iglshistory s:shard3 r:core_node12 x:iglshistory_shard3_replica_n10]
> > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > versions.  sync failed.
> > >
> > >
> > > Not quite sure why it would be executing the auto-add-replicas trigger
> > > since it's definitely set to false on the collection. (I checked).  Also,
> > > this log comes from very early in the startup procedure, probably before
> > > solr has been launched on the other servers.
> > >
> > >
> > >
> > > Kyle
> > >
> > > On Wed, 5 Dec 2018 at 12:58, Kevin Risden <[hidden email]> wrote:
> > >
> > > > Do you have logs right before the following?
> > > >
> > > > "we notice that the nodes go into "Recovering" state for about 10-12
> > hours
> > > > before finally coming alive."
> > > >
> > > > Is there a peersync failure or something else in the logs indicating
> > why
> > > > there is a full recovery?
> > > >
> > > > Kevin Risden
> > > >
> > > >
> > > > On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]>
> > wrote:
> > > >
> > > > > Hi All,
> > > > >
> > > > > We have a collection:
> > > > >   - solr 7.5
> > > > >   - 3 shards, replication factor 2 for a total of 6 NRT replicas
> > > > >   - 3 servers, 16GB ram each
> > > > >   - 2 billion documents
> > > > >   - autoAddReplicas: false
> > > > >   - 2.1 TB on-disk index size
> > > > >   - index stored on hdfs on separate servers.
> > > > >
> > > > > If we (gracefully) shut down solr on all 3 servers, when we re-launch
> > > > solr
> > > > > we notice that the nodes go into "Recovering" state for about 10-12
> > hours
> > > > > before finally coming alive.
> > > > >
> > > > > During this recovery time, we notice high network traffic outbound
> > from
> > > > our
> > > > > HDFS servers to our solr servers. The sum total of which is roughly
> > > > > equivalent to the index size on disk.
> > > > >
> > > > > So it seems to us that on startup, solr has to re-read the entire
> > index
> > > > > before coming back alive.
> > > > >
> > > > > 1. is this assumption correct?
> > > > > 2. is there any way to mitigate this, so that solr can launch faster?
> > > > >
> > > > > Thanks!
> > > > >
> > > > > Kyle
> > > > >
> > > >
> >
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

lstusr 5u93n4
Hi Erick,

First off: " Whether that experience is accurate or not is certainly
debatable."  Just want to acknowledge the work you put in on these forums,
and how much we DO appreciate you helping us out. I've been in this game
long enough to know when listening to the experts is a good thing...  We'll
take all the feedback we can get!

So, wrt the shutdown/restart behaviour, I've deployed a smaller system (2
servers, only 180 documents total, NO indexing), and I can bring it down
and up gracefully. So that's good. I'm going to try a few more things on
the "big system", but I'm a bit limited to how fast I can test there, since
I can really only do one "stop" per day. Currently I'm waiting for the last
replica to recover before killing it again.

So, on to the bigger system:

1. I hear what you're saying about the GC. We'll profile it for sure.

2. The network is not a culprit. We have hbase servers deployed on the same
ESXi hosts that access the same target for HDFS storage. These can (and
regularly do) push up to 2Gb/s easily. Solr never seems to exceed a few
hundred Mb/s.  We've always kind of wondered why, but just assumed that
"that's the way that Solr is." Unconstrained, how much HDFS bandwidth would
you expect that Solr could consume?

3. So, with regards to sizing. I know the answer is always "it depends". I
promise not to hold you to it, but let's say you had similar requirements:
2TB index size, 2 billion documents, HDFS storage, and you care more about
indexing rate than query time. Where would you roughly start, in terms of
resources?

4. I also know there's no silver bullet, but are there any settings that
would be beneficial for us to tweak, that would help to run an index that's
much larger than the available ram?

Thanks,

Kyle




On Thu, 6 Dec 2018 at 12:27, Erick Erickson <[hidden email]> wrote:

> First, your indexing rate _probably_ isn't the culprit if it's as slow
> as you indicate, although testing will tell.
>
> bq. could it be that we're waiting TOO LONG between stopping the solr
> processes on the different servers?
> At your query rate this is probably not an issue. One thing you might
> do is change the updatelog, see
> numRecordsToKeep here:
> https://lucene.apache.org/solr/guide/7_5/updatehandlers-in-solrconfig.html
> This defines how many documents are kept in each replica's transaction
> log. When told to recover,
> Solr tries first to replay documents in the tlog and if it's not
> possible/reasonable then  does the full
> recovery (i.e. copies the index from the leader). The default number
> is 100, making it 1,000 might help,
> especially at your update rate.
>
> I wouldn't bother changing your autocommit interval with an update
> rate so low, it's pretty irrelevant.
>
> bq. I'm curious as to why you say this is undersized
>
> Solr is pretty sensitive to GC pauses when it comes to recoveries. One
> scenario: ZooKeeper sends a keep-alive to each Solr instance, and when
> the response exceeds the timeout, ZK says, in effect, "that node is
> dead, when I see it again I'll tell it to recover". Actually, the
> leader of that shard will fire a "Leader Initiated Recovery". A
> stop-the-world GC pause will trigger this situation if it takes longer
> than the timeout. With your index soooo much larger than your RAM, my
> first guess would be exactly that. Collect the GC logs and use
> something like GCViewer to see....
>
> Another scenario is when the leader sends the doc to the follower, if
> the request times out (again possibly due to a stop-the-world GC
> pause) the leader, you guessed it, sends the follower into recovery.
>
> You also say that you care most about indexing, now querying and that
> querying is unpredictable. That'll drive a lot of swapping and/or GC
> and/or....
>
> And once a follower _does_ go into recovery, you'll have some
> "interesting" times moving that much data around, contributing to GC
> pressure, I/O waits, network saturation leading, possibly, to _more_
> recoveries. The fact that it takes 10-12 hours to resync on startup
> leads me to question whether your network is slow as well. Admittedly
> it's a lot of data, but it's still just a copy operation.
>
> All the above is just things that I've seen go wrong, by no means
> exhaustive. I've seen a lot of Solr installations, and never seen  one
> be stable with that much disparity  between index size and available
> RAM so part of this is "the voice of experience". Whether that
> experience is accurate or not is certainly debatable.
>
> Best,
> Erick
> On Wed, Dec 5, 2018 at 2:02 PM lstusr 5u93n4 <[hidden email]> wrote:
> >
> > Hey Erick,
> >
> > Some thoughts:
> >
> > Solr should _not_ have to replicate the index or go into peer sync on
> > > startup.
> > >
> >
> > Okay, that's good to know! Tells us that this is a problem that can be
> > solved.
> >
> >
> > >
> > > > are you stopping indexing before you shut your servers down?
> > >
> >
> > By indexing, you mean adding new entries to solr, right? We havent'
> > explicity stopped it, but it's very quiet (rate of 1 doc / minute).
> >
> >
> > >
> > > > Be very sure you have passed your autocommit interval after you've
> > > stopped indexing and before you stop Solr.
> > >
> >
> > This we have not done... Autocommit is set fairly long on our system (5
> > mins) I'll do another test where I completely quiesce first.
> >
> >
> > >
> > > > How are you shutting down? bin/solr stop is the proper way, and you
> > > should NOT be seeing any kind of message about force killing the Solr
> > > process. There are timeouts in solr.in.sh (unix) that you can
> lengthen if
> > > you are seeing any message about force killing.
> > >
> >
> > Nothing about force killing shows up in the logs, but I'll extend the
> > timeouts anyways and monitor the next shutdown (yes with bin/solr stop).
> > One thought: could it be that we're waiting TOO LONG between stopping the
> > solr processes on the different servers? Like by killing it on server 1,
> > we're causing servers 2 and 3 to go into a non-stable state? So they're
> not
> > perfectly "green" at the time of shutdown?
> >
> >
> > >
> > > > Bring all the nodes back up before you start indexing again.
> > >
> >
> > if an entry were to trickle in before the last node were online, this
> could
> > cause the behaviour?  I'll block it anyways and see.
> >
> >
> > >
> > > With the above, you should not see peer sync on startup. Of course you
> > > have to have all your Solr nodes in the "active" state before shutting
> > > down.
> > >
> > >  That said, some observations:
> > >
> > > > your indexes are very large. Very very large  given your hardware.
> You
> > > have roughly 700M docs per replica,  I'm not quite sure whether your
> 2.1T
> > > is aggregate across all 6 replicas or not. Even if so (and that's the
> best
> > > case), each replica is roughly 350G in size.You have, at best, 700G per
> > > server trying to run with 16G of RAM. This is extremely undersized in
> my
> > > experience.
> > >
> >
> > Your math is good. :D The replicas range between 337G and 355G in size.
> > That said, I'm curious as to why you say this is undersized. We're
> > optimized for index speed, not query speed. Based on the amount of data
> we
> > want to hold, we have to accept the fact that the full index will not fit
> > in RAM. (We're not going to provision 2-3T of RAM on the servers...) We
> > also have unpredictable query patterns, so we don't benefit much by
> > caching. Some data will have to be read from disk on nearly every query.
> > The queries on this system DO take a little bit long (like 10 seconds or
> > so, up to 100 seconds at the worst) but that's acceptable for our use
> > case.  Resource-wise, each server has 6GB allocated for solr's jvm, and
> > we're not pushing that beyond about 50% utilization (jvm memory usage
> > hovers around 3G, typically.) So, do we really gain anything by adding
> more
> > hardware?
> >
> >
> > >
> > > > I suspect you're hitting a lot of GC. What kind of GC observations
> have
> > > you made?
> > >
> >
> > None, yet. Given that the jvm isn't pushing its limits, we haven't
> profiled
> > the GC. We will one day, certainly, to squeeze more performance out of
> the
> > system, but haven't gone down that road so far.
> >
> >
> > >
> > > > I would turn off autoscaling, your index sizes and hardware are too
> > > small to even consider automatically moving that much data around.
> > >
> >
> > Yeah, absolutely. We explicity set autoAddReplicas to false on the
> > collection, and we have no other triggers setup.
> >
> > Anyways, I'll report back with some findings, after the system comes back
> > online and I can kill it again. :D
> >
> > Thanks for all your help!
> >
> >
> > >
> > > In summary, this seems on the surface to be an extremely undersized
> > > system, and unless and until you properly size it you'll have problems
> > >
> > > Best,
> > > Erick
> > > On Wed, Dec 5, 2018 at 10:12 AM lstusr 5u93n4 <[hidden email]>
> wrote:
> > > >
> > > > Hi Kevin,
> > > >
> > > > We do have logs. Grepping for peersync, I can see
> > > >
> > > > solr               | 2018-12-05 03:31:41.301 INFO
> > > >
> > >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > [c:iglshistory s:shard3 r:core_node12
> x:iglshistory_shard3_replica_n10]
> > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > >
> > >
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> > > ]
> > > > nUpdates=100
> > > > solr               | 2018-12-05 03:31:41.307 INFO
> > > >
> > >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > [c:iglshistory s:shard3 r:core_node12
> x:iglshistory_shard3_replica_n10]
> > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > > versions.  sync failed.
> > > > solr               | 2018-12-05 03:31:44.007 INFO
> > > >
> > >
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > > > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > >
> > >
> http://solr.node4.metaonly01.eca.local:8983/solr/iglshistory_shard2_replica_n6/
> > > ]
> > > > nUpdates=100
> > > > solr               | 2018-12-05 03:31:44.008 INFO
> > > >
> > >
> (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > > > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > > versions.  sync failed.
> > > > solr               | 2018-12-05 05:48:44.202 INFO
> > > >
> > >
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls
> s:shard1
> > > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > > core=igls_shard1_replica_n1 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > >
> http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> > > ]
> > > > nUpdates=100
> > > > solr               | 2018-12-05 05:48:44.646 WARN
> > > >
> > >
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls
> s:shard1
> > > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > > core=igls_shard1_replica_n1 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr  got a 503 from
> > > >
> http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> > > ,
> > > > counting as success
> > > > solr               | 2018-12-05 05:48:44.682 INFO
> > > >
> > >
> (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls
> s:shard1
> > > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > > core=igls_shard1_replica_n1 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync
> succeeded
> > > > solr               | 2018-12-05 05:51:18.369 INFO
> (qtp2131952342-10232)
> > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> o.a.s.u.PeerSync
> > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > >
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > ]
> > > > nUpdates=100
> > > > solr               | 2018-12-05 06:01:18.496 WARN
> (qtp2131952342-10232)
> > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> o.a.s.u.PeerSync
> > > > Replica did not return a fingerprint - possibly an older Solr
> version or
> > > > exception
> > > > solr               | 2018-12-05 06:01:31.126 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> > > Attempting
> > > > to PeerSync from [
> > > >
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> > > -
> > > > recoveringAfterStartup=[true]
> > > > solr               | 2018-12-05 06:01:31.129 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > > >
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > nUpdates=100
> > > > solr               | 2018-12-05 06:11:18.535 WARN
> (qtp2131952342-10232)
> > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> o.a.s.u.PeerSync
> > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr  exception talking
> to
> > > >
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > ,
> > > > failed
> > > > solr               | 2018-12-05 06:11:18.583 INFO
> (qtp2131952342-10232)
> > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> o.a.s.u.PeerSync
> > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > > > solr               |    at
> > > >
> > >
> org.apache.solr.update.PeerSyncWithLeader.request(PeerSyncWithLeader.java:321)
> > > > solr               |    at
> > > >
> > >
> org.apache.solr.update.PeerSyncWithLeader.alreadyInSync(PeerSyncWithLeader.java:341)
> > > > solr               |    at
> > > >
> > >
> org.apache.solr.update.PeerSyncWithLeader.sync(PeerSyncWithLeader.java:135)
> > > > solr               | 2018-12-05 09:21:31.831 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> > > Attempting
> > > > to PeerSync from [
> > > >
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> > > -
> > > > recoveringAfterStartup=[true]
> > > > solr               | 2018-12-05 09:21:31.831 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > > >
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > nUpdates=100
> > > > solr               | 2018-12-05 12:28:26.698 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > Fingerprint comparison result: 1
> > > > solr               | 2018-12-05 12:28:26.698 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> Leader
> > > > fingerprint: {maxVersionSpecified=9223372036854775807,
> > > > maxVersionEncountered=1619003108526915584,
> maxInHash=1619003108526915584,
> > > > versionsHash=-2647181038600325382, numVersions=701868706,
> > > > numDocs=701868706, maxDoc=13478974}, Our fingerprint:
> > > > {maxVersionSpecified=9223372036854775807,
> > > > maxVersionEncountered=1618994939968880640,
> maxInHash=1618994939968880640,
> > > > versionsHash=-2861577316323569427, numVersions=701868706,
> > > > numDocs=701868706, maxDoc=13478974}
> > > > solr               | 2018-12-05 12:30:38.183 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> Leader
> > > > fingerprint {maxVersionSpecified=9223372036854775807,
> > > > maxVersionEncountered=1619014810634027008,
> maxInHash=1619014810634027008,
> > > > versionsHash=-5367247708654169186, numVersions=701868706,
> > > > numDocs=701868706, maxDoc=13478974}
> > > > solr               | 2018-12-05 12:30:38.183 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr  Received 13
> versions
> > > from
> > > >
> http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > solr               | 2018-12-05 12:30:38.184 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync PeerSync:
> > > > core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr  Our versions are
> too
> > > old.
> > > > ourHighThreshold=1618976334275411968
> > > otherLowThreshold=1619012608476577792
> > > > ourHighest=1619014810634027008 otherHighest=1619014936356192256
> > > > solr               | 2018-12-05 12:30:38.185 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > > > solr               | 2018-12-05 12:30:38.185 INFO
> > > >
> > >
> (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> s:shard2
> > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> PeerSync
> > > > Recovery was not successful - trying replication.
> > > >
> > > >
> > > >
> > > > Expanding one of them, we have:
> > > >
> > > >
> > > > solr               | 2018-12-05 03:31:39.421 INFO
> > > > (AutoscalingActionExecutor-8-thread-1) [   ]
> o.a.s.c.a.ExecutePlanAction
> > > No
> > > > operations to execute for event: {
> > > > solr               |
>  "id":"11402ae38efc8T1dr1vcl6ut11qh9fq6ncle94t",
> > > > solr               |   "source":".auto_add_replicas",
> > > > solr               |   "eventTime":303476722167752,
> > > > solr               |   "eventType":"NODELOST",
> > > > solr               |   "properties":{
> > > > solr               |     "eventTimes":[303476722167752],
> > > > solr               |     "preferredOperation":"movereplica",
> > > > solr               |     "_enqueue_time_":303959110445696,
> > > > solr               |
> > > >  "nodeNames":["solr.node4.metaonly01.eca.local:8983_solr"]}}
> > > > solr               | 2018-12-05 03:31:41.290 INFO
> > > >
> > >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > [c:iglshistory s:shard3 r:core_node12
> x:iglshistory_shard3_replica_n10]
> > > > o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu
> > > > e.
> > > > solr               | 2018-12-05 03:31:41.291 INFO
> > > >
> > >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > [c:iglshistory s:shard3 r:core_node12
> x:iglshistory_shard3_replica_n10]
> > > > o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an
> > > > d sync
> > > > solr               | 2018-12-05 03:31:41.291 INFO
> > > >
> > >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > [c:iglshistory s:shard3 r:core_node12
> x:iglshistory_shard3_replica_n10]
> > > > o.a.s.c.SyncStrategy Sync replicas to http://solr.node2.metaonly01.
> > > > eca.local:8983/solr/iglshistory_shard3_replica_n10/
> > > > solr               | 2018-12-05 03:31:41.301 INFO
> > > >
> > >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > [c:iglshistory s:shard3 r:core_node12
> x:iglshistory_shard3_replica_n10]
> > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > >
> > >
> http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> > > ]
> > > > nUpdates=100
> > > > solr               | 2018-12-05 03:31:41.307 INFO
> > > >
> > >
> (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > [c:iglshistory s:shard3 r:core_node12
> x:iglshistory_shard3_replica_n10]
> > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > > versions.  sync failed.
> > > >
> > > >
> > > > Not quite sure why it would be executing the auto-add-replicas
> trigger
> > > > since it's definitely set to false on the collection. (I checked).
> Also,
> > > > this log comes from very early in the startup procedure, probably
> before
> > > > solr has been launched on the other servers.
> > > >
> > > >
> > > >
> > > > Kyle
> > > >
> > > > On Wed, 5 Dec 2018 at 12:58, Kevin Risden <[hidden email]>
> wrote:
> > > >
> > > > > Do you have logs right before the following?
> > > > >
> > > > > "we notice that the nodes go into "Recovering" state for about
> 10-12
> > > hours
> > > > > before finally coming alive."
> > > > >
> > > > > Is there a peersync failure or something else in the logs
> indicating
> > > why
> > > > > there is a full recovery?
> > > > >
> > > > > Kevin Risden
> > > > >
> > > > >
> > > > > On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]
> >
> > > wrote:
> > > > >
> > > > > > Hi All,
> > > > > >
> > > > > > We have a collection:
> > > > > >   - solr 7.5
> > > > > >   - 3 shards, replication factor 2 for a total of 6 NRT replicas
> > > > > >   - 3 servers, 16GB ram each
> > > > > >   - 2 billion documents
> > > > > >   - autoAddReplicas: false
> > > > > >   - 2.1 TB on-disk index size
> > > > > >   - index stored on hdfs on separate servers.
> > > > > >
> > > > > > If we (gracefully) shut down solr on all 3 servers, when we
> re-launch
> > > > > solr
> > > > > > we notice that the nodes go into "Recovering" state for about
> 10-12
> > > hours
> > > > > > before finally coming alive.
> > > > > >
> > > > > > During this recovery time, we notice high network traffic
> outbound
> > > from
> > > > > our
> > > > > > HDFS servers to our solr servers. The sum total of which is
> roughly
> > > > > > equivalent to the index size on disk.
> > > > > >
> > > > > > So it seems to us that on startup, solr has to re-read the entire
> > > index
> > > > > > before coming back alive.
> > > > > >
> > > > > > 1. is this assumption correct?
> > > > > > 2. is there any way to mitigate this, so that solr can launch
> faster?
> > > > > >
> > > > > > Thanks!
> > > > > >
> > > > > > Kyle
> > > > > >
> > > > >
> > >
>
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

Erick Erickson
bq: The network is not a culprit. We have hbase servers deployed on the same
ESXi hosts that access the same target for HDFS storage. These can (and
regularly do) push up to 2Gb/s easily

Let's assume you're moving 350G, that's still almost 3 minutes. Times
however many
replicas need to do a full recovery. Which may well get in the way of
other requests
etc. Point is that kind of data movement doesn't _help_ stability when timeouts
are something Solr is sensitive to....

And you're saying 10-12 hours to recover, so that doesn't square either.

re: sizing. Somebody wrote this blog:
https://lucidworks.com/2012/07/23/sizing-hardware-in-the-abstract-why-we-dont-have-a-definitive-answer/

You've said a couple of times that you care about indexing, but not
query response
much. Here's the trap: _Indexing_ doesn't take much memory. The memory
is bounded
by ramBufferSizeMB, which defaults to 100. So you can merrily index
and index and index
and memory stays reasonable _until_ the first query comes along. At
that point a bunch of
heap may be allocated and lots of data is required to be memory mapped, see:
http://blog.thetaphi.de/2012/07/use-lucenes-mmapdirectory-on-64bit.html

So you're indexing merrily along and then a query comes in. and blows
things out of the water.
You simply cannot be confident that your system is sized correctly
unless you're both querying
and indexing at the same time. It's not necessary to throw queries at
Solr at a furious rate, but
the system requirements can change drastically due to querying. And
the queries _must_ be
"real". One example: Let's say you sort on field X. At that point, either
1> an on-heap structure will be built containing the values (assuming
you don't have docValues enabled for that field)
or
2> the field will need to be memory-resident in the OS memory space
(see Uwe's blog).

Either way, with 16G of memory and 700M documents, I expect Bad Things
start to happen.

So I'd strongly recommend you use some load tester tool to be querying
at the same time you're indexing, I'd
guess things will go unstable very quickly.

As for size, I've seen 20M docs require 32G+ heaps. I've seen 300M
docs get by on 12G. The first blog I
referenced outlines how to stress test your hardware to destruction to
see what the limits of your hardware are.

As for settings, you can lengthen all sorts of timeouts, but that's a
band-aid if your hardware is incorrectly sized.

The numRecordsToKeep in your update log can help with recoveries, but
that's a bandaid too.

Best,
Erick
On Thu, Dec 6, 2018 at 1:20 PM lstusr 5u93n4 <[hidden email]> wrote:

>
> Hi Erick,
>
> First off: " Whether that experience is accurate or not is certainly
> debatable."  Just want to acknowledge the work you put in on these forums,
> and how much we DO appreciate you helping us out. I've been in this game
> long enough to know when listening to the experts is a good thing...  We'll
> take all the feedback we can get!
>
> So, wrt the shutdown/restart behaviour, I've deployed a smaller system (2
> servers, only 180 documents total, NO indexing), and I can bring it down
> and up gracefully. So that's good. I'm going to try a few more things on
> the "big system", but I'm a bit limited to how fast I can test there, since
> I can really only do one "stop" per day. Currently I'm waiting for the last
> replica to recover before killing it again.
>
> So, on to the bigger system:
>
> 1. I hear what you're saying about the GC. We'll profile it for sure.
>
> 2. The network is not a culprit. We have hbase servers deployed on the same
> ESXi hosts that access the same target for HDFS storage. These can (and
> regularly do) push up to 2Gb/s easily. Solr never seems to exceed a few
> hundred Mb/s.  We've always kind of wondered why, but just assumed that
> "that's the way that Solr is." Unconstrained, how much HDFS bandwidth would
> you expect that Solr could consume?
>
> 3. So, with regards to sizing. I know the answer is always "it depends". I
> promise not to hold you to it, but let's say you had similar requirements:
> 2TB index size, 2 billion documents, HDFS storage, and you care more about
> indexing rate than query time. Where would you roughly start, in terms of
> resources?
>
> 4. I also know there's no silver bullet, but are there any settings that
> would be beneficial for us to tweak, that would help to run an index that's
> much larger than the available ram?
>
> Thanks,
>
> Kyle
>
>
>
>
> On Thu, 6 Dec 2018 at 12:27, Erick Erickson <[hidden email]> wrote:
>
> > First, your indexing rate _probably_ isn't the culprit if it's as slow
> > as you indicate, although testing will tell.
> >
> > bq. could it be that we're waiting TOO LONG between stopping the solr
> > processes on the different servers?
> > At your query rate this is probably not an issue. One thing you might
> > do is change the updatelog, see
> > numRecordsToKeep here:
> > https://lucene.apache.org/solr/guide/7_5/updatehandlers-in-solrconfig.html
> > This defines how many documents are kept in each replica's transaction
> > log. When told to recover,
> > Solr tries first to replay documents in the tlog and if it's not
> > possible/reasonable then  does the full
> > recovery (i.e. copies the index from the leader). The default number
> > is 100, making it 1,000 might help,
> > especially at your update rate.
> >
> > I wouldn't bother changing your autocommit interval with an update
> > rate so low, it's pretty irrelevant.
> >
> > bq. I'm curious as to why you say this is undersized
> >
> > Solr is pretty sensitive to GC pauses when it comes to recoveries. One
> > scenario: ZooKeeper sends a keep-alive to each Solr instance, and when
> > the response exceeds the timeout, ZK says, in effect, "that node is
> > dead, when I see it again I'll tell it to recover". Actually, the
> > leader of that shard will fire a "Leader Initiated Recovery". A
> > stop-the-world GC pause will trigger this situation if it takes longer
> > than the timeout. With your index soooo much larger than your RAM, my
> > first guess would be exactly that. Collect the GC logs and use
> > something like GCViewer to see....
> >
> > Another scenario is when the leader sends the doc to the follower, if
> > the request times out (again possibly due to a stop-the-world GC
> > pause) the leader, you guessed it, sends the follower into recovery.
> >
> > You also say that you care most about indexing, now querying and that
> > querying is unpredictable. That'll drive a lot of swapping and/or GC
> > and/or....
> >
> > And once a follower _does_ go into recovery, you'll have some
> > "interesting" times moving that much data around, contributing to GC
> > pressure, I/O waits, network saturation leading, possibly, to _more_
> > recoveries. The fact that it takes 10-12 hours to resync on startup
> > leads me to question whether your network is slow as well. Admittedly
> > it's a lot of data, but it's still just a copy operation.
> >
> > All the above is just things that I've seen go wrong, by no means
> > exhaustive. I've seen a lot of Solr installations, and never seen  one
> > be stable with that much disparity  between index size and available
> > RAM so part of this is "the voice of experience". Whether that
> > experience is accurate or not is certainly debatable.
> >
> > Best,
> > Erick
> > On Wed, Dec 5, 2018 at 2:02 PM lstusr 5u93n4 <[hidden email]> wrote:
> > >
> > > Hey Erick,
> > >
> > > Some thoughts:
> > >
> > > Solr should _not_ have to replicate the index or go into peer sync on
> > > > startup.
> > > >
> > >
> > > Okay, that's good to know! Tells us that this is a problem that can be
> > > solved.
> > >
> > >
> > > >
> > > > > are you stopping indexing before you shut your servers down?
> > > >
> > >
> > > By indexing, you mean adding new entries to solr, right? We havent'
> > > explicity stopped it, but it's very quiet (rate of 1 doc / minute).
> > >
> > >
> > > >
> > > > > Be very sure you have passed your autocommit interval after you've
> > > > stopped indexing and before you stop Solr.
> > > >
> > >
> > > This we have not done... Autocommit is set fairly long on our system (5
> > > mins) I'll do another test where I completely quiesce first.
> > >
> > >
> > > >
> > > > > How are you shutting down? bin/solr stop is the proper way, and you
> > > > should NOT be seeing any kind of message about force killing the Solr
> > > > process. There are timeouts in solr.in.sh (unix) that you can
> > lengthen if
> > > > you are seeing any message about force killing.
> > > >
> > >
> > > Nothing about force killing shows up in the logs, but I'll extend the
> > > timeouts anyways and monitor the next shutdown (yes with bin/solr stop).
> > > One thought: could it be that we're waiting TOO LONG between stopping the
> > > solr processes on the different servers? Like by killing it on server 1,
> > > we're causing servers 2 and 3 to go into a non-stable state? So they're
> > not
> > > perfectly "green" at the time of shutdown?
> > >
> > >
> > > >
> > > > > Bring all the nodes back up before you start indexing again.
> > > >
> > >
> > > if an entry were to trickle in before the last node were online, this
> > could
> > > cause the behaviour?  I'll block it anyways and see.
> > >
> > >
> > > >
> > > > With the above, you should not see peer sync on startup. Of course you
> > > > have to have all your Solr nodes in the "active" state before shutting
> > > > down.
> > > >
> > > >  That said, some observations:
> > > >
> > > > > your indexes are very large. Very very large  given your hardware.
> > You
> > > > have roughly 700M docs per replica,  I'm not quite sure whether your
> > 2.1T
> > > > is aggregate across all 6 replicas or not. Even if so (and that's the
> > best
> > > > case), each replica is roughly 350G in size.You have, at best, 700G per
> > > > server trying to run with 16G of RAM. This is extremely undersized in
> > my
> > > > experience.
> > > >
> > >
> > > Your math is good. :D The replicas range between 337G and 355G in size.
> > > That said, I'm curious as to why you say this is undersized. We're
> > > optimized for index speed, not query speed. Based on the amount of data
> > we
> > > want to hold, we have to accept the fact that the full index will not fit
> > > in RAM. (We're not going to provision 2-3T of RAM on the servers...) We
> > > also have unpredictable query patterns, so we don't benefit much by
> > > caching. Some data will have to be read from disk on nearly every query.
> > > The queries on this system DO take a little bit long (like 10 seconds or
> > > so, up to 100 seconds at the worst) but that's acceptable for our use
> > > case.  Resource-wise, each server has 6GB allocated for solr's jvm, and
> > > we're not pushing that beyond about 50% utilization (jvm memory usage
> > > hovers around 3G, typically.) So, do we really gain anything by adding
> > more
> > > hardware?
> > >
> > >
> > > >
> > > > > I suspect you're hitting a lot of GC. What kind of GC observations
> > have
> > > > you made?
> > > >
> > >
> > > None, yet. Given that the jvm isn't pushing its limits, we haven't
> > profiled
> > > the GC. We will one day, certainly, to squeeze more performance out of
> > the
> > > system, but haven't gone down that road so far.
> > >
> > >
> > > >
> > > > > I would turn off autoscaling, your index sizes and hardware are too
> > > > small to even consider automatically moving that much data around.
> > > >
> > >
> > > Yeah, absolutely. We explicity set autoAddReplicas to false on the
> > > collection, and we have no other triggers setup.
> > >
> > > Anyways, I'll report back with some findings, after the system comes back
> > > online and I can kill it again. :D
> > >
> > > Thanks for all your help!
> > >
> > >
> > > >
> > > > In summary, this seems on the surface to be an extremely undersized
> > > > system, and unless and until you properly size it you'll have problems
> > > >
> > > > Best,
> > > > Erick
> > > > On Wed, Dec 5, 2018 at 10:12 AM lstusr 5u93n4 <[hidden email]>
> > wrote:
> > > > >
> > > > > Hi Kevin,
> > > > >
> > > > > We do have logs. Grepping for peersync, I can see
> > > > >
> > > > > solr               | 2018-12-05 03:31:41.301 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > > [c:iglshistory s:shard3 r:core_node12
> > x:iglshistory_shard3_replica_n10]
> > > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > > >
> > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> > > > ]
> > > > > nUpdates=100
> > > > > solr               | 2018-12-05 03:31:41.307 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > > [c:iglshistory s:shard3 r:core_node12
> > x:iglshistory_shard3_replica_n10]
> > > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > > > versions.  sync failed.
> > > > > solr               | 2018-12-05 03:31:44.007 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > > > > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > > >
> > > >
> > http://solr.node4.metaonly01.eca.local:8983/solr/iglshistory_shard2_replica_n6/
> > > > ]
> > > > > nUpdates=100
> > > > > solr               | 2018-12-05 03:31:44.008 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:iglshistory_shard2_replica_n4 c:iglshistory s:shard2 r:core_node7)
> > > > > [c:iglshistory s:shard2 r:core_node7 x:iglshistory_shard2_replica_n4]
> > > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard2_replica_n4 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > > > versions.  sync failed.
> > > > > solr               | 2018-12-05 05:48:44.202 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls
> > s:shard1
> > > > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > > > core=igls_shard1_replica_n1 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > > >
> > http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> > > > ]
> > > > > nUpdates=100
> > > > > solr               | 2018-12-05 05:48:44.646 WARN
> > > > >
> > > >
> > (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls
> > s:shard1
> > > > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > > > core=igls_shard1_replica_n1 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr  got a 503 from
> > > > >
> > http://solr.node4.metaonly01.eca.local:8983/solr/igls_shard1_replica_n2/
> > > > ,
> > > > > counting as success
> > > > > solr               | 2018-12-05 05:48:44.682 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-3-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard1_replica_n1 c:igls s:shard1 r:core_node3) [c:igls
> > s:shard1
> > > > > r:core_node3 x:igls_shard1_replica_n1] o.a.s.u.PeerSync PeerSync:
> > > > > core=igls_shard1_replica_n1 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync
> > succeeded
> > > > > solr               | 2018-12-05 05:51:18.369 INFO
> > (qtp2131952342-10232)
> > > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> > o.a.s.u.PeerSync
> > > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > ]
> > > > > nUpdates=100
> > > > > solr               | 2018-12-05 06:01:18.496 WARN
> > (qtp2131952342-10232)
> > > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> > o.a.s.u.PeerSync
> > > > > Replica did not return a fingerprint - possibly an older Solr
> > version or
> > > > > exception
> > > > > solr               | 2018-12-05 06:01:31.126 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> > > > Attempting
> > > > > to PeerSync from [
> > > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> > > > -
> > > > > recoveringAfterStartup=[true]
> > > > > solr               | 2018-12-05 06:01:31.129 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > > nUpdates=100
> > > > > solr               | 2018-12-05 06:11:18.535 WARN
> > (qtp2131952342-10232)
> > > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> > o.a.s.u.PeerSync
> > > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr  exception talking
> > to
> > > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > ,
> > > > > failed
> > > > > solr               | 2018-12-05 06:11:18.583 INFO
> > (qtp2131952342-10232)
> > > > > [c:igls s:shard2 r:core_node9 x:igls_shard2_replica_n6]
> > o.a.s.u.PeerSync
> > > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > > > > solr               |    at
> > > > >
> > > >
> > org.apache.solr.update.PeerSyncWithLeader.request(PeerSyncWithLeader.java:321)
> > > > > solr               |    at
> > > > >
> > > >
> > org.apache.solr.update.PeerSyncWithLeader.alreadyInSync(PeerSyncWithLeader.java:341)
> > > > > solr               |    at
> > > > >
> > > >
> > org.apache.solr.update.PeerSyncWithLeader.sync(PeerSyncWithLeader.java:135)
> > > > > solr               | 2018-12-05 09:21:31.831 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> > > > Attempting
> > > > > to PeerSync from [
> > > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/]
> > > > -
> > > > > recoveringAfterStartup=[true]
> > > > > solr               | 2018-12-05 09:21:31.831 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr START leader=
> > > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > > nUpdates=100
> > > > > solr               | 2018-12-05 12:28:26.698 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > > Fingerprint comparison result: 1
> > > > > solr               | 2018-12-05 12:28:26.698 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > Leader
> > > > > fingerprint: {maxVersionSpecified=9223372036854775807,
> > > > > maxVersionEncountered=1619003108526915584,
> > maxInHash=1619003108526915584,
> > > > > versionsHash=-2647181038600325382, numVersions=701868706,
> > > > > numDocs=701868706, maxDoc=13478974}, Our fingerprint:
> > > > > {maxVersionSpecified=9223372036854775807,
> > > > > maxVersionEncountered=1618994939968880640,
> > maxInHash=1618994939968880640,
> > > > > versionsHash=-2861577316323569427, numVersions=701868706,
> > > > > numDocs=701868706, maxDoc=13478974}
> > > > > solr               | 2018-12-05 12:30:38.183 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > Leader
> > > > > fingerprint {maxVersionSpecified=9223372036854775807,
> > > > > maxVersionEncountered=1619014810634027008,
> > maxInHash=1619014810634027008,
> > > > > versionsHash=-5367247708654169186, numVersions=701868706,
> > > > > numDocs=701868706, maxDoc=13478974}
> > > > > solr               | 2018-12-05 12:30:38.183 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr  Received 13
> > versions
> > > > from
> > > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/igls_shard2_replica_n4/
> > > > > solr               | 2018-12-05 12:30:38.184 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSync PeerSync:
> > > > > core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr  Our versions are
> > too
> > > > old.
> > > > > ourHighThreshold=1618976334275411968
> > > > otherLowThreshold=1619012608476577792
> > > > > ourHighest=1619014810634027008 otherHighest=1619014936356192256
> > > > > solr               | 2018-12-05 12:30:38.185 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.u.PeerSyncWithLeader
> > > > > PeerSync: core=igls_shard2_replica_n6 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE. sync failed
> > > > > solr               | 2018-12-05 12:30:38.185 INFO
> > > > >
> > > >
> > (recoveryExecutor-4-thread-1-processing-n:solr.node2.metaonly01.eca.local:8983_solr
> > > > > x:igls_shard2_replica_n6 c:igls s:shard2 r:core_node9) [c:igls
> > s:shard2
> > > > > r:core_node9 x:igls_shard2_replica_n6] o.a.s.c.RecoveryStrategy
> > PeerSync
> > > > > Recovery was not successful - trying replication.
> > > > >
> > > > >
> > > > >
> > > > > Expanding one of them, we have:
> > > > >
> > > > >
> > > > > solr               | 2018-12-05 03:31:39.421 INFO
> > > > > (AutoscalingActionExecutor-8-thread-1) [   ]
> > o.a.s.c.a.ExecutePlanAction
> > > > No
> > > > > operations to execute for event: {
> > > > > solr               |
> >  "id":"11402ae38efc8T1dr1vcl6ut11qh9fq6ncle94t",
> > > > > solr               |   "source":".auto_add_replicas",
> > > > > solr               |   "eventTime":303476722167752,
> > > > > solr               |   "eventType":"NODELOST",
> > > > > solr               |   "properties":{
> > > > > solr               |     "eventTimes":[303476722167752],
> > > > > solr               |     "preferredOperation":"movereplica",
> > > > > solr               |     "_enqueue_time_":303959110445696,
> > > > > solr               |
> > > > >  "nodeNames":["solr.node4.metaonly01.eca.local:8983_solr"]}}
> > > > > solr               | 2018-12-05 03:31:41.290 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > > [c:iglshistory s:shard3 r:core_node12
> > x:iglshistory_shard3_replica_n10]
> > > > > o.a.s.c.ShardLeaderElectionContext Enough replicas found to continu
> > > > > e.
> > > > > solr               | 2018-12-05 03:31:41.291 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > > [c:iglshistory s:shard3 r:core_node12
> > x:iglshistory_shard3_replica_n10]
> > > > > o.a.s.c.ShardLeaderElectionContext I may be the new leader - try an
> > > > > d sync
> > > > > solr               | 2018-12-05 03:31:41.291 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > > [c:iglshistory s:shard3 r:core_node12
> > x:iglshistory_shard3_replica_n10]
> > > > > o.a.s.c.SyncStrategy Sync replicas to http://solr.node2.metaonly01.
> > > > > eca.local:8983/solr/iglshistory_shard3_replica_n10/
> > > > > solr               | 2018-12-05 03:31:41.301 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > > [c:iglshistory s:shard3 r:core_node12
> > x:iglshistory_shard3_replica_n10]
> > > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr START replicas=[
> > > > >
> > > >
> > http://solr.node3.metaonly01.eca.local:8983/solr/iglshistory_shard3_replica_n8/
> > > > ]
> > > > > nUpdates=100
> > > > > solr               | 2018-12-05 03:31:41.307 INFO
> > > > >
> > > >
> > (coreZkRegister-1-thread-2-processing-n:solr.node2.metaonly01.eca.local:8983_solr)
> > > > > [c:iglshistory s:shard3 r:core_node12
> > x:iglshistory_shard3_replica_n10]
> > > > > o.a.s.u.PeerSync PeerSync: core=iglshistory_shard3_replica_n10 url=
> > > > > http://solr.node2.metaonly01.eca.local:8983/solr DONE.  We have no
> > > > > versions.  sync failed.
> > > > >
> > > > >
> > > > > Not quite sure why it would be executing the auto-add-replicas
> > trigger
> > > > > since it's definitely set to false on the collection. (I checked).
> > Also,
> > > > > this log comes from very early in the startup procedure, probably
> > before
> > > > > solr has been launched on the other servers.
> > > > >
> > > > >
> > > > >
> > > > > Kyle
> > > > >
> > > > > On Wed, 5 Dec 2018 at 12:58, Kevin Risden <[hidden email]>
> > wrote:
> > > > >
> > > > > > Do you have logs right before the following?
> > > > > >
> > > > > > "we notice that the nodes go into "Recovering" state for about
> > 10-12
> > > > hours
> > > > > > before finally coming alive."
> > > > > >
> > > > > > Is there a peersync failure or something else in the logs
> > indicating
> > > > why
> > > > > > there is a full recovery?
> > > > > >
> > > > > > Kevin Risden
> > > > > >
> > > > > >
> > > > > > On Wed, Dec 5, 2018 at 12:53 PM lstusr 5u93n4 <[hidden email]
> > >
> > > > wrote:
> > > > > >
> > > > > > > Hi All,
> > > > > > >
> > > > > > > We have a collection:
> > > > > > >   - solr 7.5
> > > > > > >   - 3 shards, replication factor 2 for a total of 6 NRT replicas
> > > > > > >   - 3 servers, 16GB ram each
> > > > > > >   - 2 billion documents
> > > > > > >   - autoAddReplicas: false
> > > > > > >   - 2.1 TB on-disk index size
> > > > > > >   - index stored on hdfs on separate servers.
> > > > > > >
> > > > > > > If we (gracefully) shut down solr on all 3 servers, when we
> > re-launch
> > > > > > solr
> > > > > > > we notice that the nodes go into "Recovering" state for about
> > 10-12
> > > > hours
> > > > > > > before finally coming alive.
> > > > > > >
> > > > > > > During this recovery time, we notice high network traffic
> > outbound
> > > > from
> > > > > > our
> > > > > > > HDFS servers to our solr servers. The sum total of which is
> > roughly
> > > > > > > equivalent to the index size on disk.
> > > > > > >
> > > > > > > So it seems to us that on startup, solr has to re-read the entire
> > > > index
> > > > > > > before coming back alive.
> > > > > > >
> > > > > > > 1. is this assumption correct?
> > > > > > > 2. is there any way to mitigate this, so that solr can launch
> > faster?
> > > > > > >
> > > > > > > Thanks!
> > > > > > >
> > > > > > > Kyle
> > > > > > >
> > > > > >
> > > >
> >
Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

Shawn Heisey-2
On 12/7/2018 8:54 AM, Erick Erickson wrote:
> Here's the trap:_Indexing_  doesn't take much memory. The memory
> is bounded
> by ramBufferSizeMB, which defaults to 100.

This statement is completely true.  But it hides one detail:  A large
amount of indexing will allocate this buffer repeatedly.  So although
indexing doesn't take a huge amount of memory space at any given moment,
the amount of total memory allocated by large indexing will be enormous,
keeping the garbage collector busy.  This is particularly true when
segment merging happens.

Going over the whole thread:

Graceful shutdown on Solr 7.5 (for non-Windows operating systems) should
allow up to three minutes for Solr to shut down normally before it
hard-kills the instance.  On Windows it only waits 5 seconds, which is
not enough.  What OS is it on?

The problems you've described do sound like your Solr instances are
experiencing massive GC pauses.  This can make *ALL* Solr activity take
a long time, including index recovery operations.  Increasing the heap
size MIGHT alleviate these problems.

If every machine is handling 700GB of index data and 1.4 billion docs
(assuming one third of the 2.1 billion docs per shard replica, two
replicas per machine), you're going to need a lot of heap memory for
Solr to run well.  With your indexes in HDFS, the HDFS software running
inside Solr also needs heap memory to operate, and is probably going to
set aside part of the heap for caching purposes.  I thought I saw
something in the thread about a 6GB heap size.  This is probably way too
small.   For everything you've described, I have to agree with Erick ...
16GB total memory is VERY undersized.  It's likely unrealistic to have
enough memory for the whole index ... but for this setup, I'd definitely
want a LOT more than 16GB.

As Solr runs, it writes a GC log.  Can you share all of the GC log files
that Solr has created?  There should not be any proprietary information
in those files.

Thanks,
Shawn

Reply | Threaded
Open this post in threaded view
|

Re: solr reads whole index on startup

lstusr 5u93n4
Hi Guys,

>  What OS is it on?
CentOS 7

>  With your indexes in HDFS, the HDFS software running
> inside Solr also needs heap memory to operate, and is probably going to
> set aside part of the heap for caching purposes.
We still have the solr.hdfs.blockcache.slab.count parameter set to the
default of 1, but we're going to tune this a bit and see what happens.

> but for this setup, I'd definitely want a LOT more than 16GB.GB
So where would you start? We can easily double the number of servers to 6,
and put one replica on each (probably going to do this anyways.)  Would you
go bigger than 6 x 16GB ? Keeping in mind, even with our little 3 x 16GB we
haven't had performance problems... This thread kind of diverged that way,
but really the initial issue was just that the whole index seems to be read
on startup. (Which I fully understand may be resource related, but I have
yet to try reproduce on a smaller scale to confirm/deny.)

> As Solr runs, it writes a GC log.  Can you share all of the GC log files
> that Solr has created?  There should not be any proprietary information
> in those files.

This I can do. Actually, I've collected a lot of things, redacted any
private info, and collected here into a series of logs / screenshots.

So what I did:
 - 16:49 GMT -- stopped solr on one node (node 4) using bin/solr stop, and
keeping the others alive.. Captured the solr log as it was stopping, and
uploaded here:
     - https://pastebin.com/raw/UhSTdb1h

- 17:00 GMT  - restarted solr on the same node (other two stayed up the
whole time) and let it run for an hour. Captured the solr logs since the
startup here:
    - https://pastebin.com/raw/S4Z9XVrG

 - Observed the outbound network traffic from HDFS to this particular solr
instance during this time, screenshotted it, and put the image here: (times
are in EST for that screenshot)
    - https://imagebin.ca/v/4PY63LAMSVV1

 - Screenshotted the resource usage on the node according to the solr UI:
   - https://imagebin.ca/v/4PY6dYddWGXn

 - Captured the GC logs for the 20 mins after restart, and pasted here:
   - https://pastebin.com/raw/piswTy1M

Some notes:
 - the main collection (the big one) is called "main"
 - there is an empty collection on the system called "history" but this has
0 documents.
 - I redacted any private info in the logs... if there are inconsistencies
it might be due to this manual process (but I think it's okay)

Thanks!

Kyle







On Mon, 10 Dec 2018 at 12:43, Shawn Heisey <[hidden email]> wrote:

> On 12/7/2018 8:54 AM, Erick Erickson wrote:
> > Here's the trap:_Indexing_  doesn't take much memory. The memory
> > is bounded
> > by ramBufferSizeMB, which defaults to 100.
>
> This statement is completely true.  But it hides one detail:  A large
> amount of indexing will allocate this buffer repeatedly.  So although
> indexing doesn't take a huge amount of memory space at any given moment,
> the amount of total memory allocated by large indexing will be enormous,
> keeping the garbage collector busy.  This is particularly true when
> segment merging happens.
>
> Going over the whole thread:
>
> Graceful shutdown on Solr 7.5 (for non-Windows operating systems) should
> allow up to three minutes for Solr to shut down normally before it
> hard-kills the instance.  On Windows it only waits 5 seconds, which is
> not enough.  What OS is it on?
>
> The problems you've described do sound like your Solr instances are
> experiencing massive GC pauses.  This can make *ALL* Solr activity take
> a long time, including index recovery operations.  Increasing the heap
> size MIGHT alleviate these problems.
>
> If every machine is handling 700GB of index data and 1.4 billion docs
> (assuming one third of the 2.1 billion docs per shard replica, two
> replicas per machine), you're going to need a lot of heap memory for
> Solr to run well.  With your indexes in HDFS, the HDFS software running
> inside Solr also needs heap memory to operate, and is probably going to
> set aside part of the heap for caching purposes.  I thought I saw
> something in the thread about a 6GB heap size.  This is probably way too
> small.   For everything you've described, I have to agree with Erick ...
> 16GB total memory is VERY undersized.  It's likely unrealistic to have
> enough memory for the whole index ... but for this setup, I'd definitely
> want a LOT more than 16GB.
>
> As Solr runs, it writes a GC log.  Can you share all of the GC log files
> that Solr has created?  There should not be any proprietary information
> in those files.
>
> Thanks,
> Shawn
>
>