NHibernate second level caching not working with HashTableCacheProvider

Question

I'm basically just trying to reproduce the Ayende's first and second level caching http://nhibernate.hibernatingrhinos.com/28/first-and-second-level-caching-in-nhibernate .

I've wired up the configuration as:

<hibernate-configuration xmlns="urn:nhibernate-configuration-2.2">
  <session-factory name="NHibernate.Test">
  <property name="connection.driver_class">NHibernate.Driver.OracleDataClientDriver</property>
  <property name="dialect">NHibernate.Dialect.Oracle10gDialect</property>
  <property name="show_sql">true</property>
  <property name="query.substitutions">true 1, false 0, yes 'Y', no 'N'</property>
  <property name="cache.use_query_cache">true</property>
  <property name="cache.use_second_level_cache">true</property>
  <property name="cache.provider_class">NHibernate.Cache.HashtableCacheProvider</property>
  <property name="cache.default_expiration">1801</property>
</session-factory>

and I've mapped the entity as:

<class name="HeaderDTO" mutable="false" check="none">
<cache usage="read-write"/>
  <id name="Id" type="System.Int32" >
    <column name="id" sql-type="NUMBER" not-null="true" unique="true"/>
    <generator class="assigned"/>
  </id>
  <property name="Description" column="description" type="System.String" />
</class>

and my named query looks like this:

<sql-query name="GetHeaderDTO">
  <query-param name="id" type="int"/>
  <return class="HeaderDTO" />
  { call MyPackage.get_header(:id) }
</sql-query>

and now I'm trying to do some tests (ignore the fact the test is not a very good one to test caching).

[TestMethod]
public void Cacching_Entity_FirstCallIsCached()
{
DateTime StartTime;
DateTime EndTime;
TimeSpan FirstTry;
TimeSpan SecondTry;
int Id = 2888469;
string key = string.Concat("Id", Id);

using (var session = factory.OpenSession())
{
    //Act
    var query = session.GetNamedQuery("GetHeaderDTO");
    query.SetInt32("in_nom_id", Id);
    query.SetCacheable(true);
    query.SetCacheMode(CacheMode.Normal);
    query.SetCacheRegion(key);
    StartTime = DateTime.Now;
    HeaderDTO MyHeader = query.UniqueResult<HeaderDTO>();
    EndTime = DateTime.Now;
    FirstTry = EndTime - StartTime;
}

using (var session = factory.OpenSession())
{
    //Act
    var query = session.GetNamedQuery("GetHeaderDTO");
    query.SetInt32("in_nom_id", Id);
    query.SetCacheable(true);
    StartTime = DateTime.Now;
    HeaderDTO MyHeader = query.UniqueResult<HeaderDTO>();
    EndTime = DateTime.Now;
    SecondTry = EndTime - StartTime;
}

Assert.IsTrue(FirstTry>SecondTry);
}

But when I run the test and look at the NHibernate logs:

NHibernate.Impl.SessionImpl: DEBUG [session-id=e9de687f-1ef5-4824-9964-9b94f636a15d] opened session at timestamp: 5517356014678016, for session factory: [NHibernate.Test/ca36467732ff486380672aeb062ef749] NHibernate.Impl.SessionImpl: DEBUG setting cache mode to: Normal NHibernate.Loader.Custom.Sql.SQLCustomQuery: DEBUG starting processing of sql query [{ call MyPackage.get_header(:id) }] NHibernate.Loader.Custom.Sql.SQLQueryReturnProcessor: DEBUG mapping alias [nh] to entity-suffix [0_] NHibernate.Cache.StandardQueryCache: INFO starting query cache at region: Id2888469 NHibernate.Cache.StandardQueryCache: DEBUG checking cached query results in region: 'Id2888469'; sql: { call MyPackage.get_header(?) }; parameters: []; named parameters: {'id'='2888469'} NHibernate.Cache.StandardQueryCache: DEBUG query results were not found in cache: sql: { call MyPackage.get_header(?) }; parameters: []; named parameters: {'id'='2888469'} NHibernate.AdoNet.AbstractBatcher: DEBUG Opened new IDbCommand, open IDbCommands: 1 NHibernate.AdoNet.AbstractBatcher: DEBUG Building an IDbCommand object for the SqlString: { call MyPackage.get_header(?) } NHibernate.Type.Int32Type: DEBUG binding '2888469' to parameter: 0 NHibernate.Loader.Loader: INFO { call MyPackage.get_header(:p0) } NHibernate.SQL: DEBUG { call MyPackage.get_header(:p0) };:p0 = 2888469 [Type: Int32 (0)] blah blah NHibernate.AdoNet.ConnectionManager: DEBUG aggressively releasing database connection NHibernate.Connection.ConnectionProvider: DEBUG Closing connection NHibernate.Loader.Loader: DEBUG total objects hydrated: 1 NHibernate.Engine.TwoPhaseLoad: DEBUG resolving associations for [MyAssembly.HeaderDTO#2888469] NHibernate.Engine.TwoPhaseLoad: DEBUG adding entity to second-level cache: [MyAssembly.HeaderDTO#2888469] NHibernate.Cache.ReadWriteCache: DEBUG Caching: MyAssembly.HeaderDTO#2888469 NHibernate.Cache.ReadWriteCache: DEBUG Cached: MyAssembly.HeaderDTO#2888469 NHibernate.Engine.TwoPhaseLoad: DEBUG done materializing entity [MyAssembly.HeaderDTO#2888469] NHibernate.Engine.StatefulPersistenceContext: DEBUG initializing non-lazy collections NHibernate.Cache.StandardQueryCache: DEBUG caching query results in region: 'Id2888469'; sql: { call MyPackage.get_header(?) }; parameters: []; named parameters: {'id'='2888469'} NHibernate.AdoNet.ConnectionManager: DEBUG after autocommit NHibernate.Impl.SessionImpl: DEBUG transaction completion NHibernate.AdoNet.ConnectionManager: DEBUG aggressively releasing database connection NHibernate.Impl.SessionImpl: DEBUG setting cache mode to: Normal NHibernate.Impl.SessionImpl: DEBUG [session-id=e9de687f-1ef5-4824-9964-9b94f636a15d] running ISession.Dispose() NHibernate.Impl.SessionImpl: DEBUG [session-id=e9de687f-1ef5-4824-9964-9b94f636a15d] executing real Dispose(True) NHibernate.Impl.SessionImpl: DEBUG closing session NHibernate.AdoNet.AbstractBatcher: DEBUG running BatcherImpl.Dispose(true) NHibernate.Impl.SessionImpl: DEBUG [session-id=78820256-77e8-4596-8374-98f8b5cc946b] opened session at timestamp: 5517356016148480, for session factory: [NHibernate.Test/ca36467732ff486380672aeb062ef749] NHibernate.Loader.Custom.Sql.SQLCustomQuery: DEBUG starting processing of sql query [{ call MyPackage.get_header(:id) }] NHibernate.Loader.Custom.Sql.SQLQueryReturnProcessor: DEBUG mapping alias [nh] to entity-suffix [0_] NHibernate.Cache.StandardQueryCache: DEBUG checking cached query results in region: 'NHibernate.Cache.StandardQueryCache'; sql: { call MyPackage.get_header(?) }; parameters: []; named parameters: {'id'='2888469'} NHibernate.Cache.StandardQueryCache: DEBUG query results were not found in cache: sql: { call MyPackage.get_header(?) }; parameters: []; named parameters: {'id'='2888469'} NHibernate.AdoNet.AbstractBatcher: DEBUG Opened new IDbCommand, open IDbCommands: 1 NHibernate.AdoNet.AbstractBatcher: DEBUG Building an IDbCommand object for the SqlString: { call MyPackage.get_header(?) } NHibernate.Type.Int32Type: DEBUG binding '2888469' to parameter: 0 NHibernate.Loader.Loader: INFO { call MyPackage.get_header(:p0) } NHibernate.SQL: DEBUG { call MyPackage.get_header(:p0) };:p0 = 2888469 [Type: Int32 (0)] NHibernate.Connection.DriverConnectionProvider: DEBUG Obtaining IDbConnection from Driver NHibernate.AdoNet.AbstractBatcher: DEBUG ExecuteReader took 2 ms NHibernate.AdoNet.AbstractBatcher: DEBUG Opened IDataReader, open IDataReaders: blah blah NHibernate.Loader.Loader: DEBUG done processing result set (1 rows) NHibernate.AdoNet.AbstractBatcher: DEBUG Closed IDataReader, open IDataReaders :0 NHibernate.AdoNet.AbstractBatcher: DEBUG DataReader was closed after 27 ms blah blah NHibernate.Loader.Loader: DEBUG total objects hydrated: 1 NHibernate.Engine.TwoPhaseLoad: DEBUG resolving associations for [MyAssembly.HeaderDTO#2888469] NHibernate.Engine.TwoPhaseLoad: DEBUG adding entity to second-level cache: [MyAssembly.HeaderDTO#2888469] NHibernate.Cache.ReadWriteCache: DEBUG Caching: MyAssembly.HeaderDTO#2888469 NHibernate.Cache.ReadWriteCache: DEBUG Item was already cached: MyAssembly.HeaderDTO#2888469 NHibernate.Engine.TwoPhaseLoad: DEBUG done materializing entity [MyAssembly.HeaderDTO#2888469] NHibernate.Engine.StatefulPersistenceContext: DEBUG initializing non-lazy collections NHibernate.Cache.StandardQueryCache: DEBUG caching query results in region: 'NHibernate.Cache.StandardQueryCache'; sql: { call MyPackage.get_header(?) }; parameters: []; named parameters: {'id'='2888469'} NHibernate.AdoNet.ConnectionManager: DEBUG after autocommit blah blah

How can NHibernate say it was cached? Can't find it and then NHibernate won't cache it because it is already cached?

Maybe it is something to do with HashTable provider? Any help would be appreciated.

Thanks, Bill N

not sure at all, but maybe it has to do with the fact that you also have to mark your query as cachable — J. Ed, Sep 07 '12 at 15:06
I thought I am when I set cacheable = true (query.SetCacheable(true);) — Bill Nielsen, Sep 08 '12 at 06:09
I think you might also need to specify it as cachable in your xml mapping — J. Ed, Sep 08 '12 at 06:16
Haven't you already asked this question and GOT an answer? http://stackoverflow.com/questions/12273302/nhibernate-second-level-caching-not-returning-object — Rippo, Sep 08 '12 at 09:23
Thanks for the responses. I think I am making the mapping cacheable in my xml when I applied the . @Rippo, no it is different. I did have the caching setup like this with the SysCache provider and did indeed find that I was missing the in my xml. However, I'm using Fluent NHibernate and can't use SysCache (http://stackoverflow.com/questions/10491876/nhibernate-3-3-and-syscache). Now, i was just using the hashtable provider, and for whatever reason it is not working. — Bill Nielsen, Sep 09 '12 at 19:52

score 0 · Answer 1 · answered Sep 12 '12 at 14:48

You should put your code in a transaction:

using (var session = factory.OpenSession())
using (var tx = session.BeginTransaction())
{
    //Act
    var query = session.GetNamedQuery("GetHeaderDTO");
    query.SetInt32("in_nom_id", Id);
    query.SetCacheable(true);
    query.SetCacheMode(CacheMode.Normal);
    query.SetCacheRegion(key);
    StartTime = DateTime.Now;
    HeaderDTO MyHeader = query.UniqueResult<HeaderDTO>();
    EndTime = DateTime.Now;
    FirstTry = EndTime - StartTime;

    tx.Commit();
}

using (var session = factory.OpenSession())
using (var tx = session.BeginTransaction())
{
    //Act
    var query = session.GetNamedQuery("GetHeaderDTO");
    query.SetInt32("in_nom_id", Id);
    query.SetCacheable(true);
    StartTime = DateTime.Now;
    HeaderDTO MyHeader = query.UniqueResult<HeaderDTO>();
    EndTime = DateTime.Now;
    SecondTry = EndTime - StartTime;

    tx.Commit();
}

NHibernate second level caching not working with HashTableCacheProvider

1 Answers1