Thanks for letting us know. Yeah, many thousands of fields is an anti-pattern.
At some point I’d like to put in a limit or log warning or something so people
would get warning when something like this happens.
And to make matters more “interesting”, the meta-data associated with the
fields doesn’t go away.. ever. You need to re-index to a new collection.
Certainly the soft commits should be much faster if you re-index without using
a new collection, but there’s still some inefficiencies in the meta-data being
kept.
Best,
Erick
> On Jun 4, 2019, at 1:05 AM, André Widhani <an...@digicol.com> wrote:
>
> almost forgot to report back, maybe it helps somebody else .... it turned
> out to be caused by a feature in our software being used in a way we did
> not anticipate.
>
> That resulted in a lot (> 100.000) of different dynamic fields which
> probably is an anti-pattern on its own, but the slow commits where related
> to the fact that these fields had DocValues. After some profiling, it
> clearly showed a lot of time was spent in FieldInfos' addOrUpdateInternal()
> and related code.
>
> André
>
>
> Am Mi., 22. Mai 2019 um 18:12 Uhr schrieb André Widhani <an...@digicol.com>:
>
>> Hi everyone,
>>
>> I need some advice how to debug slow soft commits.
>>
>> We use Solr for searches in a DAM system and in similar setups, soft
>> commits take about one to two seconds, in this case nearly ten seconds.
>> Solr runs on a dedicated VM with eight cores and 64 GB RAM (16G heap),
>> which is common scenario with our software and the index holds about 20
>> million documents. Queries are as fast as expected.
>>
>> This is Solr 7.5.0, stand-alone, auto hard-commit set to 60 seconds, no
>> explicit soft-commits but documents added with commitWhitin=5000 or 1000
>> depending on the use case. No warm-up queries, caches set to zero.
>>
>> I enabled infostream and debug logging. Here is a little test case where I
>> stopped any other requests to Solr and just manually added a single
>> document and then posted a soft commit request.
>>
>> 2019-05-22 17:19:42.160 INFO (qtp26728049-20)
>> o.a.s.u.DirectUpdateHandler2 start
>> commit{_version_=1634245942610755584,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
>> 2019-05-22 17:19:42.160 DEBUG (qtp26728049-20) o.a.s.u.UpdateLog TLOG:
>> preSoftCommit: prevMap=1930097580 new map=1023061476
>> 2019-05-22 17:19:42.160 DEBUG (qtp26728049-20)
>> o.a.s.c.CachingDirectoryFactory Reusing cached directory:
>> CachedDir<<refCount=1;path=/solr/core-tex73oy02hnxgx1dqc14p5o-index1;done=false>>
>> 2019-05-22 17:19:42.160 DEBUG (qtp26728049-20)
>> o.a.s.c.CachingDirectoryFactory Releasing directory:
>> /solr/core-tex73oy02hnxgx1dqc14p5o-index1 0 false
>> 2019-05-22 17:19:42.160 INFO (qtp26728049-20) o.a.s.u.LoggingInfoStream
>> [DW][qtp26728049-20]: anyChanges? numDocsInRam=1 deletes=true
>> hasTickets:false pendingChangesInFullFlush: false
>> 2019-05-22 17:19:42.160 INFO (qtp26728049-20) o.a.s.u.LoggingInfoStream
>> [IW][qtp26728049-20]: nrtIsCurrent: infoVersion matches: false; DW changes:
>> true; BD changes: false
>> 2019-05-22 17:19:42.160 INFO (qtp26728049-20) o.a.s.u.LoggingInfoStream
>> [IW][qtp26728049-20]: flush at getReader
>> ... a lot of things logged here (omitted) that happen within milli-seconds
>> ...
>> 2019-05-22 17:19:42.168 INFO (qtp26728049-20) o.a.s.u.LoggingInfoStream
>> [IW][qtp26728049-20]: getReader took 8 msec
>> 2019-05-22 17:19:47.499 INFO (qtp26728049-20) o.a.s.s.SolrIndexSearcher
>> Opening [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1] main]
>> 2019-05-22 17:19:47.499 DEBUG (qtp26728049-20)
>> o.a.s.c.CachingDirectoryFactory incRef'ed:
>> CachedDir<<refCount=4;path=/solr/core-tex73oy02hnxgx1dqc14p5o-index1/index;done=false>>
>> 2019-05-22 17:19:50.233 DEBUG (qtp26728049-20) o.a.s.s.SolrIndexSearcher
>> Closing [Searcher@78d9785[core-tex73oy02hnxgx1dqc14p5o-index1] realtime]
>> 2019-05-22 17:19:50.233 INFO (qtp26728049-20) o.a.s.u.LoggingInfoStream
>> [IW][qtp26728049-20]: decRefDeleter for NRT reader version=10560246
>> segments=_22lfz(7.5.0):c1033782/56603:delGen=2772
>> _22lfp(7.5.0):c1025574/39055:delGen=2113
>> _22lfr(7.5.0):c759249/32191:delGen=1386
>> _26q49(7.5.0):c923418/29825:delGen=958
>> _22lfx(7.5.0):c684064/30952:delGen=1098
>> _22lfv(7.5.0):c856317/78777:delGen=928
>> _22lg1(7.5.0):c1062384/188447:delGen=1750
>> _22lg0(7.5.0):c561881/1480:delGen=386
>> _22lg5(7.5.0):c1104218/1004:delGen=139 _22lgh(7.5.0):c1156482/46:delGen=33
>> _22lgf(7.5.0):c626273/27:delGen=19 _22lfy(7.5.0):c697224/6:delGen=6
>> _22lgd(7.5.0):c399283/6:delGen=3 _22lgg(7.5.0):c482373/3:delGen=3
>> _22lg4(7.5.0):c656746/2:delGen=2 _22lgc(7.5.0):c664274/3:delGen=3
>> _22lg7(7.5.0):c703377 _22lfu(7.5.0):c700340/3:delGen=3
>> _22lg2(7.5.0):c743334 _22lg6(7.5.0):c1091387/44659:delGen=946
>> _22lfs(7.5.0):c845018 _22lg8(7.5.0):c675649 _22lg9(7.5.0):c686292
>> _22lft(7.5.0):c636751/1004:delGen=300 _22lgb(7.5.0):c664531
>> _22lga(7.5.0):c647696/1:delGen=1 _22lge(7.5.0):c659794
>> _22lfw(7.5.0):c568537/1:delGen=1 _22lg3(7.5.0):c837568/1426:delGen=423
>> _26r20(7.5.0):c63899/10456:delGen=257 _273qn(7.5.0):c39076/8075:delGen=323
>> _27q6g(7.5.0):c40830/8111:delGen=195 _27aii(7.5.0):c30182/6777:delGen=287
>> _27tkq(7.5.0):c57620/6234:delGen=162 _27jrm(7.5.0):c33298/4797:delGen=202
>> _280zq(7.5.0):c60476/2341:delGen=173 _28h7x(7.5.0):c48570/453:delGen=35
>> _28c75(7.5.0):c29536/1088:delGen=47 _28h71(7.5.0):c1191/138:delGen=5
>> _28idl(7.5.0):c782/57:delGen=6 _28ihc(7.5.0):c5398/348:delGen=9
>> _28ig3(7.5.0):c1118/302:delGen=4 _28j1s(7.5.0):c917/269:delGen=2
>> _28iu9(7.5.0):c758/129:delGen=4 _28j23(7.5.0):c567/70:delGen=2
>> _28j3j(7.5.0):c802/11:delGen=1 _28j3u(7.5.0):c697/11:delGen=2
>> _28iz5(7.5.0):c858/116:delGen=4 _28j2n(7.5.0):c566/78:delGen=1
>> _28j3t(7.5.0):C20/11:delGen=1 _28j3v(7.5.0):C13/8:delGen=1 _28j3y(7.5.0):C1
>> 2019-05-22 17:19:50.234 DEBUG (qtp26728049-20)
>> o.a.s.c.CachingDirectoryFactory Releasing directory:
>> /solr/core-tex73oy02hnxgx1dqc14p5o-index1/index 3 false
>> 2019-05-22 17:19:50.234 INFO (qtp26728049-20)
>> o.a.s.u.DirectUpdateHandler2 end_commit_flush
>> 2019-05-22 17:19:50.234 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ...Uninverting(_28j3z(7.5.0):C1)))}] from
>> [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3y(7.5.0):C1)))}]
>> fieldValueCache{lookups=0, hits=0, cumulative_evictions=0, size=0,
>> hitratio=0.0, evictions=0, cumulative_lookups=0, cumulative_hitratio=0.0,
>> warmupTime=0, inserts=0, cumulative_inserts=0, cumulative_hits=0}
>> 2019-05-22 17:19:50.234 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming result for
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... Uninverting(_28j3z(7.5.0):C1)))}]
>> fieldValueCache
>> 2019-05-22 17:19:50.234 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3z(7.5.0):C1)))}] from
>> [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3y(7.5.0):C1)))}]
>> filterCache{lookups=0, hits=0, cumulative_evictions=0, size=0,
>> hitratio=0.0, evictions=0, cumulative_lookups=0, cumulative_hitratio=0.0,
>> warmupTime=0, inserts=0, cumulative_inserts=0, cumulative_hits=0}
>> 2019-05-22 17:19:50.234 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming result for
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3z(7.5.0):C1)))}]
>> filterCache
>> 2019-05-22 17:19:50.235 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3z(7.5.0):C1)))}] from
>> [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... Uninverting(_28j3y(7.5.0):C1)))}]
>> queryResultCache{lookups=3, hits=2, cumulative_evictions=0, size=1,
>> hitratio=0.67, evictions=0, cumulative_lookups=865,
>> cumulative_hitratio=0.97, warmupTime=0, inserts=1, cumulative_inserts=29,
>> cumulative_hits=836}
>> 2019-05-22 17:19:50.235 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming result for
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... Uninverting(_28j3z(7.5.0):C1)))}]
>> queryResultCache
>> 2019-05-22 17:19:50.235 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3z(7.5.0):C1)))}] from
>> [Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3y(7.5.0):C1)))}]
>> documentCache{lookups=0, hits=0, cumulative_evictions=0, size=0,
>> hitratio=0.0, evictions=0, cumulative_lookups=0, cumulative_hitratio=0.0,
>> warmupTime=0, inserts=0, cumulative_inserts=0, cumulative_hits=0}
>> 2019-05-22 17:19:50.235 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher autowarming result for
>> [Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... Uninverting(_28j3z(7.5.0):C1)))}]
>> documentCache
>> 2019-05-22 17:19:50.236 INFO
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.c.SolrCore [core-tex73oy02hnxgx1dqc14p5o-index1] Registered new
>> searcher Searcher@6211242f[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main{ExitableDirectoryReader(UninvertingDirectoryReader(Uninverting(_22lfz(7.5.0):c1033782/56603:delGen=2772)
>> ... <shortened> ... Uninverting(_28j3z(7.5.0):C1)))}
>> 2019-05-22 17:19:50.237 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.s.SolrIndexSearcher Closing
>> Searcher@680b1764[core-tex73oy02hnxgx1dqc14p5o-index1]
>> main
>> fieldValueCache{lookups=0, hits=0, cumulative_evictions=0, size=0,
>> hitratio=0.0, evictions=0, cumulative_lookups=0, cumulative_hitratio=0.0,
>> warmupTime=0, inserts=0, cumulative_inserts=0, cumulative_hits=0}
>> filterCache{lookups=0, hits=0, cumulative_evictions=0, size=0,
>> hitratio=0.0, evictions=0, cumulative_lookups=0, cumulative_hitratio=0.0,
>> warmupTime=0, inserts=0, cumulative_inserts=0, cumulative_hits=0}
>> queryResultCache{lookups=3, hits=2, cumulative_evictions=0, size=1,
>> hitratio=0.67, evictions=0, cumulative_lookups=865,
>> cumulative_hitratio=0.97, warmupTime=0, inserts=1, cumulative_inserts=29,
>> cumulative_hits=836}
>> documentCache{lookups=0, hits=0, cumulative_evictions=0, size=0,
>> hitratio=0.0, evictions=0, cumulative_lookups=0, cumulative_hitratio=0.0,
>> warmupTime=0, inserts=0, cumulative_inserts=0, cumulative_hits=0}
>> 2019-05-22 17:19:50.237 INFO
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.u.LoggingInfoStream
>> [IW][searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1]:
>> decRefDeleter for NRT reader version=10560244
>> segments=_22lfz(7.5.0):c1033782/56603:delGen=2772
>> _22lfp(7.5.0):c1025574/39055:delGen=2113
>> _22lfr(7.5.0):c759249/32191:delGen=1386
>> _26q49(7.5.0):c923418/29825:delGen=958
>> _22lfx(7.5.0):c684064/30952:delGen=1098
>> _22lfv(7.5.0):c856317/78777:delGen=928
>> _22lg1(7.5.0):c1062384/188447:delGen=1750
>> _22lg0(7.5.0):c561881/1480:delGen=386
>> _22lg5(7.5.0):c1104218/1004:delGen=139 _22lgh(7.5.0):c1156482/46:delGen=33
>> _22lgf(7.5.0):c626273/27:delGen=19 _22lfy(7.5.0):c697224/6:delGen=6
>> _22lgd(7.5.0):c399283/6:delGen=3 _22lgg(7.5.0):c482373/3:delGen=3
>> _22lg4(7.5.0):c656746/2:delGen=2 _22lgc(7.5.0):c664274/3:delGen=3
>> _22lg7(7.5.0):c703377 _22lfu(7.5.0):c700340/3:delGen=3
>> _22lg2(7.5.0):c743334 _22lg6(7.5.0):c1091387/44659:delGen=946
>> _22lfs(7.5.0):c845018 _22lg8(7.5.0):c675649 _22lg9(7.5.0):c686292
>> _22lft(7.5.0):c636751/1004:delGen=300 _22lgb(7.5.0):c664531
>> _22lga(7.5.0):c647696/1:delGen=1 _22lge(7.5.0):c659794
>> _22lfw(7.5.0):c568537/1:delGen=1 _22lg3(7.5.0):c837568/1426:delGen=423
>> _26r20(7.5.0):c63899/10456:delGen=257 _273qn(7.5.0):c39076/8075:delGen=323
>> _27q6g(7.5.0):c40830/8111:delGen=195 _27aii(7.5.0):c30182/6777:delGen=287
>> _27tkq(7.5.0):c57620/6234:delGen=162 _27jrm(7.5.0):c33298/4797:delGen=202
>> _280zq(7.5.0):c60476/2341:delGen=173 _28h7x(7.5.0):c48570/453:delGen=35
>> _28c75(7.5.0):c29536/1088:delGen=47 _28h71(7.5.0):c1191/138:delGen=5
>> _28idl(7.5.0):c782/57:delGen=6 _28ihc(7.5.0):c5398/348:delGen=9
>> _28ig3(7.5.0):c1118/302:delGen=4 _28j1s(7.5.0):c917/269:delGen=2
>> _28iu9(7.5.0):c758/129:delGen=4 _28j23(7.5.0):c567/70:delGen=2
>> _28j3j(7.5.0):c802/11:delGen=1 _28j3u(7.5.0):c697/11:delGen=2
>> _28iz5(7.5.0):c858/116:delGen=4 _28j2n(7.5.0):c566/78:delGen=1
>> _28j3t(7.5.0):C20/11:delGen=1 _28j3v(7.5.0):C13/8:delGen=1 _28j3y(7.5.0):C1
>> 2019-05-22 17:19:50.237 DEBUG
>> (searcherExecutor-10-thread-1-processing-x:core-tex73oy02hnxgx1dqc14p5o-index1)
>> o.a.s.c.CachingDirectoryFactory Releasing directory:
>> /solr/core-tex73oy02hnxgx1dqc14p5o-index1/index 2 false
>> 2019-05-22 17:19:50.237 DEBUG (qtp26728049-20) [
>> x:core-tex73oy02hnxgx1dqc14p5o-index1] o.a.s.u.p.LogUpdateProcessorFactory
>> PRE_UPDATE FINISH {{params(),defaults(wt=xml)}}
>> 2019-05-22 17:19:50.237 INFO (qtp26728049-20) [
>> x:core-tex73oy02hnxgx1dqc14p5o-index1] o.a.s.u.p.LogUpdateProcessorFactory
>> [core-tex73oy02hnxgx1dqc14p5o-index1] webapp=/solr path=/update
>> params={}{commit=} 0 8078
>>
>> You see the part (line 10 from the log excerpt) where it spends approx.
>> five seconds without logging anything.
>>
>> Now I am aware that there could be several reasons for it, but it would
>> probably help me I knew what is actually being done in that part of code
>> where it is silent so I can look further.
>>
>> This is not GC related, btw, this was one of the first things I checked
>> and the pause is always at the same place and it is always taking approx.
>> the same time.
>>
>> Thanks,
>> André
>>
>
>
> --
> André Widhani
> Research & Development
>
> *Don’t miss our latest news! *
> www.digicol.de/news
>
> Digital Collections Content Systems GmbH
> Hindenburgstraße 49, 22297 Hamburg
>
> Tel: +49 40 23535-128
> Fax: +49 40 23535-180
> E-Mail: andre.widh...@digicol.de
> Internet: www.digicol.de
> HRB Hamburg 48373, Geschäftsführer: Jörn Olsen
>
> Haftungsbeschränkung:
> Diese Nachricht enthält vertrauliche Informationen und ist ausschließlich
> für den Adressaten bestimmt. Der Gebrauch durch Dritte ist verboten. Das
> Unternehmen ist nicht verantwortlich für die ordnungsgemäße, vollständige
> oder verzögerungsfreie Übertragung dieser Nachricht.
