我遇到的Hibernate使用查询缓存的一个问题

liangguanhui

这两天在优化人事系统的性能，其中一个工作就是为系统应用Hibernate的缓存。Hibernate有几个缓存：一级缓存、二级缓存、查询缓存。其中我在实现查询缓存的时候出了一些毛病，弄了我两天。
事情是这样的，系统有一大堆代码表，按照一般的原则，代码表当然是缓存起来用。以其中一个表为例：

/** * 代码抽象类 */@MappedSuperclasspublic abstract class Code implements Serializable {　　　　private static final long serialVersionUID = 8945711128421853350L;　　　　protected long id;　　　　protected String code;　　　　protected String name;　　　　public Code() {　　　　super();　　}　　　　@Id　　@GeneratedValue(strategy=GenerationType.AUTO)　　public long getId() {　　　　return id;　　}　　其它getter、setter....　　}/** * 工资类别代码 */@Entity@Table(name="C_SalaryType")@Cache(usage = CacheConcurrencyStrategy.NONSTRICT_READ_WRITE)public class SalaryType extends Code {　　　　public SalaryType() {　　}　　}/** * 工资级别码 */@Entity@Table(name="C_SalaryLevel")@Cache(usage = CacheConcurrencyStrategy.NONSTRICT_READ_WRITE)public class SalaryLevel extends Code {　　　　public SalaryLevel() {　　}　　}

可以看到我这里的所有代码都继承一个Code的base class。在选择代码缓存类型的时候，考虑到代码不是经常修改，所以选择菲严格读写，即NONSTRICT_READ_WRITE。
（开始的时候，我把“@Cache(usage = CacheConcurrencyStrategy.NONSTRICT_READ_WRITE)”这句放到Code类里面，发现并不起作用，必须要把它放到具体的类里面才能起作用。不过这是题外话。）

然后重新部署应用，登陆、查看基本信息，问题来了：第二次或者之后查看基本信息，载入需要很长时间，凭感觉比不用缓存的时候还要慢。什么原因呢？查看了一下日志，不看不知道，一看吓一条，系统输出n条下面的sql语句：
Hibernate:
　　select
　　　　salarytype0_.id as id77_0_,
　　　　salarytype0_.code as code77_0_,
　　　　salarytype0_.name as name77_0_
　　from
　　　　C_SalaryType salarytype0_
　　where
　　　　salarytype0_.id in (
　　　　　　?, ?, ?, ?, ?, ?, ?, ?
　　　　)
怎么回事？
开始我还以为是查询基本信息表的时候有问题，不过经过查证并且使用调试（netbeans的webapp调试做得还可以）终于查到是查询这个代码表“From SalaryLevel”的时候出事。
我大概数了一下，貌似是使用这种方法重新遍历了一遍alarytype的所有数据，查询缓存不起作用。
不过其它代码类倒是没有这个问题，怎么回事？我认真查了一下代码，发现除了表名、类名不同之外，所有代码的确是一样的，既然一样，何解效果不同呢？

我又尝试改变缓存类型，结果还是一样。怪了，到底怎么回事？

第二天，我还是没有什么头绪，难道是hibernate的bug？不过应该不大可能，其它代码都没什么问题，就几个代码有这种问题。后来突发奇想，打开了org.hibernate.cache包的debug输出（之前是warn输出），输出如下：
junit测试代码是
　　public void testGetCodeList() {　　　　for (int i = 0; i < 2; i++) {　　　　　　System.out.println("\n\nTimes: " + (i + 1));　　　　　　service.getCodeList(SalaryType.class);　　　　}　　}
测试结果是


//////////////////////////////////////////////////////////////////////////////////////////////////////////////////////
SimpleContext: bind [java:comp/env/jdbc/hsDB]
SimpleContext: lookup [java:comp/env/jdbc/hsDB]
12:39:03,031 DEBUG org.hibernate.cache.CacheFactory:39 - instantiating cache region: com.dcampus.hr3.domain.code.JobType usage strategy: nonstrict-read-write
12:39:03,031　WARN org.hibernate.cache.EhCacheProvider:86 - Could not find configuration [com.dcampus.hr3.domain.code.JobType]; using defaults.
12:39:03,046 DEBUG org.hibernate.cache.EhCacheProvider:89 - started EHCache region: com.dcampus.hr3.domain.code.JobType
(一大堆重复上面三句)
12:39:05,015　INFO org.hibernate.cache.UpdateTimestampsCache:41 - starting update timestamps cache at region: org.hibernate.cache.UpdateTimestampsCache
12:39:05,015　WARN org.hibernate.cache.EhCacheProvider:86 - Could not find configuration [org.hibernate.cache.UpdateTimestampsCache]; using defaults.
12:39:05,015 DEBUG org.hibernate.cache.EhCacheProvider:89 - started EHCache region: org.hibernate.cache.UpdateTimestampsCache
12:39:05,031　INFO org.hibernate.cache.StandardQueryCache:52 - starting query cache at region: org.hibernate.cache.StandardQueryCache
12:39:05,031　WARN org.hibernate.cache.EhCacheProvider:86 - Could not find configuration [org.hibernate.cache.StandardQueryCache]; using defaults.
12:39:05,031 DEBUG org.hibernate.cache.EhCacheProvider:89 - started EHCache region: org.hibernate.cache.StandardQueryCache


Times: 1
12:39:05,781 DEBUG org.hibernate.cache.StandardQueryCache:102 - checking cached query results in region: org.hibernate.cache.StandardQueryCache
12:39:05,781 DEBUG org.hibernate.cache.EhCache:68 - key: sql: select salarytype0_.id as id77_, salarytype0_.code as code77_, salarytype0_.name as name77_ from C_SalaryType salarytype0_; parameters: ; named parameters: {}
12:39:05,781 DEBUG org.hibernate.cache.EhCache:77 - Element for sql: select salarytype0_.id as id77_, salarytype0_.code as code77_, salarytype0_.name as name77_ from C_SalaryType salarytype0_; parameters: ; named parameters: {} is null
12:39:05,781 DEBUG org.hibernate.cache.StandardQueryCache:107 - query results were not found in cache
Hibernate:
　　select
　　　　salarytype0_.id as id77_,
　　　　salarytype0_.code as code77_,
　　　　salarytype0_.name as name77_
　　from
　　　　C_SalaryType salarytype0_
12:39:06,015 DEBUG org.hibernate.cache.NonstrictReadWriteCache:71 - Caching: com.dcampus.hr3.domain.code.SalaryType#1
12:39:06,015 DEBUG org.hibernate.cache.NonstrictReadWriteCache:71 - Caching: com.dcampus.hr3.domain.code.SalaryType#2
12:39:06,015 DEBUG org.hibernate.cache.NonstrictReadWriteCache:71 - Caching: com.dcampus.hr3.domain.code.SalaryType#3
(重复至1546)
12:39:07,312 DEBUG org.hibernate.cache.StandardQueryCache:73 - caching query results in region: org.hibernate.cache.StandardQueryCache; timestamp=4887704147902464


Times: 2
12:39:07,328 DEBUG org.hibernate.cache.StandardQueryCache:102 - checking cached query results in region: org.hibernate.cache.StandardQueryCache
12:39:07,328 DEBUG org.hibernate.cache.EhCache:68 - key: sql: select salarytype0_.id as id77_, salarytype0_.code as code77_, salarytype0_.name as name77_ from C_SalaryType salarytype0_; parameters: ; named parameters: {}
12:39:07,328 DEBUG org.hibernate.cache.StandardQueryCache:156 - Checking query spaces for up-to-dateness: [C_SalaryType]
12:39:07,328 DEBUG org.hibernate.cache.EhCache:68 - key: C_SalaryType
12:39:07,328 DEBUG org.hibernate.cache.EhCache:77 - Element for C_SalaryType is null
12:39:07,328 DEBUG org.hibernate.cache.StandardQueryCache:117 - returning cached query results
12:39:07,343 DEBUG org.hibernate.cache.NonstrictReadWriteCache:41 - Cache lookup: com.dcampus.hr3.domain.code.SalaryType#1
12:39:07,343 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#1
12:39:07,343 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#1 is null
12:39:07,343 DEBUG org.hibernate.cache.NonstrictReadWriteCache:49 - Cache miss
12:39:07,343 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#2
12:39:07,343 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#2 is null
12:39:07,343 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#3
12:39:07,343 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#3 is null
12:39:07,343 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#4
12:39:07,343 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#4 is null
12:39:07,343 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#5
12:39:07,343 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#5 is null
12:39:07,359 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#6
12:39:07,359 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#6 is null
12:39:07,359 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#7
12:39:07,359 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#7 is null
12:39:07,359 DEBUG org.hibernate.cache.EhCache:68 - key: com.dcampus.hr3.domain.code.SalaryType#8
12:39:07,359 DEBUG org.hibernate.cache.EhCache:77 - Element for com.dcampus.hr3.domain.code.SalaryType#8 is null
Hibernate:
　　select
　　　　salarytype0_.id as id77_0_,
　　　　salarytype0_.code as code77_0_,
　　　　salarytype0_.name as name77_0_
　　from
　　　　C_SalaryType salarytype0_
　　where
　　　　salarytype0_.id in (
　　　　　　?, ?, ?, ?, ?, ?, ?, ?
　　　　)
(重复上面Time2后面的内容至1546)

////////////////////// end ////////////////////////////////////////////////////////////////////

从上面可以看到，原来是每次查询都不能击中缓存。怎么会击不中？我看到1546，突然想起我的ehcache的配置是默认1000个

<ehcache>　　<defaultCache　　　　　　maxElementsInMemory="1000"　　　　　　timeToIdleSeconds="600"　　　　　　timeToLiveSeconds="1800"　　　　　　eternal="false"　　　　　　overflowToDisk="false"　　　　　　diskPersistent="false"　　　　　　memoryStoreEvictionPolicy="LRU"　　　　　　/></ehcache>
而那些代码的数目超过一千个，所以每次查询都不能命中。把1000改为10000，测试通过。