I'm trying to configure caching for my Lookup Tables using NHibernate's second-level caching provider SysCache2, and SqlCacheDependency.
I'm testing my framework on a single Countries table, but reading NHibernate's logs makes me understand that caching doesn't work .. And I don't know why.
I'm clueless :/
SqlCacheDependency is enabled in the database and on the table LUT_Countries.
Web.Config:
<system.web>
<compilation debug="true" targetFramework="4.0" />
<caching>
<sqlCacheDependency enabled="true" pollTime="30000"> <!-- -->
<databases>
<clear />
<add name="Default" connectionStringName="Test" />
</databases>
</sqlCacheDependency>
</caching>
</system.web>
<syscache2>
<cacheRegion name="CountriesRegion" relativeExpiration="604800">
<dependencies>
<tables>
<add name="Countries" databaseEntryName="Default" tableName="LUT_Countries" />
</tables>
</dependencies>
</cacheRegion>
</syscache2>
Fluent Configuration:
_baseConfiguration = Fluently.Configure()
.ExposeConfiguration(c =>
{
c.SetProperty("connection.isolation", "ReadCommitted");
c.SetProperty("show_sql", "true");
c.SetProperty("format_sql", "true");
})
.Database(MsSqlConfiguration.MsSql2008.ConnectionString(_connectionString))
.Cache(c => c.ProviderClass<SysCacheProvider>()
.UseSecondLevelCache()
.UseQueryCache());
NHibernate's Country Fluent Mapping:
public class CountryMap : ClassMap<Country>
{
public CountryMap()
{
Cache.IncludeAll().ReadOnly().Region("CountriesRegion");
Table("LUT_Countries");
Id(c => c.Code);
Map(c => c.Name);
Map(c => c.Alpha3IsoCode).Column("Alpha3_IsoCode");
Map(c => c.NumericCode);
}
}
NHibernate's Logs:
...
14:20:53.544 : DEBUG : cache for: CountriesRegion usage strategy: read-only
14:20:53.546 : WARN : read-only cache configured for mutable: CountriesRegion
14:20:53.551 : DEBUG : building cache region, 'CountriesRegion', from configuration
14:20:53.559 : DEBUG : Configuring cache region
14:20:53.559 : DEBUG : using priority: Default
14:20:53.559 : DEBUG : using relative expiration :7.00:00:00
14:20:53.571 : DEBUG : configuring sql table dependency, 'Countries' using table, 'LUT_Countries', and database entry. 'Default'
...
14:20:53.811 : DEBUG : initializing class SessionFactoryObjectFactory
14:20:53.813 : DEBUG : registered: 311e0b6b7e7a41b289b4347267f963f9(unnamed)
14:20:53.813 : INFO : no name configured
14:20:53.813 : DEBUG : Instantiated session factory
14:20:53.817 : INFO : starting update timestamps cache at region: UpdateTimestampsCache
14:20:53.817 : DEBUG : building non-configured cache region : UpdateTimestampsCache
14:20:53.817 : DEBUG : Configuring cache region
14:20:53.817 : DEBUG : no priority specified using default : Default
14:20:53.817 : DEBUG : no expiration specified using default : 00:05:00
14:20:53.819 : INFO : starting query cache at region: NHibernate.Cache.StandardQueryCache
14:20:53.819 : DEBUG : building non-configured cache region : NHibernate.Cache.StandardQueryCache
14:20:53.819 : DEBUG : Configuring cache region
14:20:53.819 : DEBUG : no priority specified using default : Default
14:20:53.819 : DEBUG : no expiration specified using default : 00:05:00
14:20:53.825 : DEBUG : Checking 0 named HQL queries
14:20:53.825 : DEBUG : Checking 0 named SQL queries
14:20:53.868 : DEBUG : [session-id=76cd9097-abc6-49f4-9fcb-2f5a0ca446ae] opened session at timestamp: 5622576143695872, for session factory: [/311e0b6b7e7a41b289b4347267f963f9]
14:20:54.169 : DEBUG : Expression (partially evaluated): value(NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country])
14:20:54.191 : DEBUG : unable to locate HQL query plan in cache; generating (NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country])
14:20:54.922 : DEBUG : select << begin [level=1, statement=select]
14:20:54.957 : DEBUG : FromClause{level=1} : Web.DataAccess.ORM.Models.Country (0) -> country0
14:20:54.992 : DEBUG : Resolved : 0 -> country0.Code
14:20:55.000 : DEBUG : select : finishing up [level=1, statement=select]
14:20:55.004 : DEBUG : processQuery() : ( SELECT ( {select clause} country0_.Code ) ( FromClause{level=1} LUT_Countries country0_ ) )
14:20:55.065 : DEBUG : Using FROM fragment [LUT_Countries country0_]
14:20:55.070 : DEBUG : select >> end [level=1, statement=select]
14:20:55.073 : DEBUG : throwQueryException() : no errors
14:20:55.199 : DEBUG : SQL: select country0_.Code as Code1_, country0_.Name as Name1_, country0_.Alpha3_IsoCode as Alpha3_1_, country0_.NumericCode as NumericC4_1_ from LUT_Countries country0_
14:20:55.199 : DEBUG : throwQueryException() : no errors
14:20:55.255 : DEBUG : located HQL query plan in cache (NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country])
14:20:55.263 : DEBUG : find: NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country]
...
14:20:55.639 : DEBUG : result set row: 11
14:20:55.639 : DEBUG : returning 'AP' as column: Code1_
14:20:55.639 : DEBUG : result row: EntityKey[Web.DataAccess.ORM.Models.Country#AP]
14:20:55.639 : DEBUG : Initializing object from DataReader: [Web.DataAccess.ORM.Models.Country#AP]
14:20:55.639 : DEBUG : Hydrating entity: [Web.DataAccess.ORM.Models.Country#AP]
14:20:55.639 : DEBUG : returning 'Asia/Pacific Region' as column: Name1_
14:20:55.639 : DEBUG : returning 'AP' as column: Alpha3_1_
14:20:55.639 : DEBUG : returning '0' as column: NumericC4_1_
14:20:55.639 : DEBUG : result set row: 12
...
14:20:55.701 : DEBUG : Closed IDataReader, open IDataReaders :0
14:20:55.702 : DEBUG : DataReader was closed after 290 ms
14:20:55.704 : DEBUG : Closed IDbCommand, open IDbCommands: 0
14:20:55.707 : DEBUG : aggressively releasing database connection
14:20:55.707 : DEBUG : Closing connection
14:20:55.713 : DEBUG : total objects hydrated: 251
14:20:55.722 : DEBUG : resolving associations for [Web.DataAccess.ORM.Models.Country#A1]
14:20:55.730 : DEBUG : adding entity to second-level cache: [Web.DataAccess.ORM.Models.Country#A1]
14:20:55.736 : DEBUG : Caching: Web.DataAccess.ORM.Models.Country#A1
14:20:55.740 : DEBUG : root cache item for region not found.
14:20:55.744 : DEBUG : Creating root cache entry for cache region: CountriesRegion
14:20:55.745 : DEBUG : Enlisting cache dependency for change notification
14:20:56.042 : DEBUG : Attaching cache dependencies to root cache entry. Cache entry will be removed when change is detected.
14:20:56.045 : DEBUG : adding new data: key=NHibernate-Cache:CountriesRegion:Web.DataAccess.ORM.Models.Country#A1@-1467239096 & value=NHibernate.Cache.Entry.CacheEntry
14:20:56.047 : DEBUG : item will expire at: 07/08/2013 17:20:56
14:20:56.058 : DEBUG : done materializing entity [Web.DataAccess.ORM.Models.Country#A1]
14:20:56.061 : DEBUG : resolving associations for [Web.DataAccess.ORM.Models.Country#A2]
14:20:56.061 : DEBUG : adding entity to second-level cache: [Web.DataAccess.ORM.Models.Country#A2]
14:20:56.061 : DEBUG : Caching: Web.DataAccess.ORM.Models.Country#A2
... .. .
Second run, 5 seconds after results in a new SQL query, same as the first, and this outputs many of the following logs (returning values and registering in the cache:
15:17:34.076 : DEBUG : [session-id=e1feb78d-6c3e-40a4-8b46-6d5742bd0f85] opened session at timestamp: 5622590071095296, for session factory: [/0ee3e73fbf6741d28adcff632c68b671]
15:17:34.077 : DEBUG : Expression (partially evaluated): value(NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country])
15:17:34.077 : DEBUG : located HQL query plan in cache (NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country])
15:17:34.077 : DEBUG : located HQL query plan in cache (NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country])
15:17:34.077 : DEBUG : find: NHibernate.Linq.NhQueryable`1[Web.DataAccess.ORM.Models.Country]
15:17:34.077 : DEBUG : named parameters: {}
15:17:34.077 : DEBUG : Opened new IDbCommand, open IDbCommands: 1
15:17:34.077 : DEBUG : Building an IDbCommand object for the SqlString: select country0_.Code as Code1_, country0_.Name as Name1_, country0_.Alpha3_IsoCode as Alpha3_1_, country0_.NumericCode as NumericC4_1_ from LUT_Countries country0_
15:17:34.077 : INFO : select country0_.Code as Code1_, country0_.Name as Name1_, country0_.Alpha3_IsoCode as Alpha3_1_, country0_.NumericCode as NumericC4_1_ from LUT_Countries country0_
15:17:34.078 : DEBUG : Obtaining IDbConnection from Driver
15:17:34.079 : DEBUG : ExecuteReader took 1 ms
15:17:34.079 : DEBUG : Opened IDataReader, open IDataReaders: 1
15:17:34.079 : DEBUG : processing result set
15:17:34.079 : DEBUG : result set row: 0
15:17:34.080 : DEBUG : returning 'A1' as column: Code1_
15:17:34.080 : DEBUG : result row: EntityKey[Web.DataAccess.ORM.Models.Country#A1]
15:17:34.080 : DEBUG : Initializing object from DataReader: [Web.DataAccess.ORM.Models.Country#A1]
15:17:34.080 : DEBUG : Hydrating entity: [Web.DataAccess.ORM.Models.Country#A1]
15:17:34.080 : DEBUG : returning 'Anonymous Proxy' as column: Name1_
15:17:34.080 : DEBUG : returning 'A1' as column: Alpha3_1_
15:17:34.080 : DEBUG : returning '0' as column: NumericC4_1_
15:17:34.080 : DEBUG : result set row: 1
...
You should run this in a transaction and commit the transaction at the end.
NHibernate updates the 2nd level cache only if the transaction has been committed successfully. If you don't start a NHibernate transaction, NHibernate will not know if the results are good enough to be cached.