Docker环境Spring Boot应用undertow大量http请求超时

Docker环境Spring Boot应用undertow大量http请求超时

背景

• 项目采用Spring Cloud微服务架构，每个微服务都是一个Spring Boot应用。
• undertow做嵌入式Web容器，http接口相互通讯。
• 使用阿里云容器服务部署在Docker环境。
• Spring Boot版本——1.5.9.RELEASE
• undertow版本——1.4.21.Final

问题

一个关键微服务接口出现大量超时，严重影响系统正常运营。

定位过程

发现一

查看某个超时请求运行日志，发现一条Warn级别日志：timerCache is above the warning threshold of 1000 with size 2312

• 2312位置数字只增不减
• 今天这种日志的数量明显比前几天多很多

日志是org.springframework.cloud.netflix.metrics.servo.ServoMonitorCache类getTimer方法输出。经查询，发现这个类是netflix的运行指标收集相关类。

有人发现它和RestTemplate出现服务不可用相关。参考
使用RestTemplate遇到线上的问题

结合自己这个微服务接口需要大量使用RestTemplate的情况，初步怀疑是这个问题。

解决办法：微服务yml文件增加spring.metrics.servo.enabled=false

最初，想利用actuator的/refresh接口动态刷新这个配置，这样不需要重启微服务。

• refresh接口调用成功，但配置不生效。
  （后面发现，这个开关配置是决定是否执行某个Configuration的，只有启动时生效。
  具体见类org.springframework.cloud.netflix.metrics.servo.ServoMetricsAutoConfiguration）

接下来，只好重启微服务。

重启后，不再有上面的Warn日志输出，说明配置生效。但无法确定是否解决请求大量超时问题，只能继续观察。

不久，又出现大量http请求超时…

发现二

初步怀疑是不是应用JVM内存出现问题。

于是进入微服务的container，使用jstat -gcutil PID 1s观察一段时间，
发现除了YGC会每隔10s执行一次，其他区域及GC次数和时长都没有异常。
暂时无法确定每10s一次的YGC频率是否有问题，继续观察。

又查看一条调用超时请求，结合调用方和此微服务日志一起看，发现问题：
调用方5s超时，此微服务十多秒后才输出这次请求的入口日志。

首先，确定调用方和此微服务所在容器时间没有差异；那么，有个怀疑：是不是此微服务无法处理这么多请求，部分请求进入队列排队，导致请求超时且日志延时输出？

我们使用嵌入式Web容器undertow，没有做任何配置调整，也不太清晰undertow内部实现，初步推断它处理http请求也是采用线程池模式。

通过Spring Boot Admin查看此微服务的线程堆栈Threads，发现只有16个worker线程（XNIO-2-task开头），大部分处于waiting状态。

• 虽然处于waiting状态的线程阻塞在JDK本身的LockSupport.park方法，少部分阻塞于业务逻辑；但结合这个微服务承载的请求量，16个worker线程肯定是不够的。
• 同时，我发现此微服务在Spring Boot Admin上的状态是时而在线，时而离线（离线是因为请求/health接口超时）。

结合上面情况，基本确定是undertow工作线程不足导致问题。

解决方法：yml文件增加

server:
  undertow:
    io-threads: 16
    worker-threads: 256

重启微服务。观察一段时间，没有再出现http请求超时，问题解决。

结论

undertow的工作线程不足，导致大量http请求超时。

拓展

1、遇到web应用大量http请求超时，应该首先检查Web容器的配置及负载情况。
2、Web容器作为web应用的核心组件，应该加上监控，方便查看Web容器状态（总线程数、当前正在处理请求数、排队请求数等）。后续查找或自写一个监控组件。

疑问

undertow的默认配置是怎样的？为什么其他微服务也没配置参数，有256个工作线程？

疑问已有解答，精彩待续…