本文导读: 生产故障场景介绍 TCP 建连三次握手过程 TCP 断连四次挥手过程 结合 Java 堆栈剖析源码 再从堆栈中找到"罪魁祸首" 问题优化方案总结 1、生产故障场景介绍 业务简介: 该服务主要是提供对外的代理接口,大部分接口都会调用第三方接口,获取数据后做聚合处理后,提供给客户端使用。 有一天晚上,系统正处于高峰期间,项目组小伙伴正在津津有味的吃着「加班餐」,刚把🍚塞进嘴里,邮件和短信同时发起来告警。 有一台服务器接口超时,平时偶尔也会收到类似告警,有时会因为网络波动等原因。实在不好意思,没事总让人家「网络」同学背锅 : )。但是,这次告警并没有收敛,持续告警了十几分钟以上,感到了不妙。 点击邮件中告警的 URL 接口链接,一直在页面转圈圈,响应很慢,悲剧! 此刻,默默的把🍱盒饭推到一边去,不忍直视 :( 问题定位基本流程: 1)确定影响范围 该服务后面挂着多台服务器,仅有一台服务器挂掉了,所以对用户不会有太大的影响。 先临时从注册中心上摘掉,别让客户端继续重试到这台机器上了,保留事故现场。 2)排查监控指标 查看接口服务的访问量,因为是晚高峰,因此会比其他时间段用户访问量会更大些,但是这个访问量看上去跟平时同一时段对比,并没有特别明显突增现象。 监控上观察服务器的 CPU、内存、IO、网络指标看起来也一切正常。 3)服务器排查 登录到服务器上,结合监控进一步查看服务器 CPU、内存 等指标,查看服务日志都是正常的,并且也没有发现特别的异常日志输出,Exception 或者 OOM 等异常。 我们看到的现象是,接口服务已经无法正常响应了,应用跑在 JVM 上,快速通过 JDK 自带的常用命令排查一番了。 如下命令打印堆栈信息: jstack -l $pid > jstack.log 统计结果如下: cat jstack.log | grep "java.lang.Thread.State" | sort -nr | uniq -c 994 java.lang.Thread.State: WAITING (parking) 501 java.lang.Thread.State: WAITING (on object monitor) 7 java.lang.Thread.State: TIMED_WAITING (sleeping) 13 java.lang.Thread.State: TIMED_WAITING (parking) 2 java.lang.Thread.State: TIMED_WAITING (on object monitor) 23 java.lang.Thread.State: RUNNABLE 如果遇到 java.lang.Thread.State: WAITING (parking)、java.lang.Thread.State: WAITING (on object monitor) 这类线程状态,就要引起注意了,一般可能都是程序本身问题导致的。 根据 java.lang.Thread.State: WAITING 查看 jstack.log 里的堆栈信息,发现了了大量的调用 HttpClient 工具类请求等待挂起的日志,具体堆栈信息待下面详细分析。 这些服务调用都是通过 HttpClient 工具直接调用的,对 Spring RestTemplate 做了一次封装,其底层也是调用的 Apache HttpClient 工具类来实现服务调用的。 除看到上述 jstack 日志异常外,还排查了服务器上的网络状态,这也是运维同学们常用的排查手段。 附上统计网络连接状态的命令: netstat -n | awk '/^tcp/ {++State[$NF]} END {for(i in State) print i, State[i]}' 统计结果: TIME_WAIT 9 CLOSE_WAIT 3826 SYN_SENT 2 ESTABLISHED 28 SYN_RECV 8 这里注意了,我们看到服务器诡异的网络连接统计中,出现了大量的 CLOSE_WAIT 状态的连接。 而且这个状态,当你间隔一段时间再次执行统计命令,还是会存在,也就是不会被释放掉了,看上去问题有些严重。 进一步猜测,出现这些 CLOSE_WAIT 状态跟接口响应慢应该是有关系的,同时,也跟 java 堆栈信息中出现的 HttpClient 线程阻塞有关系,作为问题突破口去分析。 不如,我们先来了解下 CLOSE_WAIT 状态,这个 CLOSE_WAIT 状态处于 TCP 网络断开连接过程中,当客户端发起断连请求,服务端首次收到断连请求,回复确认消息,之后便处于 CLOSE_WAIT 状态了,当服务端响应处理完毕会回复网络包给客户端,正常连接会被关闭掉的。 2、 TCP 建连三次握手过程 尽管 CLOSE_WAIT 状态是在 TCP 网络连接四次挥手过程中的。我们还是有必要,先来了解下 TCP 网络连接的三次握手,因为它是请求服务器要做的第一件事情,那就是建立 TCP 连接。 技术源于生活。 我们可以举个日常生活中的例子来理解 TCP 三次握手的过程。 比如你在微信上想与一位很久未曾谋面的朋友聊一聊: 小东:小升,在吗? (过了很久... ... ) 小升: 在了,你还在吗? (小东刚好在线,天天刷朋友圈... ... ) 小东:嗯嗯,在了 (然后两位开始热聊起来... ...) 如果你平时跟朋友,开头总这么聊天是不是觉得很累呢。 其实上面的过程,可以很好的理解 TCP 三次握手的过程。 我们姑且将小东看做是「客户端」,小升看做是「服务端」。 小东是做名程序员,做 IT 工作。小升在老家开店创业中。 理解TCP三次握手过程: 1)小东作为「客户端」,向作为「服务端」的小升发起聊天,就是发送了一个网络包(包签名为 syn )给小升。【这是 TCP 第一次握手,小东状态此时处于 syn_sent 状态】 2)小升收到了小东的聊天网络包,你得确认下吧,表示你收到了。此时,小升还有别的事情,不像小东那样搞 IT 工作的,上班还上着微信。到了晚上,小升得空看了一眼手机微信,弹出了小东的消息。然后,激动的做了个回复「 针对小东发来的 sync 包,做了个 ack 回复确认」。因隔了一段时间了,小升也不确定小东还在不在线了。【这是 TCP 第二次握手,小升状态此时处于 syn_rcvd 状态 】 3)小东因为刚好在线,收到了小升的回复确认消息,马上对这次消息做了一个回复「对着小升给的 sync + ack,做了进一步 ack 回复确认,这是 TCP 第三次握手」 。【小升状态此时变成了 established 可马上聊天状态】 4)此时,小升也在线,两位就开始热聊起来了。【正式传输数据了,小东和小升的状态都处于 established 状态】 上述提到的那些状态 syn_sent syn_rcvd established ,正是 TCP 三次握手过程中涉及的关键状态。 上一张图来直观理解下: file 3、 TCP 断连四次挥手过程 小东和小升的热聊结束了,已经很晚了,也忙了一天了,需要休息了。 小东因工作原因明天要早起,所以提前跟小升说了: 小东:明天要凌晨4点起床升级系统,我要早点休息了,改天过来请你喝酒! 小升:额 ???这样,反正我也不懂! 小升:那你早点休息吧。你说的这顿酒还是要喝的! 小东:嗯嗯,晚安啊!你也早点休息。 小升:好的,晚安,兄弟! 对应理解 TCP 四次挥手过程: 1)小东要休息了,发起了 fin1 包打算结束聊天了。【小东状态此时处于 fin_wait1 状态,这是 TCP 第一次挥手】 2)小升收到了小东的 fin1 包,回复了 ack 确认消息。【此时,小升状态处于 close_wait 状态,小东此时状态为 fin_wait2,这是 TCP 第二次挥手】 3)小升来了一次最后确认,不打算继续聊了,发送了 fin2 包。【此时,小升状态处于 last_ack 状态,这是 TCP 第三次挥手】 4)小东针对小升发来的 fin2 包,最终回复了个 ack 确认。【此时,小东状态处于 time_wait 状态,这是 TCP 第四次挥手】 为什么小东还要处于 time_wait 状态等一下呢? 因为他们按照「老规矩」,得确保最后这次消息小升的确收到了,才能最终结束这次聊天。 time_wait 状态标准持续等待时间是** 4** 分钟,在这段时间内,小东和小升建立的 TCP 网络连接套接字资源(端口),是不能被其他人所使用的,也不能被系统回收重新利用的。 如果小升没有收到反馈,还会继续问下「重发 fin2 消息」,直到小东发送了 ack 消息成功了。 双方正式关闭聊天通道,释放端口资源,连接关闭。 等待的 4 分钟就是 2 个 MSL,每个 MSL 是 2 分钟。MSL就是 maximium segment lifetime——最长报文寿命。这个时间是由官方 RFC 协议规定的。 上一张图,进一步直观理解下: file 4、结合 Java 堆栈剖析源码 分析完 TCP 四次挥手过程了,当服务端接收到 TCP 断开连接的请求包,需要回复一个确认消息给客户端,此时服务端状态便处于 CLOSE_WAIT 状态了。 我们清楚了该状态所在的网络连接中的位置,结合前文中提到的问题,大量的线程阻塞在了 HttpClient 调用上。线程状态为 WAITING,服务器上统计出来,有大量处于 CLOSE_WAIT 状态的网络连接无法释放。 线程是 JVM 进程中比较宝贵的资源,如果一直有大量线程处于等待或阻塞状态,慢慢的所有线程都被占满,导致服务没法正常响应了。 我们来通过 java 线程堆栈信息,再结合源码来分析下具体原因。 找到第一段关键的堆栈日志: "http-nio-8970-exec-1108" #24971 daemon prio=5 os_prio=0 tid=0x00007f45b4445800 nid=0x61ad waiting on condition [0x00007f444ad69000] java.lang.Thread.State: WAITING (parking) at sun.misc.Unsafe.park(Native Method) - parking to wait for <0x00000006c2f30968> (a java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject) at java.util.concurrent.locks.LockSupport.park(LockSupport.java:175) at java.util.concurrent.locks.AbstractQueuedSynchronizer$ConditionObject.await(AbstractQueuedSynchronizer.java:2039) at org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:380) at org.apache.http.pool.AbstractConnPool.access$200(AbstractConnPool.java:69) at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:246) - locked <0x0000000641c7fe38> (a org.apache.http.pool.AbstractConnPool$2) at org.apache.http.pool.AbstractConnPool$2.get(AbstractConnPool.java:193) at org.apache.http.impl.conn.PoolingHttpClientConnectionManager.leaseConnection(PoolingHttpClientConnectionManager.java:303) at org.apache.http.impl.conn.PoolingHttpClientConnectionManager$1.get(PoolingHttpClientConnectionManager.java:279) at org.apache.http.impl.execchain.MainClientExec.execute(MainClientExec.java:191) at org.apache.http.impl.execchain.ProtocolExec.execute(ProtocolExec.java:185) at org.apache.http.impl.execchain.RetryExec.execute(RetryExec.java:89) at org.apache.http.impl.execchain.RedirectExec.execute(RedirectExec.java:111) 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:56) at org.springframework.http.client.HttpComponentsClientHttpRequest.executeInternal(HttpComponentsClientHttpRequest.java:89) at org.springframework.http.client.AbstractBufferingClientHttpRequest.executeInternal(AbstractBufferingClientHttpRequest.java:48) at org.springframework.http.client.AbstractClientHttpRequest.execute(AbstractClientHttpRequest.java:53) at org.springframework.web.client.RestTemplate.doExecute(RestTemplate.java:660) at org.springframework.web.client.RestTemplate.execute(RestTemplate.java:629) at org.springframework.web.client.RestTemplate.getForEntity(RestTemplate.java:329) at com.xxx.proxy.common.util.HttpClientUtil.getForEntity(HttpClientUtil.java:267) at com.xxx.proxy.common.util.HttpClientUtil.getForObject(HttpClientUtil.java:521) ... ... 堆栈日志中出现了大量的上述日志,基本都是 HttpClient 工具类所调用的,所有线程状态处于 java.lang.Thread.State: WAITING (parking) 状态。 出现 WAITING (parking)线程挂起状态,因为接口服务内部大量调用了第三方接口,要获取 Http 连接,但始终无法获取到,只能等待。 HttpClientUtil 工具类是继承自 Spring RestTemplate 并做了一些参数、重试机制、代理定制,其包路径位于 org.springframework.web.client.RestTemplate 。 类图如下所示: HttpClientUtil 创建 HttpClient 工具示例代码: HttpClientFactoryBean httpClientFactoryBean = new HttpClientFactoryBean(config); HttpComponentsClientHttpRequestFactory httpRequestFactory = new HttpComponentsClientHttpRequestFactory(httpClientFactoryBean.getObject()); return new HttpClientUtil(httpRequestFactory); HttpClientFactoryBean 继承自 AbstractFactoryBean,重写 getObjectType() 和 createInstance() 方法。 类图如下所示: HttpClientFactoryBean HttpClientFactoryBean 部分示例方法: @Override public Class getObjectType() { return HttpClient.class; } @Override protected HttpClient createInstance() { if (restConfig == null) { HttpClients.custom().build(); } // 每个路由最大的连接数 int maxPerRoute = restConfig.getMaxConnections(); // 总的最大连接数 int maxTotal = restConfig.getMaxTotalConnections(); // 连接超时时间 int connectTimeout = restConfig.getConnectionTimeout(); // 读取数据的超时时间 int socketTimeout = restConfig.getTimeout(); PoolingHttpClientConnectionManager connManager = new PoolingHttpClientConnectionManager(30, TimeUnit.SECONDS); connManager.setDefaultMaxPerRoute(maxPerRoute); connManager.setMaxTotal(maxTotal); connManager.setValidateAfterInactivity(1000); RequestConfig requestConfig = RequestConfig.custom().setConnectTimeout(connectTimeout) .setSocketTimeout(socketTimeout).build(); / ... 省略部分代码 return HttpClients.custom().setConnectionManager(connManager).evictExpiredConnections().setDefaultRequestConfig(requestConfig).build(); } 根据堆栈信息也能看到是从 PoolingHttpClientConnectionManager 的 leaseConnection() 方法获取连接,那我们可以详细看下源代码,为什么没有获取成功呢? 怎么查找源码,通过堆栈信息中的调用栈链路,就能非常容易的找到经过了哪些类哪些方法,第多少行代码。 根据上面jstack中的日志: org.apache.http.pool.AbstractConnPool.getPoolEntryBlocking(AbstractConnPool.java:380) 根据名称猜测,通过 AbstractConnPool 抽象连接池的类,调用 getPoolEntryBlocking 阻塞式方法获取连接,第 380 行代码。 查看源码: private E getPoolEntryBlocking( final T route, final Object state, final long timeout, final TimeUnit tunit, final Future future) throws IOException, InterruptedException, TimeoutException { Date deadline = null; // 连接获取超时时间参数 if (timeout > 0) { deadline = new Date (System.currentTimeMillis() + tunit.toMillis(timeout)); } this.lock.lock(); try { final RouteSpecificPool pool = getPool(route); // .... 省略部分源码 boolean success = false; try { if (future.isCancelled()) { throw new InterruptedException("Operation interrupted"); } // 将 future,实际类型为 Future,放入 pending 双向链表队列中 pool.queue(future); this.pending.add(future); if (deadline != null) { success = this.condition.awaitUntil(deadline); } else { // 这里正是第 380 行源代码 this.condition.await(); success = true; } if (future.isCancelled()) { throw new InterruptedException("Operation interrupted"); } } finally { // In case of 'success', we were woken up by the // connection pool and should now have a connection // waiting for us, or else we're shutting down. // Just continue in the loop, both cases are checked. pool.unqueue(future); this.pending.remove(future); } // check for spurious wakeup vs. timeout if (!success && (deadline != null && deadline.getTime() <= System.currentTimeMillis())) { break; } } throw new TimeoutException("Timeout waiting for connection"); } finally { this.lock.unlock(); } } 查找到第 380 行源码,调用了 condition 的 await() 方法: this.condition.await(); 这里使用了并发包下的 Condition 实现多线程协调通讯机制,await() 方法调用后,会将当前线程加入到 Condition 等待队列中,是一个FIFO结构的队列,同时当前线程锁释放,如果不释放,会导致其他线程无法获得锁,可能造成死锁。 await() 方法源码: public final void await() throws InterruptedException { if (Thread.interrupted()) throw new InterruptedException(); // 加入 Condition 等待队列 Node node = addConditionWaiter(); // 释放当前线程的锁 long savedState = fullyRelease(node); int interruptMode = 0; // 不在 AQS 同步队列中,将当前线程挂起,如果在 AQS 队列中退出循环 while (!isOnSyncQueue(node)) { LockSupport.park(this); if ((interruptMode = checkInterruptWhileWaiting(node)) != 0) break; } // 已被 signal() 方法唤醒,自旋等待尝试再次获取锁 if (acquireQueued(node, savedState) && interruptMode != THROW_IE) interruptMode = REINTERRUPT; if (node.nextWaiter != null) // clean up if cancelled unlinkCancelledWaiters(); if (interruptMode != 0) reportInterruptAfterWait(interruptMode); } 当前线程加入 Condition 等待队列结构图: Condition 等待队列 当通过 Condtion 调用 signalAll() 或者 signal() 方法时,会获取等待队列的首节点,将其移动到同步队列,利用 LockSupport 唤醒节点中的线程。节点从等待队列,移动到 AQS 同步队列如下结构图所示: Condtion&AQS 同步队列 在 AbstractConnPool 类的找到了 release() 释放连接的代码。 release() 方法源码如下: @Override public void release(final E entry, final boolean reusable) { this.lock.lock(); try { if (this.leased.remove(entry)) { final RouteSpecificPool pool = getPool(entry.getRoute()); pool.free(entry, reusable); if (reusable && !this.isShutDown) { this.available.addFirst(entry); } else { entry.close(); } onRelease(entry); Future future = pool.nextPending(); if (future != null) { this.pending.remove(future); } else { future = this.pending.poll(); } if (future != null) { this.condition.signalAll(); } } } finally { this.lock.unlock(); } } 我们看到了释放连接时,调用 this.condition.si