Excessive Hibernate overhead when using larger collections

nefilim · **Joined:** Wed Jan 28, 2004 3:42 pm **Posts:** 36

Hibernate version: 3.2.5 GA

I have some serious reservations about the scalability of Hibernate, here's why:

I am using Hibernate with a local (not distributed, yet) Coherence L2 & query cache, the cache high-units are set large enough so that all entities in question can fit into the cache. The Hibernate/Spring app is running on a 2.66Ghz Core2 Quad and the database is running on a Athlon X2 64 connected via gigabit ethernet.

When loading a collection on my User object with the following code:

Code:

        log.warn("GETTING CONTACTS");
        start = System.currentTimeMillis();
        Set<ContactAssociation> contacts = testUser.getContactAssociations();
        contacts.size(); // trigger proxy
        total = (System.currentTimeMillis() - start);
        log.warn("FOUND {} CONTACTS in {}ms", contacts.size(), total);

it will produce the following output on first run:

Code:

2007-12-22 22:33:20,684 [RMI TCP Connection(6)-192.168.100.3] WARN service.impl.UserServiceImpl - GETTING CONTACTS
2007-12-22 22:33:20,858 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 1 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: SET autocommit=0
2007-12-22 22:33:20,859 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,861 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.commit(NewProxyConnection.java:803) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: commit
2007-12-22 22:33:20,861 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.commit(NewProxyConnection.java:803) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,862 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 1 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: SET autocommit=1
2007-12-22 22:33:20,862 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,864 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: SET autocommit=0
2007-12-22 22:33:20,864 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,865 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.commit(NewProxyConnection.java:803) duration: 1 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: commit
2007-12-22 22:33:20,865 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.commit(NewProxyConnection.java:803) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,866 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: SET autocommit=1
2007-12-22 22:33:20,866 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,867 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: SET autocommit=0
2007-12-22 22:33:20,867 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,869 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.commit(NewProxyConnection.java:803) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: commit
2007-12-22 22:33:20,869 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.commit(NewProxyConnection.java:803) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:20,869 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0, message: SET autocommit=1
2007-12-22 22:33:20,870 [Compass Scheduled Optimizer] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyConnection.setAutoCommit(NewProxyConnection.java:881) duration: 0 ms, connection-id: 377, statement-id: 999, resultset-id: 0
2007-12-22 22:33:21,208 [RMI TCP Connection(6)-192.168.100.3] INFO MySQL - Profiler Event: [QUERY]    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76) duration: 183 ms, connection-id: 383, statement-id: 378, resultset-id: 646, message: select contactass0_.USER_ID as USER3_4_, contactass0_.CONTACT_ASSOCIATION_ID as CONTACT1_4_, contactass0_.CONTACT_ASSOCIATION_ID as CONTACT1_2_3_, contactass0_.LAST_MODIFIED as LAST2_2_3_, contactass0_.USER_ID as USER3_2_3_, contactass0_.CONTACT_ID as CONTACT4_2_3_, contactass0_.CREATED as CREATED2_3_, contactass0_.GROUP_ID as GROUP6_2_3_, user1_.USER_ID as USER1_1_0_, user1_.LAST_MODIFIED as LAST2_1_0_, user1_.GLOBAL_USER_ID as GLOBAL3_1_0_, user1_.USERNAME as USERNAME1_0_, user1_.PASSWORD as PASSWORD1_0_, user1_.SCREEN_NAME as SCREEN6_1_0_, user1_.CREATED as CREATED1_0_, user1_.AVAILABLE_INVITE_COUNT as AVAILABLE8_1_0_, user1_.ENABLED as ENABLED1_0_, user1_.PRIORITY_ACKNOWLEDGE_ID as PRIORITY10_1_0_, user1_.PROFILE_ID as PROFILE11_1_0_, profile2_.PROFILE_ID as PROFILE1_47_1_, profile2_.CREATED as CREATED47_1_, profile2_.LAST_MODIFIED as LAST3_47_1_, profile2_.avatar_FILE_STORE_ID as avatar17_47_1_, profile2_.DESCRIPTION as DESCRIPT4_47_1_, profile2_.DOB_DAY as DOB5_47_1_, profile2_.DOB_MONTH as DOB6_47_1_, profile2_.DOB_YEAR as DOB7_47_1_, profile2_.GENDER as GENDER47_1_, profile2_.LOCATION_CITY as LOCATION9_47_1_, profile2_.country_COUNTRY_ID as country18_47_1_, profile2_.LOCATION_STATE as LOCATION10_47_1_, profile2_.FIRST_NAME as FIRST11_47_1_, profile2_.LAST_NAME as LAST12_47_1_, profile2_.MIDDLE_NAME as MIDDLE13_47_1_, profile2_.TITLE as TITLE47_1_, profile2_.OCCUPATION as OCCUPATION47_1_, profile2_.USER_ID as USER16_47_1_, group3_.GROUP_ID as GROUP1_3_2_, group3_.LAST_MODIFIED as LAST2_3_2_, group3_.GLOBAL_GROUP_ID as GLOBAL3_3_2_, group3_.NAME as NAME3_2_, group3_.SHORT_NAME as SHORT5_3_2_, group3_.DESCRIPTION as DESCRIPT6_3_2_, group3_.TYPE as TYPE3_2_, group3_.SECURITY_MODEL as SECURITY8_3_2_, group3_.CREATED as CREATED3_2_, group3_.DELETED as DELETED3_2_, group3_.USER_ID as USER11_3_2_, group3_.FILE_STORE_ID as FILE12_3_2_, group3_.GROUP_CUSTOMIZATION_ID as GROUP13_3_2_ from CONTACT_ASSOCIATION contactass0_ inner join USER user1_ on contactass0_.CONTACT_ID=user1_.USER_ID left outer join PROFILE profile ... (truncated)
2007-12-22 22:33:21,208 [RMI TCP Connection(6)-192.168.100.3] INFO MySQL - Profiler Event: [FETCH]    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76) duration: 340 ms, connection-id: 383, statement-id: 378, resultset-id: 646
2007-12-22 22:33:21,209 [RMI TCP Connection(6)-192.168.100.3] INFO MySQL - Profiler Event: [SLOW QUERY]    at com.mchange.v2.c3p0.impl.NewProxyPreparedStatement.executeQuery(NewProxyPreparedStatement.java:76) duration: 183 ms, connection-id: 383, statement-id: 378, resultset-id: 646, message: The following query was executed with a bad index, use 'EXPLAIN' for more details: select contactass0_.USER_ID as USER3_4_, contactass0_.CONTACT_ASSOCIATION_ID as CONTACT1_4_, contactass0_.CONTACT_ASSOCIATION_ID as CONTACT1_2_3_, contactass0_.LAST_MODIFIED as LAST2_2_3_, contactass0_.USER_ID as USER3_2_3_, contactass0_.CONTACT_ID as CONTACT4_2_3_, contactass0_.CREATED as CREATED2_3_, contactass0_.GROUP_ID as GROUP6_2_3_, user1_.USER_ID as USER1_1_0_, user1_.LAST_MODIFIED as LAST2_1_0_, user1_.GLOBAL_USER_ID as GLOBAL3_1_0_, user1_.USERNAME as USERNAME1_0_, user1_.PASSWORD as PASSWORD1_0_, user1_.SCREEN_NAME as SCREEN6_1_0_, user1_.CREATED as CREATED1_0_, user1_.AVAILABLE_INVITE_COUNT as AVAILABLE8_1_0_, user1_.ENABLED as ENABLED1_0_, user1_.PRIORITY_ACKNOWLEDGE_ID as PRIORITY10_1_0_, user1_.PROFILE_ID as PROFILE11_1_0_, profile2_.PROFILE_ID as PROFILE1_47_1_, profile2_.CREATED as CREATED47_1_, profile2_.LAST_MODIFIED as LAST3_47_1_, profile2_.avatar_FILE_STORE_ID as avatar17_47_1_, profile2_.DESCRIPTION as DESCRIPT4_47_1_, profile2_.DOB_DAY as DOB5_47_1_, profile2_.DOB_MONTH as DOB6_47_1_, profile2_.DOB_YEAR as DOB7_47_1_, profile2_.GENDER as GENDER47_1_, profile2_.LOCATION_CITY as LOCATION9_47_1_, profile2_.country_COUNTRY_ID as country18_47_1_, profile2_.LOCATION_STATE as LOCATION10_47_1_, profile2_.FIRST_NAME as FIRST11_47_1_, profile2_.LAST_NAME as LAST12_47_1_, profile2_.MIDDLE_NAME as MIDDLE13_47_1_, profile2_.TITLE as TITLE47_1_, profile2_.OCCUPATION as OCCUPATION47_1_, profile2_.USER_ID as USER16_47_1_, group3_.GROUP_ID as GROUP1_3_2_, group3_.LAST_MODIFIED as LAST2_3_2_, group3_.GLOBAL_GROUP_ID as GLOBAL3_3_2_, group3_.NAME as NAME3_2_, group3_.SHORT_NAME as SHORT5_3_2_, group3_.DESCRIPTION as DESCRIPT6_3_2_, group3_.TYPE as TYPE3_2_, group3_.SECURITY_MODEL as SECURITY8_3_2_, group3_.CREATED as CREATED3_2_, group3_.DELETED as DELETED3_2_, group3_.USER_ID as USER11_3_2_, group3_.FILE_STORE_ID as FILE12_3_2_, group3_.GROUP_CUSTOMIZATION_ID as GROUP13_3_2_ from CONTACT_ASSOCIATION contactass0_ inner join USER user1_ on contactass0_.CONTACT_ID=user1_.USER_ID left outer join PROFILE profile ... (truncated)
2007-12-22 22:33:23,194 [RMI TCP Connection(6)-192.168.100.3] WARN service.impl.UserServiceImpl - FOUND 4772 CONTACTS in 2510ms

Note that the query to produce the data (which if I rewrote manually I can half the time again) took about 180ms and fetching the data from the database took about 340ms... what happened during the other 1990ms?!

Now running the same code a second time (using a new session)

Code:

2007-12-22 22:36:16,280 [RMI TCP Connection(8)-192.168.100.3] WARN service.impl.UserServiceImpl - GETTING CONTACTS
2007-12-22 22:36:17,018 [RMI TCP Connection(8)-192.168.100.3] WARN service.impl.UserServiceImpl - FOUND 4772 CONTACTS in 738ms

Notice no database queries were executed, the data is coming from the L2 cache (from the User.contactAssociations cache and the User & Profile entities cache). I can retrieve the same set of data from the Coherence cache in about 6ms, so the overhead is not with Coherence. Looking further with a profiler (JProfiler) I confirmed that 90% of this overheard is with Hibernate assembling objects from cache, using some sort of custom "serialization" reassembling entities from disassembled state. Realizing this collection of entities from cache is slower than it was from the database originally!!

Obviously this gets exponentially worse with large collections, with small collections it's relatively benign vs database time.

This is a specific example but our application is littered with them.

This amount of overhead seemingly makes Hibernate unsuitable for large applications needing to deal with 10,000s of concurrent users due to excessive cache assembly times and hence CPU usage.

john_gregg · **Joined:** Fri Dec 07, 2007 6:19 pm **Posts:** 2

I have similar concerns. Just recently we started using Hibernate (3.1) for data sets of hundreds or thousands of rows instead of the handful we had before and the performance is very poor. We're not using Hibernate-Coherence integration yet. Using JProbe, I can see that nearly all the time is divided between Loader.initializeEntitiesAndCollections() and Loader.getRowFromResultSet(). Together, those 2 calls account for 98% of the time on a 1000-row result. Statement.execute() and ResultSet.next() total account for only 8%.

I don't know what to do about this yet, other than to not use Hibernate for cases like this or to put Coherence in front of Hibernate and use either their inline or side cache patterns.

FWIW, I don't know how Hibernate uses Coherence exactly, but with Coherence if the caches are distributed (in other JVMs) it's critical for performance that you implement Externalizable or ExternalizableLite instead of Serializable. It's MUCH faster and much more compact.

john

gonzao_diaz · **Joined:** Mon Nov 26, 2007 2:29 pm **Posts:** 443

Guys, Hibernate has a lot of defects, but it is kind of unfair to blame it for not performing satisfactorily when asked to retrieve "hundred of thousands of records".

In principle, if ANY query returns that many records using ANY tool, you might want to probably revise your application design.

By the way, nefilim, if you are retrieving the size just for informational purposes, I would suggest issuing a HQL count(*) before or besides your main query.

I don't know the first thing about Convergence, but I am pretty sure those "thousands of concurrent users" won't require all the thousands of rows at the same time. Any chance to use the Hibernate's pagination capabilities, for example?

having thousands of concurrent users is perfectly OK, but there must be a way, in my opinion, to reduce the amount of data those users ask at a time.

nefilim · **Joined:** Wed Jan 28, 2004 3:42 pm **Posts:** 36

gonzao_diaz wrote:

Guys, Hibernate has a lot of defects, but it is kind of unfair to blame it for not performing satisfactorily when asked to retrieve "hundred of thousands of records".

nobody said "hundreds of thousands" ... hundreds OR thousands, it's really not asking that much retrieve a few thousands rows... from cache.

when working with 10,000+ concurrent users every milliseconds counts, spending 500ms or 1000ms on a single cached query will absolutely kill vertical scalability.

gonzao_diaz · **Joined:** Mon Nov 26, 2007 2:29 pm **Posts:** 443

I am sorry, I misread.

ytsedt · **Joined:** Tue Jun 24, 2008 9:41 am **Posts:** 1

Is there any traction/interest in this issue?

I've got an app that gets about 45,000 hits per hour. Each request loads a "Hibernated" object from cache and the CPU is about 17x more than just straight JDBC. I've actually got a DAO layer where I can switch between Hibernate and Spring JDBC with the flick of a switch, so our code is acting the same (thought maybe our code could be doing something to spike the cpu). The difference in the JDBC stuff is that we cache our own objects in pure form.

We even ran a shell script to consistently take top snapshots along with thread dumps. Out of all the threads that had high cpu in top, 85% of them were in the middle of initializing from cache. Just watching top, we've noticed that the threads are really short bursts of energy.

Now granted, we're still on ibm jdk 1.4.2 (i know!...don't ask!) but my assumption is that since we're limited to 1.5G of memory and the garbage collector is antiquated, this could be part of the problem.

Has anyone experienced this issue with the newer garbage collectors?

Also, would changing the Hibernate cache to read-only help? This application is read-only from the database, so I'm not too concerned with object synchronization