问题现象:
订单状态更新任务卡主,不执行了,导致bmcp订单状态无法更新,造成用户订单状态更新延迟;
肯定是线程卡主了,准备分析进程,找出是做什么操作造成的;
对进程io和gc进行分析
获取进程id
|
|
得到进程id:22780
查看gc情况
使用jstat检查gc情况,主要看fullgc频率次数是否异常,正常
|
|
gc情况大致正常,没有fgc很频繁的情况(之前遇到过服务不可用,fgc很频繁,超过ygc)
查看机器io情况
使用 iostat -x 查看io情况,主要看iowait是否过高
|
|
执行了几次该命令之后,发现下面这个thread始终存在,并且状态始终是RUNNABLE
|
|
通过上面的线程调用堆栈信息,可以发现它是个定时任务,名称为:scheduler-10
分析业务日志
发现该任务的最后一个操作,是在向微信发送请求,日志内容如下:
|
|
与上面jstack的线索相吻合,该定时任务scheduler-10的最后一个操作是向微信某个地址发请求,于是怀疑是请求卡主了
准备证实:
查看域名映射的ip地址
|
|
查看进程中此ip是否存在,以及次ip占用的进程端口:
|
|
得到端口号:50785
查看端口对应linux磁盘上的文件(万物皆文件)
|
|
(lsof 是个好东西,很强大,还可以恢复被删除的文件。)
查看socket链接建立的时间
|
|
发现链接的建立已经有段时间了,怀疑是调用httpclient的时候,没有设置socketTimeout时间(之前遇到过一次这种情况,因为没有设置,导致卡死),于是查看代码
代码检查
|
|
很遗憾,代码中是设置了socketTimeout了的,于是又开始怀疑人生了,但是种种迹象表明就是这块的原因,回过头又仔细看了下jstack信息,发现是SSLHandShake的时候,一直在等待socketRead,于是找了同事一起帮忙,怀疑会不会是4.3.5版本的bug,于是又开始google;
果不其然,搜到一篇apache的官方jira,报告了这个问题
|
|
https calls ignore http.socket.timeout during SSL Handshake.
This can result in a https call hanging forever waiting for socket read.
In both SSLSocketFactory and SSLConnectionSocketFactory, sslsock.startHandshake();
is called before socket timeout is set on the socket.
This means timeout is not respected during the SSL handshake,
and the thread can hang with a stacktrace that looks like this:
org.apache.http.impl.client.AbstractHttpClient.doExecute
org.apache.http.impl.client.DefaultRequestDirector.execute
org.apache.http.impl.client.DefaultRequestDirector.tryConnect
org.apache.http.impl.conn.ManagedClientConnectionImpl.open
org.apache.http.impl.conn.DefaultClientConnectionOperator.openConnection
org.apache.http.conn.ssl.SSLSocketFactory.connectSocket
org.apache.http.conn.ssl.SSLSocketFactory.connectSocket
sun.security.ssl.SSLSocketImpl.startHandshake
sun.security.ssl.SSLSocketImpl.startHandshake
sun.security.ssl.SSLSocketImpl.performInitialHandshake
sun.security.ssl.SSLSocketImpl.readRecord
sun.security.ssl.InputRecord.read
sun.security.ssl.InputRecord.readV3Record
sun.security.ssl.InputRecord.readFully
java.net.SocketInputStream.read
java.net.SocketInputStream.socketRead0
确实在402行也加上了socket.setSoTimeout(socketTimeout);
于是,又是一顿各种代码检查、依赖包检查,看是否有依赖过低版本的包导致的,无果。
之前交易通知模块使用的一直都是4.3.6版本,一直都很稳定,于是先试探性的升级下版本,只能试试了。
=========================
但,还是不甘心啊,使用没有找到问题的原因。
第二天,也就是双11晚上看双11玩会马云变魔术的时候,无意间看到我们的代码中使用的ssl connect是SSLConnectionSocketFactory
并不是SSLSocketFactory
,而且SSLSocketFactory
这个类也已经是被Deprecated
,并且说明了替代类是:
|
|
马上检查4.3.5与4.3.6这两个类的区别,功夫不负有心人
- 4.3.6版本
|
|
- 4.3.5版本
|
|
差别就是,在4.3.6版本中,ssl handshake之前,设置了socketTimeout
|
|
而,4.3.5版本,也就是我们使用的版本中,并未设置上socketTimeout。
终于水落石出了!以后这个版本不要用啦!
总结下:解决问题的过程一定是很曲折的,但结果不会太坏。
吐槽一下:
- apache httpclient release note 一点都不规范,解决的上面的bug号1478都不写
https://archive.apache.org/dist/httpcomponents/httpclient/RELEASE_NOTES-4.3.x.txt - 代码写的也不规范,一个方法几百行、方法参数还有9个的;