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é