I'm stuck with a problem, I feel really lost and don't know what to do. 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="11"
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 12 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 11 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(12000);
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();
}
}
}
P.S. I guess the reason of the problem is a bug in Hibernate. If I upgrade from 5.2 to 5.4 the problem goes away. However I accept the Vlad's answer because it contains helpful information in general.
This is the infamous N+1 Query Cache issue.
You have to make sure that the TTL (Time To Live) for the Entity Cache region is higher than the TTL of the Query Cache or Collection Cache.
Otherwise, Hibernate will find the entity identifiers in the Query Cache or Collection Cache and will assume that the entities were already stored in the Entity Cache region. But if the entities are not found in the Entity Cache, then they can only be fetched from the DB, therefore triggering an N+1 query issue.
Now, back to your settings. This is what you set for the Entity Cache region:
<cache name = "TestEntity"
maxElementsInMemory="100"
eternal="false"
timeToLiveSeconds="10"
memoryStoreEvictionPolicy="LRU">
</cache>
Notice the timeToLiveSeconds is set to 10 seconds only.
The QueryCache is set like this:
<cache name="org.hibernate.cache.internal.StandardQueryCache"
maxElementsInMemory="100"
eternal="false"
timeToLiveSeconds="10"
memoryStoreEvictionPolicy="LRU">
</cache>
So the timeToLiveSeconds is also set to 10 seconds and make sure that the Entity Query Cache is not set to expire sooner than the Query Cache and the associated Collection Cache.
Next, raise the timeToLiveSeconds for the TestEntity to 60 or 120 seconds. Or make it eternal = true and disable the TTL as the entity is using the CacheConcurrencyStartegy.READ_ONLY.
<cache name = "TestEntity"
maxElementsInMemory="100"
eternal="false"
timeToLiveSeconds="60"
memoryStoreEvictionPolicy="LRU">
</cache>