Before loading an entity from the database the session first checks if the entity has already been cached. This can greatly reduce the number of database accesses and thus improve the performance on each cache hit.
As a consequence of using the Hibernate second-level cache, you - as a developer - have to be aware of the fact that each call of a data access method can either result in a cache hit or miss.
I'm no fan of gambling so I prefer to see some log messages on accessing the cache. One possible solution is to use Hibernates built-in cache logging. You have to alter the log level, e.g. in your log4.xml:
<logger name="org.hibernate.cache"> <level value="DEBUG" /> </logger>My advice on this is: don't use it! It results in horrible big numbers of log messages and thus slows the execution time.
So, let's utilize Spring AOP to log the cache access on our DAO methods. What's the idea behind this approach? I declare an around advice to do the logging for me. The so called
CacheMonitor aspect will be woven around each DAO method, so every potential cache hit or miss will be logged.There's only one last question to be answered: How is it possible to determine if any cache hit or miss has been occured? This is easily achievable by utilising another Hibernate feature, statistics! Each hibernate session factory is capable of generating certain statistics. These statistics contain useful information, e.g. number of commited transactions, slowest database query or *drum roll* different caching data like number of cache hits or misses.
Let's take a look at the source code of the
CacheMonitor aspect:@Aspect
public class CacheMonitor {
private final static Logger LOG = LoggerFactory.getLogger(CacheMonitor.class);
private final static NumberFormat NF = new DecimalFormat("0.0###");
@Autowired
private SessionFactory sessionFactory;
@Around("execution(* com.mycompany.myproject.dao..*.*(..))")
public Object log(ProceedingJoinPoint pjp) throws Throwable {
if (!LOG.isDebugEnabled()) {
return pjp.proceed();
}
Statistics statistics = sessionFactory.getStatistics();
statistics.setStatisticsEnabled(true);
long hit0 = statistics.getQueryCacheHitCount();
long miss0 = statistics.getSecondLevelCacheMissCount();
Object result = pjp.proceed();
long hit1 = statistics.getQueryCacheHitCount();
long miss1 = statistics.getQueryCacheMissCount();
double ratio = (double) hit1 / (hit1 + miss1);
if (hit1 > hit0) {
LOG.debug(String.format("CACHE HIT; Ratio=%s; Signature=%s#%s()", NF.format(ratio), pjp.getTarget().getClass().getName(), pjp.getSignature().toShortString()));
}
else if (miss1 > miss0){
LOG.debug(String.format("CACHE MISS; Ratio=%s; Signature=%s#%s()", NF.format(ratio), pjp.getTarget().getClass().getName(), pjp.getSignature().toShortString()));
}
else {
LOG.debug("query cache not used");
}
return result;
}
}As you can see the pointcut as defined in the @Around annotation has to be modified to point at the projects dao package.To get things working you have to add two lines of code to the Spring configuration:
<aop:aspectj-autoproxy /> <bean class="com.mycompany.myproject.aspect.CacheMonitor" />If you got any compiler or runtime errors, ensure both
spring-aop.jar and aspectj.jar has been added to the classpath of your project correctly.Executing dao methods with the woven aspects results in log messages like this:
CACHE HIT; Ratio=0,7818; Signature=com.mycompany.myproject.dao.MyDaoImpl#find()
3 comments:
Have you actually compared the performance with reasonable appenders?
Many log4j appenders do the appending on a separate thread, so while it might be slow on console, it might not be slow in a production file logger. And aspects don't come for free either.
Anyway an interesting article, especially since I am convinced, that AOP isn't mainstream enough and needs all the advertising it can get.
Hi Jens,
it might be true that its only slow on console logging. But other than that the default hibernate cache logging is not that useful. It produces multiple log lines for each and every (cache) GET or PUT. So if you cache a query which returns e.g. 10.000 hibernate entities you'll see 10.000*n log lines. This is ridiculous. =)
Hello
long miss0 = statistics.getSecondLevelCacheMissCount();
...
long miss1 = statistics.getQueryCacheMissCount();
Is that correct comparing second level cache misses with query cache misses?
Post a Comment