一次线上问题定位步骤及解决复盘demo

一次线上问题定位步骤及解决复盘demo

前段时间由于公司rabbitmq集群网络出现故障导致Rabbitmq响应延迟,引发楼主团队的一个核心服务出现连锁问题,现用这个demo复盘一下当时情景,及演示如何快速定位问题,以及总结经验教训思考如何避免类似情况发生
项目地址: https://gitee.com/kenwar/debug_online_demo

场景再现

  1. "十万火急群"有大量反馈系统xx/xx/xxx功能不可用,同时告警系统发出大量告警:"xxx服务获取数据库连接失败异常"
  2. 登录日志平台查看该服务:error级别日志中存在大量异常 [com.alibaba.druid.pool.GetConnectionTimeoutException: wait millis 1500, active 30, maxActive 30]
  3. 登录Grafana平台查看对应MySQL实例,CPU,内存,带宽,连接数等指标水平非常低,基本没有负载,排除长查询/数据库并发高/数据库死锁等原因
  4. Grafana平台查看对应tomcat实例,发现CPU占比高,线程数高,初步怀疑某些耗时操作导致连接未释放(目标定位到耗时代码块,耗时原因)
  5. 登录K8s管理平台,exec进入对应容器中
  6. jps找到容器中运行的java项目进程号18(其实我们所有docker中的java项目都是指定了进程号18)
    avatar
  7. top -Hp 18 查看该进程中线程CPU前十,所有线程cpu占比较均匀,排除某些线程执行死循环/大量cpu运算等原因
    avatar
  8. jstack -l 18 打印该进程中所有线程堆栈(可用jstack -l 18 > fileName的方式将结果写入指定文件中,便于后续分析 )
    avatar
  9. vi打开文件,搜索关键词"wait"发现大量请求waiting on condition [0x00007f6a32167000],大量请求在等待某个condition.其实是在获取连接时等待notEmpty的condition(并无卵用)
    线程堆栈信息
    avatar
    "http-nio-8093-exec-7" #20 daemon prio=5 os_prio=0 tid=0x00007f6a58b8c000 nid=0x15a8 waiting on condition [0x00007f6a32167000]
   java.lang.Thread.State: TIMED_WAITING (parking)
        at sun.misc.Unsafe.park(Native Method)
        - parking to wait for  <0x00000000ed03f468> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject)
        at java.util.concurrent.locks.LockSupport.parkNanos(LockSupport.java:215)
        at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.awaitNanos(AbstractQueuedSynchronizer.java:2078)
        at com.alibaba.druid.pool.DruidDataSource.pollLast(DruidDataSource.java:1487)
        at com.alibaba.druid.pool.DruidDataSource.getConnectionInternal(DruidDataSource.java:1086)
        at com.alibaba.druid.pool.DruidDataSource.getConnectionDirect(DruidDataSource.java:953)
        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:933)
        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:923)
        at com.alibaba.druid.pool.DruidDataSource.getConnection(DruidDataSource.java:100)
        at org.springframework.jdbc.datasource.DataSourceTransactionManager.doBegin(DataSourceTransactionManager.java:264)
    DruidDataSource.java:1487
        
    // druid连接池获取连接时会通过该condition进行限时等待,限时时间为连接池中配置的maxWAit值
    estimate = notEmpty.awaitNanos(estimate); // signal by
  10. 另有几十个线程状态为BLOCKED waiting for monitor entry [0x00007f7243af6000],都在wait同一把锁,通过堆栈信息是RabbitTemplate中使用CachingConnectionFactory进行createConnection()时在同步代码块中创建连接阻塞了,就是他了,定位到具体业务代码
    阻塞的线程堆栈信息
    avatar
    "http-nio-8093-exec-6" #19 daemon prio=5 os_prio=0 tid=0x00007f7274b0d000 nid=0x2930 waiting for monitor entry [0x00007f7243af6000]
   java.lang.Thread.State: BLOCKED (on object monitor)
        at com.ken.debugonline.sender.MsgSender.sender(MsgSender.java:29)
        - waiting to lock <0x00000000ed1202f8> (a java.lang.Object)
        at com.ken.debugonline.sender.MsgSender.sendMsg(MsgSender.java:20)
        at com.ken.debugonline.service.impl.TestServiceImpl.sendMsg(TestServiceImpl.java:23)
        at sun.reflect.NativeMethodAccessorImpl.invoke0(Native Method)
        at sun.reflect.NativeMethodAccessorImpl.invoke(NativeMethodAccessorImpl.java:62)
        at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
        at java.lang.reflect.Method.invoke(Method.java:498)
        at org.springframework.aop.support.AopUtils.invokeJoinpointUsingReflection(AopUtils.java:344)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.invokeJoinpoint(ReflectiveMethodInvocation.java:198)
        at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:163)
        at org.springframework.transaction.interceptor.TransactionInterceptor$$Lambda$508/65382615.proceedWithInvocation(Unknown Source)
    模拟阻塞的代码
    private void sender(Integer msg){
    // 该锁模拟rabbitmq获取connection是的逻辑 CachingConnectionFactory.java-> createConnection
    synchronized (connectionMonitor){
        try {
            // 模拟mq建立连接时的网络阻塞
            Thread.sleep(20000);
            log.info("send msg:{} to mq",msg);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}
    CachingConnectionFactory.java->createConnection()实际rabbitmq代码片段
        public final Connection createConnection() throws AmqpException {
            Assert.state(!this.stopped, "The ApplicationContext is closed and the ConnectionFactory can no longer create connections.");
            Object var1 = this.connectionMonitor;
            synchronized(this.connectionMonitor) {
            ...
    模拟业务代码TestServiceImpl.java
        // 声明事务
    @Transactional(rollbackFor = Exception.class)
    public void sendMsg() {
        int id = testMapper.insert();
        事务中进行发送
        testMapper.select(1L);
        // 模拟发送消息
        msgSender.sendMsg(id);

    }
  11. 分析:阅读该位置代码发现是在事务中调用了发送消息到mq的方法,该方法本会将消息offer到一个队列中,队列容量2w,再由其他线程异步消费发送至mq,讲道理是不会阻塞的,但是有一段神奇的逻辑是,当队列满后,将有当前线程进行同步发送
    // 示例代码com.ken.debugonline.sender.MsgSender
/**
 * 将消息放入队列中,使用线程异步发送,若队列已满则同步发送
 * @param msg
 */
public void sendMsg(Integer msg){
    boolean offer = needSend.offer(msg);
    // 若队列已满则同步发送
    if (!offer){
        this.sender(msg);
    }
}

private void sender(Integer msg){
    // 该锁模拟rabbitmq获取connection是的逻辑 CachingConnectionFactory.java-> createConnection
    synchronized (connectionMonitor){
        try {
            // 模拟mq建立连接时的网络阻塞
            Thread.sleep(20000);
            log.info("send msg:{} to mq",msg);
        } catch (InterruptedException e) {
            e.printStackTrace();
        }
    }
}
  12. 分析出原因,第一mq网络出现问题导致发送阻塞(沟通运维得知确实出了故障),第二在事务中调用了同步发送逻辑导致出现长事务,连接得不到释放,导致其他所有依赖该连接池的接口都获取不到连接,第三:mq未设置超时时间,导致阻塞在mq的时间过长
  13. 解决方案,设置mq超时时间,使发送逻辑快速失败,队列满时不再转同步发送,直接丢弃
  14. 重新打包发版
  15. 发版失败,由于项目启动时强依赖Rabbitmq,Rabbitmq连接超时就启动不了
  16. 怎么办,不搞了等运维把Rabbitmq恢复吧(反正不是我背锅)....咳咳,新项目启动不了没关系,可以进行热替换
  17. 下载arthas:curl -O https://arthas.aliyun.com/arthas-boot.jar
    avatar
  18. 启动arthas: java -jar arthas-boot.jar 根据进程号选择要注入的java项目
    avatar
  19. 将新的/MsgSender.class上传进容器指定路径(运维帮忙)
    avatar
  20. redefine /MsgSender.class
    avatar
  21. 等待30s(原mq超时时间),观察到获取连接失败的报错不再有,服务恢复正常(该替换只是替换内存中的class,重启后失效,不过我们服务不存在重启,只会新开容器部署)
  22. mq恢复后再次发布修改好的服务
  23. 坐等丢锅大会(复盘)

从该次事件中发现的问题

  1. 所有有可能出现延迟的网络中间件的使用都要设置好超时时间,考虑好如何在不可用时保证核心服务可用
  2. 开发同学不要在事务中进行耗时操作,长事务将导致连接迟迟无法释放,会快速耗完连接池(还会导致其他晚于该事务的回滚段不会被清理,占用大量存储空间:详情可了解MVCC)
  3. DBA增加对长事务的监听[查找超过60s的事务的代码: select * from information_schema.innodb_trx where TIME_TO_SEC(timediff(now(),trx_started))>60 ]
  4. 中间件出现故障时,运维团队应及时跟各部门同步,还需尽量保证高可用
  5. 消息发送的sdk不应进行异步转同步操作:如果是可靠消息,那么肯定先落表再发送,如果是非可靠消息,那么丢了也无所谓,所以理论上无需转同步
【推广】 免费学中医，健康全家人
原文地址：https://www.cnblogs.com/kenwar/p/13620431.html