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
