龙空技术网

从句柄泄露到质疑Httpclient4.2.x存在缺陷

马森马 1162

前言:

现在咱们对“linux 查看句柄占用”都比较关怀,朋友们都需要知道一些“linux 查看句柄占用”的相关资讯。那么小编也在网摘上网罗了一些有关“linux 查看句柄占用””的相关资讯,希望同学们能喜欢,兄弟们一起来了解一下吧!

这篇文章已经在“Arthas排查问题征文活动”中获奖。

现象和背景

最近刚换了部门,由于还在熟悉环境,于是先拿一些线上问题来练练手,顺便熟悉一下各个子系统。

线上有A、B两台机器,运行着同样的Java应用,同时机器功能也比较纯净,没有别的应用在上面跑,其中A存在句柄泄露问题(too many open files),B不存在;A的机器配置较低,资源只有B的一半。机器A每隔一段时间句柄数就会涨到操作系统上限,需要重启应用才能解决问题。

由于两台服务器上运行的都是调度任务,调度是通过http请求去触发的,句柄泄露大概率是连接未关闭造成的,先看看A机器当前句柄数。

[root@lg_a7-36-f3_ops ~]# lsof | wc -l24192

发现如下文件句柄占比非常高

java    19165 jboss  166r     FIFO                0,8      0t0  463549930 pipejava    19165 jboss  167r     FIFO                0,8      0t0  451446562 pipejava    19165 jboss  168r     FIFO                0,8      0t0  423993915 pipejava    19165 jboss  169r     FIFO                0,8      0t0  436722899 pipejava    19165 jboss  170r     FIFO                0,8      0t0  423623794 pipejava    19165 jboss  171r     FIFO                0,8      0t0  422890484 pipejava    19165 jboss  172w     FIFO                0,8      0t0  422890484 pipe

问题肯定是出在这个类型的文件句柄上,但是,如何确定这类文件句柄是被谁创建的呢?后面一系列的操作也算踩了很多坑,如果有大佬能告诉我有什么办法能快速确定这种pipe/FIFO文件句柄和Java进程/Java代码之间的关系,还请不吝赐教。

75s

没什么头绪的时候,就开始查看应用的Java代码,调度任务是通过配置任务类名,通过http请求发送出去的,每个http请求连接创建之后到释放之前,在linux层面都应该是一个文件句柄,就先从这里开是看吧,发现http请求用的是Apache Httpclient发送的,这里某位前辈简单封装了一个Util如下

    public static String httpGet(String uri) throws ClientProtocolException, IOException {        DefaultHttpClient hc = new DefaultHttpClient();        HttpGet httpGet = new HttpGet(uri);        HttpResponse hr = hc.execute(httpGet);        HttpEntity e = hr.getEntity();        return EntityUtils.toString(e, "utf-8");    }

由于httpclient的稳定性和apache的背书,我不敢相信自己在十几分钟后会对httpclient源码产生质疑。

你这么膨胀?竟然敢质疑巨佬写的代码了?

可以看到,上面这个Util里,没有设置任何参数,其中最重要的一个参数就是超时时间;在httpclient4.2版本中,如果不设置超时时间,在这里会将超时时间设置为0,并且这个0会一路传递到PlainSocketImpl中的native方法socketConnect中。

// PlainSocketImpl.java native void socketConnect(InetAddress address, int port, int timeout) throws IOException;

到了这一步,我暂时停下了跟踪native方法的源码,先开始测试。

于是本地进行模拟,for循环跑这个httpGet,请求一个不通的端口,发现大部分情况下都会抛出异常,并且异常等待时间都在75s(75xxx ms)左右,异常栈如下。

有少数情况下卡着不动,不会抛异常,一直处于等待状态。

java.net.ConnectException: Operation timed out (Connection timed out)	at java.net.PlainSocketImpl.socketConnect(Native Method)	at java.net.AbstractPlainSocketImpl.doConnect(AbstractPlainSocketImpl.java:350)	at java.net.AbstractPlainSocketImpl.connectToAddress(AbstractPlainSocketImpl.java:206)	at java.net.AbstractPlainSocketImpl.connect(AbstractPlainSocketImpl.java:188)	at java.net.SocksSocketImpl.connect(SocksSocketImpl.java:392)	at java.net.Socket.connect(Socket.java:589)

这里似乎是发现了一个问题,如果存在某些调度任务已经迁移/下线,但是调度还是定期执行,就可能会出现少量文件句柄被占用的情况出现。

至于为什么大部分请求都会在75s超时,就得查看JDK的源码了。出于好奇,去下载了jdk7的源码(线上环境是JDK7)

然后找了个地方跪好了,开始看祖师爷的C代码

C代码今天看还有点费力。但是在PlainSocketImpl.c源文件中,有这么一句注释引起了注意

passing a timeout of 0 to poll will return immediately,but in the case of ServerSocket 0 means infinite.
请看第二句infinite,当是一个ServerSocket连接的时候,如果timeout参数为0,则这个超时时间是无限的

那么这会不会是之前测试时发现的卡顿之后一直等待的情况呢,毕竟那个native方法,就是socketConnect啊?由于没有C的调试环境,就没有继续往下追查。也许这会放在下一篇文章中。

缺陷并非BUG

说到这里,似乎发现了文件句柄不释放的可能场景之一,但是,也不能解释A服务器中有如此之多,每天增长几百个的现象。并且也没有证据表明大量的pipe文件句柄和httpclient有直接的关联。但是,这里确实存在不设置超时时间可能出现不可预期的后果的可能性。本想向官方提个bug,但是在4.5的版本中,发现这个Client官方在4.3版本之后已经不推荐使用了(IDEA自带的划线代表@Deprecated),但是4.5的版本中,如果客户端不设置timeout,仍然会被设置为默认值0,传递给Native方法。

感觉走向了人生巅峰

自己使用不当还怪别人写的有问题o(╯□╰)o

再次阻断

到这里又一次阻断了思路,即便是真的有httclient阻塞导致的句柄存在,也不应该有这么多。

由于期间一直被各个部门其他同事的临时需求打断,回来重新看这个问题的时候,已经是几天后了。

回到A机器,打开Arthas,继续看看Jvm信息,是否能获取到什么有价值的信息。

没错,句柄数又稳稳的上升了

[arthas@11681]$ thread | wc -l2447

然后又一次把占比较高的线程随机抽了几个出来看,终于,发现了一个可疑的地方。下面这个线程栈中,有个zmq看起来比较陌生。

[arthas@11681]$ thread 946"reaper-1" Id=946 RUNNABLE (in native)    at sun.nio.ch.EPollArrayWrapper.epollWait(Native Method)    at sun.nio.ch.EPollArrayWrapper.poll(EPollArrayWrapper.java:269)    at sun.nio.ch.EPollSelectorImpl.doSelect(EPollSelectorImpl.java:79)    at sun.nio.ch.SelectorImpl.lockAndDoSelect(SelectorImpl.java:87)    -  locked sun.nio.ch.Util$2@288b5e68    -  locked java.util.Collections$UnmodifiableSet@55e312a3    -  locked sun.nio.ch.EPollSelectorImpl@7653d630    at sun.nio.ch.SelectorImpl.select(SelectorImpl.java:98)    at zmq.Poller.run(Poller.java:216)    at java.lang.Thread.run(Thread.java:745)

会不会是某种第三方插件呢,于是回到项目代码中,全局搜索,的确发现了这么一个组件。

<dependency><groupId>org.zeromq</groupId><artifactId>jeromq</artifactId><version>0.3.5</version></dependency>

工具类代码如下

public static String tcpReqRep(String ip, int port, String msgReq) {        Socket client = null;        try {            client = ctx.socket(ZMQ.REQ);            client.connect("tcp://" + ip + ":" + port);            client.send(msgReq);            PollItem items[] = { new PollItem(client, Poller.POLLIN) };            int rc = ZMQ.poll(items, REQUEST_TIMEOUT);            if (rc == -1) return null;            if (items[0].isReadable()) {                String reply = client.recvStr();                if (reply != null) return reply;            }        } catch (Throwable e) {          	log.error("fail! msgReq:" + msgReq, e);            ctx = ZMQ.context(1);        } finally {            if (null != client) {                client.close();            }        }        return null;    }

到了这里,感觉就明朗了,这段代码一定是有问题的,异常处理中为什么要再new一个ZMQ.Context呢,ctx和client的关闭都处理的不够妥当,于是马上开始本地测试,循环调用这个方法,并且强行抛异常,观察句柄数是否会上升。

throw new UnknownHostException(";);

本地跑可以很方便的确定线程号,lsof看一下,的确是随着执行次数的增加,句柄数在不断增加。

回到线上A服务器,发现日志中,每天也都有几百行这样的异常日志。并且在本地debug的时候,出现一个线程名称和之前用Arthas观察中发现的一样。

总结

修复方案

完善ZMQ工具类中的逻辑,关闭client连接。httclient增加超时时间,可以避免出现较长时间等待的http连接;甚至永久的等待。

过程那么辛酸,结果却往往出人意料的简单明了。但是如果没有这个过程,又如何会发现奉为圭臬的Httpclient也存在这种“缺陷”呢。Java的Native方法对Java开发者来说,是透明的,大多数情况下我们不知道也不关心底层到底为我们做了什么,毕竟,质疑祖师爷怕是大部分情况下都会被打脸吧。

上面的内容都是我编的,那么我们有病再见吧。

标签: #linux 查看句柄占用