一次线上Debug过程记录

背景

我所在项目组是做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

最后编辑于
©著作权归作者所有,转载或内容合作请联系作者
  • 序言:七十年代末,一起剥皮案震惊了整个滨河市,随后出现的几起案子,更是在滨河造成了极大的恐慌,老刑警刘岩,带你破解...
    沈念sama阅读 206,839评论 6 482
  • 序言:滨河连续发生了三起死亡事件,死亡现场离奇诡异,居然都是意外死亡,警方通过查阅死者的电脑和手机,发现死者居然都...
    沈念sama阅读 88,543评论 2 382
  • 文/潘晓璐 我一进店门,熙熙楼的掌柜王于贵愁眉苦脸地迎上来,“玉大人,你说我怎么就摊上这事。” “怎么了?”我有些...
    开封第一讲书人阅读 153,116评论 0 344
  • 文/不坏的土叔 我叫张陵,是天一观的道长。 经常有香客问我,道长,这世上最难降的妖魔是什么? 我笑而不...
    开封第一讲书人阅读 55,371评论 1 279
  • 正文 为了忘掉前任,我火速办了婚礼,结果婚礼上,老公的妹妹穿的比我还像新娘。我一直安慰自己,他们只是感情好,可当我...
    茶点故事阅读 64,384评论 5 374
  • 文/花漫 我一把揭开白布。 她就那样静静地躺着,像睡着了一般。 火红的嫁衣衬着肌肤如雪。 梳的纹丝不乱的头发上,一...
    开封第一讲书人阅读 49,111评论 1 285
  • 那天,我揣着相机与录音,去河边找鬼。 笑死,一个胖子当着我的面吹牛,可吹牛的内容都是我干的。 我是一名探鬼主播,决...
    沈念sama阅读 38,416评论 3 400
  • 文/苍兰香墨 我猛地睁开眼,长吁一口气:“原来是场噩梦啊……” “哼!你这毒妇竟也来了?” 一声冷哼从身侧响起,我...
    开封第一讲书人阅读 37,053评论 0 259
  • 序言:老挝万荣一对情侣失踪,失踪者是张志新(化名)和其女友刘颖,没想到半个月后,有当地人在树林里发现了一具尸体,经...
    沈念sama阅读 43,558评论 1 300
  • 正文 独居荒郊野岭守林人离奇死亡,尸身上长有42处带血的脓包…… 初始之章·张勋 以下内容为张勋视角 年9月15日...
    茶点故事阅读 36,007评论 2 325
  • 正文 我和宋清朗相恋三年,在试婚纱的时候发现自己被绿了。 大学时的朋友给我发了我未婚夫和他白月光在一起吃饭的照片。...
    茶点故事阅读 38,117评论 1 334
  • 序言:一个原本活蹦乱跳的男人离奇死亡,死状恐怖,灵堂内的尸体忽然破棺而出,到底是诈尸还是另有隐情,我是刑警宁泽,带...
    沈念sama阅读 33,756评论 4 324
  • 正文 年R本政府宣布,位于F岛的核电站,受9级特大地震影响,放射性物质发生泄漏。R本人自食恶果不足惜,却给世界环境...
    茶点故事阅读 39,324评论 3 307
  • 文/蒙蒙 一、第九天 我趴在偏房一处隐蔽的房顶上张望。 院中可真热闹,春花似锦、人声如沸。这庄子的主人今日做“春日...
    开封第一讲书人阅读 30,315评论 0 19
  • 文/苍兰香墨 我抬头看了看天上的太阳。三九已至,却和暖如春,着一层夹袄步出监牢的瞬间,已是汗流浃背。 一阵脚步声响...
    开封第一讲书人阅读 31,539评论 1 262
  • 我被黑心中介骗来泰国打工, 没想到刚下飞机就差点儿被人妖公主榨干…… 1. 我叫王不留,地道东北人。 一个月前我还...
    沈念sama阅读 45,578评论 2 355
  • 正文 我出身青楼,却偏偏与公主长得像,于是被迫代替她去往敌国和亲。 传闻我的和亲对象是个残疾皇子,可洞房花烛夜当晚...
    茶点故事阅读 42,877评论 2 345