Declaring Collections ExpensiveI was able to confirm that declaring many Collections, even lazy ones, is expensive and the expense is a function of the number of collection properties declared. The expense comes from CollectionType.assemble(). Here are two profiler snapshot of exactly the same client code (see 1st post above for pseudo-code). the only difference is, in the 1st snapshot, User class has 20 @OneToMany's, in the second - 1. Please note that in both cases the client code accesses only one collection.
User class with 20 @OneToMany's declaredCode:
Merged callees
+-------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+-----------------+--------------------+
| Name | Time (ms) | Own Time (ms) | Invocation Count |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+-----------------+--------------------+
| +---org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(LoadEvent, EntityPersister, LoadEventListener$LoadType) | 984 100 % | 0 | 199 |
| | | | | |
| +---org.hibernate.event.def.DefaultLoadEventListener.assembleCacheEntry(CacheEntry, Serializable, EntityPersister, LoadEvent) | 781 79 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.cache.entry.CacheEntry.assemble(Object, Serializable, EntityPersister, Interceptor, EventSource) | 640 65 % | 0 | 199 |
| | | | | | | |
| | | +---org.hibernate.cache.entry.CacheEntry.assemble(Serializable[], Object, Serializable, EntityPersister, Interceptor, EventSource) | 640 65 % | 31 | 199 |
| | | | | | | |
| | | +---org.hibernate.type.TypeFactory.assemble(Serializable[], Type[], SessionImplementor, Object) | 484 49 % | 0 | 199 |
| | | | | | | | |
| | | | +---org.hibernate.type.CollectionType.assemble(Serializable, SessionImplementor, Object) | 453 46 % | 31 | 2,198 |
| | | | | | | | |
| | | | +---org.hibernate.type.AbstractType.assemble(Serializable, SessionImplementor, Object) | 31 3 % | 0 | 3,289 |
| | | | | | | |
| | | +---org.hibernate.persister.entity.AbstractEntityPersister.setPropertyValues(Object, Object[], EntityMode) | 125 13 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.persister.entity.AbstractEntityPersister.afterInitialize(Object, boolean, SessionImplementor) | 46 5 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.type.TypeFactory.deepCopy(Object[], Type[], boolean[], Object[], SessionImplementor) | 46 5 % | 15 | 199 |
| | | | | | |
| | +---org.hibernate.impl.SessionImpl.instantiate(EntityPersister, Serializable) | 31 3 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.engine.TwoPhaseLoad.addUninitializedCachedEntity(EntityKey, Object, EntityPersister, LockMode, boolean, Object, SessionImplementor) | 15 2 % | 0 | 199 |
| | | | | |
| +---org.hibernate.cache.jbc2.entity.TransactionalAccess.get(Object, long) | 156 16 % | 0 | 199 |
| | | | | |
| +---org.hibernate.cache.entry.StructuredCacheEntry.destructure(Object, SessionFactoryImplementor) | 46 5 % | 0 | 199 |
+-------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+-----------------+--------------------+
Generated by YourKit Java Profiler 8.0.7 May 25, 2009 4:35:43 PM
User class with 1 @OneToMany declaredCode:
Merged callees
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+-----------------+--------------------+
| Name | Time (ms) | Own Time (ms) | Invocation Count |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+-----------------+--------------------+
| +---org.hibernate.event.def.DefaultLoadEventListener.loadFromSecondLevelCache(LoadEvent, EntityPersister, LoadEventListener$LoadType) | 546 100 % | 0 | 199 |
| | | | | |
| +---org.hibernate.event.def.DefaultLoadEventListener.assembleCacheEntry(CacheEntry, Serializable, EntityPersister, LoadEvent) | 281 51 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.cache.entry.CacheEntry.assemble(Object, Serializable, EntityPersister, Interceptor, EventSource) | 171 31 % | 0 | 199 |
| | | | | | | |
| | | +---org.hibernate.cache.entry.CacheEntry.assemble(Serializable[], Object, Serializable, EntityPersister, Interceptor, EventSource) | 171 31 % | 15 | 199 |
| | | | | | | |
| | | +---org.hibernate.type.TypeFactory.assemble(Serializable[], Type[], SessionImplementor, Object) | 93 17 % | 0 | 199 |
| | | | | | | | |
| | | | +---org.hibernate.type.CollectionType.assemble(Serializable, SessionImplementor, Object) | 62 11 % | 0 | 298 |
| | | | | | | | |
| | | | +---org.hibernate.type.AbstractType.assemble(Serializable, SessionImplementor, Object) | 31 6 % | 0 | 3,289 |
| | | | | | | |
| | | +---org.hibernate.persister.entity.AbstractEntityPersister.setPropertyValues(Object, Object[], EntityMode) | 62 11 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.impl.SessionImpl.instantiate(EntityPersister, Serializable) | 31 6 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.persister.entity.AbstractEntityPersister.afterInitialize(Object, boolean, SessionImplementor) | 15 3 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.engine.TwoPhaseLoad.addUninitializedCachedEntity(EntityKey, Object, EntityPersister, LockMode, boolean, Object, SessionImplementor) | 15 3 % | 0 | 199 |
| | | | | | |
| | +---org.slf4j.impl.Log4jLoggerAdapter.isTraceEnabled() | 15 3 % | 15 | 398 |
| | | | | | |
| | +---org.hibernate.engine.StatefulPersistenceContext.addEntry(Object, Status, Object[], Object, Serializable, Object, LockMode, boolean, EntityPersister, boolean, boolean) | 15 3 % | 0 | 199 |
| | | | | | |
| | +---org.hibernate.type.TypeFactory.deepCopy(Object[], Type[], boolean[], Object[], SessionImplementor) | 15 3 % | 0 | 199 |
| | | | | |
| +---org.hibernate.cache.jbc2.entity.TransactionalAccess.get(Object, long) | 234 43 % | 0 | 199 |
| | | | | |
| +---org.hibernate.cache.CacheKey.<init>(Serializable, Type, String, EntityMode, SessionFactoryImplementor) | 15 3 % | 15 | 199 |
| | | | | |
| +---org.hibernate.stat.StatisticsImpl.secondLevelCacheHit(String) | 15 3 % | 0 | 199 |
+----------------------------------------------------------------------------------------------------------------------------------------------------------------------------------+--------------+-----------------+--------------------+
Generated by YourKit Java Profiler 8.0.7 May 25, 2009 4:38:19 PM
So what now?Don't really know - but the fact that 2.5x more is spent in CollectionType.assemble for collections that don't end up getting used in a service method then in fetching the data from 2nd level cache is a critical Hibernate perf problem IMO. The ideal would be to:
* stash serialized states representing collection properties during assembleCacheEntry
* call CollectionType.assemble lazily when collection property field is actually accessed (a la lazy properties)
Does anyone have other suggestions?
thanks!