Re: Slow soft-commit
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 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 :
>
>> 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<>
>> 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<>
>> 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/1045
Re: Slow soft-commit
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 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 :
>
>> 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<>
>> 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<>
>> 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/1045
Re: Slow soft-commit
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 :
> 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<>
> 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<>
> 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:delG
