Query performance regressions in Hibernate 6

Hibernate ORM
1

I originally reported my findings as HHH-15854.

Since reporting the issue, major performance improvements have been made and of the 4 test-cases attached to the ticket, 3 are now faster in v6. However, one of the tests is still significantly slower and seems to have major performance implications in our application:

5.6 Main
Fetch Entities with Associations 38.74S 41.60S
Fetch Entities without Associations 23.41S 22.82S
Small Transactions Criteria 1M5.81S 56.42S
Small Transactions HQL 1M7.38S 56.19S

I just re-ran our mass indexer that issues hundreds of thousands of queries to rebuild our search index. Here are the results:

5.6.15: MassIndexerImpl - Finished updating index in 418s.
6.2.0-CR4: MassIndexerImpl - Finished updating index in 459s.

So H6 is roughly 10% slower than H5. A similar difference in performance can be seen in my minimal test case testFetchEntityWithAssociationsPerformance.

Hibernate 6 seems to do significantly more work to initialize associations than H5.

These PRs contain the performance tests against the various branches:

I tried profiling the testFetchEntityWithAssociationsPerformance test against main and 5.6, but there have been so many changes to the code between the two versions that it isnā€™t possible for me to determine the root cause of these regressions.

Can someone take another look at this? I think H6 has the potential to be significantly faster than H5, but the problem with associations currently makes it slower in our application.

2

Thanks for your help so far and for the great test cases. This is on our radar and we are aiming to fix this. Please be patient :slight_smile:

3

Thatā€™s great news, thanks @beikov!

4

These are the updated results against the current main (including the improvements to batch loading and caching of AST):

5.6 Main
Fetch Entities with Associations 38.74S 35.88S
Fetch Entities without Associations 23.41S 21.22S
Small Transactions Criteria 1M5.81S 51.45S
Small Transactions HQL 1M7.38S 51.47S

This looks very promising!

Iā€™ll re-test with our mass indexer, as soon as there is a new release.

1 Like
5

OK, unfortunately Hibernate 6.2.2 is still about 5-10% slower for our mass indexer.

The remaining difference might not be due to slower query performance though. It is likely caused by Hibernate 6 allocating significantly more memory and causing more frequent GC.

This is the memory allocation for a full indexer run in Hibernate 5:

image
image844Ɨ484 35.7 KB

And this is the corresponding data for Hibernate 6.2.2:

image
image860Ɨ486 35.5 KB

These are the graphs for GC. The first run is Hibernate 6, the second run is Hibernate 5:

image
image3236Ɨ482 43.6 KB

I can share JFR data privately if that could be of help.

6

Thanks a lot for these insights. Iā€™ll let @Sanne chime in on this as he is probably more capable to read and interpret the JFR data.

7

We just upgraded to 6.2.3. I was hoping that our performance issues would be fixed by one of the bugs fixed in this release, but unfortunately not.

I decided to dig a bit deeper and enable session level statistics for part of our mass indexer. This is the result for a very small batch:

Hibernate 5:

INF o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    9417 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    53216371 nanoseconds spent preparing 642 JDBC statements;
    588230375 nanoseconds spent executing 642 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    12079215 nanoseconds spent performing 277 L2C puts;
    2105709 nanoseconds spent performing 182 L2C hits;
    1194357 nanoseconds spent performing 594 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    720122 nanoseconds spent executing 608 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Hibernate 6.2.3:

INF o.h.e.i.StatisticalLoggingSessionEventListener - Session Metrics {
    9792 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    92944055 nanoseconds spent preparing 712 JDBC statements;
    669429997 nanoseconds spent executing 712 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    13459828 nanoseconds spent performing 342 L2C puts;
    1049323 nanoseconds spent performing 110 L2C hits;
    1264545 nanoseconds spent performing 505 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    1094284 nanoseconds spent executing 608 partial-flushes (flushing a total of 0 entities and 0 collections)
}

Hibernate 6 currently issues significantly more queries because of L2C misses. I think we could be affected by Hibernate ORM - Issues - Hibernate JIRA.

I will pause my investigations until HHH-16594 has been fixed. It would explain the degraded performance and additional allocations.

8

I just ran the tests again against 6.2.4 with the new fixes for query caches. The situation has improved, but only very slightly. Iā€™m afraid that the caching issues are not the root of the regressions either.

Hibernate 5:

2023-06-02 15:27:53,322 [or-4] INF c.s.b.s.s.i.MassIndexerImpl - Finished updating index in 429s.

Hibernate 6.2.4:

2023-06-03 12:30:45,081 [or-4] INF c.s.b.s.s.i.MassIndexerImpl - Finished updating index in 452s.

Cache statistics look much better now, but there still seem to fewer hits than in H5:

Hibernate 5:

2023-06-02 16:08:44.848  INFO 87433 --- [nio-8443-exec-3] i.StatisticalLoggingSessionEventListener : Session Metrics {
    10042 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    4291471 nanoseconds spent preparing 473 JDBC statements;
    360642499 nanoseconds spent executing 473 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    469380 nanoseconds spent performing 52 L2C puts;
    1599750 nanoseconds spent performing 428 L2C hits;
    113323 nanoseconds spent performing 642 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    66626 nanoseconds spent executing 608 partial-flushes (flushing a total of 0 entities and 0 collections)

Hibernate 6.2.4:

2023-06-02T16:03:48.167+02:00  INFO 86658 --- [nio-8443-exec-3] i.StatisticalLoggingSessionEventListener : Session Metrics {
    11042 nanoseconds spent acquiring 1 JDBC connections;
    0 nanoseconds spent releasing 0 JDBC connections;
    5335166 nanoseconds spent preparing 477 JDBC statements;
    410154462 nanoseconds spent executing 477 JDBC statements;
    0 nanoseconds spent executing 0 JDBC batches;
    247541 nanoseconds spent performing 62 L2C puts;
    794125 nanoseconds spent performing 403 L2C hits;
    66296 nanoseconds spent performing 642 L2C misses;
    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);
    55099 nanoseconds spent executing 608 partial-flushes (flushing a total of 0 entities and 0 collections)

Iā€™ll try to investigate where these additional puts/misses are coming from.

@beikov: Do you have any suggestions how we can proceed from here? Does it make sense for me to share some JFR data?

9

I donā€™t know what queries the MassIndexer emits, but there is one open improvement that might affect the overall performance: [HHH-15086] - Hibernate JIRA

No idea what the best way forward would be at this point. I think you would have to do some debugging to understand what is going on and compare query logs.

It seems a bit odd that with Hibernate 6.2 you have more cache puts than with 5.6. Maybe you can investigate what it is that Hibernate 6.2 puts into the cache that hasnā€™t been before? Set a break point in org.hibernate.engine.internal.StatisticalLoggingSessionEventListener#cachePutEnd to figure this out. Donā€™t forget to bump up the transaction timeout for that test.

Apart from that, It would also be interesting to compare the SQL queries that are emitted and figure out which extra queries are emitted in 6.2. One possible reason for this I could imagine is the scenario described in hibernate-orm/migration-guide.adoc at 6.0 Ā· hibernate/hibernate-orm Ā· GitHub

10

I just found the time to do some more investigations:

Caching

My first experiment was to disable query and 2nd-level caches in my project to make sure that caching isnā€™t the root cause of my issues. This are the results:

Hibernate 5.6:

INF MassIndexerImpl - Finished updating index in 445s.

Hibernate 6 (Main):

INF MassIndexerImpl - Finished updating index in 523s.

So without caches, the situation is even worse. Caching actually hid some of the performance issues in my case.

Performance Tests

Then I decided to revisit my original performance tests to add some more lazy-loading and batch fetching, which the mass indexer uses heavily. I was able to reproduce a major difference in performance with a very basic test:

Hibernate 5.6:

Query took 51.71S

Hibernate 6 (Main):

Query took 1M10.13S

These are the PRs containing the tests:

I hope the test-cases are enough to find the root cause of these issues.

11

@theigl I tried running your test on the Hibernate 6 branch under a profiler and noticed that it seems to be spending a lot of time on the auto-flush.

Bear in mind that the profiler adds some overhead to every method so the results might be distorted.

image
image1296Ɨ1300 154 KB

Maybe you could try disabling the auto-flush on the queries (or on the session)?

12

It would be interesting to compare how much time is spent flushing in 5.6 vs 6. I donā€™t think the flushing logic has changed much between 5.6 and 6 so Iā€™m not sure it is the source of the performance regressions.

Letā€™s see what the devs say :wink:

13

I just ran the tests with FlushMode.COMMIT. These are the results:

Hibernate 5.6:

Query took 16.01S

Hibernate 6 (Main):

Query took 20.93S

So it probably makes sense to profile this without flushing as well, so it is easier to see where the additional overhead is coming from.

14

:+1: that removes the flush from the equation and makes the difference even more significant

15

In Hibernate 6, besides the part where the actual SQL queries are executed and the results fetched some of the time is spent creating the entities:

image
image1517Ɨ1357 359 KB

And also creating the query plan:

image
image1898Ɨ737 179 KB

With the usual caveat that the profiler distorts the results because it adds overhead to every method call.

I do not know Hibernate well enough to see what might be off here. I will have very limited Internet connectivity for a while so I wonā€™t be able to look into it further for now.

16

Iā€™ll try to spend some time on this today. Like I wrote initially, it would be best to first look into the queries that are generated and trace back where the queries come from which werenā€™t generated before.

17

I think the additional queries are only a minor issue. Iā€™m on vacation for the next 2-3 weeks and will look into it when Iā€™m back.

It would be great if you could profile the test cases I provided. There are some inefficiencies hiding here that add significant overhead compared to Hibernate 5 and Iā€™m pretty sure they are the source of my performance problems. Iā€™ve seen the same hotspots when I profiled the mass indexer on our staging system.

18

Iā€™ll start off with investigating the additional queries, and when that is done, look into possible code inefficiencies. Additional queries never is a minor thing. Depending on the data/index situation these additional queries can add up a few seconds.

19

After investigating a bit, I found that the amount of queries is the same. Hibernate 6.2 generates array_contains predicates instead of in predicates in the lazy loading queries, but the performance seems equivalent. The only deviation I could notice is due to the use of a CriteriaQuery.

Hibernate 5 translates the criteria query to HQL and then re-parses that to then finally make use of a cached query plan based on that HQL.

Hibernate 6 on the other hand does not do that anymore, but instead re-translates the query plan. By altering the test to create the TypedQuery only once, the performance is almost the same. The difference is 0.5 - 1 second on my machine. I created [HHH-16782] - Hibernate JIRA to track the query plan caching for criteria queries.

Iā€™ll keep digging to find out what the rest of the performance drop is about and keep you posted.

20

Small correction, Hibernate 6 re-translates the query all the time even when reusing the TypedQuery. I quickly played around with caching the query plan and the performance obviously improves. On my machine, with caching, this runs 5 seconds faster than Hibernate 5.
Iā€™ll discuss with the team how to continue with this, but either way, please track [HHH-16782] - Hibernate JIRA for further progress. Also, please create a new discourse topic if something else comes up. This one is already way too big :slight_smile: