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.