线上问题解决系列——记一次HTTP连接池导致的Java服务雪崩

vlambda
2021-05-20

线上问题解决系列——记一次HTTP连接池导致的Java服务雪崩

某天早晨的9点15分开始，笔者所在部门的一个服务（SpringBoot），不断有用户反馈接口调用无法正常返回结果。考虑到最近服务并没有上线，配置也没有修改，毫无疑问，一定是服务出现了异常。

遇到这种线上问题时，一定要采取先止损、先恢复，后定位、后处理的方式来解决。因此，研发同学果断在9点37分进行了服务重启。重启后，一切恢复正常。接下来，就需要详细分析异常产生的原因了。

遇到这类服务异常问题时，如果服务有网关，首先要确定网关是否正常，之后再看服务是否出现了异常。

通过查看日志可知，网关一切正常。之后，就需要查看服务是否出现了异常。查看服务是否出现了异常，主要的检测点为：内存使用率，CPU使用率，IO速率等。

内存使用率如下所示，非常平稳。

CPU使用率如下所示，非常平稳。

线上问题解决系列——记一次HTTP连接池导致的Java服务雪崩

IO速率如下所示，也是非常平稳。

上述3个指标并没有出现什么异常，因此笔者怀疑，是否是线程出现了什么问题。带着这个怀疑，笔者查看了服务的线程数量。某个服务实例的线程数量如下图所示：

可以看到，大概9:00-9:15之间，线程数量急剧上升。这一时间段内服务QPS并未提升，因此基本可以定位为线程阻塞问题。

如果能够保留生产现场的话，就可以直接dump线程来进行问题的分析。如果生产现场无法保留的话，就只能通过日志来定位实际的问题。比较悲催的是，笔者只能通过后一种方式来定位问题。

既然产生了线程阻塞，那么就可以看一下，在服务实例停止时，被阻塞的线程到底输出了什么。笔者选取148号线程进行了日志的查看，如下的两条日志引起了笔者的注意：

[INFO][2021-04-11T09:09:14.917+0800][http-nio-8099-exec-148][ERROR][2021-04-11T09:37:01.618+0800][http-nio-8099-exec-148]

两条日志的输出，居然间隔了将近28分钟！

进一步查看日志，发现了如下的异常：

org.apache.http.impl.execchain.RequestAbortedException: Request execution failed at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:199) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110) at org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108) at org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)        at com.xxx.xxx.xxx.xxx.XxxxxxClient.execute(XxxxxxxClient.java:49)

原因已经很明确了，就是rest请求导致了线程阻塞问题。那么为什么这个rest请求会导致线程阻塞呢？

深入到代码中，发现了这样一段代码：

// 这里就是抛出异常的地方，使用http连接池HttpResponse httpResponse = httpClient.execute(httpPost);if (httpResponse == null) { throw new RuntimeException("HttpResponse is null");}
if (httpResponse.getStatusLine().getStatusCode() != HttpStatus.SC_OK) {    // 非200状态，直接抛出异常 throw new RuntimeException(httpResponse.toString());}// 读取返回结果，后续处理逻辑response = EntityUtils.toString(httpResponse.getEntity());

抛出异常的地方，就是上述第2行。此处出现问题时，可能的原因有两个：

http请求调用时间过长
获取不到可用连接

在服务中，已经设置了http请求3s超时，因此第一种情况不会发生。也就是说，一定是第2种情况导致了线程阻塞。那么，又是什么原因导致了http连接池耗尽，拿不到可用连接呢？

在第8行，当http请求的状态非200时，不做任何事情，直接抛出了异常。这也就导致了这条http连接并没有被释放掉！

这里额外补充一下，为何各位读者朋友在平时使用过程中，连接会自动的释放。

一般在http请求返回结果后，会读取http请求返回结果的信息。比如使用以下方法读取http请求返回结果的信息。

EntityUtils.toString(httpResponse.getEntity());

那么，这个toString方法究竟做了什么呢？通过下述的源码可知， toString方法里面，关闭了输入流，也就使得连接得以释放。

public static String toString(final HttpEntity entity) throws IOException, ParseException { Args.notNull(entity, "Entity"); return toString(entity, ContentType.get(entity));}private static String toString( final HttpEntity entity, final ContentType contentType) throws IOException { final InputStream inStream = entity.getContent(); if (inStream == null) { return null; } try { Args.check(entity.getContentLength() <= Integer.MAX_VALUE, "HTTP entity too large to be buffered in memory"); int capacity = (int)entity.getContentLength(); if (capacity < 0) { capacity = DEFAULT_BUFFER_SIZE; } Charset charset = null; if (contentType != null) { charset = contentType.getCharset(); if (charset == null) { final ContentType defaultContentType = ContentType.getByMimeType(contentType.getMimeType()); charset = defaultContentType != null ? defaultContentType.getCharset() : null; } } if (charset == null) { charset = HTTP.DEF_CONTENT_CHARSET; } final Reader reader = new InputStreamReader(inStream, charset); final CharArrayBuffer buffer = new CharArrayBuffer(capacity); final char[] tmp = new char[1024]; int l; while((l = reader.read(tmp)) != -1) { buffer.append(tmp, 0, l); } return buffer.toString(); } finally {        // 这里，关闭了输入流，因此可以释放连接 inStream.close(); }}

也就是说，如果当http请求的状态非200时，不做任何事情，直接抛出了异常，连接并不会被释放！

到这里为止，问题已经基本定位到了，只需要在抛出异常前，关闭输入流，即可使连接得以释放。

如果保留了生产现场，又该如何解决呢？可以使用jstack或者 jconsole，会查询出下述内容。同样也能够知道线程阻塞的点。

名称: http-nio-8099-exec-6状态: java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject@15c3ce0e上的WAITING总阻止数: 0, 总等待数: 17
堆栈跟踪: sun.misc.Unsafe.park(Native Method)java.util.concurrent.locks.LockSupport.park(LockSupport.java:175)java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039)org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:393)org.apache.http.pool.AbstractConnPool.access$300(AbstractConnPool.java:70)org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:253) - 已锁定 org.apache.http.pool.AbstractConnPool$2@123689b2org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:198)org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:306)org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:282)org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:190)org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:186)org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89)org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:110)org.apache.http.impl.client.InternalHttpClient.doExecute(InternalHttpClient.java:185)org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:83)org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:108)org.apache.http.impl.client.CloseableHttpClient.execute(CloseableHttpClient.java:56)com.xxx.xxx.xxx.xxx.XxxxxxClient.execute(XxxxxxClient.java:49)