谨慎使用ibatis的缓存

    周五调试线上环境的应用，发现某个服务响应时间非常慢，以正常情况衡量，一般每个请求处理时间大概在500ms以内，但是该请求处理时间长达3~5秒
    线上应用的大致情况为：该应用为一个运营支撑系统，主要处理运营数据的推送和查询，ORM 采用ibatis框架，日志使用log4j。
    针对响应时间较长的请求进行调试（还好日志跟踪比较全面），该请求包含多个业务处理，在某个日志区间，发现处理时间跨度竟然在3-5秒，应该就是这个区间的处理时间长，导致请求响应速度下降。
    大致分析了下该区间的处理，基本排除业务处理代码的性能瓶颈，定位是某个数据库查询SQL操作耗时长。但是ibatis在该SQL上设置了缓存，查询了某个配置表的全部数据，然后做全表缓存。理论上应该是初次查询速度较慢（这个可以接受），但是后续的请求应该全部命中缓存，不会再有数据库查询。通过DBA的协助，线上数据库也未发现该数据表的查询，说明后续的查询请求确实命中了缓存。

    使用jprofiler进行cpu的处理时间的剖析，发现主要问题还是和业务的处理方式有关，在使用缓存的方式上存在一定的偷懒，过于依赖程序的处理速度，为了节省数据库查询，一次将数据库表中的数据（近8w条）全部查询出来，并用一个key进行缓存，众所周知ibtais是基于查询的缓存而非对象，因此缓存的数据量较大时，下一次的查询在通过cache获取数据时会带来大量的性能消耗，如下：



CacheModel.getObject用来根据key从缓存取数据（这里缓存了一个仅8w多个数据对象的hashmap）

 if ( log.isDebugEnabled() )  {
      	if ( value != null )  {
            log("retrieved object", true, value);
      	}
      	else  {
      		log("cache miss", false, null);
      	}
      }

由于存在上诉代码，会存在将这个8w多个数据对象进行toString()的过程，虽然每个对象toString 的时间在 微秒级别，但是由于数据量较大，总的耗时较长




avg：27us , 88404次的invoke，总耗时2s多

当然也可以通过修改日志级别来解决问题
private static final Log log = LogFactory.getLog(CacheModel.class);
为该logger指定日志级别，避免CacheModel.getObject中log方法的调用

********************************************************************
对于未声明的logger，LogFactory会创建一个
level=null，
parentLogger=org.apache.log4j.spi.RootLogger
的logger
见如下代码

Log instance = (Log) instances.get(name);
        if (instance == null) {
            instance = newInstance(name);
            instances.put(name, instance);
        }

当ibatis调用 log.isDebugEnabled() 时，先判断当前logger的level，为空继续判断parentlogger的level，org.apache.log4j.spi.RootLogger默认level为debug，见如下代码

Hierarchy h = new Hierarchy(new RootLogger((Level) Level.DEBUG));

就会导致获取每个缓存object都会调用一次log记录

********************************************************************
但是这么大的数据量放在那里，无论做排除或者做筛选，无论业务处理 or  ORM 框架处理，都会导致总耗时超长的情况

因此在使用ibatis的缓存时，要明白基于查询的缓存，是否缓存的数据量会较大，尽量避免一次查询缓存多条数据，尽量将缓存数据根据查询条件分拆到多个key中，提升处理性能。