线上问题排查的心路历程-GC时间过长

最新推荐文章于 2024-05-27 16:33:28 发布

Java思享汇

最新推荐文章于 2024-05-27 16:33:28 发布

阅读量1.5k

点赞数 1

分类专栏：系统异常总结文章标签： mysql redis java

本文链接：https://blog.csdn.net/qq_30035133/article/details/103969802

版权

系统异常总结专栏收录该内容

3 篇文章 0 订阅

订阅专栏

「扫码关注我，面试、各种技术（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文件等等。

Java思享汇

关注

1
点赞
踩
7

收藏

觉得还不错? 一键收藏
4
评论
线上问题排查的心路历程-GC时间过长

一天突然收到其他组伙伴反馈调用我们组的一个接口超时了，信息如下：cause:java.net.SocketTimeoutException: Read timed out于是乎赶快打开Postman访问了下这个接口，结果可以访问，经过沟通发现并不是每次访问都失败，怀疑是其中一台机器宕机了，为了不影响线上系统正常运行，优先进行了服务重启，之后服务可用。接下来开始了问题的排查和猜想。猜想1:Ngi...
复制链接

扫一扫

专栏目录