一个Java应用频繁抛异常导致cpu us诡异现象的案例
某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,堆栈信息如下:
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脚本如下:
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的时候,会直接吃掉异常:
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在升级前和升级后的对比状况图示如下:
另外一个数据是压测数据,在升级前当引5倍流量进行压测时,cpu us就会到80%左右,rt接近1s,升级后引10倍流量压测,cpu us也才13%左右,rt在100ms以下,可见效果非常明显。
总结:从这个案例可以看到,Java应用里频繁抛异常对于高并发而言影响还是非常的大,因此在编写Java应用时,还是要尽可能减少抛异常,尤其是吃异常这种事情,要少做。