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

说起来这个事情还是挺悲催的,记得上周忙的不亦乐乎,目标是修改之前另外一个团队留下来的一坨代码中的一些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方法,它其实就是对成员变量的cacheHelper对象加锁,然后使用cacheHelper的flushCache方法,打开cacheHelper对象才发现它又是一个MemberCacheHelper对象,这时候问题来了,为什么父类和子类都保存了一个MemberCacheHelper对象呢?其实MemberCacheHelper这个对象就是一个缓存的结构体,父类有一些公有的缓存数据,子类有自己的缓存信息,这样也能说得过去,继续到MemberCacheHelper类的flushCache方法:

     // Must sync here because we want the three maps to be modified together.
    public synchronized void flushCache() {
        mapMemberToChildren.clear();
        mapKeyToMember.clear();
        mapLevelToMembers.clear();

        if (rolapHierarchy instanceof RolapCubeHierarchy){
             ((RolapCubeHierarchy)rolapHierarchy ).flushCacheSimple();
        }
        // We also need to clear the approxRowCount of each level.
        for (Level level : rolapHierarchy.getLevels()) {
            ((RolapLevel)level ).setApproxRowCount(Integer. MIN_VALUE);
        }
    }

这里对缓存中的每一个map进行clear,然后又对这个hierarchy执行flushCacheSimple方法,我勒个擦,怎么又回来了,这个hierarchy对象不就是我们进出进入flushCache的那个hierarchy对象吗?过了一遍flushCacheSimple方法发现它最终又调用了reader的flushCacheSimple方法,这个函数执行的操作类似于flushCache:

     public void flushCacheSimple(){
           super.flushCacheSimple();
           rolapCubeCacheHelper.flushCacheSimple();
        }

好了,继续到MemberCacheHelper的flushCacheSimple方法:

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

我勒个擦,这里又加锁,之前不是已经加过了吗?当然这个锁因该是可重入的,这里自然不会造成死锁,但是下面的rolapCubeCacheHelper对象也是MemberCacheHelper对象啊!最后进入flushCacheSimple方法,这彻底凌乱了:

    public synchronized void flushCacheSimple() {
        mapMemberToChildren.clear();
        mapKeyToMember.clear();
        mapLevelToMembers.clear();
        // We also need to clear the approxRowCount of each level.
        for (Level level : rolapHierarchy.getLevels()) {
            ((RolapLevel)level).setApproxRowCount(Integer.MIN_VALUE);
        }
    }

这里面执行的操作和flushCache方法不是一样的吗?!这到底是在做什么,当然理了这么多也发现了出现死锁的根源了,就在于reader执行的flushCache方法,这里面分别调用了父类和当前类的cacheHelper对象的flushCache,但是这个方法还会调用flushCacheSimple方法,这个方法再次调用reader的flushCacheSimple方法,这里再次调用父类和当前类的cacheHelper对象的flushCacheSimple方法,而且每次调用都需要加锁,这就导致了如下的死锁情况:

A线程执行flushCache方法,它已经完成了super.flushCache方法,然后执行当前reader对象的flushCache方法,首先及时需要持有这个helper对象的锁,然后再执行到flushCacheSimple的时候申请父类的helper对象的锁。B线程可能在执行super.flushCache进入这个函数意味着需要持有父类的helper,但是当它执行flushCacheSimple的时候有需要申请当前类的helper对象的锁,于是就造成了死锁。

开始没有定位到这个问题之前不晓得死锁到底是怎么回事造成的,于是想着让所有的线程顺序执行flushCache方法就可以避免死锁了(不要并发了),但是尝试了一下发现不能这样,因为其他线程还是有可能调用这个flushCache方法,这个不是由我控制的,于是只能具体了解这个函数到底执行了什么,发现flushCache和flushCacheSimple方法其实是重复的,不晓得当初写这段代码的人是怎么想的,于是就把所有的flushCacheSimple方法的调用去掉,这样就不会再有持有A锁再去申请B锁的情况了。

问题算是解决了,最终hotfix版本也算是上线了,一颗悬着的心也算放下了,着这个过程中我也学到了不少知识:

1、学会并且善于使用java提供的分析工具,例如jstack、jstat、jmap、以及开源的MAT等等。

2、遇到问题不要害怕,不要一味的埋怨这个问题不是我造成的,我也不知道怎么回事之类的,静下心来思考整个流程,运用以前的理论知识和经验一定能够把问题解决的,没有什么问题是偶然的,如果出错一定是代码有问题。

3、测试很重要,尤其压力测试,我们项目目前人手紧缺,QA也没有专职的,所以基本上是开发在开发环境上测试一下功能,并没有做过性能测试之类的东西,我觉得测试应该尽可能覆盖线上可能出现的各种情况。

4、上线之前做好回滚,否则你会很狼狈,幸亏这点我每次操作之前都先备份。

5、在编码的时候,尤其一个操作会涉及到多个synchronized操作的时候尤其要注意,回忆一下当初避免死锁的几个方法,按顺序加锁往往是最好的解决办法。

6、搞清楚一个方法到底想要做什么?输入是什么,输出是什么,会造成什么影响,在写完一个方法之后在脑子中模拟一下整个函数的执行流程是否符合预想。

7、如果真的遇到这样的需求:父类和子类都持有一个类型的对象,让他们独立操作,父类对象的操作完成之后在执行子类对象的操作,而不要穿插着调用。

接下来的一段时间要开始搞mondrian了,希望能够从这个OLAP执行引擎中学到一些东西,不过自己的编译原理方面的知识几乎为0,这方面需要补强啊,我对于mondrian中重点要看的东西应该是:1、如何解析MDX(类似于如何解析SQL),2、如何将MDX动态的翻译成一串SQL(类似于如何生成执行计划),3、缓存如何实现,4、执行MDX或者SQL时如何使用缓存,5、如果使用聚合表进行优化。

希望顺利~

时间: 2024-08-04 11:23:07

记一次死锁问题的排查和解决的相关文章

记一次服务器被挖矿经历与解决办法

记一次服务器被挖矿经历与解决办法 在最近的某一天里面,中午的一个小息过后,突然手机的邮件和公众号监控zabbix的告警多了起来.我拿起手机一看原来是某台服务器上的CPU跑满了,就开始登上去看一下是哪个脚本导致负荷高的(在期间使用top -d 1命令查看负荷占用情况).可以静下来想了下,中午大家都在休息不应该CPU负载会这么高的,心里想80%是服务器被黑了. 后来发现是/tmp/ddgs.3013和/tmp/qW3xT.2这两个文件跑满了服务器CPU,后来决定先kill掉文件PID和删除/tmp目

arcgis安装msi安装包提示&quot;在未标记为正在运行时,调用了RunScript”解决办法

安装msi安装包提示"在未标记为正在运行时,调用了RunScript”解决办法 windows/temp目录相关权限不对,右击temp文件夹,选择管理员获取所有权限.

Oracle常见死锁发生的原因以及解决方法

Oracle常见死锁发生的原因以及解决办法 一,删除和更新之间引起的死锁 造成死锁的原因就是多个线程或进程对同一个资源的争抢或相互依赖.这里列举一个对同一个资源的争抢造成死锁的实例. Oracle 10g, PL/SQL version 9.2 CREATE TABLE testLock(  ID NUMBER, test VARCHAR(100)  ) COMMIT INSERT INTO testLock VALUES(1,'test1'); INSERT INTO testLock VAL

ceph集群报 Monitor clock skew detected 错误问题排查,解决

ceph集群报 Monitor clock skew detected 错误问题排查,解决           告警信息如下: [[email protected] ceph]# ceph -w    cluster ddc1b10b-6d1a-4ef9-8a01-d561512f3c1d     health HEALTH_WARN            clock skew detected on mon.ceph-100-81, mon.ceph-100-82            Mon

mysql数据库死锁的产生原因及解决办法

这篇文章主要介绍了mysql数据库锁的产生原因及解决办法,需要的朋友可以参考下 数据库和操作系统一样,是一个多用户使用的共享资源.当多个用户并发地存取数据 时,在数据库中就会产生多个事务同时存取同一数据的情况.若对并发操作不加控制就可能会读取和存储不正确的数据,破坏数据库的一致性.加锁是实现数据库并 发控制的一个非常重要的技术.在实际应用中经常会遇到的与锁相关的异常情况,当两个事务需要一组有冲突的锁,而不能将事务继续下去的话,就会出现死锁,严 重影响应用的正常执行. 在数据库中有两种基本的锁类型

Oracle死锁产生的原因和解决办法

如果有两个会话,每个会话都持有另一个会话想要的资源,此时就会发生死锁.用下面实验来说明死锁的产生原因和解决办法.SESSION1:SQL> create table t2 as select * from emp;SQL> select * from t2 where empno=7369; EMPNO ENAME      JOB              MGR HIREDATE                 SAL       COMM     DEPTNO---------- ---

Mysql死锁如何排查:insert on duplicate死锁一次排查分析过程

前言 遇到Mysql死锁问题,我们应该怎么排查分析呢?之前线上出现一个insert on duplicate死锁问题,本文将基于这个死锁问题,分享排查分析过程,希望对大家有帮助. 死锁案发还原 表结构: CREATE TABLE `song_rank` ( `id` int(11) NOT NULL AUTO_INCREMENT, `songId` int(11) NOT NULL, `weight` int(11) NOT NULL DEFAULT '0', PRIMARY KEY (`id`

Kafka 异步消息也会阻塞?记一次 Dubbo 频繁超时排查过程

线上某服务 A 调用服务 B 接口完成一次交易,一次晚上的生产变更之后,系统监控发现服务 B 接口频繁超时,后续甚至返回线程池耗尽错误 Thread pool is EXHAUSTED.因为服务 B 依赖外部接口,刚开始误以为外部接口延时导致,所以临时增加服务 B dubbo 线程池线程数量.配置变更之后,重启服务,服务恢复正常.一段时间之后,服务 B 再次返回线程池耗尽错误.这次深入排查问题之后,才发现 Kafka 异步发送消息阻塞了 dubbo 线程,从而导致调用超时. 一.问题分析 Dub

记一次window服务器木马排查(后门植入挖矿程序)

1,新项目需要一台windows服务器,安装所需环境和服务后,发现服务器资源不足无法运行,查看任务管理器,发现可疑程序占满了CPU 通过百度发现,这个一个挖矿程序,显然是被后门植入了矿机,果断杀掉进程,删掉文件 第二天,发现CPU又被挖矿沾满,经过分析,这个后门程序,和系统的svchost.exe很像,删除过后一直自动新建出来. 通过一个一个的排查进程,发现一个可疑进程,和程序,经过仔细的对比了解,可疑判断这是一个后门木马 由于服务器跑的服务比较多,不能开防火墙,只能选择第三方防护软件,综合对比