В некоторых случаях, когда я передаю документ для индексации в Solr, документ не индексируется или индексируется очень поздно.Это происходит с SolrCloud 7.1.0.
Мой случай:
- В 08: 59: 48.157 я добавляю документ A
- В 08: 59: 48.264 я добавляю документ B
- В 09: 00: 19.467 я выполняю запрос, и только документ А. найден.
Это происходит в автоматическом тесте, но не часто воспроизводится.Он работает нормально (и A, и B обнаруживаются) в ~ 90% случаев, а в остальные 10% я не получаю оба документа.
Я настроил autoCommit isдо 15 секунд (openSearcher=false), autoSoftCommit до 1 секунды (я знаю, что это должно быть как можно выше, я собираюсь увеличить это позже).
Я предполагаю, что Solr регистрируется вместе с нимавтоматическое (мягкое) принятие, и я действительно вижу запись в журнал "commitScheduler" потока DirectUpdateHandler2, но он запускается очень редко.Первое вхождение commitScheduler в журнале после добавления обоих документов A и B происходит в 9:00:25, почти через 40 секунд после добавления документов.
Кажется, я получилТакая же проблема при удалении и объекта из индекса.Иногда этого просто не происходит, или, по крайней мере, очень поздно.В журнале отображается сообщение «Удалить», а запрос, выполненный через 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
Кажется, что только тест first иногда дает сбой.Этот тест выполняется сразу после запуска SolrCloud.Я еще не видел, чтобы более поздние тесты провалились.
Буду признателен за любые предложения.