Solr 索引文档很晚
Solr indexes documents very late
在某些情况下，当我将要索引的文档提供给 Solr 时，该文档似乎没有被索引，或者很晚才被索引。 SolrCloud 7.1.0 会发生这种情况。
我的情况：
- 在 08:59:48.157 我添加了一个文档 A
- 在 08:59:48.264 我添加了一个文档 B
- 在 09:00:19.467，我执行了一个查询，并且 仅 找到了文档 A。
这发生在自动化测试中，但不会经常重现。在大约 90% 的情况下它工作正常（A 和 B 都出现），而在另外 10% 的情况下我没有同时获得这两个文件。
我已将 autoCommit 配置为 15 秒（openSearcher=false），autoSoftCommit 为 1 秒（我知道这应该尽可能高，我打算稍后增加）。
我假设 Solr 记录自动（软）提交，我确实看到 "commitScheduler" 线程记录 DirectUpdateHandler2，但是它 运行 很少见。添加文档 A 和 B 后日志中第一次出现 commitScheduler 是在 9:00:25，添加文档后将近 40 秒。
从索引中删除对象时，我似乎遇到了同样的问题。有时它只是没有发生，或者至少很晚才发生。我在日志中看到 "delete" 并且 50 秒后触发的查询仍然产生已删除的对象。
当我将成功 运行 的日志与不成功 运行 的日志进行比较时，我没有发现任何差异。 SolrCloud 日志（不成功 运行）：
2018-09-14 08:59:48.144 INFO (zkCallback-3-thread-4-processing-n:localhost:5100_solr) [ ] o.a.s.s.ZkIndexSchemaReader Finished refreshing schema in 34 ms
2018-09-14 08:59:48.151 INFO (Thread-80) [ ] o.a.s.s.IndexSchema [Cloud_shard1_replica_n1] Schema name=base-schema
2018-09-14 08:59:48.156 INFO (Thread-80) [ ] o.a.s.s.IndexSchema Loaded schema base-schema/1.6 with uniqueid field id
2018-09-14 08:59:48.157 INFO (qtp947679291-17) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [Cloud_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[5f8ecb57-2135-4c26-a9b3-6808531badd0 (1611572799756828672)]} 0 9
2018-09-14 08:59:48.160 INFO (Thread-80) [ ] o.a.s.c.CoreContainer Reloading SolrCore 'Cloud_shard1_replica_n1' using configuration from collection Cloud
2018-09-14 08:59:48.160 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [[Cloud_shard1_replica_n1] ] Opening new SolrCore at [/var/app/current/solr/work/Cloud_shard1_replica_n1], dataDir=[/var/app/current/solr/work/Cloud_shard1_replica_n1/data/]
2018-09-14 08:59:48.181 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.h.a.SystemInfoHandler Resolving canonical hostname for local host prevented due to 'solr.dns.prevent.reverse.lookup' sysprop
2018-09-14 08:59:48.186 WARN (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.RequestHandlers no default request handler is registered (either '/select' or 'standard')
2018-09-14 08:59:48.187 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: if uncommited for 15000ms;
2018-09-14 08:59:48.187 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: if uncommited for 1000ms;
2018-09-14 08:59:48.202 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3844c2e[Cloud_shard1_replica_n1] main]
2018-09-14 08:59:48.203 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/tenant
2018-09-14 08:59:48.203 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/tenant
2018-09-14 08:59:48.203 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/tenant/managed-schema
2018-09-14 08:59:48.204 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.ZkIndexSchemaReader Current schema version 66 is already the latest
2018-09-14 08:59:48.204 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
2018-09-14 08:59:48.204 INFO (searcherExecutor-540-thread-1-processing-n:localhost:5100_solr x:Cloud_shard1_replica_n1 s:shard1 c:Cloud r:core_node2) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [Cloud_shard1_replica_n1] Registered new searcher Searcher@3844c2e[Cloud_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.2.0):C1870) Uninverting(_1(7.2.0):C4) Uninverting(_2(7.2.0):C1)))}
2018-09-14 08:59:48.227 INFO (qtp947679291-15) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
2018-09-14 08:59:48.228 INFO (qtp947679291-15) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
2018-09-14 08:59:48.237 INFO (qtp947679291-15) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.S.Request [Cloud_shard1_replica_n1] webapp=/solr path=/schema/fields params={wt=javabin&version=2} status=0 QTime=0
2018-09-14 08:59:48.252 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
2018-09-14 08:59:48.264 INFO (qtp947679291-15) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [Cloud_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[8e209dd4-03ef-4397-8c6a-b947270af684 (1611572799877414912)]} 0 2
2018-09-14 08:59:48.269 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@73887417[Cloud_shard1_replica_n1] main]
2018-09-14 08:59:48.270 INFO (searcherExecutor-540-thread-1-processing-n:localhost:5100_solr x:Cloud_shard1_replica_n1 s:shard1 c:Cloud r:core_node2) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [Cloud_shard1_replica_n1] Registered new searcher Searcher@73887417[Cloud_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.2.0):C1870) Uninverting(_1(7.2.0):C4) Uninverting(_2(7.2.0):C1)))}
2018-09-14 08:59:48.270 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [Cloud_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@2460d222
2018-09-14 08:59:48.271 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.Cloud.shard1.replica_n1, tag=610325026
2018-09-14 08:59:48.271 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.Cloud.shard1.leader, tag=610325026
2018-09-14 09:00:19.467 INFO (qtp947679291-18) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.S.Request [Cloud_shard1_replica_n1] webapp=/solr path=/query params={q=*&df=_text_&qt=/query&_stateVer_=Cloud:4&fl=id,_displayName&start=0&sort=_displayName+asc&fq=(MY-FQ)&rows=1000&wt=javabin&version=2} hits=1 status=0 QTime=1
似乎只有第一个测试偶尔会失败。此测试在启动 SolrCloud 后立即执行。我还没有看到后面的测试失败。
如有任何建议，我们将不胜感激。
感谢 freenode 上的#solr 人员，找出问题所在。
问题是我们更新了 Solr 模式，然后就为 Solr 提供了新文档。 Solr 显然在更新架构后需要短暂休息，或者配置的自动提交无法正常工作（有人告诉我这可能是 Solr 错误，但我不确定）。也就是说，触发了自动提交，但在某些情况下不会提交第二个文档，而只会提交第一个文档。只有在另一次提交（手动或通过添加另一个文档）之后，第二个文档才真正提交。
我找到了两个可能的修复方法：
- 正在删除架构更新。
- 更新架构后重新加载集合。
在某些情况下，当我将要索引的文档提供给 Solr 时，该文档似乎没有被索引，或者很晚才被索引。 SolrCloud 7.1.0 会发生这种情况。
我的情况：
- 在 08:59:48.157 我添加了一个文档 A
- 在 08:59:48.264 我添加了一个文档 B
- 在 09:00:19.467，我执行了一个查询，并且 仅 找到了文档 A。
这发生在自动化测试中，但不会经常重现。在大约 90% 的情况下它工作正常（A 和 B 都出现），而在另外 10% 的情况下我没有同时获得这两个文件。
我已将 autoCommit 配置为 15 秒（openSearcher=false），autoSoftCommit 为 1 秒（我知道这应该尽可能高，我打算稍后增加）。
我假设 Solr 记录自动（软）提交，我确实看到 "commitScheduler" 线程记录 DirectUpdateHandler2，但是它 运行 很少见。添加文档 A 和 B 后日志中第一次出现 commitScheduler 是在 9:00:25，添加文档后将近 40 秒。
从索引中删除对象时，我似乎遇到了同样的问题。有时它只是没有发生，或者至少很晚才发生。我在日志中看到 "delete" 并且 50 秒后触发的查询仍然产生已删除的对象。
当我将成功 运行 的日志与不成功 运行 的日志进行比较时，我没有发现任何差异。 SolrCloud 日志（不成功 运行）：
2018-09-14 08:59:48.144 INFO (zkCallback-3-thread-4-processing-n:localhost:5100_solr) [ ] o.a.s.s.ZkIndexSchemaReader Finished refreshing schema in 34 ms
2018-09-14 08:59:48.151 INFO (Thread-80) [ ] o.a.s.s.IndexSchema [Cloud_shard1_replica_n1] Schema name=base-schema
2018-09-14 08:59:48.156 INFO (Thread-80) [ ] o.a.s.s.IndexSchema Loaded schema base-schema/1.6 with uniqueid field id
2018-09-14 08:59:48.157 INFO (qtp947679291-17) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [Cloud_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[5f8ecb57-2135-4c26-a9b3-6808531badd0 (1611572799756828672)]} 0 9
2018-09-14 08:59:48.160 INFO (Thread-80) [ ] o.a.s.c.CoreContainer Reloading SolrCore 'Cloud_shard1_replica_n1' using configuration from collection Cloud
2018-09-14 08:59:48.160 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [[Cloud_shard1_replica_n1] ] Opening new SolrCore at [/var/app/current/solr/work/Cloud_shard1_replica_n1], dataDir=[/var/app/current/solr/work/Cloud_shard1_replica_n1/data/]
2018-09-14 08:59:48.181 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.h.a.SystemInfoHandler Resolving canonical hostname for local host prevented due to 'solr.dns.prevent.reverse.lookup' sysprop
2018-09-14 08:59:48.186 WARN (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.RequestHandlers no default request handler is registered (either '/select' or 'standard')
2018-09-14 08:59:48.187 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.CommitTracker Hard AutoCommit: if uncommited for 15000ms;
2018-09-14 08:59:48.187 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.CommitTracker Soft AutoCommit: if uncommited for 1000ms;
2018-09-14 08:59:48.202 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@3844c2e[Cloud_shard1_replica_n1] main]
2018-09-14 08:59:48.203 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Configured ZooKeeperStorageIO with znodeBase: /configs/tenant
2018-09-14 08:59:48.203 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.r.ManagedResourceStorage Loaded null at path _rest_managed.json using ZooKeeperStorageIO:path=/configs/tenant
2018-09-14 08:59:48.203 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.ZkIndexSchemaReader Creating ZooKeeper watch for the managed schema at /configs/tenant/managed-schema
2018-09-14 08:59:48.204 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.ZkIndexSchemaReader Current schema version 66 is already the latest
2018-09-14 08:59:48.204 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.h.ReplicationHandler Commits will be reserved for 10000ms.
2018-09-14 08:59:48.204 INFO (searcherExecutor-540-thread-1-processing-n:localhost:5100_solr x:Cloud_shard1_replica_n1 s:shard1 c:Cloud r:core_node2) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [Cloud_shard1_replica_n1] Registered new searcher Searcher@3844c2e[Cloud_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.2.0):C1870) Uninverting(_1(7.2.0):C4) Uninverting(_2(7.2.0):C1)))}
2018-09-14 08:59:48.227 INFO (qtp947679291-15) [ ] o.a.s.h.a.CollectionsHandler Invoked Collection Action :list with params action=LIST&wt=javabin&version=2 and sendToOCPQueue=true
2018-09-14 08:59:48.228 INFO (qtp947679291-15) [ ] o.a.s.s.HttpSolrCall [admin] webapp=null path=/admin/collections params={action=LIST&wt=javabin&version=2} status=0 QTime=0
2018-09-14 08:59:48.237 INFO (qtp947679291-15) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.S.Request [Cloud_shard1_replica_n1] webapp=/solr path=/schema/fields params={wt=javabin&version=2} status=0 QTime=0
2018-09-14 08:59:48.252 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.DefaultSolrCoreState New IndexWriter is ready to be used.
2018-09-14 08:59:48.264 INFO (qtp947679291-15) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.u.p.LogUpdateProcessorFactory [Cloud_shard1_replica_n1] webapp=/solr path=/update params={wt=javabin&version=2}{add=[8e209dd4-03ef-4397-8c6a-b947270af684 (1611572799877414912)]} 0 2
2018-09-14 08:59:48.269 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.s.SolrIndexSearcher Opening [Searcher@73887417[Cloud_shard1_replica_n1] main]
2018-09-14 08:59:48.270 INFO (searcherExecutor-540-thread-1-processing-n:localhost:5100_solr x:Cloud_shard1_replica_n1 s:shard1 c:Cloud r:core_node2) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [Cloud_shard1_replica_n1] Registered new searcher Searcher@73887417[Cloud_shard1_replica_n1] main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_0(7.2.0):C1870) Uninverting(_1(7.2.0):C4) Uninverting(_2(7.2.0):C1)))}
2018-09-14 08:59:48.270 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.SolrCore [Cloud_shard1_replica_n1] CLOSING SolrCore org.apache.solr.core.SolrCore@2460d222
2018-09-14 08:59:48.271 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.core.Cloud.shard1.replica_n1, tag=610325026
2018-09-14 08:59:48.271 INFO (Thread-80) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.m.SolrMetricManager Closing metric reporters for registry=solr.collection.Cloud.shard1.leader, tag=610325026
2018-09-14 09:00:19.467 INFO (qtp947679291-18) [c:Cloud s:shard1 r:core_node2 x:Cloud_shard1_replica_n1] o.a.s.c.S.Request [Cloud_shard1_replica_n1] webapp=/solr path=/query params={q=*&df=_text_&qt=/query&_stateVer_=Cloud:4&fl=id,_displayName&start=0&sort=_displayName+asc&fq=(MY-FQ)&rows=1000&wt=javabin&version=2} hits=1 status=0 QTime=1
似乎只有第一个测试偶尔会失败。此测试在启动 SolrCloud 后立即执行。我还没有看到后面的测试失败。
如有任何建议，我们将不胜感激。
感谢 freenode 上的#solr 人员，找出问题所在。
问题是我们更新了 Solr 模式，然后就为 Solr 提供了新文档。 Solr 显然在更新架构后需要短暂休息，或者配置的自动提交无法正常工作（有人告诉我这可能是 Solr 错误，但我不确定）。也就是说，触发了自动提交，但在某些情况下不会提交第二个文档，而只会提交第一个文档。只有在另一次提交（手动或通过添加另一个文档）之后，第二个文档才真正提交。
我找到了两个可能的修复方法：
- 正在删除架构更新。
- 更新架构后重新加载集合。