[hibernate-issues] [Hibernate-JIRA] Updated: (HHH-4838) 2L-Querycache ImmutableNaturalKeyLookup not properly recognized as hasImmutableNaturalId() is called on wrong EntityMetamodel

2L-Querycache ImmutableNaturalKeyLookup not properly recognized as hasImmutableNaturalId() is called on wrong EntityMetamodel ----------------------------------------------------------------------------------------------------------------------------- Key: HHH-4838 URL: http://opensource.atlassian.com/projects/hibernate/browse/HHH-4838 Project: Hibernate Core Issue Type: Bug Components: caching (L2) Affects Versions: 3.5.0-Beta-3 Environment: 3.5.0-Beta3, HSQLDB, EHCache as 2L cache implementation Reporter: Guenther Demetz Assignee: Gail Badner Fix For: 3.5.x, 3.6 Attachments: TestImmutableNaturalId.jar, TestImmutableNaturalKeyLookup.jar If a entityclass with immutable naturalId has non-lazy properties (for instance a OneToOne association), then more entityPersisters are involved in the query as it becomes a join-query eager loading the associated entity. The method Loader#getResultFromQueryCache presumes that the first entityPersister in the array is the main entity class. boolean isImmutableNaturalKeyLookup = queryParameters.isNaturalKeyLookup() && getEntityPersisters()[0].getEntityMetamodel().hasImmutableNaturalId(); Debugging attached testcase you can see indeed that getEntityPersisters()[0] returns SingleTableEntityPersister(hello.D) which is the persister of the associated entity, not the main one! Consequently the query is not considered as isImmutableNaturalKeyLookup, despite fullfilling all conditions. Here my output (with enabled p6spy): 11:53:15,651 INFO Version:37 - Hibernate Annotations 3.5.0.Beta1 11:53:15,690 INFO Environment:563 - Hibernate 3.5.0-Beta-3 11:53:15,694 INFO Environment:596 - hibernate.properties not found 11:53:15,700 INFO Environment:774 - Bytecode provider name : javassist 11:53:15,706 INFO Environment:655 - using JDK 1.4 java.sql.Timestamp handling 11:53:15,863 INFO Version:38 - Hibernate EntityManager 3.5.0.Beta1 11:53:16,356 INFO AnnotationBinder:446 - Binding entity from annotated class: hello.A 11:53:16,424 INFO EntityBinder:471 - Bind entity hello.A on table A 11:53:16,526 INFO AnnotationBinder:446 - Binding entity from annotated class: hello.D 11:53:16,527 INFO EntityBinder:471 - Bind entity hello.D on table D 11:53:16,686 WARN Ejb3Configuration:943 - hibernate.connection.autocommit = false break the EJB3 specification 11:53:16,702 INFO HibernateSearchEventListenerRegister:75 - Unable to find org.hibernate.search.event.FullTextIndexEventListener on the classpath. Hibernate Search is not enabled. 11:53:16,718 INFO DriverManagerConnectionProvider:64 - Using Hibernate built-in connection pool (not for production use!) 11:53:16,719 INFO DriverManagerConnectionProvider:65 - Hibernate connection pool size: 20 11:53:16,720 INFO DriverManagerConnectionProvider:68 - autocommit mode: false 11:53:16,921 INFO DriverManagerConnectionProvider:103 - using driver: com.p6spy.engine.spy.P6SpyDriver at URL: jdbc:hsqldb:hsql://localhost 11:53:16,922 INFO DriverManagerConnectionProvider:109 - connection properties: {user=sa, password=****, autocommit=false, release_mode=after_transaction} 11:53:17,002 INFO SettingsFactory:117 - RDBMS: HSQL Database Engine, version: 1.8.0 11:53:17,004 INFO SettingsFactory:118 - JDBC driver: HSQL Database Engine Driver, version: 1.8.0 11:53:17,068 INFO Dialect:223 - Using dialect: org.hibernate.dialect.HSQLDialect 11:53:17,082 INFO JdbcSupportLoader:79 - Disabling contextual LOB creation as JDBC driver reported JDBC version [3] less than 4 11:53:17,085 INFO TransactionFactoryFactory:62 - Transaction strategy: org.hibernate.transaction.JDBCTransactionFactory 11:53:17,089 INFO TransactionManagerLookupFactory:80 - No TransactionManagerLookup configured (in JTA environment, use of read-write or transactional second-level cache is not recommended) 11:53:17,090 INFO SettingsFactory:169 - Automatic flush during beforeCompletion(): disabled 11:53:17,091 INFO SettingsFactory:173 - Automatic session close at end of transaction: disabled 11:53:17,097 INFO SettingsFactory:188 - Scrollable result sets: enabled 11:53:17,098 INFO SettingsFactory:196 - JDBC3 getGeneratedKeys(): disabled 11:53:17,099 INFO SettingsFactory:204 - Connection release mode: after_transaction 11:53:17,101 INFO SettingsFactory:231 - Default batch fetch size: 1 11:53:17,103 INFO SettingsFactory:235 - Generate SQL with comments: disabled 11:53:17,104 INFO SettingsFactory:239 - Order SQL updates by primary key: disabled 11:53:17,105 INFO SettingsFactory:243 - Order SQL inserts for batching: disabled 11:53:17,107 INFO SettingsFactory:410 - Query translator: org.hibernate.hql.ast.ASTQueryTranslatorFactory 11:53:17,114 INFO SettingsFactory:251 - Query language substitutions: {} 11:53:17,115 INFO SettingsFactory:256 - JPA-QL strict compliance: enabled 11:53:17,121 INFO SettingsFactory:261 - Second-level cache: enabled 11:53:17,130 INFO SettingsFactory:265 - Query cache: enabled 11:53:17,143 INFO SettingsFactory:395 - Cache region factory : org.hibernate.cache.impl.bridge.RegionFactoryCacheProviderBridge 11:53:17,144 INFO RegionFactoryCacheProviderBridge:61 - Cache provider: net.sf.ehcache.hibernate.SingletonEhCacheProvider 11:53:17,150 INFO SettingsFactory:275 - Optimize cache for minimal puts: disabled 11:53:17,151 INFO SettingsFactory:284 - Structured second-level cache entries: disabled 11:53:17,151 INFO SettingsFactory:374 - Query cache factory: org.hibernate.cache.StandardQueryCacheFactory 11:53:17,165 INFO SettingsFactory:313 - Statistics: disabled 11:53:17,166 INFO SettingsFactory:317 - Deleted entity synthetic identifier rollback: disabled 11:53:17,166 INFO SettingsFactory:332 - Default entity-mode: pojo 11:53:17,167 INFO SettingsFactory:336 - Named query checking : enabled 11:53:17,167 INFO SettingsFactory:340 - Check Nullability in Core (should be disabled when Bean Validation is on): disabled 11:53:17,240 INFO SessionFactoryImpl:197 - building session factory 11:53:17,260 WARN ConfigurationFactory:131 - No configuration found. Configuring ehcache from ehcache-failsafe.xml found in the classpath: jar:file:/home/pb00067/Desktop/ehcache-1.7.1/lib/ehcache-core-1.7.1.jar!/ehcache-failsafe.xml 11:53:17,361 WARN SingletonEhCacheProvider:92 - Could not find a specific ehcache configuration for cache named [hello.A]; using defaults. 11:53:17,566 WARN SingletonEhCacheProvider:92 - Could not find a specific ehcache configuration for cache named [hello.D]; using defaults. 11:53:17,661 INFO SchemaExport:226 - Running hbm2ddl schema export 11:53:17,663 INFO SchemaExport:251 - exporting generated schema to database p6spy - 1264416797664|0|0|commit|| p6spy - 1264416797670|1|0|statement alter table A drop constraint FK41F7BDC12E p6spy - 1264416797672|0|0|statement drop table A if exists p6spy - 1264416797673|0|0|statement drop table D if exists p6spy - 1264416797674|1|0|statement drop table hibernate_sequences if exists p6spy - 1264416797675|1|0|statement create table A (oid bigint not null, name varchar(255), version integer not null, assSingleD_oid bigint, primary key (oid), unique (name)) p6spy - 1264416797676|0|0|statement create table D (oid bigint not null, version integer not null, primary key (oid)) p6spy - 1264416797678|1|0|statement alter table A add constraint FK41F7BDC12E foreign key (assSingleD_oid) references D p6spy - 1264416797679|1|0|statement create table hibernate_sequences ( sequence_name varchar(255), sequence_next_hi_value integer ) 11:53:17,679 INFO SchemaExport:268 - schema export complete 11:53:17,684 INFO UpdateTimestampsCache:57 - starting update timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache 11:53:17,686 WARN SingletonEhCacheProvider:92 - Could not find a specific ehcache configuration for cache named [org.hibernate.cache.UpdateTimestampsCache]; using defaults. 11:53:17,689 INFO StandardQueryCache:75 - starting query cache at region: org.hibernate.cache.StandardQueryCache 11:53:17,690 WARN SingletonEhCacheProvider:92 - Could not find a specific ehcache configuration for cache named [org.hibernate.cache.StandardQueryCache]; using defaults. 11:53:17,841 DEBUG ConnectionManager:444 - opening JDBC connection p6spy - 1264416797874|6|1|statement select sequence_next_hi_value from hibernate_sequences where sequence_name = 'A' p6spy - 1264416797876|0|1|statement insert into hibernate_sequences (sequence_name, sequence_next_hi_value) values ('A', 0) p6spy - 1264416797878|0|1|statement update hibernate_sequences set sequence_next_hi_value = 1 where sequence_next_hi_value = 0 and sequence_name = 'A' p6spy - 1264416797879|0|1|commit|| p6spy - 1264416797915|0|0|statement insert into A (assSingleD_oid, name, version, oid) values ('', 'name1', 0, 1) 11:53:17,919 DEBUG UpdateTimestampsCache:66 - Pre-invalidating space [A] p6spy - 1264416797931|0|0|commit|| 11:53:17,934 DEBUG UpdateTimestampsCache:81 - Invalidating space [A], timestamp: 5179051204337665 11:53:17,974 DEBUG StandardQueryCache:127 - checking cached query results in region: org.hibernate.cache.StandardQueryCache 11:53:17,975 DEBUG StandardQueryCache:132 - query results were not found in cache p6spy - 1264416797978|0|0|statement select this_.oid as oid0_1_, this_.assSingleD_oid as assSingleD4_0_1_, this_.name as name0_1_, this_.version as version0_1_, d2_.oid as oid1_0_, d2_.version as version1_0_ from A this_ left outer join D d2_ on this_.assSingleD_oid=d2_.oid where ( this_.name='name1' ) p6spy - 1264416797981|-1||resultset|oid=1, oid=null 11:53:17,985 DEBUG StandardQueryCache:94 - caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=5179051204546560 11:53:17,992 DEBUG StandardQueryCache:127 - checking cached query results in region: org.hibernate.cache.StandardQueryCache 11:53:17,993 DEBUG StandardQueryCache:185 - Checking query spaces for up-to-dateness: [A] 11:53:17,994 DEBUG UpdateTimestampsCache:102 - [A] last update timestamp: 5179051204337665, result set timestamp: 5179051204546560 11:53:17,994 DEBUG StandardQueryCache:142 - returning cached query results 11:53:17,997 INFO SessionFactoryImpl:908 - closing