I’ve posted this question at SO already but haven’t got any answers yet - java - Hibernate performs N+1 selects instead of 1 query when using the Query Cache - Stack Overflow.
I use query cache + second-level cache and I want to cache results for 10 seconds properly. So here is my
ehcache.xml:
<ehcache xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:noNamespaceSchemaLocation="../config/ehcache.xsd">
<diskStore path="java.io.tmpdir"/>
<cache name = "TestEntity"
maxElementsInMemory="100"
eternal="false"
timeToLiveSeconds="10"
memoryStoreEvictionPolicy="LRU">
</cache>
<cache name="org.hibernate.cache.internal.StandardQueryCache"
maxElementsInMemory="100"
eternal="false"
timeToLiveSeconds="10"
memoryStoreEvictionPolicy="LRU">
</cache>
<defaultCache
maxElementsInMemory="10000"
eternal="false"
timeToLiveSeconds="120"
maxElementsOnDisk="100"
diskExpiryThreadIntervalSeconds="120"
memoryStoreEvictionPolicy="LRU">
<persistence strategy="localTempSwap"/>
</defaultCache>
</ehcache>
First, I populate my database using the insert() method.
Then, I call my select() method to get data for the first time. Everything works fine - query and the entities become cached and if I call the select() method 2 seconds later I’ll get the data without any requests to the database.
Then I wait for 11 seconds (in order for cache to expire completely), call select() and 2 seconds after call select() again. And that’s where I get n+1 selects:
2019-02-13 18:52:17,101 [DEBUG]
org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:92)
select testentity0_.id as id1_0_0_, testentity0_.value as value2_0_0_
from test testentity0_ where testentity0_.id=? 2019-02-13 18:52:17,107
[DEBUG]
org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:92)
select testentity0_.id as id1_0_0_, testentity0_.value as value2_0_0_
from test testentity0_ where testentity0_.id=? 2019-02-13 18:52:17,108
[DEBUG]
org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:92)
select testentity0_.id as id1_0_0_, testentity0_.value as value2_0_0_
from test testentity0_ where testentity0_.id=? 2019-02-13 18:52:17,108
[DEBUG]
org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:92)
select testentity0_.id as id1_0_0_, testentity0_.value as value2_0_0_
from test testentity0_ where testentity0_.id=? 2019-02-13 18:52:17,109
[DEBUG]
org.hibernate.engine.jdbc.spi.SqlStatementLogger.logStatement(SqlStatementLogger.java:92)
select testentity0_.id as id1_0_0_, testentity0_.value as value2_0_0_
from test testentity0_ where testentity0_.id=?
I know that these requests are made because query cache caches only ids and it seems that entities for these ids are missing in the second level cache. But why are they missing? When I enable full logging I see that after third call to select() there are log entries like
Adding entity to second-level cache: [TestEntity#1]
So if entities are added to second level cache and they should expire only in 10 seconds, why are they missing just after 2?
Part of my pom.xml:
<dependencies>
<dependency>
<groupId>com.h2database</groupId>
<artifactId>h2</artifactId>
<version>1.4.194</version>
</dependency>
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate-core</artifactId>
<version>5.2.7.Final</version>
</dependency>
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate-ehcache</artifactId>
<version>5.2.7.Final</version>
</dependency>
<dependency>
<groupId>org.hibernate</groupId>
<artifactId>hibernate-c3p0</artifactId>
<version>5.2.7.Final</version>
</dependency>
</dependencies>
persistence.xml:
<persistence xmlns="http://java.sun.com/xml/ns/persistence"
xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance"
xsi:schemaLocation="http://java.sun.com/xml/ns/persistence http://java.sun.com/xml/ns/persistence/persistence_2_0.xsd"
version="2.0">
<persistence-unit name="main">
<class>TestEntity</class>
<exclude-unlisted-classes>true</exclude-unlisted-classes>
<properties>
<property name="hibernate.hbm2ddl.auto" value="create-drop"/>
<property name="hibernate.use_sql_comments" value="true"/>
<property name="hibernate.cache.use_second_level_cache" value="true"/>
<property name="hibernate.cache.region.factory_class" value="org.hibernate.cache.ehcache.EhCacheRegionFactory"/>
<property name="hibernate.cache.use_query_cache" value="true"/>
<property name="net.sf.ehcache.configurationResourceName" value="ehcache.xml"/>
</properties>
</persistence-unit>
</persistence>
TestEntity.java:
import org.hibernate.annotations.CacheConcurrencyStrategy;
import javax.persistence.*;
/**
* User: Kirill Smirnov (k.smirnov@sirena2000.ru)
* Date: 18.12.18
* Time: 19:20
*/
@Entity
@Table(name = "test")
@Cacheable
@org.hibernate.annotations.Cache(usage = CacheConcurrencyStrategy.READ_ONLY)
public class TestEntity {
@Id
@GeneratedValue(generator = "test_seq")
@SequenceGenerator(name = "test_seq", sequenceName="TEST_SEQ")
@Column(name = "id")
private int id;
@Column(name = "value", nullable = false)
private String value;
public TestEntity() {
}
public TestEntity(String value) {
this.value = value;
}
public int getId() {
return id;
}
public void setId(int id) {
this.id = id;
}
public String getValue() {
return value;
}
public void setValue(String value) {
this.value = value;
}
}
Main.java:
import javax.persistence.EntityManager;
import javax.persistence.EntityManagerFactory;
import javax.persistence.Persistence;
import javax.persistence.TypedQuery;
import java.util.Properties;
/**
* User: Kirill Smirnov (k.smirnov@sirena2000.ru)
* Date: 14.11.14
* Time: 15:55
*/
public class Main {
public static void main(String[] args) throws Exception {
Properties entityManagerFactoryProperties = new Properties();
entityManagerFactoryProperties.setProperty("javax.persistence.jdbc.driver", "org.h2.Driver");
entityManagerFactoryProperties.setProperty("javax.persistence.jdbc.url", "jdbc:h2:mem:");
entityManagerFactoryProperties.setProperty("javax.persistence.jdbc.user", "sa");
entityManagerFactoryProperties.setProperty("javax.persistence.jdbc.password", "");
entityManagerFactoryProperties.setProperty("hibernate.c3p0.min_size", "" + 1);
entityManagerFactoryProperties.setProperty("hibernate.c3p0.max_size", "" + 1);
entityManagerFactoryProperties.setProperty("hibernate.c3p0.timeout", "" + 5000);
EntityManagerFactory entityManagerFactory = Persistence.createEntityManagerFactory("main", entityManagerFactoryProperties);
insert(entityManagerFactory);
select(entityManagerFactory);
Thread.sleep(2000);
select(entityManagerFactory);
Thread.sleep(11000);
select(entityManagerFactory);
Thread.sleep(2000);
select(entityManagerFactory);
entityManagerFactory.close();
}
private static void insert(EntityManagerFactory entityManagerFactory) {
EntityManager entityManager = entityManagerFactory.createEntityManager();
entityManager.getTransaction().begin();
try {
entityManager.persist(new TestEntity("1"));
entityManager.persist(new TestEntity("2"));
entityManager.persist(new TestEntity("3"));
entityManager.persist(new TestEntity("4"));
entityManager.persist(new TestEntity("5"));
entityManager.getTransaction().commit();
} catch (Exception e) {
entityManager.getTransaction().rollback();
throw e;
} finally {
entityManager.close();
}
}
private static void select(EntityManagerFactory entityManagerFactory) {
EntityManager entityManager = entityManagerFactory.createEntityManager();
entityManager.getTransaction().begin();
try {
String queryText = "FROM TestEntity";
TypedQuery<TestEntity> query = entityManager.createQuery(queryText, TestEntity.class).setHint("org.hibernate.cacheable", true);
query.getResultList();
entityManager.getTransaction().commit();
} catch (Exception e) {
entityManager.getTransaction().rollback();
throw e;
} finally {
entityManager.close();
}
}
}