Hi Michael, Thanks for your thoughts. In Solr 6, we were using `indexed="true" stored="false" docValues="true"`, and it was slower than I would have liked but roughly the same whether stored was false or true (about 2s in either case under 6.6.6).
Here's a representative `newEntry` stack trace from solr 9.4.0 (not doing the exact partial updates I posted, but doing lots of partial updates that were unexpectedly slow): org.apache.solr.search.DocValuesIteratorCache.newEntry(DocValuesIteratorCache.java) org.apache.solr.search.DocValuesIteratorCache$$Lambda$872.apply() java.util.HashMap.computeIfAbsent(HashMap.java:1134) org.apache.solr.search.DocValuesIteratorCache.lambda$new$2(DocValuesIteratorCache.java:91) org.apache.solr.search.DocValuesIteratorCache$$Lambda$868.apply() org.apache.solr.search.DocValuesIteratorCache.getSupplier(DocValuesIteratorCache.java:98) org.apache.solr.search.SolrDocumentFetcher.decorateDocValueFields(SolrDocumentFetcher.java:578) org.apache.solr.search.SolrDocumentFetcher$RetrieveFieldsOptimizer.getSolrDoc(SolrDocumentFetcher.java:894) org.apache.solr.search.SolrDocumentFetcher.solrDoc(SolrDocumentFetcher.java:311) org.apache.solr.handler.component.RealTimeGetComponent.fetchSolrDoc(RealTimeGetComponent.java:619) org.apache.solr.handler.component.RealTimeGetComponent.getInputDocument(RealTimeGetComponent.java:803) org.apache.solr.update.processor.DistributedUpdateProcessor.getUpdatedDocument(DistributedUpdateProcessor.java:788) org.apache.solr.update.processor.DistributedUpdateProcessor.doVersionAdd(DistributedUpdateProcessor.java:406) org.apache.solr.update.processor.DistributedUpdateProcessor.lambda$versionAdd$0(DistributedUpdateProcessor.java:356) org.apache.solr.update.processor.DistributedUpdateProcessor$$Lambda$861.apply() org.apache.solr.update.VersionBucket.runWithLock(VersionBucket.java:51) org.apache.solr.update.processor.DistributedUpdateProcessor.versionAdd(DistributedUpdateProcessor.java:353) org.apache.solr.update.processor.DistributedUpdateProcessor.processAdd(DistributedUpdateProcessor.java:234) org.apache.solr.update.processor.LogUpdateProcessorFactory$LogUpdateProcessor.processAdd(LogUpdateProcessorFactory.java:111) org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.handleAdds(JsonLoader.java:553) org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.processUpdate(JsonLoader.java:183) org.apache.solr.handler.loader.JsonLoader$SingleThreadedJsonLoader.load(JsonLoader.java:151) org.apache.solr.handler.loader.JsonLoader.load(JsonLoader.java:86) org.apache.solr.handler.UpdateRequestHandler$1.load(UpdateRequestHandler.java:102) org.apache.solr.handler.ContentStreamHandlerBase.handleRequestBody(ContentStreamHandlerBase.java:100) org.apache.solr.handler.RequestHandlerBase.handleRequest(RequestHandlerBase.java:226) org.apache.solr.core.SolrCore.execute(SolrCore.java:2901) org.apache.solr.servlet.HttpSolrCall.executeCoreRequest(HttpSolrCall.java:875) org.apache.solr.servlet.HttpSolrCall.call(HttpSolrCall.java:561) org.apache.solr.servlet.SolrDispatchFilter.dispatch(SolrDispatchFilter.java:262) org.apache.solr.servlet.SolrDispatchFilter.lambda$doFilter$0(SolrDispatchFilter.java:219) org.apache.solr.servlet.SolrDispatchFilter$$Lambda$842.run() org.apache.solr.servlet.ServletUtils.traceHttpRequestExecution2(ServletUtils.java:246) org.apache.solr.servlet.ServletUtils.rateLimitRequest(ServletUtils.java:215) org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:213) org.apache.solr.servlet.SolrDispatchFilter.doFilter(SolrDispatchFilter.java:195) org.eclipse.jetty.servlet.FilterHolder.doFilter(FilterHolder.java:210) org.eclipse.jetty.servlet.ServletHandler$Chain.doFilter(ServletHandler.java:1635) org.eclipse.jetty.servlet.ServletHandler.doHandle(ServletHandler.java:527) org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:131) org.eclipse.jetty.security.SecurityHandler.handle(SecurityHandler.java:598) org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122) org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:223) org.eclipse.jetty.server.session.SessionHandler.doHandle(SessionHandler.java:1570) org.eclipse.jetty.server.handler.ScopedHandler.nextHandle(ScopedHandler.java:221) org.eclipse.jetty.server.handler.ContextHandler.doHandle(ContextHandler.java:1384) org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:176) org.eclipse.jetty.servlet.ServletHandler.doScope(ServletHandler.java:484) org.eclipse.jetty.server.session.SessionHandler.doScope(SessionHandler.java:1543) org.eclipse.jetty.server.handler.ScopedHandler.nextScope(ScopedHandler.java:174) org.eclipse.jetty.server.handler.ContextHandler.doScope(ContextHandler.java:1306) org.eclipse.jetty.server.handler.ScopedHandler.handle(ScopedHandler.java:129) org.eclipse.jetty.server.handler.ContextHandlerCollection.handle(ContextHandlerCollection.java:149) org.eclipse.jetty.server.handler.InetAccessHandler.handle(InetAccessHandler.java:228) org.eclipse.jetty.server.handler.HandlerCollection.handle(HandlerCollection.java:141) org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122) org.eclipse.jetty.rewrite.handler.RewriteHandler.handle(RewriteHandler.java:301) org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122) org.eclipse.jetty.server.handler.gzip.GzipHandler.handle(GzipHandler.java:822) org.eclipse.jetty.server.handler.HandlerWrapper.handle(HandlerWrapper.java:122) org.eclipse.jetty.server.Server.handle(Server.java:563) org.eclipse.jetty.server.HttpChannel$RequestDispatchable.dispatch(HttpChannel.java:1598) org.eclipse.jetty.server.HttpChannel.dispatch(HttpChannel.java:753) org.eclipse.jetty.server.HttpChannel.handle(HttpChannel.java:501) org.eclipse.jetty.server.HttpConnection.onFillable(HttpConnection.java:287) org.eclipse.jetty.io.AbstractConnection$ReadCallback.succeeded(AbstractConnection.java:314) org.eclipse.jetty.io.FillInterest.fillable(FillInterest.java:100) org.eclipse.jetty.io.SelectableChannelEndPoint$1.run(SelectableChannelEndPoint.java:53) org.eclipse.jetty.util.thread.QueuedThreadPool.runJob(QueuedThreadPool.java:969) org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.doRunJob(QueuedThreadPool.java:1194) org.eclipse.jetty.util.thread.QueuedThreadPool$Runner.run(QueuedThreadPool.java:1149) java.lang.Thread.run(Thread.java:829) In the profiling snapshot, it shows that `newEntry` had 6,877 calls, taking 73% of the time out of total time 188.6s for that thread. The name of the thread was qtp1196982797-283 (Group 'main') if that means anything. Higher up in the call tree, `RealTimeGetComponent.java:619 org.apache.solr.search.SolrDocumentFetcher.solrDoc(int, SolrReturnFields)` took 98% of the time in that same thread, and `SolrDocumentFetcher.java:894 org.apache.solr.search.SolrDocumentFetcher.decorateDocValueFields(SolrDocumentBase, int, Set, DocValuesIteratorCache)` took 88% of the time. I'll review the issue you mentioned further later, but I do still see the partial updates being pretty slow with 9.0 (7.2s vs 8.8s in 9.5.0), so that could possibly be related to that apparent difference, but the bulk of the difference between solr 6 and solr 9 seems to come in earlier versions. I'm still testing different versions, but will post a reply to Christine's message when I have all the data. Thanks, Calvin On Wed, Feb 21, 2024 at 10:13 AM Michael Gibney <mich...@michaelgibney.net> wrote: > Also, you don't explicitly mention, but just to be sure: in your Solr > 6 deployment, were the `playlist_index_*` fields stored? Some degree > of performance difference between stored=true/false is expected, > because retrieving dynamic fields with many field names is definitely > problematic for docValues-only. SOLR-16989 was in fact designed to > mitigate this to some extent, but with 100k separate fields, this is > going to definitely be a problem, and I suspect it would have been > _more_ of a problem before SOLR-16989 ... but I don't want to jump to > conclusions! > > On Wed, Feb 21, 2024 at 12:43 PM Michael Gibney > <mich...@michaelgibney.net> wrote: > > > > It might be worth looking at this issue: > > https://issues.apache.org/jira/browse/SOLR-16989 > > > > The irony is that this issue was supposed to help with slowness in > > cases similar to what you describe. Can you send a full stack trace > > for a representative call to > > `DocValuesIteratorCache.newEntry(String)`? > > > > On Tue, Feb 20, 2024 at 11:36 PM Rahul Goswami <rahul196...@gmail.com> > wrote: > > > > > > Did you happen to change the DirectoryFactory in solrconfig to > > > SimpleFSDirectoryFactory or NIOFSDirecotryFactory by any chance? > Default is > > > Mmap which is much more performant for atomic updates (and also > practical, > > > especially given the small(ish) size of your index). > > > > > > -Rahul > > > > > > On Tue, Feb 20, 2024 at 4:52 AM Christine Poerschke (BLOOMBERG/ > LONDON) < > > > cpoersc...@bloomberg.net> wrote: > > > > > > > Hello Calvin, > > > > > > > > Thank you for this wonderful issue write-up! > > > > > > > > You mention upgrading from Solr 6 to 9.5 versions and I wonder if it > might > > > > be practical or insightful to assess for some versions in between > too e.g. > > > > 9.5/9.4/9.3 going backwards or 6/7/8/9.0 going forward or some sort > of > > > > binary search variant. > > > > > > > > Best wishes, > > > > Christine > > > > > > > > From: users@solr.apache.org At: 02/16/24 17:59:59 UTCTo: > > > > solr-u...@lucene.apache.org > > > > Subject: Partial update slowness with a stored="false" dynamic field > and > > > > lots of distinct field names > > > > > > > > Hi solr users, > > > > > > > > While tracking down a severe performance regression doing partial > updates > > > > when upgrading from Solr 6 to solr 9.5.0, I discovered the following > > > > unexpected behavior. > > > > > > > > In my schema.xml file, I have the following fields (among many > others): > > > > > > > > <field name="id" type="string" indexed="true" stored="true" > > > > required="true"/> > > > > <field name="_version_" type="long" indexed="false" stored="false"/> > > > > <field name="name" type="text_en_splitting_tight" indexed="true" > > > > stored="true" omitNorms="true"/> > > > > > > > > <dynamicField name="playlist_index_*" type="int" .../> <!-- The int > field > > > > type has docValues="true" --> > > > > > > > > The unexpected impact on partial update performance depends on > whether the > > > > dynamic field above is stored (with `docValues="true"`). The index in > > > > question contains about 30 million documents and is 15GB in size, > and there > > > > are a large number of distinct `playlist_index_*`` field names (more > than > > > > 100K). The purpose of that dynamic field is to support sorting, with > > > > queries sometimes specifying a sort like `playlist_index_3141 asc` > to sort > > > > the results by that field. > > > > > > > > For all the cases below, I added to the existing index the following > 25 new > > > > documents: > > > > > > > > [ > > > > {"id": "12345678901234567891", "name": "."}, > > > > {"id": "12345678901234567892", "name": "."}, > > > > {"id": "12345678901234567893", "name": "."}, > > > > {"id": "12345678901234567894", "name": "."}, > > > > {"id": "12345678901234567895", "name": "."}, > > > > {"id": "12345678901234567896", "name": "."}, > > > > {"id": "12345678901234567897", "name": "."}, > > > > {"id": "12345678901234567898", "name": "."}, > > > > {"id": "12345678901234567899", "name": "."}, > > > > {"id": "12345678901234567900", "name": "."}, > > > > {"id": "12345678901234567901", "name": "."}, > > > > {"id": "12345678901234567902", "name": "."}, > > > > {"id": "12345678901234567903", "name": "."}, > > > > {"id": "12345678901234567904", "name": "."}, > > > > {"id": "12345678901234567995", "name": "."}, > > > > {"id": "12345678901234567996", "name": "."}, > > > > {"id": "12345678901234567997", "name": "."}, > > > > {"id": "12345678901234567998", "name": "."}, > > > > {"id": "12345678901234567999", "name": "."}, > > > > {"id": "12345678901234568000", "name": "."}, > > > > {"id": "12345678901234568001", "name": "."}, > > > > {"id": "12345678901234568002", "name": "."}, > > > > {"id": "12345678901234568003", "name": "."}, > > > > {"id": "12345678901234568004", "name": "."}, > > > > {"id": "12345678901234568005", "name": "."} > > > > ] > > > > > > > > and did both a soft and hard commit before continuing. > > > > > > > > Then I did a partial update with `commitWithin=600000` to update > each of > > > > those documents: > > > > > > > > [ > > > > {"id": "12345678901234567891", "name": {"set": "1"}}, > > > > {"id": "12345678901234567892", "name": {"set": "2"}}, > > > > {"id": "12345678901234567893", "name": {"set": "3"}}, > > > > {"id": "12345678901234567894", "name": {"set": "4"}}, > > > > {"id": "12345678901234567895", "name": {"set": "5"}}, > > > > {"id": "12345678901234567896", "name": {"set": "6"}}, > > > > {"id": "12345678901234567897", "name": {"set": "7"}}, > > > > {"id": "12345678901234567898", "name": {"set": "8"}}, > > > > {"id": "12345678901234567899", "name": {"set": "9"}}, > > > > {"id": "12345678901234567900", "name": {"set": "10"}}, > > > > {"id": "12345678901234567901", "name": {"set": "11"}}, > > > > {"id": "12345678901234567902", "name": {"set": "12"}}, > > > > {"id": "12345678901234567903", "name": {"set": "13"}}, > > > > {"id": "12345678901234567904", "name": {"set": "14"}}, > > > > {"id": "12345678901234567995", "name": {"set": "15"}}, > > > > {"id": "12345678901234567996", "name": {"set": "16"}}, > > > > {"id": "12345678901234567997", "name": {"set": "17"}}, > > > > {"id": "12345678901234567998", "name": {"set": "18"}}, > > > > {"id": "12345678901234567999", "name": {"set": "19"}}, > > > > {"id": "12345678901234568000", "name": {"set": "20"}}, > > > > {"id": "12345678901234568001", "name": {"set": "21"}}, > > > > {"id": "12345678901234568002", "name": {"set": "22"}}, > > > > {"id": "12345678901234568003", "name": {"set": "23"}}, > > > > {"id": "12345678901234568004", "name": {"set": "24"}}, > > > > {"id": "12345678901234568005", "name": {"set": "25"}} > > > > ] > > > > > > > > The time it takes to perform the update varies drastically depending > on > > > > whether the `playlist_index_*` dynamic field is stored: > > > > > > > > - 0.017s: <dynamicField name="playlist_index_*" type="int" > indexed="true" > > > > stored="true" docValues="true"/> > > > > - 0.016s: <dynamicField name="playlist_index_*" type="int" > indexed="false" > > > > stored="true" docValues="true"/> > > > > - 8.850s: <dynamicField name="playlist_index_*" type="int" > indexed="false" > > > > stored="false" docValues="true"/> > > > > - 8.867s: <dynamicField name="playlist_index_*" type="int" > indexed="true" > > > > stored="false" docValues="true"/> > > > > > > > > The surprise is the poor performance of the last two, when stored is > false > > > > and so the partial update may need to use the docValues to generate > the new > > > > doc, compared to the first two when stored is true. > > > > > > > > When I profiled the code for the last of the four settings above, I > saw > > > > that the majority of the time was spent in > > > > > > > > > `org.apache.solr.search.SolrDocumentFetcher.decorateDocValueFields(SolrDocumentB > > > > ase, > > > > int, Set, DocValuesIteratorCache)` and further down in the callees > under > > > > that hot spot there is a call to > > > > `org.apache.solr.search.DocValuesIteratorCache.newEntry(String)` > that I > > > > added some print statements to in order to see which fields > `newEntry` was > > > > being called for. There were many thousands of calls to the > > > > `playlist_index_*` fields, with each call being a different field > name, and > > > > no other fields. > > > > > > > > My schema does have other dynamic fields, but none of them resulted > in > > > > calls to `newEntry`. What is distinct about this dynamic field is > that it's > > > > the only one that is a numeric field type and the only one that has > more > > > > than a few hundred or so distinct field names. > > > > > > > > Does this seem like expected behavior that solr has to make so many > > > > `newEntry` calls for that dynamic field to perform the update that it > > > > seriously impacts update performance? > > > > > > > > Thanks for your time, > > > > Calvin > > > > > > > > > > > > >
