一、问题
今天发现有一台服务器的内存飙升,然后有预警,立即排查,发现该服务内存使用达到了 2G ,询问开发,当天是否有活动,被告知没有,登陆 Pinpoint 发现该服务是有两台机器,并且所有的访问都是到那台内存飙升的机器上面。这就很清楚了,是所有请求到一台服务器,导致的,我们查看那台没有收到任何请求的服务器上,发现服务是启动了,端口也在监听的。
启动日志:
2019-11-05 16:07:09.024 [main] INFO o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.061 [main] INFO o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.062 [main] INFO o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read
2019-11-05 16:07:09.122 [main] INFO o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)
二、故障排查
2.1 第一次排查(服务没有正常启动)
启动日志里面也没有任何异常的报错。我就以为服务是已经 启动了,可能是 Nginx 的问题,登陆到 Nginx 服务器进行查看 ,是配置了 fair 插件的,想着是不是 fair 判断 那台服务器内存不够就不把请求转发过去了,我们就把 fair 这个插件去除了。然后 Nginx reload 了一下(16.26这个时间)。不到 一分钟,我 Pinpoint 发现 有访问到这个服务器上了,心想难道真的是这个问题导致的,不可能啊,然后我回到我 控制台(幸好我有个 tail -f ),然后发现下面的,日志。 到底是 fair 导致的还是 启动没有成功导致的。后面查阅昨天发版日志,发现昨天发版后,下面后面那三行日志就一直没打印,也就是一直没启动成功,但是正常的服务的那个服务器是有后面三行日志的。
当时启动打印的
2019-11-05 16:07:09.024 [main] INFO o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.061 [main] INFO o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.062 [main] INFO o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read
2019-11-05 16:07:09.122 [main] INFO o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)
后面打印的
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started
2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms
第一次排查结论
基于上面的情况,我们认为问题就是服务没有初始化成功,应该是由于服务器内存不足导致的。也可能是和 Tomcat 启动慢的原因是一致的。
2.2 第二次排查
再次排障后发现这个问题取决于 Nginx 与应用 两者。
场景
我们有另一个服务也部署在两个服务器上,一个服务器上启动后正常提供服务,另外一台服务一直没有接收到请求,也没有处理任何东西,日志如下:
当我们启动 spring boot 框架的服务后。日志出现了
2019-11-05 16:07:09.024 [main] INFO o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.061 [main] INFO o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.062 [main] INFO o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read
2019-11-05 16:07:09.122 [main] INFO o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)
一直停留在这个界面。
然后我们通过 模拟请求,也就是在服务器上通过 curl ip+port, 立马就打印出来日志。
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started
2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms
第二次排查结论
第一就是出现在 Nginx
上,我们 Nginx
上使用了 fair
模块(github链接)。 fair
模块采用的不是负载均衡默认的轮询的均衡算法,而是可以根据页面大小、加载时间长短智能的进行负载均衡。
推测是fair
将其中一台服务器直接屏蔽掉了(也就是我们没有收到请求的机器),然后就把所有的请求发送到另外一台机器了。
怪异之处
屏蔽掉的服务器内存和CPU 都是正常状态(内存还有剩余),为什么会屏蔽掉它,fair模块算法是有什么问题?
-- 去监控下请求返回的时常,对比下另外一台。(对比后无异常,返回都在 1s 内)
- 为什么启动后接受了请求才会打印类似初始化的日志。
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started
2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms
询问开发后: 得到答复:
2019-11-05 16:07:09.024 [main] INFO o.a.coyote.http11.Http11NioProtocol - Initializing ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.061 [main] INFO o.a.coyote.http11.Http11NioProtocol - Starting ProtocolHandler ["http-nio-18096"]
2019-11-05 16:07:09.062 [main] INFO o.a.tomcat.util.net.NioSelectorPool - Using a shared selector for servlet write/read
2019-11-05 16:07:09.122 [main] INFO o.s.b.c.e.t.TomcatEmbeddedServletContainer - Tomcat started on port(s): 18096 (http)
上面的日志,就是表明已经启动了,web 容器 Tomcat
已经 ok了。可以正常提供服务。
那么下面那个日志是怎么回事?
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.a.c.c.C.[Tomcat].[localhost].[/] - Initializing Spring FrameworkServlet 'dispatcherServlet'
2019-11-05 16:26:53.435 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization started
2019-11-05 16:26:53.473 [http-nio-18096-exec-5] INFO o.s.web.servlet.DispatcherServlet - FrameworkServlet 'dispatcherServlet': initialization completed in 38 ms
原因是(开发告知): 这个是DispatcherServlet初始化,当第一个请求过来后,它才初始化。
三、总结
上述的故障最后的问题定位于 : Nginx 的 fair
插件导致的问题,与服务本身没有任何关系,但是 fair
插件的具体的问题没有去细究。