高手的存在,就是让服务10亿人的时候,你感觉只是为你一个人服务......

perm区gc 导致tps不断下降

目录
  1. 1. 现象描述:
  2. 2. 问题排查:
  3. 3. 优化

一直以来都没有碰到过perm区 gc问题,最近一个项目代码重构,惊现perm区 gc问题。


jdk版本:

java version “1.7.0_25”
Java(TM) SE Runtime Environment (build 1.7.0_25-b15)
Java HotSpot(TM) 64-Bit Server VM (build 23.25-b01, mixed mode)


现象描述:

一个简单的http post请求接口,传入的是xml格式报文,服务端会对xml做解析。

对该接口做压测,刚开始tps、响应时间、服务器cpu都perfect,随着时间流逝…,开始出现cpu 上升,响应时间增加,tps下降的不良现象。
Alt text


问题排查:

看了一下应用日志,没啥有用的信息。

连续打印java 堆栈(jstack),发现大量线程在处理同一个业务

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
default task-2 - priority:10 - threadId:0x00007f987000e800 - nativeId:0x7861 - state:RUNNABLE
stackTrace:
java.lang.Thread.State: RUNNABLE
at java.lang.Class.getDeclaredConstructors0(Native Method)
at java.lang.Class.privateGetDeclaredConstructors(Class.java:2483)
at java.lang.Class.getConstructor0(Class.java:2793)
at java.lang.Class.newInstance(Class.java:345)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:399)
at sun.reflect.MethodAccessorGenerator$1.run(MethodAccessorGenerator.java:396)
at java.security.AccessController.doPrivileged(Native Method)
at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:395)
at sun.reflect.MethodAccessorGenerator.generateSerializationConstructor(MethodAccessorGenerator.java:113)
at sun.reflect.ReflectionFactory.newConstructorForSerialization(ReflectionFactory.java:331)
at com.thoughtworks.xstream.converters.reflection.Sun14ReflectionProvider.getMungedConstructor(Sun14ReflectionProvider.java:95)
- locked <0x0000000092c619f8> (a java.util.HashMap)
at com.thoughtworks.xstream.converters.reflection.Sun14ReflectionProvider.newInstance(Sun14ReflectionProvider.java:74)
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.instantiateNewInstance(AbstractReflectionConverter.java:428)
at com.thoughtworks.xstream.converters.reflection.AbstractReflectionConverter.unmarshal(AbstractReflectionConverter.java:233)
at com.thoughtworks.xstream.core.TreeUnmarshaller.convert(TreeUnmarshaller.java:72)
at com.thoughtworks.xstream.core.AbstractReferenceUnmarshaller.convert(AbstractReferenceUnmarshaller.java:65)
at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:66)
at com.thoughtworks.xstream.core.TreeUnmarshaller.convertAnother(TreeUnmarshaller.java:50)
at com.thoughtworks.xstream.core.TreeUnmarshaller.start(TreeUnmarshaller.java:134)
at com.thoughtworks.xstream.core.AbstractTreeMarshallingStrategy.unmarshal(AbstractTreeMarshallingStrategy.java:32)
at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1058)
at com.thoughtworks.xstream.XStream.unmarshal(XStream.java:1042)
at com.thoughtworks.xstream.XStream.fromXML(XStream.java:913)
at com.thoughtworks.xstream.XStream.fromXML(XStream.java:904)
at com.suning.epps.oma.common.util.XStreamParser.fromXML(XStreamParser.java:58)
at com.suning.epps.oma.nucc.service.impl.AbstractNuccBusiHandleService.validateHead(AbstractNuccBusiHandleService.java:53)
at com.suning.epps.oma.nucc.service.impl.AbstractNuccBusiHandleService.validateRequestParam(AbstractNuccBusiHandleService.java:37)
at com.suning.epps.oma.nucc.service.impl.NuccPayTradeOrderHandleServiceImpl.doBusinessHandle(NuccPayTradeOrderHandleServiceImpl.java:81)
at com.suning.epps.oma.nucc.service.impl.NuccPayTradeOrderHandleServiceImpl$$FastClassByCGLIB$$5ea67cb0.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at com.suning.epp.pu.common.aop.advice.ServiceAdvice.invoke(ServiceAdvice.java:77)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.aspectj.MethodInvocationProceedingJoinPoint.proceed(MethodInvocationProceedingJoinPoint.java:80)
at com.suning.ftmc.ffcs.aop.AnnoAspectJServ.process(AnnoAspectJServ.java:113)
at sun.reflect.GeneratedMethodAccessor46.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethodWithGivenArgs(AbstractAspectJAdvice.java:621)
at org.springframework.aop.aspectj.AbstractAspectJAdvice.invokeAdviceMethod(AbstractAspectJAdvice.java:610)
at org.springframework.aop.aspectj.AspectJAroundAdvice.invoke(AspectJAroundAdvice.java:65)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
at com.suning.epps.oma.nucc.service.impl.NuccPayTradeOrderHandleServiceImpl$$EnhancerByCGLIB$$15593518.doBusinessHandle(<generated>)
at com.suning.epps.oma.nucc.service.impl.NuccMsgBusiServiceImpl.processNuccMsg(NuccMsgBusiServiceImpl.java:71)
at com.suning.epps.oma.nucc.service.impl.NuccMsgBusiServiceImpl$$FastClassByCGLIB$$58526500.invoke(<generated>)
at net.sf.cglib.proxy.MethodProxy.invoke(MethodProxy.java:204)
at org.springframework.aop.framework.Cglib2AopProxy$CglibMethodInvocation.invokeJoinpoint(Cglib2AopProxy.java:689)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:150)
at com.suning.epp.pu.common.aop.advice.ServiceAdvice.invoke(ServiceAdvice.java:77)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:161)
at org.springframework.aop.interceptor.ExposeInvocationInterceptor.invoke(ExposeInvocationInterceptor.java:90)
at org.springframework.aop.framework.ReflectiveMethodInvocation.proceed(ReflectiveMethodInvocation.java:172)
at org.springframework.aop.framework.Cglib2AopProxy$DynamicAdvisedInterceptor.intercept(Cglib2AopProxy.java:622)
at com.suning.epps.oma.nucc.service.impl.NuccMsgBusiServiceImpl$$EnhancerByCGLIB$$2f40e7cf.processNuccMsg(<generated>)
at com.suning.epps.oma.nucc.portal.web.controller.NuccGatewayController.gatewayRecive(NuccGatewayController.java:88)
at sun.reflect.GeneratedMethodAccessor26.invoke(Unknown Source)
at sun.reflect.DelegatingMethodAccessorImpl.invoke(DelegatingMethodAccessorImpl.java:43)
at java.lang.reflect.Method.invoke(Method.java:606)
at org.springframework.web.method.support.InvocableHandlerMethod.invoke(InvocableHandlerMethod.java:213)
at org.springframework.web.method.support.InvocableHandlerMethod.invokeForRequest(InvocableHandlerMethod.java:126)
at org.springframework.web.servlet.mvc.method.annotation.ServletInvocableHandlerMethod.invokeAndHandle(ServletInvocableHandlerMethod.java:96)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.invokeHandlerMethod(RequestMappingHandlerAdapter.java:617)
at org.springframework.web.servlet.mvc.method.annotation.RequestMappingHandlerAdapter.handleInternal(RequestMappingHandlerAdapter.java:578)
at org.springframework.web.servlet.mvc.method.AbstractHandlerMethodAdapter.handle(AbstractHandlerMethodAdapter.java:80)
at org.springframework.web.servlet.DispatcherServlet.doDispatch(DispatcherServlet.java:923)
at org.springframework.web.servlet.DispatcherServlet.doService(DispatcherServlet.java:852)
at org.springframework.web.servlet.FrameworkServlet.processRequest(FrameworkServlet.java:882)
at org.springframework.web.servlet.FrameworkServlet.doPost(FrameworkServlet.java:789)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:707)
at javax.servlet.http.HttpServlet.service(HttpServlet.java:790)
at io.undertow.servlet.handlers.ServletHandler.handleRequest(ServletHandler.java:85)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:130)
at org.springframework.web.filter.CharacterEncodingFilter.doFilterInternal(CharacterEncodingFilter.java:88)
at org.springframework.web.filter.OncePerRequestFilter.doFilter(OncePerRequestFilter.java:76)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132)
at com.suning.epps.oma.portal.web.filter.AccessLogFilter.doFilter(AccessLogFilter.java:117)
at org.springframework.web.filter.DelegatingFilterProxy.invokeDelegate(DelegatingFilterProxy.java:346)
at org.springframework.web.filter.DelegatingFilterProxy.doFilter(DelegatingFilterProxy.java:259)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132)
at com.suning.epps.oma.portal.web.filter.SpecialCharacterFilter.doFilter(SpecialCharacterFilter.java:77)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132)
at com.suning.epp.tcc.srv.TrafficControlFilterSrv.doTrafficControl(TrafficControlFilterSrv.java:165)
at com.suning.epp.tcc.srv.TrafficControlFilterSrv.doFilter(TrafficControlFilterSrv.java:133)
at io.undertow.servlet.core.ManagedFilter.doFilter(ManagedFilter.java:60)
at io.undertow.servlet.handlers.FilterHandler$FilterChainImpl.doFilter(FilterHandler.java:132)
at io.undertow.servlet.handlers.FilterHandler.handleRequest(FilterHandler.java:85)
at io.undertow.servlet.handlers.security.ServletSecurityRoleHandler.handleRequest(ServletSecurityRoleHandler.java:61)
at io.undertow.servlet.handlers.ServletDispatchingHandler.handleRequest(ServletDispatchingHandler.java:36)
at org.wildfly.extension.undertow.security.SecurityContextAssociationHandler.handleRequest(SecurityContextAssociationHandler.java:78)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)
at io.undertow.servlet.handlers.security.SSLInformationAssociationHandler.handleRequest(SSLInformationAssociationHandler.java:113)
at io.undertow.servlet.handlers.security.ServletAuthenticationCallHandler.handleRequest(ServletAuthenticationCallHandler.java:56)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)
at io.undertow.security.handlers.AbstractConfidentialityHandler.handleRequest(AbstractConfidentialityHandler.java:45)
at io.undertow.servlet.handlers.security.ServletConfidentialityConstraintHandler.handleRequest(ServletConfidentialityConstraintHandler.java:61)
at io.undertow.security.handlers.AuthenticationMechanismsHandler.handleRequest(AuthenticationMechanismsHandler.java:58)
at io.undertow.servlet.handlers.security.CachedAuthenticatedSessionHandler.handleRequest(CachedAuthenticatedSessionHandler.java:70)
at io.undertow.security.handlers.SecurityInitialHandler.handleRequest(SecurityInitialHandler.java:76)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)
at org.wildfly.extension.undertow.security.jacc.JACCContextIdHandler.handleRequest(JACCContextIdHandler.java:61)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)
at io.undertow.server.handlers.PredicateHandler.handleRequest(PredicateHandler.java:25)
at io.undertow.servlet.handlers.ServletInitialHandler.handleFirstRequest(ServletInitialHandler.java:241)
at io.undertow.servlet.handlers.ServletInitialHandler.dispatchRequest(ServletInitialHandler.java:228)
at io.undertow.servlet.handlers.ServletInitialHandler.access$000(ServletInitialHandler.java:74)
at io.undertow.servlet.handlers.ServletInitialHandler$1.handleRequest(ServletInitialHandler.java:147)
at io.undertow.server.Connectors.executeRootHandler(Connectors.java:177)
at io.undertow.server.HttpServerExchange$1.run(HttpServerExchange.java:727)
at java.util.concurrent.ThreadPoolExecutor.runWorker(ThreadPoolExecutor.java:1145)
at java.util.concurrent.ThreadPoolExecutor$Worker.run(ThreadPoolExecutor.java:615)
at java.lang.Thread.run(Thread.java:724)
Locked ownable synchronizers:
- <0x000000009862d960> (a java.util.concurrent.ThreadPoolExecutor$Worker)

关注点在此:

1
2
3
4
at sun.reflect.MethodAccessorGenerator.generate(MethodAccessorGenerator.java:395)
at sun.reflect.MethodAccessorGenerator.generateSerializationConstructor(MethodAccessorGenerator.java:113)
at sun.reflect.ReflectionFactory.newConstructorForSerialization(ReflectionFactory.java:331)
at com.thoughtworks.xstream.converters.reflection.Sun14ReflectionProvider.getMungedConstructor(Sun14ReflectionProvider.java:95)

有大量xstream动态创建class的嫌疑。

遂监控gc perm区情况(jstat -gccause)和class类加载(jstat -class)情况,发现gc频繁,而且class类不断加载和卸载。

可以看到cpu消耗的前几名都是gc线程:

1
2
3
4
5
6
7
8
9
10
11
12
[jbossuser@eppsomspstapp02 bin]$ bash show-busy-java-threads.sh
[1] Busy(4.9%) thread(21744/0x54f0) stack of java process(21739) under user(jbossuser):
"Gang worker#3 (Parallel GC Threads)" prio=10 tid=0x00007fe1f0017800 nid=0x54f0 runnable

[2] Busy(4.9%) thread(21743/0x54ef) stack of java process(21739) under user(jbossuser):
"Gang worker#2 (Parallel GC Threads)" prio=10 tid=0x00007fe1f0015800 nid=0x54ef runnable

[3] Busy(4.9%) thread(21742/0x54ee) stack of java process(21739) under user(jbossuser):
"Gang worker#1 (Parallel GC Threads)" prio=10 tid=0x00007fe1f0013800 nid=0x54ee runnable

[4] Busy(4.9%) thread(21741/0x54ed) stack of java process(21739) under user(jbossuser):
"Gang worker#0 (Parallel GC Threads)" prio=10 tid=0x00007fe1f0012000 nid=0x54ed runnable

大概得出一个结论:

perm区满了以后,一直gc,导致cpu慢慢上来了,然后响应时间慢慢升高,tps慢慢下降。


优化

检查业务中涉及xstream的代码,惊然发现有位小哥写了几行

Alt text

每次都new新的xstream出来,立即想打人了。项目中明确说过不允许这么做,正确的做法是将xstream的设置成static变量,保证JVM当中只有一个xstream实例。

Alt text


至此世界清净了。