You are viewing a plain text version of this content. The canonical link for it is here.
Posted to solr-user@lucene.apache.org by André Widhani <an...@digicol.com> on 2019/05/22 16:12:31 UTC
Slow soft-commit
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é
Re: Slow soft-commit
Posted by Erick Erickson <er...@gmail.com>.
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.widhani@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.
Re: Slow soft-commit
Posted by Erick Erickson <er...@gmail.com>.
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.widhani@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.
Re: Slow soft-commit
Posted by André Widhani <an...@digicol.com>.
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.widhani@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.