「扫码关注我,面试、各种技术(mysql、zookeeper、微服务、redis、jvm)持续更新中~」
一天突然收到其他组伙伴反馈调用我们组的一个接口超时了,信息如下:cause:java.net.SocketTimeoutException: Read timed out
于是乎赶快打开Postman访问了下这个接口,结果可以访问,经过沟通发现并不是每次访问都失败,怀疑是其中一台机器宕机了,为了不影响线上系统正常运行,优先进行了服务重启,之后服务可用。接下来开始了问题的排查和猜想。
猜想1:Nginx的负载均衡策略是否有问题?
从问题出现的现象上来看,感觉确实有一台机器不能对外提供服务了,但是如果宕机的话,Nginx会主动摘掉宕机的机器,流量并不会进来,难道Nginx配置的是ip hash的策略,和运维沟通发现并不是这个问题,并且运维跟踪到在这个时间段是有流量进来的,但是返回状态码为499(在nginx源码中,499对应的定义是 “client has closed connection”。这很有可能是因为服务器端处理的时间过长,客户端“不耐烦”了)这就有可能是服务端处理过慢导致的了。
猜想2:Redis被缓存穿透
因为该接口为高频查询接口,所以最初设计通过redis来作为缓存,并且通过追踪返回日志发现确实在这个时间有大量的请求访问redis没有获取到数据然后直接访问了数据库,难到真是这个问题引发到该问题吗?但是向前继续追踪日志,发现其他时间段也存在穿过缓存直接查数据库的情况,看来这并不是造成这个问题的直接原因。
猜想3:缓存穿透后慢sql导致
由于上面穿过缓存直接走的数据库,所以考虑是不是在查询数据库的时候存在慢sql导致系统反应比较慢,于是将执行的sql explain一下如下:
id = 1
select_type = SIMPLE
table = tb_finance
type = ref
possible_keys = index_fina_student_id,idx_fina_entity_metavalue
key = index_fina_student_id
key_len = 99
ref = const
rows = 1
Extra = Using where
因为该查询走了索引,而且扫描行数只有一行,响应非常快,这样看来也不是慢sql导致,但是还不放心,考虑是不是访问量较大,导致数据库有延迟等待呢?联系DBA看了下数据库QPS和连接等监控信息如下,都比较平稳,并没有出现高峰数据,于是也排除了该种可能。
猜想4:CPU和内存飙升导致
在以前出现过运行时内存消耗达到预警上线后tomcat重启的情况,这次是不是也存在这样的状况呢,但是很遗憾,查看了监控信息如下,发现CPU和内存以及磁盘IO在该时间段并没有太大波动。
猜想5:JVM GC时间过长
继续将集群中的8台机器排查一遍,发现其中有一台JVM在该时间段存在问题,果然查看GC监控后,有重大发现如下图:
在19:10分的时候GC时间开始出现猛的飙升,最长时间甚至超过了3分钟,而且正好和反馈的时间点对上,于是缩小排查范围,将这台机器对应时间点日志继续排查,发现在此时间有很多相似的报错,报错信息如下:
[2020-01-12 19:35:35.469] [ERROR] [http-nio-8080-exec-13] [com.xes.payment.safe.handler.GlobalExceptionHandler] - 服务器异常,请联系管理员!
org.apache.catalina.connector.ClientAbortException: java.io.IOException: Broken pipe
at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:356)
at org.apache.catalina.connector.OutputBuffer.flushByteBuffer(OutputBuffer.java:825)
at org.apache.catalina.connector.OutputBuffer.append(OutputBuffer.java:730)
at org.apache.catalina.connector.OutputBuffer.writeBytes(OutputBuffer.java:391)
at org.apache.catalina.connector.OutputBuffer.write(OutputBuffer.java:369)
at org.apache.catalina.connector.CoyoteOutputStream.write(CoyoteOutputStream.java:96)
at com.fasterxml.jackson.core.json.UTF8JsonGenerator._flushBuffer(UTF8JsonGenerator.java:2085)
at com.fasterxml.jackson.core.json.UTF8JsonGenerator.writeNumber(UTF8JsonGenerator.java:899)
at com.fasterxml.jackson.databind.ser.std.NumberSerializers$IntegerSerializer.serialize(NumberSerializers.java:137)
at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:727)
at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:719)
at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:155)
at com.fasterxml.jackson.databind.ser.impl.IndexedListSerializer.serializeContents(IndexedListSerializer.java:119)
at com.fasterxml.jackson.databind.ser.impl.IndexedListSerializer.serialize(IndexedListSerializer.java:79)
at com.fasterxml.jackson.databind.ser.impl.IndexedListSerializer.serialize(IndexedListSerializer.java:18)
at com.fasterxml.jackson.databind.ser.BeanPropertyWriter.serializeAsField(BeanPropertyWriter.java:727)
at com.fasterxml.jackson.databind.ser.std.BeanSerializerBase.serializeFields(BeanSerializerBase.java:719)
at com.fasterxml.jackson.databind.ser.BeanSerializer.serialize(BeanSerializer.java:155)
at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider._serialize(DefaultSerializerProvider.java:480)
at com.fasterxml.jackson.databind.ser.DefaultSerializerProvider.serializeValue(DefaultSerializerProvider.java:319)
at com.fasterxml.jackson.databind.ObjectWriter$Prefetch.serialize(ObjectWriter.java:1396)
at com.fasterxml.jackson.databind.ObjectWriter.writeValue(ObjectWriter.java:913)
at org.springframework.http.converter.json.AbstractJackson2HttpMessageConverter.writeInternal(AbstractJackson2HttpMessageConverter.java:286)
at org.springframework.http.converter.AbstractGenericHttpMessageConverter.write(AbstractGenericHttpMessageConverter.java:102)
at org.springframework.web.servlet.mvc.method.annotation.AbstractMessageConverterMethodProcessor.writeWithMessageConverters(AbstractMessageConverterMethodProcessor.java:272)
at org.springframework.web.servlet.mvc.method.annotation.RequestResponseBodyMethodProcessor.handleReturnValue(RequestResponseBodyMethodProcessor.java:180)
at org.springframework.web.method.support.HandlerMethodReturnValueHandlerComposite.handleReturnValue(HandlerMethodReturnValueHandlerComposite.java:82)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:119)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:877)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:783)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:87)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:991)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:925)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:974)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:877)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:661)
at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:851)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:742)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:231)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.tomcat.websocket.server.WsFilter.doFilter(WsFilter.java:52)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:158)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.filterAndRecordMetrics(WebMvcMetricsFilter.java:126)
at org.springframework.boot.actuate.metrics.web.servlet.WebMvcMetricsFilter.doFilterInternal(WebMvcMetricsFilter.java:111)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.actuate.web.trace.servlet.HttpTraceFilter.doFilterInternal(HttpTraceFilter.java:90)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at com.xes.payment.safe.filter.XssFilter.doFilter(XssFilter.java:64)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:130)
at org.springframework.boot.web.servlet.support.ErrorPageFilter.access$000(ErrorPageFilter.java:66)
at org.springframework.boot.web.servlet.support.ErrorPageFilter$1.doFilterInternal(ErrorPageFilter.java:105)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.springframework.boot.web.servlet.support.ErrorPageFilter.doFilter(ErrorPageFilter.java:123)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:200)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:107)
at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
at org.apache.catalina.core.StandardWrapperValve.invoke(StandardWrapperValve.java:198)
at org.apache.catalina.core.StandardContextValve.invoke(StandardContextValve.java:96)
at org.apache.catalina.authenticator.AuthenticatorBase.invoke(AuthenticatorBase.java:493)
at org.apache.catalina.core.StandardHostValve.invoke(StandardHostValve.java:140)
at org.apache.catalina.valves.ErrorReportValve.invoke(ErrorReportValve.java:81)
at org.apache.catalina.valves.AbstractAccessLogValve.invoke(AbstractAccessLogValve.java:650)
at org.apache.catalina.core.StandardEngineValve.invoke(StandardEngineValve.java:87)
at org.apache.catalina.connector.CoyoteAdapter.service(CoyoteAdapter.java:342)
at org.apache.coyote.http11.Http11Processor.service(Http11Processor.java:800)
at org.apache.coyote.AbstractProcessorLight.process(AbstractProcessorLight.java:66)
at org.apache.coyote.AbstractProtocol$ConnectionHandler.process(AbstractProtocol.java:806)
at org.apache.tomcat.util.net.NioEndpoint$SocketProcessor.doRun(NioEndpoint.java:1498)
at org.apache.tomcat.util.net.SocketProcessorBase.run(SocketProcessorBase.java:49)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1142)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:617)
at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
at java.lang.Thread.run(Thread.java:745)
Caused by: java.io.IOException: Broken pipe
at sun.nio.ch.FileDispatcherImpl.write0(Native Method)
at sun.nio.ch.SocketDispatcher.write(SocketDispatcher.java:47)
at sun.nio.ch.IOUtil.writeFromNativeBuffer(IOUtil.java:93)
at sun.nio.ch.IOUtil.write(IOUtil.java:65)
at sun.nio.ch.SocketChannelImpl.write(SocketChannelImpl.java:471)
at org.apache.tomcat.util.net.NioChannel.write(NioChannel.java:134)
at org.apache.tomcat.util.net.NioBlockingSelector.write(NioBlockingSelector.java:101)
at org.apache.tomcat.util.net.NioSelectorPool.write(NioSelectorPool.java:157)
at org.apache.tomcat.util.net.NioEndpoint$NioSocketWrapper.doWrite(NioEndpoint.java:1306)
at org.apache.tomcat.util.net.SocketWrapperBase.doWrite(SocketWrapperBase.java:670)
at org.apache.tomcat.util.net.SocketWrapperBase.writeBlocking(SocketWrapperBase.java:450)
at org.apache.tomcat.util.net.SocketWrapperBase.write(SocketWrapperBase.java:388)
at org.apache.coyote.http11.Http11OutputBuffer$SocketOutputBuffer.doWrite(Http11OutputBuffer.java:623)
at org.apache.coyote.http11.filters.IdentityOutputFilter.doWrite(IdentityOutputFilter.java:127)
at org.apache.coyote.http11.Http11OutputBuffer.doWrite(Http11OutputBuffer.java:225)
at org.apache.coyote.Response.doWrite(Response.java:541)
at org.apache.catalina.connector.OutputBuffer.realWriteBytes(OutputBuffer.java:351)
... 83 common frames omitted
该报错集中在19:10分-20:00重启服务之前,一共出现了接近300次,并且在最近的一周只有在这个时间段大量出现了此异常。好像问题已经浮出水面了,那么究竟什么场景会导致java.io.IOException: Broken pipe呢?
1)客户端再发起请求后没有等服务器端相应完,点击了stop按钮,导致服务器端接收到取消请求。通常情况下是不会有这么无聊的用户,出现这种情况可能是由于用户提交了请求,服务器端相应缓慢,比如业务逻辑有问题等原因,导致页面过了很久也没有刷新出来,用户就有可能取消或重新发起请求。
2)Tomcat服务器在接受用户请求的时候,有其自身的处理能力,线程、服务器等各个资源限制,超出Tomcat承载范围的请求,就会被tomcat停掉,也可能产生该错误。
3)linux的线程机制会产生JVM出错的问题,特别是在连接高峰期间经常出现这样的问题,tomcat在linux下也出现类似情况。
接下来还需要结合dump文件来分析具体是那些对象导致的GC停顿呢?和运维沟通拿到dump文件后发现了其中具体的原因,dump分析见下图所示,所有的大对象都指向了这个com.bonree.brjapm.p对象,和组内同事沟通后发现原来是博瑞的一个监控平台导致的,而且只有ip为207的这一个节点上了博瑞监控平台,问题就真相大白了。
总结
根据以上的猜想和排查,最终定位到问题出现的原因和大致位置,其中会发现实时监控是重要的一环,不然线上问题将无从查起,系统运行情况也不能完全掌握,监控手段也有很多,比如钉钉报警、ELK、CPU和内存使用率、GC日志、dump文件等等。