Solr soft commit takes 1.5 seconds until the document is updated

["Andreas Gusenbauer [CELUM]" <An...@celum.com>]

Hi all,

We switched to soft commits recently and configured those with commitWithin=1ms, still we see that the commit takes 1.5 seconds on a system without additional load. The problem we face is that subsequent queries get outdated data within these 1.5 seconds.
The solr version is 8.7.0 (we also tested with 8.9.0).
On many other test systems the end_commit_flush immediately follows the preSoftCommit and we never receive outdated data. So now my question is whether this is expected and which factors influence this 1.5 seconds delay?
Here we see the update of the document #186116 (including commitWithin, prepareCommit, etc. settings):
2021-10-12 06:35:54.966 DEBUG (qtp758572926-3131) [   x:assets] o.a.s.u.DirectUpdateHandler2 updateDocument(add{_version_=1713394737444028416,id=186116,commitWithin=1})
2021-10-12 06:35:54.969 TRACE (qtp758572926-3131) [   x:assets] o.a.s.u.UpdateLog TLOG: added id 186116 to tlog{file=/xyz/searchindex/assets/data/tlog/tlog.0000000000001509184 refcount=1} LogPtr(7677) map=14448321
2021-10-12 06:35:54.969 INFO  (qtp758572926-3131) [   x:assets] o.a.s.u.p.LogUpdateProcessorFactory [assets]  webapp=/solr path=/update params={wt=javabin&version=2}{add=[186116 (1713394737444028416)]} 0 3
2021-10-12 06:35:54.969 DEBUG (qtp758572926-3131) [   x:assets] o.a.s.s.HttpSolrCall Closing out SolrRequest: {wt=javabin&version=2}
2021-10-12 06:35:54.970 DEBUG (commitScheduler-37-thread-1) [   x:assets] o.a.s.u.DirectUpdateHandler2 start commit{,optimize=false,openSearcher=true,waitSearcher=true,expungeDeletes=false,softCommit=true,prepareCommit=false}
2021-10-12 06:35:54.970 DEBUG (commitScheduler-37-thread-1) [   x:assets] o.a.s.u.UpdateLog TLOG: preSoftCommit: prevMap=14448321 new map=1672935947

There are two further updates on this document... this is the first:
2021-10-12 06:35:55.099 DEBUG (qtp758572926-3126) [   x:assets] o.a.s.u.DirectUpdateHandler2 updateDocument(add{_version_=1713394737583489024,id=186116,commitWithin=1})
2021-10-12 06:35:55.102 TRACE (qtp758572926-3126) [   x:assets] o.a.s.u.UpdateLog TLOG: added id 186116 to tlog{file=/xyz/searchindex/assets/data/tlog/tlog.0000000000001509184 refcount=1} LogPtr(13835) map=1672935947

This is one of the queries that receives out-dated data:
2021-10-12 06:35:55.159 INFO  (qtp758572926-3136) [   x:assets] o.a.s.c.S.Request [assets]  webapp=/solr path=/select params={q=%2B(id:186116)&fl=id,entityType,name,lastModifiedDate,lastModifiedBy,createdBy,creationDate,originalFileName,checksum,fileExtension,assetType,originalFileSize,path,previewHeight,previewWidth,activeStatus,assetStatus,validFrom,validTo,containers,originalTicket,storageLocationId_originalTicket,defaultThumbTicket,storageLocationId_defaultThumbTicket,defaultPreview,storageLocationId_defaultPreview,largePreview,storageLocationId_largePreview,previewPageCount,mediaType,mediaTypeName_en,audioPreview,storageLocationId_audioPreview,videoPreview,storageLocationId_videoPreview,alternativePreview,storageLocationId_alternativePreview,pdfPreview,storageLocationId_pdfPreview,version,versionDate,versionedBy,containerTypes,containerIdentifiers,assetValidationStatus,validationLevel,conversionTicket,conversionErrorMessage,conversionErrorMessageParams,lockStatus,customFields_boolean_113,customFields_string_114,customFields_text_116,nodeBackedPathIds_116,customFields_text_117,nodeBackedPathIds_117,customFields_text_118,nodeBackedPathIds_118,customFields_text_125,nodeBackedPathIds_125,customFields_text_126,nodeBackedPathIds_126,customFields_text_128,nodeBackedPathIds_128,customFields_date_131,customFields_text_132,nodeBackedPathIds_132,customFields_text_133,nodeBackedPathIds_133,customFields_date_137,customFields_date_138,customFields_text_140,nodeBackedPathIds_140,customFields_string_143,customFields_string_144,customFields_string_148,customFields_string_149,customFields_string_151,customFields_text_154,nodeBackedPathIds_154,customFields_string_159,customFields_long_162,customFields_long_163,customFields_string_166,customFields_int_170,customFields_string_171,customFields_boolean_174,customFields_date_175,customFields_text_177,nodeBackedPathIds_177,customFields_text_178,nodeBackedPathIds_178,customFields_text_179,customFields_text_180,nodeBackedPathIds_180,customFields_text_181,nodeBackedPathIds_181,customFields_text_182,nodeBackedPathIds_182,customFields_string_183,customFields_boolean_184,customFields_text_185,nodeBackedPathIds_185,customFields_string_186,customFields_string_187,customFields_string_188,customFields_string_189,customFields_string_190,customFields_text_191,nodeBackedPathIds_191,customFields_text_193,customFields_string_194,customFields_string_195,customFields_boolean_196,customFields_string_198,customFields_text_199,nodeBackedPathIds_199,customFields_text_201,nodeBackedPathIds_201,customFields_text_203,nodeBackedPathIds_203,customFields_text_204,nodeBackedPathIds_204,customFields_text_205,nodeBackedPathIds_205,customFields_date_207,customFields_date_208,customFields_date_209,customFields_text_210,nodeBackedPathIds_210,customFields_text_211,nodeBackedPathIds_211,customFields_text_212,nodeBackedPathIds_212,customFields_text_213,nodeBackedPathIds_213,customFields_text_214,nodeBackedPathIds_214,customFields_text_215,nodeBackedPathIds_215,customFields_string_216,customFields_string_217,customFields_date_219,customFields_text_220,nodeBackedPathIds_220,customFields_text_221,nodeBackedPathIds_221,customFields_boolean_225,customFields_text_226,nodeBackedPathIds_226,customFields_string_227,customFields_text_228,customFields_string_101_en,customFields_text_229,nodeBackedPathIds_229,customFields_text_102,customFields_text_230,nodeBackedPathIds_230,customFields_text_103,nodeBackedPathIds_103,customFields_text_231,nodeBackedPathIds_231,customFields_text_104,nodeBackedPathIds_104,customFields_text_232,nodeBackedPathIds_232,customFields_string_233,customFields_text_106,nodeBackedPathIds_106,customFields_string_234,customFields_string_108,customFields_boolean_110,score&start=200&fq=(%2BcreatedBy:1+%2BassetStatus:0)+(assetStatus:1+assetStatus:2)&sort=id+asc&rows=200&wt=javabin&version=2&debugQuery=false} hits=1 status=0 QTime=0

This is the second update on the document:
2021-10-12 06:35:55.334 DEBUG (qtp758572926-3074) [   x:assets] o.a.s.u.DirectUpdateHandler2 updateDocument(add{_version_=1713394737829904384,id=186116,commitWithin=1})
2021-10-12 06:35:55.335 TRACE (qtp758572926-3074) [   x:assets] o.a.s.u.UpdateLog TLOG: added id 186116 to tlog{file=/xyz/searchindex/assets/data/tlog/tlog.0000000000001509184 refcount=1} LogPtr(19993) map=1672935947

Finally, at 2021-10-12 06:35:56.486 we see the end_commit_flush...

2021-10-12 06:35:56.486 DEBUG (commitScheduler-37-thread-1) [   x:assets] o.a.s.u.DirectUpdateHandler2 end_commit_flush

...from this point we can query the updated document.

Thanks in advance,
ako