likes
comments
collection
share

一次线上死循环的排查过程

作者站长头像
站长
· 阅读数 4

场景

  • A写了一个服务，给B调用

  • A的这个服务针对一个key，在一次调用完成之前不能调用第二次，如果连续调用，第二次不会执行业务，而是直接返回系统繁忙，使用ConcurrentHashMap + Atomic的cas控制。（不要吐槽我们小公司小用户量暂时没有使用水平扩展的分布式服务哦，这里就考虑了单机线程安全）

    // {key -> 是否正在运算}
Map<Long, AtomicBoolean> map = new ConcurrentHashMap<>();

public * *(@RequestBody ..)  {
    //..省略校验和获取主键
    // 能够保证单机线程安全
    AtomicBoolean atomicBoolean = map.computeIfAbsent(key, (key)->new AtomicBoolean(false));
    // 如果正在执行，直接返回一会儿再来
    if(!atomicBoolean.compareAndSet(false, true)){
        return "系统繁忙";
    }
    try {
        //..业务操作并返回
    }finally {
        atomicBoolean.set(false);
    }
}

某日，调用方B看了日志，有一个key调用这个服务后一直返回系统繁忙，且没再成功过，于是，开始了排查过程。

过程

调用方日志

首先，先看调用方B的日志，找到了使用这个key第一次失败调用的位置：

20-06-06 12:09:12 INFO  ** - 开始调用某key
20-06-06 12:09:22 ERROR ** - 调用 fail :
java.net.http.HttpTimeoutException: request timed out

可以看出使用了Http调用，从开始调用到失败日志，有10s时间，正是请求超时时间。

请求没返回，之后调用过程一直返回系统繁忙，说明一直没有执行到上面的释放cas锁的块：

try {
    //..业务操作并返回
}finally {
    // 没有执行到
    atomicBoolean.set(false);
}

基本猜到了问题，业务操作代码中一直没有执行完毕；

服务方日志

再去看了服务方A的日志：

20-06-06 12:09:13.476 INFO  ** - 结束
// 关键，有一个只有开始没有结束
20-06-06 12:09:13.476 INFO  ** - 开始
// 这个开始是其它key的
20-06-06 12:09:23.267 INFO  ** - 开始

果然，在12:09:13的一次调用只有开始，没有结束。

进程

再去看了服务A的服务器进程线程运行状况：

top
top -Hp <pid>

一次线上死循环的排查过程

发现有一个线程已经占用了将近43分钟的CPU时间，而距离最后一次调用大约过去了一个小时时间，可见很可能是A的业务代码里面有死循环导致这个线程一直处于运行状态。

因为这个线上只是用了jre，没有jdk，没有jstack命令可以查看详细的线程信息，至于为什么没有，得问A。

// 假想一下我们执行了jstack 线程id查看到了确实这个线程一直处于运行状态
jstack <pid>

问题

看了看业务代码，定位到了下面一个循环，A为了分批保存大量数据，使用了一个while循环，线下测试时没有达到需要分批保存的阈值，而最后到了线上，需要分批保存，flg没有像预想的那样退出循环，导致一直插入数据。

while (flg){
    flg = false;
    if(..){
        testService.save(..);
        if(..)
	        flg = true;
    }
}

看到这里，我猜想既然while循环中插入数据，那么数据库中这个表估计这一个小时已经被插入了许多重复数据了，但是取数据库里一刷新，竟然没有明显新增：

一次线上死循环的排查过程

猜想了一下，是因为事务一直在这里循环，未提交，所以我去其它mysql连接会话中当然不可见未提交事务中的记录，但是为了更加确认，决定去查以下数据库表文件，发现这个只有八百多条记录的表竟然已经如下占用了700M左右的数据，所以，虽然事务未提交，但是它的表文件是在不停增加的。

一次线上死循环的排查过程

而且，刷新之后发现，这个表文件的更改时间一直变化，至此证明了死循环问题代码的存在性。

解决

其实A的分批插入想法可以比较可靠的使用reactor中流的一个buffer方法实现：

Flux.fromIterable(list)
    .buffer(savePerNum)
    .subscribe(testService::save);

避免了使用死循环，且可读性更加的高。

发布之后，问题解决。

总结

  • 单机情况下，对需要控制线程安全的资源可以使用ConcurrentHashMap + Atomic~ + cas控制
  • 出现问题要分析日志，找到问题出现的关键位置，观察猜想问题的可能原因
  • 查看java进程和线程信息证明猜想
  • 如果事务没有提交，表文件还是会不停改变增大的，虽然其它会话看不到未提交的数据
  • 流式的分批插入可以使用reactor的buffer优雅完成

小伙伴们有什么建议和想法，欢迎讨论啊~

转载自:https://juejin.cn/post/6844904190628593677
评论
请登录