一直以来想写一份关于 NHibernate 的缓存管理的文章，终于在迫不得已的情况下开始了：因为项目中的一个使用二级缓存的项目，发现二级缓存没有实际发挥应有的作用！！
今天我们就一步一步建立一个NH测试项目，并看看这中间我们都会遇到哪些问题。(原文链接 http://ddbiz.com/?p=107)
1. 创建项目
项目名称: ddbiz.nhtest
.netfx: framework 4
nhibernate: 2.1.2
2. 项目中对象介绍和其关系
用户: tuser ---(1:1)---> tprofile
---(1:1) ---> trole
站点登录用户, 每个用户拥有一个具体身份介绍信息tprofile，并拥有一个角色（注：用户的可以有多个角色，在我们的测试项目中，为了简化起见，我们仅仅允许用户拥有一种角色）
权限: trole ---(1:n)---> tpurview ----(1:n)-----> tpurview
每个角色有多种具体的权限，每个权限还有子权限
设置: tsetting
系统的设置，用来检测项目中 nh 的缓存应用的。这个设置将在web系统中使用一个独立的线程不断被读取，并写一个系统日志，以观测其是否有变化。
3. 数据库
测试项目使用的是oracle数据库，仅仅因为前段时间不断有人问nhibernate如何连接oracle，如何设置。 没有什么特别的意义。当然如果你使用其他的数据库，比如mysql，则映射文件tuser.hbm.xml中有一段获取数据库sql绑定需要你手动修改。
<sql-query name="CurrentTimestamp"> <![CDATA[select current_timestamp from dual]]> </sql-query>
4. 项目构成
ddbiz.nhtest
|
|------------ ddbiz.nhtest.core // 实体定义和基本操作定义
|
|------------ ddbiz.nhtest.service // 数据访问层定义
说明: 在实际的项目中，.core 和.service 更多的时候是分开来进行开发的。这里我们也是为了简化操作，放在一起了。
ddbiz.nhtest.unittest // 单元测试，使用的是 NUnit
5. 环境搭建
因为使用的是oracle数据库，所以要有oracle的客户端。再初步完成项目时，你可能遇到很多问题，这里有个简单的列表，可以供大家参考：
[Q] 尝试加载 Oracle 客户端库时引发 BadImageFormatException。如果在安装 32 位 Oracle 客户端组件的情况下以 64 位模式运行，将出现此问题。 System.InvalidOperationException: 尝试加载 Oracle 客户端库时引发 BadImageFormatException。如果在安装 32 位 Oracle 客户端组件的情况下以 64 位模式运行，将出现此问题。 ---> System.BadImageFormatException: 试图加载格式不正确的程序。 (异常来自 HRESULT:0x8007000B) [A1] 如果机器装有64位oracle客户端，可以按如下指定 <runtime> <assemblyBinding xmlns="urn:schemas-microsoft-com:asm.v1"> <dependentAssembly> <assemblyIdentity name="Oracle.DataAccess" publicKeyToken="89b483f429c47342" processorArchitecture="amd64" /> <bindingRedirect oldVersion="2.0.0.0-10.9.9.9" newVersion="2.102.3.2" /> </dependentAssembly> </assemblyBinding> </runtime> [A2] 如果没有安装64位的oracle客户端，则需要重新编译项目，用x86的体系 [Q] ddbiz.nhtest.unittest.GenerateSchema.TestGenerateSchema: NHibernate.HibernateException : ORA-01031: 权限不足 ----> System.Data.OracleClient.OracleException : ORA-01031: 权限不足 [A] grant create any table, create any index, create any sequence to app_test; [Q] ddbiz.nhtest.unittest.GenerateSchema (TestFixtureSetUp): System.TypeInitializationException : “ddbiz.nhtest.unittest.AbstractUnitTest”的类型初始值设定项引发异常。 ----> NHibernate.MappingException : Could not compile the mapping document: ddbiz.nhtest.core.domain.member.TProfile.hbm.xml ----> NHibernate.MappingException : Could not determine type for: ddbiz.nhtest.core.Clients.TGenderType,ddbiz.nhtest.core, for columns: NHibernate.Mapping.Column(gender) [A] 测试项和项目项没有采用统一的发布平台，一个是 AnyCPU，一个是 x86.统一配置后再试 [Q] ddbiz.nhtest.unittest.GenerateSchema (TestFixtureSetUp): System.TypeInitializationException : “ddbiz.nhtest.unittest.AbstractUnitTest”的类型初始值设定项引发异常。 ----> System.Data.OracleClient.OracleException : ORA-12154: TNS: 无法解析指定的连接标识符 [A] 修改配置文件，增加tns解析
更详细的问题列表，你可以在 ddbiz.nhtest.unittest下的 readme.txt中找到。并且这个文件会常常更新的。另外一个需要用到的工具是 memcached，我使用的是windows 2008 r2 版本，64位的，你可以在 这里 找到适用于这个版本的memcached, 然后用 memcached -d install 安装为系统服务。
如果你初次执行这个测试项目，请在修改完配置后，在测试单元 GenerateSchema 中执行 TestGenerateSchema()，它将帮助你建立对象，初始化数据库。
6. 配置 log4net 以方便我们跟踪nh的运行
我们使用 ConsoleAppender，这样NH的log可以直接在 unittest中展现：
我们需要同时跟踪unittest、memcache、nhibernate，因此配置log4net的 logger如下：<appender name="ConsoleAppender" type="log4net.Appender.ConsoleAppender"> <target value="Console.Out" /> <layout type="log4net.Layout.PatternLayout,log4net"> <param name="ConversionPattern" value="%p %d %c - %m%n" /> </layout> </appender>
<logger name="Memcached.ClientLibrary.MemcacheClient" additivity="false"> <level value="DEBUG" /> <appender-ref ref="ConsoleAppender" additivity="false" /> </logger> <logger name="NHibernate.SQL" additivity="false"> <level value="DEBUG" /> <appender-ref ref="ConsoleAppender" additivity="false" /> </logger> <logger name="ddbiz.nhtest.unittest" additivity="false"> <level value="INFO" /> <appender-ref ref="ConsoleAppender" additivity="false" /> </logger>
接下来，我们可以跟踪系统的执行了
7. 测试独立对象 TSetting 的操作
[Test] public void ResetSetting() { Logger.InfoFormat("装载TSetting#1"); TSetting st = ServiceFactory.BaseService.Setting(); short cpwd = (short)TextHelper.RandomGenerator.Next(1, 100); st.ChangePwd = cpwd; ServiceFactory.BaseService.SettingSave(st); Logger.InfoFormat("Setting now: [id={0}, ChangePwd={1}, UpdateTimestamp={2}", st.Id, cpwd, st.UpdateTimestamp); }
ResetSetting从数据库装载 TSetting#1，并进行修改-->保存.下面是缓存的操作过程：读取数据:
***** ddbiz.nhtest.unittest.NHCacheTest.LoadSetting INFO 2011-09-23 16:12:51,978 ddbiz.nhtest.unittest - 装载TSetting#1 DEBUG 2011-09-23 16:12:52,142 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 DEBUG 2011-09-23 16:12:52,171 Memcached.ClientLibrary.MemcachedClient - Load items line: END DEBUG 2011-09-23 16:12:52,172 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server DEBUG 2011-09-23 16:12:52,175 Memcached.ClientLibrary.MemcachedClient - memcached: got back 0 results DEBUG 2011-09-23 16:12:52,229 NHibernate.SQL - SELECT tsetting0_.Id as Id17_0_, tsetting0_.hbinterval as hbinterval17_0_, tsetting0_.hbtimeout as hbtimeout17_0_, tsetting0_.hbfailures as hbfailures17_0_, tsetting0_.flow as flow17_0_, tsetting0_.resend as resend17_0_, tsetting0_.resendinterval as resendin7_17_0_, tsetting0_.changepwd as changepwd17_0_, tsetting0_.createtimestamp as createti9_17_0_, tsetting0_.updatetimestamp as updatet10_17_0_ FROM app_test.tsetting tsetting0_ WHERE tsetting0_.Id=:p0;:p0 = 1 DEBUG 2011-09-23 16:12:52,342 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 DEBUG 2011-09-23 16:12:52,342 Memcached.ClientLibrary.MemcachedClient - Load items line: END DEBUG 2011-09-23 16:12:52,343 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server DEBUG 2011-09-23 16:12:52,343 Memcached.ClientLibrary.MemcachedClient - memcached: got back 0 results INFO 2011-09-23 16:12:52,350 Memcached.ClientLibrary.MemcachedClient - Serializing for key: $Key$ for class: $Class$ INFO 2011-09-23 16:12:52,351 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 299 537 (STORED) INFO 2011-09-23 16:12:52,352 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1
ServiceFactory.BaseService.Setting() 从数据库中装载 #1的对象，此对象在二级缓存中不存在（因为是第一次使用，当前的一级缓存也不存在），所以memcached返回的结果是 got back 0 results，因此NH从数据库中 Loader 的这笔资料。
从数据库装载的数据，首先放入二级缓存，然后再从二级缓存读取出来，Deserializing 值，并返回这个对象
修改数据:
DEBUG 2011-09-23 16:14:08,071 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server DEBUG 2011-09-23 16:14:08,071 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results INFO 2011-09-23 16:14:08,071 Memcached.ClientLibrary.MemcachedClient - Serializing for key: $Key$ for class: $Class$ INFO 2011-09-23 16:14:08,071 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 300 362 (STORED) INFO 2011-09-23 16:14:08,071 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 DEBUG 2011-09-23 16:14:08,101 NHibernate.SQL - UPDATE app_test.tsetting SET changepwd = :p0 WHERE Id = :p1;:p0 = 1, :p1 = 1 DEBUG 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 DEBUG 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 362 DEBUG 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 362 INFO 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry DEBUG 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - Load items line: END DEBUG 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server DEBUG 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results INFO 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - Serializing for key: $Key$ for class: $Class$ INFO 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 300 362 (STORED) INFO 2011-09-23 16:14:08,131 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 INFO 2011-09-23 16:14:08,141 ddbiz.nhtest.unittest - Setting now: [id=1, ChangePwd=1, UpdateTimestamp=09/23/2011 10:23:22
当我们修改TSetting的数据时，NH首先从二级缓存中提取数据，然后更新这个修改到数据库，当修改成功时，把修改过的对象，再次写入二级缓存。注意：这里我们看到的是，NH首先执行数据库的更新，然后更新二级缓存，这就避免了当数据库的更新不成功时，二级缓存和真实数据不一致的情况。
从缓存移除 TSetting
[Test] public void EvictSetting() { Logger.Info("从二级缓存中卸载TSetting#1"); sessionFactory.Evict(typeof(TSetting), 1); }
EvictSetting 则从二级缓存中卸载TSetting:
***** ddbiz.nhtest.unittest.NHCacheTest.EvictSetting INFO 2011-09-23 16:18:52,111 ddbiz.nhtest.unittest - 从二级缓存中卸载TSetting#1 INFO 2011-09-23 16:18:52,112 Memcached.ClientLibrary.MemcachedClient - Deletion of key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 from cache was a success
8. 多个ISession是否能够正确的读取到这个二级缓存呢？
7. 中的测试一切看上去很完美，那么实际情况是如何呢？如果我有另外一个应用也不断的读取这个TSetting，它是否能获得正确的值呢？看看我们下面的这个例子：
private static void ScheduleProc(object state) { Int32 checkInterval = Timeout.Infinite; //5 * 1000; IServiceFactory serviceFactory = null; DateTime timestamp = DateTime.Now; TSetting setting = null; ILog Logger = LogManager.GetLogger("inschedule"); EventWaitHandle waitCheck = new EventWaitHandle(false, EventResetMode.ManualReset, TSetting.WAIT_REFRESH); while (Thread.CurrentThread.IsAlive) try { try { if (serviceFactory == null) serviceFactory = new ServiceFactory(); timestamp = serviceFactory.CurrentTimestamp; } catch (Exception ex) { Logger.ErrorFormat("query from DB Failure:{0}", ex.Message); serviceFactory = null; Thread.Sleep(5000); continue; } setting = serviceFactory.BaseService.Setting(); if (setting != null) Logger.InfoFormat("Current Setting:[id={0}, ChangePwd={1}]", setting.Id, setting.ChangePwd); else Logger.InfoFormat("Current Setting: 未定义"); waitCheck.Reset(); waitCheck.WaitOne(checkInterval); } catch (Exception ex) { Logger.ErrorFormat("Error in ScheduleProc: {0}", ex.Message); } }
这段代码采用线程的方式，不断装载 TSetting，以跟踪数据的变化，其执行方式是在 AbstractUnitTest.cs 初始化时，一次性加入线程池中：ThreadPool.QueueUserWorkItem(new WaitCallback(ScheduleProc));
当 ChangeSetting() 修改完数据，触发一个事件，来通知等待的线程去重新装载资料。为此我们稍稍修改了 ChangeSetting() 代码如下：
[Test] public void ChangeSetting() { Logger.InfoFormat("修改TSetting#1"); TSetting st = ServiceFactory.BaseService.Setting(); short cpwd = (short)TextHelper.RandomGenerator.Next(1, 100); st.ChangePwd = cpwd; ServiceFactory.BaseService.SettingSave(st); ewhRefresh.Set(); Logger.InfoFormat("Setting now: [id={0}, ChangePwd={1}, UpdateTimestamp={2}", st.Id, cpwd, st.UpdateTimestamp); }接下来我们看看修改完资料后，线程中的ISession装载来的数据是不是我们期望中的。
当系统激活后，线程从二级缓存中成功的装载了数据：
14 2011-09-23 17:02:09,003 NHibernate.SQL - select current_timestamp from dual 14 2011-09-23 17:02:09,080 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 14 2011-09-23 17:02:09,081 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 537 14 2011-09-23 17:02:09,081 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 537 14 2011-09-23 17:02:09,081 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry 14 2011-09-23 17:02:09,081 Memcached.ClientLibrary.MemcachedClient - Load items line: END 14 2011-09-23 17:02:09,081 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server 14 2011-09-23 17:02:09,081 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results 14 2011-09-23 17:02:09,081 inschedule - Current Setting:[id=1, ChangePwd=73]
我们看到，此时TSetting的ChangePwd值为73，接下来我们触发一次修改，测试进程显示：
INFO 2011-09-23 17:03:28,424 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 299 362 (STORED) INFO 2011-09-23 17:03:28,424 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 INFO 2011-09-23 17:03:28,427 ddbiz.nhtest.unittest - Setting now: [id=1, ChangePwd=16, UpdateTimestamp=09/23/2011 10:23:22 DEBUG 2011-09-23 17:03:28,429 NHibernate.SQL - select current_timestamp from dual
TSetting的值已经修改为16，并且更新进了二级缓存，那么模拟线程中获得的是什么数据呢？
14 2011-09-23 17:03:28,429 NHibernate.SQL - select current_timestamp from dual 14 2011-09-23 17:03:28,435 inschedule - Current Setting:[id=1, ChangePwd=73]
显然，它还是 73，居然没有改变！！！
这是为什么呢？这还要从基本概念上找原因：
我们都知道，NH中存在两种缓存：一级缓存和二级缓存。当一个ISession装载对象时，首先从一级缓存中获取数据，没有找到的话，如果你的应用配置使用了二级缓存，那么它将从二级缓存中查找，还没有找到的话，再从数据库中装载。在我们上面的模拟线程中， while(Thread.IsAlive){}里，这个ISession是一个长连接，它不同于一般的web应用，随着一个页面周期被打开、使用、释放。在while{}中，它一直open着，除非数据库连接发生故障，重新开启。因此，当模拟线程中装载好数据后，不论它是从数据库装载来的，还是从二级缓存中装载来的，它都将保存在自己的一级缓存中。因为线程中从来不更新数据 --- 它只读取数据，因此这个一级缓存中的数据永远都不会被刷新，永远保持第一次的值。 这也正是我们这篇文章要查找的原因。
既然我们找到了数据没能正确加载的原因，那我们就从这里入手。首先要做的就是数据重新加载时，应该确保当前的 一级缓存中不能有这个数据，这样ISession才会去二级缓存装载新数据，因此，我们进行下面的调用：
if (setting != null && NHSessionManager.Instance.GetSession().Contains(setting)) NHSessionManager.Instance.GetSession().Evict(setting);
判断当前的ISession，并把存在的数据清除掉。按照对理论的理解，这次数据应该能够正常加载：TestRunnerThread DEBUG 2011-09-26 13:39:12,719 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:39:12,720 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 537 TestRunnerThread DEBUG 2011-09-26 13:39:12,720 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 537 TestRunnerThread INFO 2011-09-26 13:39:12,720 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry TestRunnerThread DEBUG 2011-09-26 13:39:12,720 Memcached.ClientLibrary.MemcachedClient - Load items line: END TestRunnerThread DEBUG 2011-09-26 13:39:12,720 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server TestRunnerThread DEBUG 2011-09-26 13:39:12,720 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results TestRunnerThread DEBUG 2011-09-26 13:39:12,755 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:39:12,756 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 537 TestRunnerThread DEBUG 2011-09-26 13:39:12,756 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 537 TestRunnerThread INFO 2011-09-26 13:39:12,756 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry TestRunnerThread DEBUG 2011-09-26 13:39:12,756 Memcached.ClientLibrary.MemcachedClient - Load items line: END TestRunnerThread DEBUG 2011-09-26 13:39:12,756 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server TestRunnerThread DEBUG 2011-09-26 13:39:12,756 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results TestRunnerThread INFO 2011-09-26 13:39:12,756 Memcached.ClientLibrary.MemcachedClient - Serializing for key: $Key$ for class: $Class$ TestRunnerThread INFO 2011-09-26 13:39:12,757 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 300 362 (STORED) TestRunnerThread INFO 2011-09-26 13:39:12,757 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:39:12,766 NHibernate.SQL - UPDATE app_test.tsetting SET changepwd = :p0 WHERE Id = :p1;:p0 = 82, :p1 = 1 TestRunnerThread DEBUG 2011-09-26 13:39:12,802 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:39:12,803 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 362 TestRunnerThread DEBUG 2011-09-26 13:39:12,803 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 362 TestRunnerThread INFO 2011-09-26 13:39:12,803 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry TestRunnerThread DEBUG 2011-09-26 13:39:12,803 Memcached.ClientLibrary.MemcachedClient - Load items line: END TestRunnerThread DEBUG 2011-09-26 13:39:12,803 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server TestRunnerThread DEBUG 2011-09-26 13:39:12,803 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results TestRunnerThread INFO 2011-09-26 13:39:12,804 Memcached.ClientLibrary.MemcachedClient - Serializing for key: $Key$ for class: $Class$ TestRunnerThread INFO 2011-09-26 13:39:12,804 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 300 362 (STORED) TestRunnerThread INFO 2011-09-26 13:39:12,804 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:39:12,807 NHibernate.SQL - select current_timestamp from dual 12 INFO 2011-09-26 13:39:12,815 inschedule - Current Setting (re-)Loading. 12 DEBUG 2011-09-26 13:39:12,816 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:39:12,822 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 362 12 DEBUG 2011-09-26 13:39:12,822 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 362 12 INFO 2011-09-26 13:39:12,822 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry 12 DEBUG 2011-09-26 13:39:12,822 Memcached.ClientLibrary.MemcachedClient - Load items line: END 12 DEBUG 2011-09-26 13:39:12,822 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server 12 DEBUG 2011-09-26 13:39:12,822 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results 12 DEBUG 2011-09-26 13:39:12,822 NHibernate.SQL - SELECT tsetting0_.Id as Id17_0_, tsetting0_.hbinterval as hbinterval17_0_, tsetting0_.hbtimeout as hbtimeout17_0_, tsetting0_.hbfailures as hbfailures17_0_, tsetting0_.flow as flow17_0_, tsetting0_.resend as resend17_0_, tsetting0_.resendinterval as resendin7_17_0_, tsetting0_.changepwd as changepwd17_0_, tsetting0_.createtimestamp as createti9_17_0_, tsetting0_.updatetimestamp as updatet10_17_0_ FROM app_test.tsetting tsetting0_ WHERE tsetting0_.Id=:p0;:p0 = 1 12 DEBUG 2011-09-26 13:39:12,824 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:39:12,825 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 362 12 DEBUG 2011-09-26 13:39:12,825 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 362 12 INFO 2011-09-26 13:39:12,825 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry 12 DEBUG 2011-09-26 13:39:12,825 Memcached.ClientLibrary.MemcachedClient - Load items line: END 12 DEBUG 2011-09-26 13:39:12,825 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server 12 DEBUG 2011-09-26 13:39:12,825 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results 12 INFO 2011-09-26 13:39:12,826 inschedule - Current Setting:[id=1, ChangePwd=82]
如果只看执行的最后一句：Current Setting:[id=1, ChangePwd=82]这确实是我们更新后的数据。似乎清除缓存后，修改的数据被正确加载了。但是实际情况是，这个修改后的数据是从数据库中装载来的，而不是从二级缓存装来的！！我想我们都注意到了：ID为12的线程，“
memcached: got back 1 results然后又执行了：
”我们似乎遇到了一个很奇怪的现象 -- 为什么数据未能从二级缓存成功装载呢？我们需要一个更详细的日志跟踪，因此，修改 log4net的配置如下：12 DEBUG 2011-09-26 13:39:12,822 NHibernate.SQL - SELECT tsetting0_.Id as Id17_0_, tsetting0_.hbinterval as hbinterval17_0_, tsetting0_.hbtimeout as hbtimeout17_0_, tsetting0_.hbfailures as hbfailures17_0<logger name="Memcached.ClientLibrary.MemcachedClient" additivity="false"> <level value="DEBUG" /> <appender-ref ref="ConsoleAppender" /> <appender-ref ref="inschedule"/> </logger> <logger name="NHibernate" additivity="false"> <level value="DEBUG" /> <appender-ref ref="ConsoleAppender" /> <appender-ref ref="inschedule" /> </logger>
修改 NHibernate 的logger，跟踪全部的执行过程，然后重复上面的操作流程，我们得到了如下的日志：***** ddbiz.nhtest.unittest.NHCacheTest.ChangeSetting TestRunnerThread INFO 2011-09-26 13:48:15,523 ddbiz.nhtest.unittest - 修改TSetting#1, TID=14 TestRunnerThread DEBUG 2011-09-26 13:48:15,523 NHibernate.Impl.SessionImpl - [session-id=a5e0ba32-3ea1-4ccd-8d36-2c97de4f1d74] opened session at timestamp: 5394615892062208, for session factory: [default/015d03fba3f54439aef29eb83df34d40] TestRunnerThread DEBUG 2011-09-26 13:48:15,524 NHibernate.Event.Default.DefaultLoadEventListener - loading entity: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,524 NHibernate.Event.Default.DefaultLoadEventListener - attempting to resolve: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,524 NHibernate.Cache.ReadWriteCache - Cache lookup: ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,524 NHibernate.Caches.MemCache.MemCacheClient - fetching object ddbiz.nhtest.core.domain.common.TSetting#1 from the cache TestRunnerThread DEBUG 2011-09-26 13:48:15,524 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,524 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 537 TestRunnerThread DEBUG 2011-09-26 13:48:15,524 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 537 TestRunnerThread INFO 2011-09-26 13:48:15,524 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry TestRunnerThread DEBUG 2011-09-26 13:48:15,524 Memcached.ClientLibrary.MemcachedClient - Load items line: END TestRunnerThread DEBUG 2011-09-26 13:48:15,524 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server TestRunnerThread DEBUG 2011-09-26 13:48:15,524 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results TestRunnerThread DEBUG 2011-09-26 13:48:15,524 NHibernate.Cache.ReadWriteCache - Cache hit: ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,526 NHibernate.Event.Default.DefaultLoadEventListener - assembling entity from second-level cache: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,527 NHibernate.Event.Default.DefaultLoadEventListener - Cached Version: TestRunnerThread DEBUG 2011-09-26 13:48:15,527 NHibernate.Engine.StatefulPersistenceContext - initializing non-lazy collections TestRunnerThread DEBUG 2011-09-26 13:48:15,527 NHibernate.Event.Default.DefaultLoadEventListener - resolved object in second-level cache: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,527 NHibernate.AdoNet.ConnectionManager - after autocommit TestRunnerThread DEBUG 2011-09-26 13:48:15,527 NHibernate.Impl.SessionImpl - transaction completion TestRunnerThread DEBUG 2011-09-26 13:48:15,527 NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection TestRunnerThread DEBUG 2011-09-26 13:48:15,530 NHibernate.Transaction.AdoTransaction - Begin (Unspecified) TestRunnerThread DEBUG 2011-09-26 13:48:15,530 NHibernate.Connection.DriverConnectionProvider - Obtaining IDbConnection from Driver TestRunnerThread DEBUG 2011-09-26 13:48:15,537 NHibernate.Event.Default.AbstractSaveEventListener - persistent instance of: ddbiz.nhtest.core.domain.common.TSetting TestRunnerThread DEBUG 2011-09-26 13:48:15,538 NHibernate.Event.Default.DefaultSaveOrUpdateEventListener - ignoring persistent instance TestRunnerThread DEBUG 2011-09-26 13:48:15,538 NHibernate.Event.Default.DefaultSaveOrUpdateEventListener - object already associated with session: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,539 NHibernate.Transaction.AdoTransaction - Start Commit TestRunnerThread DEBUG 2011-09-26 13:48:15,543 NHibernate.Event.Default.AbstractFlushingEventListener - flushing session TestRunnerThread DEBUG 2011-09-26 13:48:15,544 NHibernate.Event.Default.AbstractFlushingEventListener - processing flush-time cascades TestRunnerThread DEBUG 2011-09-26 13:48:15,546 NHibernate.Event.Default.AbstractFlushingEventListener - dirty checking collections TestRunnerThread DEBUG 2011-09-26 13:48:15,548 NHibernate.Event.Default.AbstractFlushingEventListener - Flushing entities and processing referenced collections TestRunnerThread DEBUG 2011-09-26 13:48:15,558 NHibernate.Persister.Entity.AbstractEntityPersister - ddbiz.nhtest.core.domain.common.TSetting.ChangePwd is dirty TestRunnerThread DEBUG 2011-09-26 13:48:15,560 NHibernate.Event.Default.DefaultFlushEntityEventListener - Updating entity: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,566 NHibernate.Event.Default.AbstractFlushingEventListener - Processing unreferenced collections TestRunnerThread DEBUG 2011-09-26 13:48:15,566 NHibernate.Event.Default.AbstractFlushingEventListener - Scheduling collection removes/(re)creates/updates TestRunnerThread DEBUG 2011-09-26 13:48:15,567 NHibernate.Event.Default.AbstractFlushingEventListener - Flushed: 0 insertions, 1 updates, 0 deletions to 1 objects TestRunnerThread DEBUG 2011-09-26 13:48:15,567 NHibernate.Event.Default.AbstractFlushingEventListener - Flushed: 0 (re)creations, 0 updates, 0 removals to 0 collections TestRunnerThread DEBUG 2011-09-26 13:48:15,568 NHibernate.Impl.Printer - listing entities: TestRunnerThread DEBUG 2011-09-26 13:48:15,569 NHibernate.Impl.Printer - ddbiz.nhtest.core.domain.common.TSetting{'Id'='1', 'HBInterval'='40', 'HBTimeout'='10', 'HBFailures'='3', 'Flow'='20', 'Resend'='True', 'ResendInterval'='60', 'ChangePwd'='89', 'CreateTimestamp'='2011/9/22 17:29:05', 'UpdateTimestamp'='2011/9/23 10:23:22'} TestRunnerThread DEBUG 2011-09-26 13:48:15,570 NHibernate.Event.Default.AbstractFlushingEventListener - executing flush TestRunnerThread DEBUG 2011-09-26 13:48:15,570 NHibernate.AdoNet.ConnectionManager - registering flush begin TestRunnerThread DEBUG 2011-09-26 13:48:15,576 NHibernate.Cache.ReadWriteCache - Invalidating: ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,576 NHibernate.Caches.MemCache.MemCacheClient - fetching object ddbiz.nhtest.core.domain.common.TSetting#1 from the cache TestRunnerThread DEBUG 2011-09-26 13:48:15,576 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,577 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 537 TestRunnerThread DEBUG 2011-09-26 13:48:15,577 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 537 TestRunnerThread INFO 2011-09-26 13:48:15,577 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry TestRunnerThread DEBUG 2011-09-26 13:48:15,577 Memcached.ClientLibrary.MemcachedClient - Load items line: END TestRunnerThread DEBUG 2011-09-26 13:48:15,577 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server TestRunnerThread DEBUG 2011-09-26 13:48:15,577 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results TestRunnerThread DEBUG 2011-09-26 13:48:15,578 NHibernate.Caches.MemCache.MemCacheClient - setting value for item ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread INFO 2011-09-26 13:48:15,578 Memcached.ClientLibrary.MemcachedClient - Serializing for key: $Key$ for class: $Class$ TestRunnerThread INFO 2011-09-26 13:48:15,579 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 300 362 (STORED) TestRunnerThread INFO 2011-09-26 13:48:15,579 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,583 NHibernate.Persister.Entity.AbstractEntityPersister - Updating entity: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,590 NHibernate.AdoNet.AbstractBatcher - Opened new IDbCommand, open IDbCommands: 1 TestRunnerThread DEBUG 2011-09-26 13:48:15,590 NHibernate.AdoNet.AbstractBatcher - Building an IDbCommand object for the SqlString: UPDATE app_test.tsetting SET changepwd = ? WHERE Id = ? TestRunnerThread DEBUG 2011-09-26 13:48:15,590 NHibernate.Persister.Entity.AbstractEntityPersister - Dehydrating entity: [ddbiz.nhtest.core.domain.common.TSetting#1] TestRunnerThread DEBUG 2011-09-26 13:48:15,593 NHibernate.Type.Int16Type - binding '89' to parameter: 0 TestRunnerThread DEBUG 2011-09-26 13:48:15,593 NHibernate.Type.Int32Type - binding '1' to parameter: 1 TestRunnerThread DEBUG 2011-09-26 13:48:15,594 NHibernate.SQL - UPDATE app_test.tsetting SET changepwd = :p0 WHERE Id = :p1;:p0 = 89, :p1 = 1 TestRunnerThread DEBUG 2011-09-26 13:48:15,594 NHibernate.Transaction.AdoTransaction - Enlist Command TestRunnerThread DEBUG 2011-09-26 13:48:15,599 NHibernate.AdoNet.AbstractBatcher - ExecuteNonQuery took 4 ms TestRunnerThread DEBUG 2011-09-26 13:48:15,601 NHibernate.AdoNet.AbstractBatcher - ExecuteBatch for 1 statements took 0 ms TestRunnerThread DEBUG 2011-09-26 13:48:15,601 NHibernate.AdoNet.AbstractBatcher - Closed IDbCommand, open IDbCommands: 0 TestRunnerThread DEBUG 2011-09-26 13:48:15,602 NHibernate.AdoNet.ConnectionManager - registering flush end TestRunnerThread DEBUG 2011-09-26 13:48:15,603 NHibernate.Event.Default.AbstractFlushingEventListener - post flush TestRunnerThread DEBUG 2011-09-26 13:48:15,604 NHibernate.Impl.SessionImpl - before transaction completion TestRunnerThread DEBUG 2011-09-26 13:48:15,623 NHibernate.Transaction.AdoTransaction - IDbTransaction Committed TestRunnerThread DEBUG 2011-09-26 13:48:15,624 NHibernate.Impl.SessionImpl - transaction completion TestRunnerThread DEBUG 2011-09-26 13:48:15,624 NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection TestRunnerThread DEBUG 2011-09-26 13:48:15,624 NHibernate.Connection.ConnectionProvider - Closing connection TestRunnerThread DEBUG 2011-09-26 13:48:15,625 NHibernate.Cache.ReadWriteCache - Releasing: ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,625 NHibernate.Caches.MemCache.MemCacheClient - fetching object ddbiz.nhtest.core.domain.common.TSetting#1 from the cache TestRunnerThread DEBUG 2011-09-26 13:48:15,625 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,625 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 362 TestRunnerThread DEBUG 2011-09-26 13:48:15,625 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 362 TestRunnerThread INFO 2011-09-26 13:48:15,626 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry TestRunnerThread DEBUG 2011-09-26 13:48:15,626 Memcached.ClientLibrary.MemcachedClient - Load items line: END TestRunnerThread DEBUG 2011-09-26 13:48:15,626 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server TestRunnerThread DEBUG 2011-09-26 13:48:15,626 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results TestRunnerThread DEBUG 2011-09-26 13:48:15,626 NHibernate.Caches.MemCache.MemCacheClient - setting value for item ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread INFO 2011-09-26 13:48:15,626 Memcached.ClientLibrary.MemcachedClient - Serializing for key: $Key$ for class: $Class$ TestRunnerThread INFO 2011-09-26 13:48:15,627 Memcached.ClientLibrary.MemcachedClient - memcached cmd (result code): set nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 300 362 (STORED) TestRunnerThread INFO 2011-09-26 13:48:15,627 Memcached.ClientLibrary.MemcachedClient - Data stored successfully with key: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 TestRunnerThread DEBUG 2011-09-26 13:48:15,627 NHibernate.Transaction.AdoTransaction - IDbTransaction disposed. TestRunnerThread INFO 2011-09-26 13:48:15,628 ddbiz.nhtest.unittest - Setting now: [id=1, ChangePwd=89, UpdateTimestamp=09/23/2011 10:23:22 12 DEBUG 2011-09-26 13:48:15,630 NHibernate.Loader.Custom.Sql.SQLCustomQuery - starting processing of sql query [select current_timestamp from dual] 12 DEBUG 2011-09-26 13:48:15,630 NHibernate.AdoNet.AbstractBatcher - Opened new IDbCommand, open IDbCommands: 1 12 DEBUG 2011-09-26 13:48:15,630 NHibernate.AdoNet.AbstractBatcher - Building an IDbCommand object for the SqlString: select current_timestamp from dual 12 INFO 2011-09-26 13:48:15,630 NHibernate.Loader.Loader - select current_timestamp from dual 12 DEBUG 2011-09-26 13:48:15,630 NHibernate.SQL - select current_timestamp from dual 12 DEBUG 2011-09-26 13:48:15,630 NHibernate.Connection.DriverConnectionProvider - Obtaining IDbConnection from Driver 12 DEBUG 2011-09-26 13:48:15,631 NHibernate.AdoNet.AbstractBatcher - ExecuteReader took 0 ms 12 DEBUG 2011-09-26 13:48:15,631 NHibernate.AdoNet.AbstractBatcher - Opened IDataReader, open IDataReaders: 1 12 DEBUG 2011-09-26 13:48:15,631 NHibernate.Loader.Loader - processing result set 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.Loader.Loader - result set row: 0 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.Loader.Loader - result row: 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.Type.DateTimeType - returning '2011/9/26 13:49:00' as column: CURRENT_TIMESTAMP 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.Loader.Loader - done processing result set (1 rows) 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.AdoNet.AbstractBatcher - Closed IDataReader, open IDataReaders :0 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.AdoNet.AbstractBatcher - DataReader was closed after 1 ms 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.AdoNet.AbstractBatcher - Closed IDbCommand, open IDbCommands: 0 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.Connection.ConnectionProvider - Closing connection 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.Engine.StatefulPersistenceContext - initializing non-lazy collections 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.AdoNet.ConnectionManager - after autocommit 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.Impl.StatelessSessionImpl - running IStatelessSession.Dispose() 12 DEBUG 2011-09-26 13:48:15,632 NHibernate.AdoNet.AbstractBatcher - running BatcherImpl.Dispose(true) 12 DEBUG 2011-09-26 13:48:15,638 NHibernate.Event.Default.DefaultEvictEventListener - evicting [ddbiz.nhtest.core.domain.common.TSetting] 12 DEBUG 2011-09-26 13:48:15,638 NHibernate.Event.Default.DefaultLoadEventListener - loading entity: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,638 NHibernate.Event.Default.DefaultLoadEventListener - attempting to resolve: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,638 NHibernate.Cache.ReadWriteCache - Cache lookup: ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:48:15,638 NHibernate.Caches.MemCache.MemCacheClient - fetching object ddbiz.nhtest.core.domain.common.TSetting#1 from the cache 12 DEBUG 2011-09-26 13:48:15,638 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:48:15,638 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 362 12 DEBUG 2011-09-26 13:48:15,638 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 362 12 INFO 2011-09-26 13:48:15,639 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry 12 DEBUG 2011-09-26 13:48:15,639 Memcached.ClientLibrary.MemcachedClient - Load items line: END 12 DEBUG 2011-09-26 13:48:15,639 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server 12 DEBUG 2011-09-26 13:48:15,639 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Cache.ReadWriteCache - Cached item was locked: ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Event.Default.DefaultLoadEventListener - object not resolved in any cache: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Persister.Entity.AbstractEntityPersister - Fetching entity: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Loader.Loader - loading entity: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.AdoNet.AbstractBatcher - Opened new IDbCommand, open IDbCommands: 1 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.AdoNet.AbstractBatcher - Building an IDbCommand object for the SqlString: SELECT tsetting0_.Id as Id17_0_, tsetting0_.hbinterval as hbinterval17_0_, tsetting0_.hbtimeout as hbtimeout17_0_, tsetting0_.hbfailures as hbfailures17_0_, tsetting0_.flow as flow17_0_, tsetting0_.resend as resend17_0_, tsetting0_.resendinterval as resendin7_17_0_, tsetting0_.changepwd as changepwd17_0_, tsetting0_.createtimestamp as createti9_17_0_, tsetting0_.updatetimestamp as updatet10_17_0_ FROM app_test.tsetting tsetting0_ WHERE tsetting0_.Id=? 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Engine.QueryParameters - BindParameters(Named:NHibernate.Type.Int32Type) 1 -> [0] 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Type.Int32Type - binding '1' to parameter: 0 12 INFO 2011-09-26 13:48:15,639 NHibernate.Loader.Loader - SELECT tsetting0_.Id as Id17_0_, tsetting0_.hbinterval as hbinterval17_0_, tsetting0_.hbtimeout as hbtimeout17_0_, tsetting0_.hbfailures as hbfailures17_0_, tsetting0_.flow as flow17_0_, tsetting0_.resend as resend17_0_, tsetting0_.resendinterval as resendin7_17_0_, tsetting0_.changepwd as changepwd17_0_, tsetting0_.createtimestamp as createti9_17_0_, tsetting0_.updatetimestamp as updatet10_17_0_ FROM app_test.tsetting tsetting0_ WHERE tsetting0_.Id=:p0 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.SQL - SELECT tsetting0_.Id as Id17_0_, tsetting0_.hbinterval as hbinterval17_0_, tsetting0_.hbtimeout as hbtimeout17_0_, tsetting0_.hbfailures as hbfailures17_0_, tsetting0_.flow as flow17_0_, tsetting0_.resend as resend17_0_, tsetting0_.resendinterval as resendin7_17_0_, tsetting0_.changepwd as changepwd17_0_, tsetting0_.createtimestamp as createti9_17_0_, tsetting0_.updatetimestamp as updatet10_17_0_ FROM app_test.tsetting tsetting0_ WHERE tsetting0_.Id=:p0;:p0 = 1 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Connection.DriverConnectionProvider - Obtaining IDbConnection from Driver 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.AdoNet.AbstractBatcher - ExecuteReader took 1 ms 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.AdoNet.AbstractBatcher - Opened IDataReader, open IDataReaders: 1 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Loader.Loader - processing result set 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Loader.Loader - result set row: 0 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Loader.Loader - result row: EntityKey[ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Loader.Loader - Initializing object from DataReader: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Persister.Entity.AbstractEntityPersister - Hydrating entity: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Type.Int32Type - returning '40' as column: hbinterval17_0_ 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Type.Int32Type - returning '10' as column: hbtimeout17_0_ 12 DEBUG 2011-09-26 13:48:15,641 NHibernate.Type.Int16Type - returning '3' as column: hbfailures17_0_ 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Type.Int16Type - returning '20' as column: flow17_0_ 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Type.BooleanType - returning 'True' as column: resend17_0_ 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Type.Int16Type - returning '60' as column: resendin7_17_0_ 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Type.Int16Type - returning '89' as column: changepwd17_0_ 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Type.DateTimeType - returning '2011/9/22 17:29:05' as column: createti9_17_0_ 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Type.DateTimeType - returning '2011/9/23 10:23:22' as column: updatet10_17_0_ 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Loader.Loader - done processing result set (1 rows) 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.AdoNet.AbstractBatcher - Closed IDataReader, open IDataReaders :0 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.AdoNet.AbstractBatcher - DataReader was closed after 2 ms 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.AdoNet.AbstractBatcher - Closed IDbCommand, open IDbCommands: 0 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Connection.ConnectionProvider - Closing connection 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Loader.Loader - total objects hydrated: 1 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Engine.TwoPhaseLoad - resolving associations for [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Engine.TwoPhaseLoad - adding entity to second-level cache: [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Cache.ReadWriteCache - Caching: ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:48:15,642 NHibernate.Caches.MemCache.MemCacheClient - fetching object ddbiz.nhtest.core.domain.common.TSetting#1 from the cache 12 DEBUG 2011-09-26 13:48:15,642 Memcached.ClientLibrary.MemcachedClient - Memcached get command: get nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:48:15,642 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 362 12 DEBUG 2011-09-26 13:48:15,642 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 362 12 INFO 2011-09-26 13:48:15,643 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry 12 DEBUG 2011-09-26 13:48:15,643 Memcached.ClientLibrary.MemcachedClient - Load items line: END 12 DEBUG 2011-09-26 13:48:15,643 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server 12 DEBUG 2011-09-26 13:48:15,643 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results 12 DEBUG 2011-09-26 13:48:15,643 NHibernate.Cache.ReadWriteCache - Item was locked: ddbiz.nhtest.core.domain.common.TSetting#1 12 DEBUG 2011-09-26 13:48:15,643 NHibernate.Engine.TwoPhaseLoad - done materializing entity [ddbiz.nhtest.core.domain.common.TSetting#1] 12 DEBUG 2011-09-26 13:48:15,643 NHibernate.Engine.StatefulPersistenceContext - initializing non-lazy collections 12 DEBUG 2011-09-26 13:48:15,643 NHibernate.Loader.Loader - done entity load 12 DEBUG 2011-09-26 13:48:15,643 NHibernate.AdoNet.ConnectionManager - after autocommit 12 DEBUG 2011-09-26 13:48:15,643 NHibernate.Impl.SessionImpl - transaction completion 12 DEBUG 2011-09-26 13:48:15,643 NHibernate.AdoNet.ConnectionManager - aggressively releasing database connection
仔细看 12开头的数据：12 DEBUG 2011-09-26 13:48:15,638 NHibernate.Event.Default.DefaultEvictEventListener - evicting [ddbiz.nhtest.core.domain.common.TSetting]OK, NHibernate 执行了缓存清理: Session.Evict();接着，当我们装载设置的时候，它确实去二级缓存搜索了，并且得到了数据：12 DEBUG 2011-09-26 13:48:15,639 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server 12 DEBUG 2011-09-26 13:48:15,639 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results 12 DEBUG 2011-09-26 13:48:15,639 NHibernate.Cache.ReadWriteCache - Cached item was locked: ddbiz.nhtest.core.domain.common.TSetting#1
咦，这里有个 Cached item was locked: ddbiz.nhtest.core.domain.common.TSetting#1正是这个原因，导致了NH去数据库重新装载了数据！可是为什么缓存的数据会被 locked 呢？因为我们的cache设置为read-write，因此我们从源头找吧，先让我们看看 ReadWriteCache在获取数据的时候，做了什么事情：NHibernate.Cache.ReadWriteCache.cs 中，从二级缓存获取数据的代码为：
public object Get(CacheKey key, long txTimestamp) { lock (_lockObject) { if (log.IsDebugEnabled) { log.Debug("Cache lookup: " + key); } // commented out in H3.1 /*try { cache.Lock( key );*/ ILockable lockable = (ILockable) cache.Get(key); bool gettable = lockable != null && lockable.IsGettable(txTimestamp); if (gettable) { if (log.IsDebugEnabled) { log.Debug("Cache hit: " + key); } return ((CachedItem) lockable).Value; } else { if (log.IsDebugEnabled) { if (lockable == null) { log.Debug("Cache miss: " + key); } else { log.Debug("Cached item was locked: " + key); } } return null; } /*} finally { cache.Unlock( key ); }*/ } }
bool gettable = lockable != null && lockable.IsGettable(txTimestamp); ReadWriteCache 在获取数据时，传入了一个时间戳 txTimestamp。这样，当NH从二级缓存中获取数据时，对缓存中的这个数据是否可用做了判断。 下面是判断缓存数据的可用性的：NHibernate.Cache.CachedItem.cs:
public bool IsGettable(long txTimestamp) { return freshTimestamp < txTimestamp; }CachedItem的 freshTimestamp，是NH在完成Transaction后，把数据更新到二级缓存时，设定的时间戳。
，这个txTimestamp又是什么呢？因为我们使用默认的NH系统装载事件，因此我们再去看看 DefaultLoadEventListener是如何从二级缓存装载数据的：
NHibernate.Event.Default.DefaultLoadEventListener.cs 中的定义如下：
/// <summary> Attempts to load the entity from the second-level cache. </summary> /// <param name="event">The load event </param> /// <param name="persister">The persister for the entity being requested for load </param> /// <param name="options">The load options. </param> /// <returns> The entity from the second-level cache, or null. </returns> protected virtual object LoadFromSecondLevelCache(LoadEvent @event, IEntityPersister persister, LoadType options) { ISessionImplementor source = @event.Session; bool useCache = persister.HasCache && ((source.CacheMode & CacheMode.Get) == CacheMode.Get) && @event.LockMode.LessThan(LockMode.Read); if (useCache) { ISessionFactoryImplementor factory = source.Factory; CacheKey ck = new CacheKey(@event.EntityId, persister.IdentifierType, persister.RootEntityName, source.EntityMode, factory); object ce = persister.Cache.Get(ck, source.Timestamp); if (factory.Statistics.IsStatisticsEnabled) { if (ce == null) { factory.StatisticsImplementor.SecondLevelCacheMiss(persister.Cache.RegionName); log.DebugFormat("Entity cache miss: {0}", ck); } else { factory.StatisticsImplementor.SecondLevelCacheHit(persister.Cache.RegionName); log.DebugFormat("Entity cache hit: {0}", ck); } } if (ce != null) { CacheEntry entry = (CacheEntry) persister.CacheEntryStructure.Destructure(ce, factory); // Entity was found in second-level cache... // NH: Different behavior (take a look to options.ExactPersister (NH-295)) if (!options.ExactPersister || persister.EntityMetamodel.SubclassEntityNames.Contains(entry.Subclass)) { return AssembleCacheEntry(entry, @event.EntityId, persister, @event); } } } return null; }
当NH从二级缓存装载数据时，调用了持久类的 Cache.Get, 并在此处传入了 source.Timestamp（稍后我们在探索 这个 Timestamp是什么时候生成的），以此判断一个二级数据是否有效，如果缓存的更新时间(freshTimestamp)早于 source.Timestamp（就是IsGettable(txTimestamp)，那么这个缓存对于当前的调用的ISession来说就是有效的，否则缓存就是无效的。freshTimestamp是NH在把数据放入二级缓存时，获取的系统当前时间（请参考 NHibernate.Cache.Timestamper.cs）。如此看来，source.Timestamp对于我们来说就相当重要了。从 NHibernate.Impl.SessionImpl.cs 中的 timestamp = info.GetInt64("timestamp"); 我们可以大致了解到，一个session在创建时，这个 Timestamp 就被用当前的系统时间戳赋值。也就是说，source.Timestamp 代表了当前Session的创建时间戳。至此，我们终于明白了，为什么LoadFromSecondLevelCache中，Cache.Get的数据是不可获取、是无效的，因为调用这个二级缓存的Session是早于缓存创建/更新的时间的（在我们的例子中）。现在我们明白了一件事： 二级缓存中的数据，！！仅对二级缓存生成后创建的ISession是有效的。！！
这也告诉我们，在NH的应用中，ISession应该是用时创建，用后销毁的，需要时再创建的。因此我们修改了例子中的 线程中的数据，类似如下：
private static void ScheduleProc(object state) { ILog Logger = LogManager.GetLogger("inschedule"); Logger.InfoFormat("ScheduleProc, TID={0}", Thread.CurrentThread.ManagedThreadId); Int32 checkInterval = Timeout.Infinite; //5 * 1000; DateTime timestamp = DateTime.Now; TSetting setting = null; EventWaitHandle ewhRefresh = new EventWaitHandle(false, EventResetMode.ManualReset, TSetting.REFRESH_WAIT), ewhRefreshDone = new EventWaitHandle(false, EventResetMode.ManualReset, TSetting.REFRESH_DONE); while (Thread.CurrentThread.IsAlive) try { ewhRefresh.Reset(); if (ewhRefresh.WaitOne(checkInterval)) Logger.InfoFormat("Waked up to Reload Setting"); else Logger.InfoFormat("Waked up for timer to Reload Setting"); using (IServiceFactory serviceFactory = new ServiceFactory()) { try { timestamp = serviceFactory.CurrentTimestamp; } catch (Exception ex) { Logger.ErrorFormat("query from DB Failure:{0}", ex.Message); Thread.Sleep(5000); continue; } if (setting != null && serviceFactory.Session.Contains(setting)) { Logger.Info("Evict Current Setting from session Cache"); serviceFactory.Session.Evict(setting); } Logger.Info("Current Setting (re-)Loading."); setting = serviceFactory.BaseService.Setting(); if (setting != null) Logger.InfoFormat("Current Setting:[id={0}, version={1}, ChangePwd={2}]", setting.Id, setting.Version, setting.ChangePwd); else Logger.InfoFormat("Current Setting: 未定义"); ewhRefreshDone.Set(); Logger.InfoFormat("Current Session Closed: TID={0}", Thread.CurrentThread.ManagedThreadId); } } catch (Exception ex) { Logger.ErrorFormat("Error in ScheduleProc: {0}", ex.Message); } } }
修改 ServiceFactory使其继承自IDisposable,以便在线程的每个循环结束的时候都能释放掉这个ISession，并在循环的开始重新建立这个ISession。接下来的测试就如我们预期的一样，二级缓存正在发挥其作用：10 DEBUG 2011-09-28 11:35:29,901 Memcached.ClientLibrary.MemcachedClient - Load items line: VALUE nhtest@ddbiz.nhtest.core.domain.common.TSetting#1 8 537 10 DEBUG 2011-09-28 11:35:29,901 Memcached.ClientLibrary.MemcachedClient - \tkey: nhtest@ddbiz.nhtest.core.domain.common.TSetting#1; flags: 8; length: 537 10 INFO 2011-09-28 11:35:29,901 Memcached.ClientLibrary.MemcachedClient - Deserializing DictionaryEntry 10 DEBUG 2011-09-28 11:35:29,901 Memcached.ClientLibrary.MemcachedClient - Load items line: END 10 DEBUG 2011-09-28 11:35:29,901 Memcached.ClientLibrary.MemcachedClient - Finished reading from cache server 10 DEBUG 2011-09-28 11:35:29,901 Memcached.ClientLibrary.MemcachedClient - memcached: got back 1 results ... ... 10 DEBUG 2011-09-28 11:35:29,901 NHibernate.Cache.ReadWriteCache - Cache hit: ddbiz.nhtest.core.domain.common.TSetting#1 10 DEBUG 2011-09-28 11:35:29,901 NHibernate.Event.Default.DefaultLoadEventListener - assembling entity from second-level cache: [ddbiz.nhtest.core.domain.common.TSetting#1] 10 DEBUG 2011-09-28 11:35:29,916 NHibernate.Event.Default.DefaultLoadEventListener - Cached Version: 10 DEBUG 2011-09-28 11:35:29,916 NHibernate.Engine.StatefulPersistenceContext - initializing non-lazy collections 10 DEBUG 2011-09-28 11:35:29,916 NHibernate.Event.Default.DefaultLoadEventListener - resolved object in second-level cache: [ddbiz.nhtest.core.domain.common.TSetting#1] ...
9. 总结
> 二级缓存不一定是在依照你的想象正常工作。
> 在NHibernate中，使用短链接处理你的数据，不管是 winform, webapp,还是thread。
10. 没有终点的节点. 源码
测试项目的源代码可以从这里下载 测试项目代码 （已更新至最新）
《未完待续，下一篇: NHibernate Event/Listener 的设定》
更多兴趣，请关注QQ群<<170113296>>
2705
被折叠的 条评论
为什么被折叠?
到【灌水乐园】发言
