近期业务大量突增微服务性能优化总结-2.开发日志输出异常堆栈的过滤插件原创
最近，业务增长的很迅猛，对于我们后台这块也是一个不小的挑战，这次遇到的核心业务接口的性能瓶颈，并不是单独的一个问题导致的，而是几个问题揉在一起：我们解决一个之后，发上线，之后发现还有另一个的性能瓶颈问题。这也是我经验不足，导致没能一下子定位解决；而我又对我们后台整个团队有着固执的自尊，不想通过大量水平扩容这种方式挺过压力高峰，导致线上连续几晚都出现了不同程度的问题，肯定对于我们的业务增长是有影响的。这也是我不成熟和要反思的地方。这系列文章主要记录下我们针对这次业务增长，对于我们后台微服务系统做的通用技术优化，针对业务流程和缓存的优化由于只适用于我们的业务，这里就不再赘述了。本系列会分为如下几篇：
1.改进客户端负载均衡算法
2.开发日志输出异常堆栈的过滤插件
3.针对 x86 云环境改进异步日志等待策略
4.增加对于同步微服务的 HTTP 请求等待队列的监控以及云上部署，需要小心达到实例网络流量上限导致的请求响应缓慢
5.针对系统关键业务增加必要的侵入式监控
开发日志输出异常堆栈的过滤插件
我们一般会在异常发生时，打印日志，同时日志中带有异常堆栈。
在线上因为某个基础组件或者某个存储慢导致大量超时异常发生时，如果都打印完整的异常栈，则一下子会输出大量的日志，导致写入日志也会成为瓶颈（虽然我们使用了 Log4j2 的异步日志 ，但是如果 RingBuffer 满了输出日志还是会导致业务线程阻塞）。从而导致同一微服务中其他本来正常的业务，也变得不正常了。
并且，我们发现
为何 JVM 参数中加入 -XX:-OmitStackTraceInFastThrow
为了避免这个问题可能首先想到的是，JVM 参数中去掉 -XX:-OmitStackTraceInFastThrow。这个 OmitStackTraceInFastThrow 默认是启用的，其作用是，当某个 JDK 内置异常通过某一个方法抛出过多次数时（常见是 NullPointerException），自动省略异常堆栈，其实就是 Throwable.getOurStacktrace() 返回空数组。底层实现的方式是当这些异常被抛出时，会记录在方法的 method_data 中。当这些异常被抛出时，检查对应方法的 method_data 是否有过多次数的这些异常被抛出，如果有，则使用不含堆栈的异常对象替换原有异常对象从而实现异常堆栈被忽略。对应源码：
bool treat_throw_as_hot = false;
ciMethodData* md = method()->method_data();
if (ProfileTraps) {
//如果有太多次，则 treat_throw_as_hot 为 true
if (too_many_traps(reason)) {
treat_throw_as_hot = true;
}
if (C->trap_count(reason) != 0
&& method()->method_data()->trap_count(reason) != 0
&& has_ex_handler()) {
treat_throw_as_hot = true;
}
}
if (treat_throw_as_hot
&& (!StackTraceInThrowable || OmitStackTraceInFastThrow)) {
ciInstance* ex_obj = NULL;
switch (reason) {
case Deoptimization::Reason_null_check:
//对于 NullPointerException 返回对应的空堆栈的内置 NullPointerException 对象
ex_obj = env()->NullPointerException_instance();
break;
case Deoptimization::Reason_div0_check:
//对于 ArithmeticException 返回对应的空堆栈的内置 ArithmeticException 对象
ex_obj = env()->ArithmeticException_instance();
break;
case Deoptimization::Reason_range_check:
//对于 ArrayIndexOutOfBounds 返回对应的空堆栈的内置 NullPoArrayIndexOutOfBoundsinterException 对象
ex_obj = env()->ArrayIndexOutOfBoundsException_instance();
break;
case Deoptimization::Reason_class_check:
if (java_bc() == Bytecodes::_aastore) {
//对于 ArrayStoreException 返回对应的空堆栈的内置 ArrayStoreException 对象
ex_obj = env()->ArrayStoreException_instance();
} else {
//对于 ClassCastException 返回对应的空堆栈的内置 ClassCastException 对象
ex_obj = env()->ClassCastException_instance();
}
break;
default:
break;
}
但是，我们一般会在 JVM 启动参数中加入 -XX:-OmitStackTraceInFastThrow 将其关闭，主要原因是：
1.OmitStackTraceInFastThrow 这个参数仅针对某些 Java 内置异常（上面源码已经列出），对于我们自定义或者框架自定义的异常没用。
2.分析是否过多，仅对于抛出异常的方法，但是是否是同一调用路径，并没有考虑。
3.微服务线程可能会运行很长时间，我们业务日志量非常大，每一个小时产生一个新文件。假设某个方法每天抛出一定量的 NullPointerException 但是不多，并没有及时发现。日积月累，某一天突然就没有堆栈了。之后如果这个方法大量抛出 NullPointerException，我们却看不到堆栈，还得去挨个翻之前的日志，这样太低效率了。
我们对于异常日志的需求
由于我们项目中使用了各种框架，有的使用了异步框架，导致异常栈会非常非常长（有的甚至有 1000 行），所以其实最符合我们需求的是：
1.每次异常都输出异常栈
2.但是异常栈只包括我们关心的包，其他的包都被省略，防止异常栈过长导致输出大量日志。
Log4j2 官方关于异常的配置
Log4j2 官方只是提供了黑名单包的配置，也就是哪些包的异常栈被省略掉；还有关于精简异常栈的就是输出日志的前几行，但是我们无法保证我们关心的日志一定位于日志的前几行，尤其是针对异步响应式代码调用的异常栈的时候。
不过 Log4j2 的这些配置，是通过 Pattern 插件的方式实现的，我们也可以通过开发自定义的 Pattern 插件实现。
开发自定义 Pattern 插件
首先，Log4j2 官方只是提供了黑名单包的配置，我们可以将黑名单包的配置的判断逻辑取反，其实就变成了白名单，其他的配置格式解析照旧。于是我们将 Log4j2 的代码 ThrowableProxyRenderer 复制出来，命名为我们自定义的 CustomizedThrowableProxyRenderer，同时将其中 package-private 的方法改成 public 的，这样我们可以在任何地方调用。并且将其中黑名单判断取反，改成白名单：
public class CustomizedThrowableProxyRenderer {
//省略没有修改的方法
//该方法改为 public
public static void formatExtendedStackTraceTo(final ThrowableProxy src, final StringBuilder sb, final List<String> whiteListedPackages, final TextRenderer textRenderer, final String suffix, final String lineSeparator) {
textRenderer.render(src.getName(), sb, "Name");
textRenderer.render(": ", sb, "NameMessageSeparator");
textRenderer.render(src.getMessage(), sb, "Message");
renderSuffix(suffix, sb, textRenderer);
textRenderer.render(lineSeparator, sb, "Text");
final StackTraceElement[] causedTrace = src.getThrowable() != null ? src.getThrowable().getStackTrace() : null;
formatElements(sb, Strings.EMPTY, 0, causedTrace, src.getExtendedStackTrace(), whiteListedPackages, textRenderer, suffix, lineSeparator);
formatSuppressed(sb, TAB, src.getSuppressedProxies(), whiteListedPackages, textRenderer, suffix, lineSeparator);
formatCause(sb, Strings.EMPTY, src.getCauseProxy(), whiteListedPackages, textRenderer, suffix, lineSeparator);
}
//原来的 blackListElement 方法改成 whiteListedElement
//结果取反，改成白名单
private static boolean whiteListedElement(final StackTraceElement element, final List<String> whiteListedPackages) {
if (whiteListedPackages != null) {
final String className = element.getClassName();
for (final String pkg : whiteListedPackages) {
if (className.startsWith(pkg)) {
return true;
}
}
}
return false;
}
}
然后，开发我们自定义的 Log4j2 Pattern 插件：
CustomizedThrowablePatternConverter.java
@Plugin(name = "CustomizedThrowablePatternConverter", category = PatternConverter.CATEGORY)
@ConverterKeys({ "cusEx", "cusThrowable", "cusException" })
public class CustomizedThrowablePatternConverter extends ThrowablePatternConverter {
public static CustomizedThrowablePatternConverter newInstance(final Configuration config, final String[] options) {
return new CustomizedThrowablePatternConverter(config, options);
}
private CustomizedThrowablePatternConverter(final Configuration config, final String[] options) {
super("CustomizedThrowable", "throwable", options, config);
}
@Override
public void format(final LogEvent event, final StringBuilder toAppendTo) {
final ThrowableProxy proxy = event.getThrownProxy();
final Throwable throwable = event.getThrown();
if ((throwable != null || proxy != null) && options.anyLines()) {
if (proxy == null) {
super.format(event, toAppendTo);
return;
}
final int len = toAppendTo.length();
if (len > 0 && !Character.isWhitespace(toAppendTo.charAt(len - 1))) {
toAppendTo.append(' ');
}
//调用上面的工具类，格式化异常
CustomizedThrowableProxyRenderer.formatExtendedStackTraceTo(proxy, toAppendTo, options.getIgnorePackages(),
options.getTextRenderer(), getSuffix(event), options.getSeparator());
}
}
}
这样，我们可以在我们的 Log4j2 配置中，加入这个异常定义 PatternLayout，例如：
<RollingFile name="file" append="true"
filePattern="${LOG_ROOT}/app.log-%d{yyyy.MM.dd.HH}-${sys:LOCAL_IP}">
<PatternLayout pattern="%d{yyyy-MM-dd HH:mm:ss.SSS} %5p [%X{traceId},%X{spanId}] [${sys:PID}] [%t]: %m%n%cusEx{filters(java, com.mycompany)}"/>
<Policies>
<TimeBasedTriggeringPolicy interval="1" modulate="true"/>
</Policies>
<DirectWriteRolloverStrategy maxFiles="72"/>
</RollingFile>
其中的 %cusEx{filters(java, com.mycompany)}，代表异常栈就只会输出这些包开头的异常堆栈，这里是 java 和 com.mycompany 开头的。如此一来，log.error("something error!", e);，输出的日志就会类似于：
2021-10-30 16:00:19.254 ERROR [65f6eda3bf6a48ee,d25cc4c9eb1deed6] [30] [subscribe-pool-9]: something error!
... suppressed 27 lines
at com.mycompany.spring.cloud.parent.web.common.undertow.jfr.JFRTracingFilter.doFilter(JFRTracingFilter.java:40) ~[spring-cloud-parent-web-common-2020.0.3-SNAPSHOT.jar!/:2020.0.3-SNAPSHOT]
at com.mycompany.spring.cloud.parent.web.common.undertow.jfr.LazyJFRTracingFilter.doFilter(LazyJFRTracingFilter.java:23) ~[spring-cloud-parent-web-common-2020.0.3-SNAPSHOT.jar!/:2020.0.3-SNAPSHOT]
... suppressed 46 lines
Caused by: com.alibaba.fastjson.JSONException: write javaBean error, fastjson version 1.2.75, class com.hopegaming.factsCenter.query.revo.controller.frontend.share.matches.MatchController$EventVO, fieldName : data
... suppressed 8 lines
... 74 more
Caused by: java.lang.NullPointerException
at com.mycompany.OrderController.postOrder(OrderController.java:103) ~[classes!/:2020.0.3-SNAPSHOT]
... suppressed 13 lines
... 74 more
