2

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.

0

1 Answer 1

2

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>
8
  • 1
    I've read your article before asking the question but I'm not sure that that's the issue here. Before the third call to select(), cache is completely empty - both Query Cache and Collection Cache. And in the logs I see that both caches get populated after the third call. But if I call select() two seconds after I'll get n+1 selects which is a surprise to me because just two seconds have passed. I tried to make TTL of Collection cache higher - 11 seconds instead of 10, and left TTL of Query Cache 10 seconds and made sleep for 12 seconds. And I still get this behavior :( Feb 14, 2019 at 9:40
  • Wait a bit please, I'll rewrite my post with new TTLs to demonstrate that the problem stays. Feb 14, 2019 at 9:42
  • I even tried 60 seconds TTL for entity and 10 seconds for query (and increased sleep to 61 seconds in order for cache to expire completely) - the problem still stays... Feb 14, 2019 at 9:48
  • Send me a Pull Request with the test case that proves the issue. Use the QueryCacheNPlus1Test as a template. Feb 14, 2019 at 9:50
  • Hmm, it seems there is a bug in 5.2.7. I made a test in your project and everything has worked just fined. Then I tried your version 5.4.1 in my project and everything became ok as well. But it's pretty hard to make a test in your project with 5.2.7, there are lots of imports that are missing. Feb 14, 2019 at 10:49

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge that you have read and understand our privacy policy and code of conduct.

Not the answer you're looking for? Browse other questions tagged or ask your own question.