Query performance regressions in Hibernate 6

[theigl]

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:

• HHH-15854 Performance tests demonstrating regressions in Hibernate 6 (Branch 5.6) by theigl · Pull Request #5741 · hibernate/hibernate-orm · GitHub
• HHH-15854 Performance tests demonstrating regressions in Hibernate 6 (Branch 6.1) by theigl · Pull Request #5742 · hibernate/hibernate-orm · GitHub
• HHH-15854 Performance tests demonstrating regressions in Hibernate 6 (Main) by theigl · Pull Request #6281 · hibernate/hibernate-orm · GitHub

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.

[beikov]

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

[theigl]

That’s great news, thanks @beikov!

[theigl]

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.

[theigl]

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:

And this is the corresponding data for Hibernate 6.2.2:

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

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

[beikov]

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.

[theigl]

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.