hibernate二级缓存测试

SessionFactory类：

import org.hibernate.Session;import org.hibernate.SessionFactory;import org.hibernate.cfg.Configuration;import org.hibernate.stat.Statistics;public class HibernateSessionFactory {    private static String CONFIG_FILE_LOCATION = "/hibernate.cfg.xml";    private static final ThreadLocal<Session> threadLocal = new ThreadLocal<Session>();    private static Configuration configuration = new Configuration();    private static SessionFactory sessionFactory;    private static String configFile = CONFIG_FILE_LOCATION;    static {        sessionFactory = configuration.configure(configFile).buildSessionFactory();    }    private HibernateSessionFactory(){    }    public static Session getSession(){        Session session = threadLocal.get();        if(session == null || !session.isOpen()){            session = (sessionFactory != null) ? sessionFactory.openSession():null;            threadLocal.set(session);        }        return session;    }    public static Statistics getstat(){        return sessionFactory.getStatistics();    }    public static void close(){        sessionFactory.close();    }}

在Stu.hbm.xml中加入（必须在配置id前完成）

<cache usage="read-write"/>

在hibernate.cfg.xml加入二级缓存配置

<!-- 设置二级缓存插件EHCache的Provider类-->        <property name="hibernate.cache.provider_class">            net.sf.ehcache.hibernate.EhCacheProvider        </property>        <!-- 启动"查询缓存" -->        <property name="hibernate.cache.use_query_cache">          true        </property>        <!-- 高速缓存提供程序 -->          <property name="hibernate.cache.region.factory_class">         org.hibernate.cache.ehcache.EhCacheRegionFactory       </property><!-- 开启二级缓存 -->         <property name="hibernate.cache.use_second_level_cache">true</property>         <!-- 强制Hibernate以更人性化的格式将数据存入二级缓存 -->          <property name="hibernate.cache.use_structured_entries">true</property>         <property name="current_session_context_class">thread</property>        <property name="hibernate.generate_statistics">true</property>

Scenario1：
开启查询缓存，开启二级缓存

import model.Stu;import org.hibernate.Query;import org.hibernate.Session;import org.hibernate.Transaction;import org.hibernate.stat.Statistics;public class CacheTest {    public static void main(String[] args) {        eacheTest();    }    public static void eacheTest(){        Session s1 = HibernateSessionFactory.getSession();        s1.beginTransaction();        System.out.println("Search Stu first time.");        Query q = s1.createQuery("from Stu");        //启用查询缓存        //Enable/disable second level query (result) caching for this query.        q.setCacheable(true);        q.list();//      q.iterate();        System.out.println("put int level-two eache.");        s1.getTransaction().commit();        s1.close();        System.out.println("-------------------------------------");        Session s2 = HibernateSessionFactory.getSession();        s2.beginTransaction();        System.out.println("Search Stu second time, don't execute sql");        Query q2 = s2.createQuery("from Stu");        //启用查询缓存        q2.setCacheable(true);        q2.list();//      q2.iterate();        s2.getTransaction().commit();        s2.close();        System.out.println("-------------------------------------");        Session s3 = HibernateSessionFactory.getSession();        Stu  stu = (Stu) s3.get(Stu.class, 1);        Stu  stu2 = (Stu) s3.get(Stu.class, 1);        Stu stu3 = (Stu)s3.get(Stu.class, 2);        System.out.println(stu.getSname());        System.out.println(stu2.getSname());        System.out.println(stu3.getSname());        s3.close();        System.out.println("-------------------------------------");        Statistics s = HibernateSessionFactory.getstat();        s.logSummary();        HibernateSessionFactory.close();    }}

运行结果：

Search Stu first time.08-13 16:23:25.772 org.hibernate.cache.internal.StandardQueryCache DEBUG - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache08-13 16:23:25.772 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f208-13 16:23:25.772 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - Element for key sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 is null08-13 16:23:25.773 org.hibernate.cache.internal.StandardQueryCache DEBUG - Query results were not found in cacheHibernate:     select        stu0_.sno as sno1_2_,        stu0_.sname as sname2_2_,        stu0_.sex as sex3_2_,        stu0_.age as age4_2_,        stu0_.sdept as sdept5_2_     from        test.stu stu0_08-13 16:23:25.841 org.hibernate.cache.internal.StandardQueryCache DEBUG - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=589600442712473608-13 16:23:25.842 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [5896004427124736, 1, 2, 3, 4, 6, 7]put int level-two eache.08-13 16:23:25.851 org.hibernate.engine.internal.StatisticalLoggingSessionEventListener INFO  - Session Metrics {    29941 nanoseconds spent acquiring 1 JDBC connections;    0 nanoseconds spent releasing 0 JDBC connections;    17828019 nanoseconds spent preparing 1 JDBC statements;    1520136 nanoseconds spent executing 1 JDBC statements;    0 nanoseconds spent executing 0 JDBC batches;    8472812 nanoseconds spent performing 7 L2C puts;    0 nanoseconds spent performing 0 L2C hits;    568019 nanoseconds spent performing 1 L2C misses;    6330335 nanoseconds spent executing 1 flushes (flushing a total of 6 entities and 0 collections);    62448 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)}-------------------------------------Search Stu second time, don't execute sql08-13 16:23:25.854 org.hibernate.cache.internal.StandardQueryCache DEBUG - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache08-13 16:23:25.855 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f208-13 16:23:25.855 org.hibernate.cache.internal.StandardQueryCache DEBUG - Checking query spaces are up-to-date: [test.stu]08-13 16:23:25.855 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: test.stu08-13 16:23:25.855 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - Element for key test.stu is null08-13 16:23:25.855 org.hibernate.cache.internal.StandardQueryCache DEBUG - Returning cached query results08-13 16:23:25.863 org.hibernate.engine.internal.StatisticalLoggingSessionEventListener INFO  - Session Metrics {    8554 nanoseconds spent acquiring 1 JDBC connections;    0 nanoseconds spent releasing 0 JDBC connections;    0 nanoseconds spent preparing 0 JDBC statements;    0 nanoseconds spent executing 0 JDBC statements;    0 nanoseconds spent executing 0 JDBC batches;    0 nanoseconds spent performing 0 L2C puts;    2024852 nanoseconds spent performing 7 L2C hits;    233966 nanoseconds spent performing 1 L2C misses;    432003 nanoseconds spent executing 1 flushes (flushing a total of 6 entities and 0 collections);    8127 nanoseconds spent executing 1 partial-flushes (flushing a total of 0 entities and 0 collections)}-------------------------------------zhszhslisi08-13 16:23:25.866 org.hibernate.engine.internal.StatisticalLoggingSessionEventListener INFO  - Session Metrics {    0 nanoseconds spent acquiring 0 JDBC connections;    0 nanoseconds spent releasing 0 JDBC connections;    0 nanoseconds spent preparing 0 JDBC statements;    0 nanoseconds spent executing 0 JDBC statements;    0 nanoseconds spent executing 0 JDBC batches;    0 nanoseconds spent performing 0 L2C puts;    68864 nanoseconds spent performing 2 L2C hits;    0 nanoseconds spent performing 0 L2C misses;    0 nanoseconds spent executing 0 flushes (flushing a total of 0 entities and 0 collections);    0 nanoseconds spent executing 0 partial-flushes (flushing a total of 0 entities and 0 collections)}-------------------------------------08-13 16:23:25.866 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000161: Logging statistics....08-13 16:23:25.866 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000251: Start time: 143945420539808-13 16:23:25.866 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000242: Sessions opened: 308-13 16:23:25.866 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000241: Sessions closed: 308-13 16:23:25.867 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000266: Transactions: 208-13 16:23:25.867 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000258: Successful transactions: 208-13 16:23:25.867 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000187: Optimistic lock failures: 008-13 16:23:25.867 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000105: Flushes: 208-13 16:23:25.867 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000048: Connections obtained: 208-13 16:23:25.867 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000253: Statements prepared: 108-13 16:23:25.868 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000252: Statements closed: 008-13 16:23:25.868 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000239: Second level cache puts: 608-13 16:23:25.868 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000237: Second level cache hits: 808-13 16:23:25.868 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000238: Second level cache misses: 008-13 16:23:25.868 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000079: Entities loaded: 608-13 16:23:25.868 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000080: Entities updated: 008-13 16:23:25.869 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000078: Entities inserted: 008-13 16:23:25.869 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000076: Entities deleted: 008-13 16:23:25.869 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000077: Entities fetched (minimize this): 008-13 16:23:25.869 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000033: Collections loaded: 008-13 16:23:25.869 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000036: Collections updated: 008-13 16:23:25.869 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000035: Collections removed: 008-13 16:23:25.869 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000034: Collections recreated: 008-13 16:23:25.870 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000032: Collections fetched (minimize this): 008-13 16:23:25.870 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000438: NaturalId cache puts: 008-13 16:23:25.870 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000439: NaturalId cache hits: 008-13 16:23:25.870 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000440: NaturalId cache misses: 008-13 16:23:25.870 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000441: Max NaturalId query time: 0ms08-13 16:23:25.871 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000442: NaturalId queries executed to database: 008-13 16:23:25.871 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000210: Queries executed to database: 108-13 16:23:25.871 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000215: Query cache puts: 108-13 16:23:25.871 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000433: update timestamps cache puts: 008-13 16:23:25.871 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000434: update timestamps cache hits: 008-13 16:23:25.871 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000435: update timestamps cache misses: 108-13 16:23:25.872 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000213: Query cache hits: 108-13 16:23:25.872 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000214: Query cache misses: 108-13 16:23:25.872 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000173: Max query time: 67ms08-13 16:23:25.885 org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl INFO  - HHH000030: Cleaning up connection pool [jdbc:mysql://localhost:3306/test]

Scenario2：
开启查询缓存，关闭二级缓存。

运行结果：

Search Stu first time.08-13 17:10:58.560 org.hibernate.cache.internal.StandardQueryCache DEBUG - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache08-13 17:10:58.560 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f208-13 17:10:58.560 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - Element for key sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 is null08-13 17:10:58.561 org.hibernate.cache.internal.StandardQueryCache DEBUG - Query results were not found in cacheHibernate:     select        stu0_.sno as sno1_2_,        stu0_.sname as sname2_2_,        stu0_.sex as sex3_2_,        stu0_.age as age4_2_,        stu0_.sdept as sdept5_2_     from        test.stu stu0_08-13 17:10:58.620 org.hibernate.cache.internal.StandardQueryCache DEBUG - Caching query results in region: org.hibernate.cache.internal.StandardQueryCache; timestamp=589601611210752008-13 17:10:58.621 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f2 value: [5896016112107520, 1, 2, 3, 4, 6, 7]-------------------------------------Search Stu second time, don't execute sql08-13 17:10:58.632 org.hibernate.cache.internal.StandardQueryCache DEBUG - Checking cached query results in region: org.hibernate.cache.internal.StandardQueryCache08-13 17:10:58.632 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: sql: select stu0_.sno as sno1_2_, stu0_.sname as sname2_2_, stu0_.sex as sex3_2_, stu0_.age as age4_2_, stu0_.sdept as sdept5_2_ from test.stu stu0_; parameters: ; named parameters: {}; transformer: org.hibernate.transform.CacheableResultTransformer@110f208-13 17:10:58.632 org.hibernate.cache.internal.StandardQueryCache DEBUG - Checking query spaces are up-to-date: [test.stu]08-13 17:10:58.632 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - key: test.stu08-13 17:10:58.632 org.hibernate.cache.ehcache.internal.regions.EhcacheGeneralDataRegion DEBUG - Element for key test.stu is null08-13 17:10:58.633 org.hibernate.cache.internal.StandardQueryCache DEBUG - Returning cached query results-------------------------------------zhszhslisi-------------------------------------08-13 17:10:58.641 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000161: Logging statistics....08-13 17:10:58.641 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000251: Start time: 143945705825508-13 17:10:58.641 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000242: Sessions opened: 008-13 17:10:58.641 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000241: Sessions closed: 008-13 17:10:58.641 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000266: Transactions: 008-13 17:10:58.642 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000258: Successful transactions: 008-13 17:10:58.642 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000187: Optimistic lock failures: 008-13 17:10:58.642 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000105: Flushes: 008-13 17:10:58.642 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000048: Connections obtained: 008-13 17:10:58.642 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000253: Statements prepared: 008-13 17:10:58.642 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000252: Statements closed: 008-13 17:10:58.642 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000239: Second level cache puts: 008-13 17:10:58.643 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000237: Second level cache hits: 008-13 17:10:58.643 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000238: Second level cache misses: 008-13 17:10:58.643 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000079: Entities loaded: 008-13 17:10:58.643 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000080: Entities updated: 008-13 17:10:58.643 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000078: Entities inserted: 008-13 17:10:58.643 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000076: Entities deleted: 008-13 17:10:58.644 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000077: Entities fetched (minimize this): 008-13 17:10:58.644 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000033: Collections loaded: 008-13 17:10:58.644 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000036: Collections updated: 008-13 17:10:58.644 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000035: Collections removed: 008-13 17:10:58.644 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000034: Collections recreated: 008-13 17:10:58.644 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000032: Collections fetched (minimize this): 008-13 17:10:58.645 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000438: NaturalId cache puts: 008-13 17:10:58.645 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000439: NaturalId cache hits: 008-13 17:10:58.645 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000440: NaturalId cache misses: 008-13 17:10:58.645 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000441: Max NaturalId query time: 0ms08-13 17:10:58.645 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000442: NaturalId queries executed to database: 008-13 17:10:58.645 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000210: Queries executed to database: 008-13 17:10:58.646 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000215: Query cache puts: 008-13 17:10:58.646 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000433: update timestamps cache puts: 008-13 17:10:58.646 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000434: update timestamps cache hits: 008-13 17:10:58.646 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000435: update timestamps cache misses: 008-13 17:10:58.647 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000213: Query cache hits: 008-13 17:10:58.647 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000214: Query cache misses: 008-13 17:10:58.647 org.hibernate.stat.internal.ConcurrentStatisticsImpl INFO  - HHH000173: Max query time: 0ms08-13 17:10:58.656 org.hibernate.engine.jdbc.connections.internal.DriverManagerConnectionProviderImpl INFO  - HHH000030: Cleaning up connection pool [jdbc:mysql://localhost:3306/test]

从两次的执行结果的日志对比发现，Scenario1中的第二次查询使用的是二级缓存中的缓存，从日志中也可以看到命中的次数。Scenario2中第二次查询使用的是查询缓存中的缓存。