58 应用服务 hang 住, 导致服务 503 Service Unavailable

Posted 蓝风9

tags:

篇首语:本文由小常识网(cha138.com)小编为大家整理,主要介绍了58 应用服务 hang 住, 导致服务 503 Service Unavailable相关的知识,希望对你有一定的参考价值。

前言

 

这是之前 我们测试环境出现的一个问题 

一个项目, 代码调整了之后, 发布到测试环境 之后, 几分钟之后 整个系统访问这个服务 出现了 "503 Service Unavailable", 然后 当时的处理方式为 临时重启服务 

但是过了一会儿之后 同样的问题还是会出现, 导致 前端服务调试不了 

这个我在调试的时候, 没有怎么查看日志, 因为一些信息已经还是比较明显了, 这里会贴出 具体的日志 

假设这个服务为 ServiceA 

jstat 的日志

这是主要的出问题的日志 

从日志上来看, 短时间内 频繁的出现了, 多次 full gc 

从情况上来看, 是真实业务所需要的内存大于 jvm 的内存, 然后 导致 jvm 内存撑满了之后, 持续的进行 gc, 但是 多次 gc 之后, 仍然没有 释放出需要的空间

然后 进而 恶性循环, 此时 当前 jvm, 不断地进行 full gc, 然后 处理不了业务代码 

导致程序 hang 住, 不能处理 外部的请求 

78.13   0.00  45.42  91.30  93.67  91.72    428    3.121    17    3.977    7.098 Allocation Failure   No GC               
78.13   0.00  96.36  91.30  93.67  91.72    428    3.121    17    3.977    7.098 Allocation Failure   No GC               
0.00  70.00   9.08  91.30  93.68  91.72    429    3.132    17    3.977    7.110 Allocation Failure   No GC               
27.50   0.00  56.40  91.31  93.68  91.72    430    3.143    17    3.977    7.120 Allocation Failure   No GC               
27.50   0.00  56.40  91.31  93.68  91.72    430    3.143    17    3.977    7.120 Allocation Failure   No GC               
0.00  76.25  60.94  91.32  93.68  91.72    431    3.150    17    3.977    7.127 Allocation Failure   No GC               
74.38   0.00  22.85  91.33  93.68  91.72    432    3.163    17    3.977    7.140 Allocation Failure   No GC               
74.38   0.00  43.55  91.33  93.68  91.72    432    3.163    17    3.977    7.140 Allocation Failure   No GC               
0.00  67.50  93.22  91.34  93.68  91.72    433    3.173    17    3.977    7.151 Allocation Failure   No GC               
0.00  67.50  93.22  91.34  93.68  91.72    433    3.173    17    3.977    7.151 Allocation Failure   No GC               
0.00  99.35   0.00  98.05  93.68  91.72    435    3.198    18    3.977    7.175 Allocation Failure   Ergonomics          
99.20   0.00  12.25  88.01  92.90  90.64    436    3.238    18    4.396    7.634 Allocation Failure   No GC               
99.20   0.00  12.25  88.01  92.90  90.64    436    3.238    18    4.396    7.634 Allocation Failure   No GC               
0.00   0.00 100.00  99.79  92.90  90.65    437    3.260    25    6.356    9.616 Allocation Failure   Ergonomics          
0.00   0.00  47.14  99.99  92.90  90.65    437    3.260    27    7.279   10.540 Allocation Failure   No GC               
0.00   0.00 100.00  99.97  92.90  90.65    437    3.260    34    9.008   12.268 Allocation Failure   Ergonomics          
0.00   0.00  66.12  75.01  92.90  90.65    437    3.260    34    9.229   12.489 Allocation Failure   No GC               
0.00  99.99  26.89  80.82  92.90  90.65    439    3.298    34    9.229   12.527 Allocation Failure   No GC               
51.31   0.00 100.00  99.93  92.90  90.65    446    3.497    36    9.706   13.203 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.97  92.90  90.65    446    3.497    47   12.625   16.123 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.97  92.90  90.65    446    3.497    58   15.427   18.924 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.95  92.90  90.65    446    3.497    69   18.251   21.748 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.88  92.90  90.65    446    3.497    80   21.010   24.507 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.87  92.90  90.65    446    3.497    91   23.817   27.314 GCLocker Initiated GC Ergonomics          
0.00   0.00 100.00  99.90  92.90  90.65    446    3.497   102   26.689   30.186 Allocation Failure   Ergonomics          
0.00   0.00 100.00 100.00  92.90  90.65    446    3.497   113   29.501   32.998 GCLocker Initiated GC Ergonomics          
0.00   0.00 100.00  99.85  92.90  90.65    446    3.497   125   32.499   35.996 GCLocker Initiated GC Ergonomics          
0.00   0.00 100.00  99.87  92.91  90.65    446    3.497   135   35.293   38.790 Allocation Failure   Ergonomics          
0.00   0.00  98.12  99.90  92.57  90.24    446    3.497   142   38.310   41.807 Allocation Failure   No GC               
0.00   0.00 100.00  99.97  92.57  90.24    446    3.497   142   38.310   41.807 Allocation Failure   No GC               
0.00   0.00 100.00  99.94  92.57  90.24    446    3.497   146   39.412   42.909 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.94  92.57  90.23    446    3.497   153   41.940   45.437 Allocation Failure   No GC               
0.00   0.00 100.00  99.94  92.57  90.23    446    3.497   153   41.940   45.437 Allocation Failure   No GC               
0.00   0.00 100.00  99.95  92.58  90.24    446    3.497   161   43.736   47.233 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.95  92.58  90.24    446    3.497   167   45.457   48.954 Allocation Failure   No GC               
0.00   0.00 100.00  99.95  92.58  90.24    446    3.497   167   45.457   48.954 Allocation Failure   No GC               
0.00   0.00 100.00  99.97  92.58  90.24    446    3.497   178   48.021   51.518 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.97  92.58  90.24    446    3.497   189   50.866   54.363 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.97  92.58  90.24    446    3.497   189   51.111   54.608 Allocation Failure   No GC               
0.00   0.00 100.00  99.97  92.58  90.24    446    3.497   194   52.124   55.621 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.96  92.58  90.24    446    3.497   205   55.105   58.603 Allocation Failure   Ergonomics          
0.00   0.00 100.00  99.96  92.58  90.24    446    3.497   210   56.688   60.185 Allocation Failure   No GC               
0.00   0.00 100.00  99.96  92.58  90.24    446    3.497   210   56.688   60.185 Allocation Failure   No GC               
0.00   0.00 100.00  99.95  92.58  90.24    446    3.497   220   59.279   62.776 Allocation Failure   Ergonomics          
0.00   0.00 100.00 100.00  92.58  90.25    446    3.497   229   62.057   65.554 GCLocker Initiated GC Ergonomics          
0.00   0.00  99.92  99.95  92.58  90.25    446    3.497   229   62.307   65.804 GCLocker Initiated GC No GC               
0.00   0.00 100.00  99.94  92.58  90.25    446    3.497   234   63.286   66.784 GCLocker Initiated GC Ergonomics          
0.00   0.00 100.00  99.94  92.58  90.25    446    3.497   246   66.412   69.909 Allocation Failure   Ergonomics          
0.00   0.00  15.63  74.89  92.58  90.25    446    3.497   249   67.372   70.870 Allocation Failure   No GC               
0.00   0.00  15.63  74.89  92.58  90.25    446    3.497   249   67.372   70.870 Allocation Failure   No GC               
0.00   1.23   8.18  78.34  92.69  90.38    449    3.516   249   67.372   70.888 GCLocker Initiated GC No GC               
0.00   1.23  17.33  78.34  92.69  90.38    449    3.516   249   67.372   70.888 GCLocker Initiated GC No GC      

业务代码的输出日志

一个关键的说明问题的字样是 "GC overhead limit exceeded" 

这个同样能够推导出上面的 "jstat -gccause" 的推导的相关 

Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
	at java.lang.Class.getDeclaredMethods0(Native Method)
	at java.lang.Class.privateGetDeclaredMethods(Class.java:2701)
	at java.lang.Class.getDeclaredMethod(Class.java:2128)
	at java.io.ObjectStreamClass.getPrivateMethod(ObjectStreamClass.java:1431)
	at java.io.ObjectStreamClass.access$1700(ObjectStreamClass.java:72)
	at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:494)
	at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:468)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.io.ObjectStreamClass.<init>(ObjectStreamClass.java:468)
	at java.io.ObjectStreamClass.lookup(ObjectStreamClass.java:365)
	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1134)
	at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1548)
	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1509)
	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
	at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
	at com.baomidou.mybatisplus.core.toolkit.SerializationUtils.serialize(SerializationUtils.java:61)
	at com.baomidou.mybatisplus.core.toolkit.support.SerializedLambda.resolve(SerializedLambda.java:58)
	at com.baomidou.mybatisplus.core.toolkit.LambdaUtils.lambda$resolve$0(LambdaUtils.java:64)
	at com.baomidou.mybatisplus.core.toolkit.LambdaUtils$$Lambda$1195/322612414.get(Unknown Source)
	at java.util.Optional.orElseGet(Optional.java:267)
	at com.baomidou.mybatisplus.core.toolkit.LambdaUtils.resolve(LambdaUtils.java:63)
	at com.baomidou.mybatisplus.core.conditions.AbstractLambdaWrapper.columnToString(AbstractLambdaWrapper.java:62)
	at com.baomidou.mybatisplus.core.conditions.AbstractLambdaWrapper.lambda$columnsToString$0(AbstractLambdaWrapper.java:53)
	at com.baomidou.mybatisplus.core.conditions.AbstractLambdaWrapper$$Lambda$1193/71871969.apply(Unknown Source)
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
	at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)
org.springframework.web.util.NestedServletException: Handler dispatch failed; nested exception is java.lang.NoClassDefFoundError: Could not initialize class org.apache.ibatis.ognl.OgnlException
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1055)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:665)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
	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:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
org.springframework.web.util.NestedServletException: Handler dispatch failed; nested exception is java.lang.OutOfMemoryError: GC overhead limit exceeded
	at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:1055)
	at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:943)
	at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:1006)
	at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:909)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:665)
	at org.springframework.web.servlet.FrameworkServlet.service(FrameworkServlet.java:883)
	at javax.servlet.http.HttpServlet.service(HttpServlet.java:750)
	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:53)
	at org.apache.catalina.core.ApplicationFilterChain.internalDoFilter(ApplicationFilterChain.java:193)
	at org.apache.catalina.core.ApplicationFilterChain.doFilter(ApplicationFilterChain.java:166)
	// 省略部分日志
	at org.apache.tomcat.util.threads.TaskThread$WrappingRunnable.run(TaskThread.java:61)
	at java.lang.Thread.run(Thread.java:745)
Caused by: java.lang.OutOfMemoryError: GC overhead limit exceeded
	at java.lang.Class.getDeclaredMethods0(Native Method)
	at java.lang.Class.privateGetDeclaredMethods(Class.java:2701)
	at java.lang.Class.getDeclaredMethod(Class.java:2128)
	at java.io.ObjectStreamClass.getPrivateMethod(ObjectStreamClass.java:1431)
	at java.io.ObjectStreamClass.access$1700(ObjectStreamClass.java:72)
	at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:494)
	at java.io.ObjectStreamClass$2.run(ObjectStreamClass.java:468)
	at java.security.AccessController.doPrivileged(Native Method)
	at java.io.ObjectStreamClass.<init>(ObjectStreamClass.java:468)
	at java.io.ObjectStreamClass.lookup(ObjectStreamClass.java:365)
	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1134)
	at java.io.ObjectOutputStream.defaultWriteFields(ObjectOutputStream.java:1548)
	at java.io.ObjectOutputStream.writeSerialData(ObjectOutputStream.java:1509)
	at java.io.ObjectOutputStream.writeOrdinaryObject(ObjectOutputStream.java:1432)
	at java.io.ObjectOutputStream.writeObject0(ObjectOutputStream.java:1178)
	at java.io.ObjectOutputStream.writeObject(ObjectOutputStream.java:348)
	at com.baomidou.mybatisplus.core.toolkit.SerializationUtils.serialize(SerializationUtils.java:61)
	at com.baomidou.mybatisplus.core.toolkit.support.SerializedLambda.resolve(SerializedLambda.java:58)
	at com.baomidou.mybatisplus.core.toolkit.LambdaUtils.lambda$resolve$0(LambdaUtils.java:64)
	at com.baomidou.mybatisplus.core.toolkit.LambdaUtils$$Lambda$1195/322612414.get(Unknown Source)
	at java.util.Optional.orElseGet(Optional.java:267)
	at com.baomidou.mybatisplus.core.toolkit.LambdaUtils.resolve(LambdaUtils.java:63)
	at com.baomidou.mybatisplus.core.conditions.AbstractLambdaWrapper.columnToString(AbstractLambdaWrapper.java:62)
	at com.baomidou.mybatisplus.core.conditions.AbstractLambdaWrapper.lambda$columnsToString$0(AbstractLambdaWrapper.java:53)
	at com.baomidou.mybatisplus.core.conditions.AbstractLambdaWrapper$$Lambda$1193/71871969.apply(Unknown Source)
	at java.util.stream.ReferencePipeline$3$1.accept(ReferencePipeline.java:193)
	at java.util.Spliterators$ArraySpliterator.forEachRemaining(Spliterators.java:948)
	at java.util.stream.AbstractPipeline.copyInto(AbstractPipeline.java:481)
	at java.util.stream.AbstractPipeline.wrapAndCopyInto(AbstractPipeline.java:471)
	at java.util.stream.ReduceOps$ReduceOp.evaluateSequential(ReduceOps.java:708)
	at java.util.stream.AbstractPipeline.evaluate(AbstractPipeline.java:234)
	at java.util.stream.ReferencePipeline.collect(ReferencePipeline.java:499)

heap 中的对象分析

我们拿到一份 运行时的 dump 文件, 然后使用最简单的 jhat 进行分析 

我们看一下 其中比较占用内存的部分对象, 这一部分是有 业务关联的 

首先是 从业务代码相关的实体开始看 

一个 entity.RkHeatMapRs 会对应于一个 Integer, 两个 Double 

我们路由到 entity.RkHeatMapRs 的整个对象链路 

ResultSetImpl
    一个对应于 321230 个 ByteArrayRow
        一个对应于一个 mysqlTextValueDecoder
        一个对应于一个 [[B
        一个对应于三个 [B
        一个对应于一个 entity.RkHeatMapRs
            一个对应于一个 java.lang.Integer
            一个对应于两个 java.lang.Double

然后 我们大致统计一下 这里实际的业务场景中多个 entity.RkHeatMapRs 占用的内存相关开销 

321230 个 ByteArrayRow = 32 * 321230 = 10M
    一个对应于一个 MysqlTextValueDecoder, 16 * 321230 = 5M
    一个对应于一个 [[B = 40 * 321233 = 12M
    一个对应于三个 [B = 取决于业务数组长度, 24 * 973275 = 23M
    一个对应于一个 entity.RkHeatMapRs, 40 * 516380 = 20M
        一个对应于一个 java.lang.Integer, 16 * 294759 = 4M
        一个对应于两个 java.lang.Double, 24 * 1072068 = 25M
合计 100M 左右

这里是完整的 RkHeatMapRsMapper.query 查询出来的结果 

然后 其中的可以回收的对象有 ByteArrayRow, MysqlTextValueDecoder, [B, [[B 

所以 经过 gc 之后内存中持续占用的空间有 321230 个 entity.RkHeatMapRs, 和其关联的 321230 个 java.lang.Integer, 和 2 * 321230 个 java.lang.Double, 合计占用空间 50M 

然后 当下一次 执行 RkHeatMapRsMapper.query 的时候

内存中合计会占用 原有的 entity.RkHeatMapRs 的相关的 50M

以及新的一个批次查询的 entity.RkHeatMapRs 的相关 50M, 和相关的 ByteArrayRow, MysqlTextValueDecoder, [B, [[B 合计 50M 

然后 内存中持有的是 其他的常驻内存的对象, 其他的 staticHolder, 其他的字符串常量, 关联的字节数据 等等 

然后 持久需要占用内存 超过了 jvm 可以控制的 new + old 

造成了 "GC overhead limit exceeded", 进而 造成了 服务本身的 "503 Service Unavailable"

测试环境的资源情况

出现问题的测试环境资源情况为 容器可用最大内存为 512M, jvm 可用的最大堆内存为 512M 

扣除掉 100M 的 metaspace, 堆可用的最大内存为 412M 

扣除 case 中硬性需要占用的 entity.RkHeatMapRs 相关的空间 150M 

其他可用空间为 262M 

其他的业务常驻内存 + 字符串常量常驻内存, 这么一计算 就内存更加匮乏了

为了 更好的复现这个问题, 我将内存更新为了 256M 

这样, 复现这个问题 就更加轻松了 

问题的解决

增大 容器可用的内存, 以及 jvm 可以使用的最大堆内存 

或者 减小一次性加载到内存的业务数据的数量, 比如这里的 entity.RkHeatMapRs 

以上是关于58 应用服务 hang 住, 导致服务 503 Service Unavailable的主要内容,如果未能解决你的问题,请参考以下文章

DBMS_JOBS调用存储过程中有DBLink,导致JOB HANG住,无法正常运行

jdk1.6.0_29的bug导致c3p0获取sqlserver连接时被hang住甚至deadlock问题的分析

一则因为numa引发的mysqldump hang住

php中的长时间计算导致503错误

转载mysql主键的缺少导致备库hang

nfs问题导致df挂起