You are viewing a plain text version of this content. The canonical link for it is here.
Posted to users@solr.apache.org by Calvin Smith <ca...@lucasfilm.com> on 2024/02/16 17:59:22 UTC
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(SolrDocumentBase,
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
Re: Partial update slowness with a stored="false" dynamic field and lots of distinct field names
Posted by Calvin Smith <ca...@lucasfilm.com>.
Hi Christine,
Thanks for the response and the suggestion. This turned out to be quite a
deep rabbit hole, but the following shows times for versions between 6.6
and 9.5.
Each row below gives the version followed by two times for the partial
update of the 25 documents listed in my original post, each of which is an
average of three runs with the first being the time for `stored="false"`
and the second for `stored="true"` (both with `indexed="true"
docValues="true"`; also, the initial add of 25 docs doesn't take more than
100-200ms or so in any version with either of these settings):
Version, stored="false", stored="true
6.6.6, 1.934s, 2.253s
7.0.0: 1.913s, 2.034s
7.3.0: 1.897s, 1.690s
7.5.0: 1.710s, 1.807s
7.6.0: 3.066s, 2.719s
7.7.0: 3.537s, 3.444s
7.7.3: 3.128s, 3.403s
8.0.0: 3.460s, 3.499s
8.3.0: 3.462s, 3.656s
8.4.0: 6.790s, 6.910s
8.5.0: 6.832s, 6.722s
8.6.0: 7.217s, 7.068s
8.11.3: 7.612s, 7.619s
9.0.0: 7.170s, 7.005s
9.3.0: 7.255s, 7.336s
9.4.0: 8.960s, 8.627s
9.5.0: 8.510s, 0.012s
It's not reflected in these partial update times, but I noticed that
between 6.6.6 and 7.0 there was a big reduction in index size and decrease
in time to build the index. 6.6.6 took almost 160 minutes to build the
index from scratch and it was 41GB in size, while 7.0 took less than 15
minutes and was 15GB in size, so bravo to the team for such a drastic
improvement.
Looking at the first of the times (`stored="false"`) in each row above, it
got much worse between 7.5.0 and 7.6.0 (1.7s to 3.0s), and then between 8.3
and 8.4 it gets worse again (almost doubling the time), and once more
between 9.3 and 9.4, while the time for the `stored="true"` in each row
seems to be roughly equal to `stored="false"` until it gets almost 1000x
times faster with 9.5.0.
Thanks,
Calvin
On Tue, Feb 20, 2024 at 1:52 AM Christine Poerschke (BLOOMBERG/ LONDON) <
cpoerschke@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
>
Re: Partial update slowness with a stored="false" dynamic field and lots of distinct field names
Posted by Calvin Smith <ca...@lucasfilm.com>.
Hi Rahul,
Thanks for the suggestion. I was using `solr.NRTCachingDirectoryFactory` in
all the versions I've tested, which was the default in the example
solrconfig:
<directoryFactory name="DirectoryFactory"
class="${solr.directoryFactory:solr.NRTCachingDirectoryFactory}"/>
I'll give `solr.MMapDirectoryFactory` a try later though.
Thanks,
Calvin
p.s. Christine, I am following up on your suggestion, but it's taking a
while, since I have to build the index from scratch each time. More later...
On Tue, Feb 20, 2024 at 8:35 PM Rahul Goswami <ra...@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) <
> cpoerschke@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-user@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
> >
> >
> >
>
Re: Partial update slowness with a stored="false" dynamic field and lots of distinct field names
Posted by Calvin Smith <ca...@lucasfilm.com>.
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 <mi...@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
> <mi...@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 <ra...@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) <
> > > cpoerschke@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-user@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
> > > >
> > > >
> > > >
>
Re: Partial update slowness with a stored="false" dynamic field and lots of distinct field names
Posted by Michael Gibney <mi...@michaelgibney.net>.
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
<mi...@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 <ra...@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) <
> > cpoerschke@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-user@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
> > >
> > >
> > >
Re: Partial update slowness with a stored="false" dynamic field and lots of distinct field names
Posted by Michael Gibney <mi...@michaelgibney.net>.
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 <ra...@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) <
> cpoerschke@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-user@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
> >
> >
> >
Re: Partial update slowness with a stored="false" dynamic field and lots of distinct field names
Posted by Rahul Goswami <ra...@gmail.com>.
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) <
cpoerschke@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-user@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
>
>
>
Re:Partial update slowness with a stored="false" dynamic field and lots of distinct field names
Posted by "Christine Poerschke (BLOOMBERG/ LONDON)" <cp...@bloomberg.net>.
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-user@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