美文网首页工作生活
一次线上Debug过程记录

一次线上Debug过程记录

作者: MccreeFei | 来源:发表于2019-07-03 15:41 被阅读0次

背景

我所在项目组是做Wifi数据传输业务的工作,简单来说,公司的wifi设备铺设到各个城市的店铺中,这些设备产生的数据会实时上传至云,而我们项目组的工作就是将各个平台管辖区域的数据传输给各平台。每个平台的数据格式、传输方式都可能是不同的,传输方式大部分以FTP为主,以及传输时间间隔大部分是每5分钟传输一次。那一天早上一个平台的客户打电话过来反馈说我们传输的数据在凌晨就断掉了,于是就有了这一次线上Debug的过程。

Debug过程

首先猜测的是该平台所在服务器的服务Down掉了,于是进入该服务器,发现Java进程依然生龙活虎,又看了下阿里云的监控,在停止传输的那段时间内Cpu、内存等指标并没有明显的异常,排除服务Down掉的原因。接着我去看了下传输的日志,确实传输的日志从凌晨开始就没有再产生,不仅仅是该平台,所有该服务器传输的平台数据传输任务都停止了。眉头一蹙,感觉事情并不简单。

系统在发送数据前,会先生成数据文件并保留一段时间,于是查看了下生成文件的情况,文件依然在正常地每5分钟生成一次。由此可知生成数据的流程是没有问题的,那么问题的范围可以进一步被缩小,猜测是发送线程池有异常导致停止发送。

带着猜想,使用jstack查看传输线程池中所有线程的状态,如下图:

图一 图二

这个传输线程池由固定20个线程组成,其中19个线程的状态如图一所示——阻塞等待0x00000006a6271680这个锁,另外一个线层状态如图二所示——获得0x00000006a6271680锁,并一直在socketRead0上挂起。有一点需要补充的是线程状态RUNNABLE既可表示线程正常运行也可表示线程正在等待系统资源而挂起,此时是第二种情况。现在bug的原因基本已经找到:某一持有锁的线程因为某种原因一直在socketRead0挂起,而其他线程都在排队等待该锁最终导致了整个传输线程池的线程不可用,也就无法传输数据了。

探寻bug发生原因

现在Bug大致原因已经明晰,但是实质性的为什么线程会在socketRead0上挂起还需要进一步去了解原因。首先针对我们的业务解释下为什么会出现锁争用的情况。

为何发生锁争用

每个平台对应了一个FTPTransfer对象用来给对方平台传输数据,传输线程池大致每隔5分钟会被调度运行一次,FTPTransfer中发送数据方法sendData是加锁的,方法结构如下:

public synchronized void sendData(final File file) throws IOException {
    //发送逻辑
}

在一般情况下,每个平台用各自的FTPTransfer发送数据是不会出现锁争用的情况的,但是现在出现了一个平台A,线程在给A发送数据时挂起并且一直占用着A对应的FTPTransfer锁,此时其他线程正常给其他平台传输数据,下一个5分钟后其余的某个线程再次想给平台A发送数据而阻塞自己等待挂起线程释放锁。在n个5分钟后其余所有线程都在等待该挂起线程释放锁,最终出现整个线程池不可用的情况。

socketRead0

这里通过一篇博客的引用来解释下socketRead0这个本地方法是做什么的。

What does SocketInputStream.socketRead0() API do?
It’s always easy to remember new concepts through real life analogies. Say suppose you are calling your wife or girlfriend on the phone. Once call gets connected, if she is in happy/good mood immediately you will get response “Hello Honey (or darling or sweetie), How are you?” If your call got connected when she is in middle of doing some work (say she is in her office, picking up kids, Gym…) there might be delay in her response to say “Hello Honey (or darling or sweetie) ….”. Suppose your call got connected when she is in angry/bad mood then response can be unpredictable. God only knows. You might get response after several seconds/minutes (or even call can get hanged up . So, the time you are waiting since the moment call got connected until the moment you hang-up the call is basically socketRead0() API. (Thanks to Douglas Spath from IBM for giving this beautiful example to explain this SocketRead0() API.)

简单来说,对于FTP,当对方FTP服务器繁忙时,就可能出现socket延时响应或者一直挂起的情况。

Bug解决

那么如何解决socketRead0一直挂起的情况呢?最常见的方法就是设置socket的超时时间setSoTimeout,我们FTP工具类使用的是apache的commons-net,其中在生成FTPClient时也都设置了socket的超时时间,没有理由会一直出现socket一直挂起的情况。

在一番google下终于找到了答案,居然是Jdk的bug,bug的标题:SocketInputStream.socketRead0 can hang even with soTimeout set,bug号码:8075484,bug详情页。最终通过将环境的jdk版本升级到解决掉bug的版本,再没有出现同样的情况,成功解决数据不传输问题。

jdk bug

参考

Threads stuck in java.net.SocketInputStream.socketRead0

相关文章

  • 一次线上Debug过程记录

    背景 我所在项目组是做Wifi数据传输业务的工作,简单来说,公司的wifi设备铺设到各个城市的店铺中,这些设备产生...

  • 记录一次debug过程

    最终证明这是一个个性化的错误。 上传本地apk进行安装时,进行到50%之后就报错——导致系统推出。 重新加载为数不...

  • ssh 连接缓慢

    今天发现要登陆线上机器特别缓慢就用-v命令debug了下整个ssh的过程 ssh 172.31.2.164 -...

  • 记一次Debug过程

    前言 在写实现等高自定义Cell自测项目时,自己导致的数个Bug。因为项目较为简单,所以在实现时特意使用了一些之前...

  • btrace线上定位问题

    开发环境可以local debug,测试环境可以remote debug,线上环境只能看看log了, debug肯...

  • windows+eclipse操作Hbase连接过程中debug

    windows+eclipse操作Hbase连接过程中debug记录(一) 4.java.lang.ClassNo...

  • stf from openstf to DeviceFarmer

    记录一次debug过程看起来是同步代码遇到的问题,顺手查一下STF的最新代码,发现这个仓库已经存档了。 opens...

  • 如何通过UIButton切换请求的服务器地址

    在我们开发的过程中免不了会有环境不同的包。测试包,线上测试包,线上包,还有一些其他特殊需求的包。 在Debug环境...

  • 有趣的一次调试

    果果小姚 [TesterGC](javascript:void(0);) 1周前 记录下今天的debug 测试过程...

  • go语言记log: glog剖析

    首发: legendtkl.comlog的一个典型应用场景就是实现log分级,比如线上环境不需要记录DEBUG的l...

网友评论

    本文标题:一次线上Debug过程记录

    本文链接:https://www.haomeiwen.com/subject/pwtchctx.html