记一次死锁问题的排查和解决 - 数据库编程

说起来这个事情还是挺悲催的，记得上周忙的不亦乐乎，目标是修改之前另外一个团队留下来的一坨代码中的一些bug，这个项目是做OLAP分析的，分为两个模块，逻辑服务器主要负责一些元数据的操作，例如页面上展示的一些信息，而分析服务器负责执行查询语句，因为他们之前使用的是mondrian作为OLAP分析引擎，所以输入的查询是MDX语句，然后结果是一个二维的数据。这是基本的项目背景，当然使用mondrian的过程中发现他的确够慢的。而且mondrian还有一个问题，它的确在内部实现了一些缓存，缓存好像是基于cell的，但是它的缓存全部是保存在进程内部的，这就导致每一个分析服务器是有状态的，不能扩展成多个，否则就不能利用这些缓存了，另外，因为我们需要支持大量的数据源（每一个产品可能有一个或者多个数据源），每一个数据源可能定义多个报表，每一个报表对应着一个MDX查询语句，这就导致缓存的数据很大，很容易就造成OOM的现象，因此我们接下来的任务就是把这个缓存移出去，放到第三方的缓存系统中。回到正题，正当忙完准备周五上线呢，上线之后没怎么验证就匆匆在用户群里面吼了一声，因此大家都打开点啊点，突然老大过来说怎么现在打开报表什么的这么慢啊，我查了一下发现的确挺慢的，为什么在测试环境中没有发现呢？多次验证之后开始怀疑自己可能真的改错了什么了，立马回滚到之前的版本，然后就剩下我一头汗水中排查到底出现了什么问题。好在将线上的环境切到测试环境中很容易就把这个现象给复现了，主要是点开某个报表，然后经过一段时间的加载，接下来点开该报表之后就会快很多，因为接下来的操作都是从缓存中获取的，但是当我在页面上点击“清除缓存”之后（这个操作其实时清除整个报表的缓存和mondrian内部的缓存），发现会等待很长的时间才能返回，然后这个操作是异步的，在页面上我还能进行其他操作。但是当我再次点击其它报表的“清除缓存“的操作就会出现卡顿，然后发现打开其他的报表可能要等待一段时间，问题就这么很容易的复现了。之前没有针对java这方面的排查经验，但是也知道jstack，jmap之类的工具，于是立即用jstack把整个进程的堆栈抓取下来（很是后悔没有在回滚之前执行jstack），发现的确出现了问题：

Found one Java-level deadlock:
=============================
"mondrian.rolap.RolapResultShepherd$executor_160":
  waiting to lock monitor 0x0000000043b2bf70 (object 0x0000000702080db0, a mondrian.rolap.MemberCacheHelper),
  which is held by "mondrian.rolap.RolapResultShepherd$executor_152"
"mondrian.rolap.RolapResultShepherd$executor_152":
  waiting to lock monitor 0x00007f4e6c0751c8 (object 0x0000000702081270, a mondrian.rolap.MemberCacheHelper),
  which is held by "http-8182-11"
"http-8182-11":
  waiting to lock monitor 0x0000000043b2bf70 (object 0x0000000702080db0, a mondrian.rolap.MemberCacheHelper),
  which is held by "mondrian.rolap.RolapResultShepherd$executor_152"

这意味着程序里面出现了死锁，这里牵扯到了三个线程，但是其中的两个线程都持有了一个锁并且希望锁住对方持有的锁，而第三个线程正在等待前两个线程中某个线程已经持有的锁，有了这个堆栈就很容易排查问题了，并且在堆栈信息中发现很多线程都在等待这两个线程中已经持有的锁，但是因为这两个线程已经处于死锁状态了，其他的线程只能同步的等待，这样继续在前端操作这些报表迟早把tomcat中的线程消耗完。根据堆栈找到对应的代码，代码执行的是清理缓存的操作，但是缓存是对于每一个cube下的hierarchy创建的，因此根据具体的堆栈中的调用信息如下：

at mondrian.rolap.SmartMemberReader.flushCacheSimple(SmartMemberReader.java:577)
        - waiting to lock <0x00000007020a8990> (a mondrian.rolap.MemberCacheHelper)
        at mondrian.rolap.RolapCubeHierarchy$CacheRolapCubeHierarchyMemberReader.flushCacheSimple(RolapCubeHierarchy.java:883)
        at mondrian.rolap.RolapCubeHierarchy.flushCacheSimple(RolapCubeHierarchy.java:458)
        at mondrian.rolap.MemberCacheHelper.flushCache(MemberCacheHelper.java:166)
        - locked <0x00000007020a8e50> (a mondrian.rolap.MemberCacheHelper)
        at mondrian.rolap.RolapCubeHierarchy$CacheRolapCubeHierarchyMemberReader.flushCache(RolapCubeHierarchy.java:878)
        at mondrian.rolap.RolapCubeHierarchy.flushCache(RolapCubeHierarchy.java:451)

最先进入的这个flushCache函数是hierarchy级别的缓存清理，它其实是调用它的成员变量reader对象的clearCache方法，这个reader用于读取这个hierarchy下的members，可以直接从数据源（关系数据库）中读取，也维护了members的缓存，因此调用reader的clearCache方法也就是调用它的cache对象的方法，这个cache对象名为rolapCubeCacheHelper，类型为MemberCacheHelper，但是发现在reader中的clearCache方法执行的具体操作如下：

         @Override
        public void flushCache(){
            super.flushCache();
            rolapCubeCacheHelper.flushCache();
        }

首先调用父类的flushCache方法，父类又是什么鬼，打开父类的flushCache方法发现更奇怪的事情：

     public void flushCache(){
      synchronized( cacheHelper){
            cacheHelper .flushCache();
     }
    }

这是父类的flushCache方法，它其实就是对成员变量的cacheHe

记一次死锁问题的排查和解决(一)