当前位置: 首页 > Java > 正文

Java应用频繁抛异常导致cpu us诡异现象的案例

1 星2 星3 星4 星5 星 (4 次投票, 评分: 5.00, 总分: 5)
Loading ... Loading ...
baidu_share

某Java应用在生产环境运行时cpu us呈现了非常诡异的现象,在qps(每秒请求数)基本稳定的情况下,cpu us会进入一个上涨–迅速下降然后又上涨的循环中,我第一眼看到这cpu us的图的时候都以为是java gc的图,于是着手排查是什么原因造成的。

1、用perf看看是什么地方在耗cpu,跟踪了一段时间后,看到主要是StringTable::intern在消耗cpu,幸运的是淘宝JVM团队之前在做一个应用的优化的时候,也碰到了StringTable::intern是cpu us消耗的主要因素的现象,当时排查的原因是应用里抛异常比较多造成的,于是同样按照这个思路继续;

至于为什么StringTable::intern会变得耗cpu,这个原因不太清楚,在JavaOne2012的《Advanced JVM Tuning》 slide里有讲到StringTable默认的大小是1009,超过了这个大小后性能会大幅度下降,在《Look into the JVM Crystal Ball》里面的footprint的提升部分,也讲到了希望将来改造为Dynamic resize StringTable。

2、Taobao自己的JDK支持输出某段时间内抛出的最多次数的异常,以及抛出异常的堆栈,于是在应用上打开了这个开关进行收集,看到应用会频繁抛出NoSuchMethodException,堆栈信息如下:

1
2
3
4
5
6
7
java.lang.Throwable.fillInStackTrace(Native Method)
java.lang.Throwable.(Throwable.java:196)
java.lang.Exception.(Exception.java:41)
java.lang.NoSuchMethodException.(NoSuchMethodException.java:32)
java.lang.Class.getMethod(Class.java:1605)
org.apache.commons.beanutils.MethodUtils.getMatchingAccessibleMethod(MethodUtils.java:957)
org.apache.commons.beanutils.MappedPropertyDescriptor.getMethod(MappedPropertyDescriptor.java:409)

3、用Btrace跟踪更为详细的堆栈信息,以及到底是什么方法找不到,BTrace脚本如下:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
import static com.sun.btrace.BTraceUtils.*;
import com.sun.btrace.annotations.*;
 
@BTrace public class Trace{
@OnMethod(
clazz=”java.lang.NoSuchMethodException”,
method=””
)
public static void traceExecute(String s){
println(“who call”);
println(s);
jstack();
}
}

挂上Btrace后很快跟踪到了找不到的方法(而且确实也能看到,NoSuchMethodException抛的是比较的频繁),最初我怀疑是应用里面有多个冲突的版本的类,导致method找不到,于是打开-XX:+TraceClassLoading,确认需要找的那个类是从哪加载的,然后反编译对应的jar包,发现确实是没有相应的方法,因为是业务代码中调BeanUtils时出现的现象,我的猜测是页面请求中提交了这样的参数,但在POJO类中相应的属性已经被删除了,于是把这个猜测提交给了应用开发的同学。

4、应用的开发同学确认是由于页面上form里会有一些隐藏域,而这些隐藏域在这个POJO类是没有对应的属性的,但有点奇怪的是,为什么外部捕捉不到这个异常,跟踪BeanUtils(1.8.3)的代码,才发现BeanUtils在出现NoSuchMethodException的时候,会直接吃掉异常:

1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
950 try {
951 // Check the cache first
952 Method method = getCachedMethod(md);
953 if (method != null) {
954 return method;
955 }
956
957 method = clazz.getMethod(methodName, parameterTypes);
958 if (log.isTraceEnabled()) {
959 log.trace(“Found straight match:+ method);
960 log.trace(“isPublic:+ Modifier.isPublic(method.getModifiers()));
961 }
962
963 setMethodAccessible(method); // Default access superclass workaround
964
965 cacheMethod(md, method);
966 return method;
967
968 } catch (NoSuchMethodException e) { /* SWALLOW */ }

到这就彻底能解释通了,于是着手做解决方案,在这里采用的解决方法是:写了一个static类,在启动时即把需要用到的相应的POJO类有的属性装载到一个map里,然后在每次调用BeanUtils之前,先判断下属性是否存在,不存在则跳过,这样就不会触发NoSuchMethodException了。

5、改造完成上线后,效果非常理想,cpu us在升级前和升级后的对比状况图示如下:
vs
另外一个数据是压测数据,在升级前当引5倍流量进行压测时,cpu us就会到80%左右,rt接近1s,升级后引10倍流量压测,cpu us也才13%左右,rt在100ms以下,可见效果非常明显。

总结:在查看String.intern的一些变化时,突然想到了这个case,发现在这个case的根本原因上,判断错误了,频繁抛NoSuchMethodException并不是造成cpu us变化的原因,而是因为method = clazz.getMethod(methodName, parameterTypes);这行代码,对应的Class.getMethod中会执行methodName.intern(),而这个case中,methodName会跟着请求而动态的变化,所以导致了位于perm gen的StringTable中的String不断的增加,而StringTable的size默认为1009,String太多的话会导致hash冲突严重,链表长度过长,导致了每次String.intern时去链表里遍历很耗cpu。

本文固定链接: http://www.chepoo.com/java-application-cpu-us-error.html | IT技术精华网

Java应用频繁抛异常导致cpu us诡异现象的案例:等您坐沙发呢!

发表评论