乐趣区

关于log4j2:近期业务大量突增微服务性能优化总结2开发日志输出异常堆栈的过滤插件

jiezi

最近，业务增长的很迅猛，对于咱们后盾这块也是一个不小的挑战，这次遇到的外围业务接口的性能瓶颈，并不是独自的一个问题导致的，而是几个问题揉在一起：咱们解决一个之后，发上线，之后发现还有另一个的性能瓶颈问题。这也是我经验不足，导致没能一下子定位解决；而我又对咱们后盾整个团队有着执著的自尊，不想通过大量程度扩容这种形式挺过压力顶峰，导致线上间断几晚都呈现了不同水平的问题，必定对于咱们的业务增长是有影响的。这也是我不成熟和要反思的中央。这系列文章次要记录下咱们针对这次业务增长，对于咱们后盾微服务零碎做的通用技术优化，针对业务流程和缓存的优化因为只实用于咱们的业务，这里就不再赘述了。本系列会分为如下几篇：

  1. 改良客户端负载平衡算法
  2. 开发日志输入异样堆栈的过滤插件
  3. 针对 x86 云环境改良异步日志期待策略
  4. 减少对于同步微服务的 HTTP 申请期待队列的监控以及云上部署，须要小心达到实例网络流量下限导致的申请响应迟缓
  5. 针对零碎要害业务减少必要的侵入式监控

开发日志输入异样堆栈的过滤插件

咱们个别会在异样产生时，打印日志，同时日志中带有异样堆栈。

在线上因为某个根底组件或者某个存储慢导致大量超时异样产生时，如果都打印残缺的异样栈，则一下子会输入大量的日志，导致写入日志也会成为瓶颈（尽管咱们应用了 Log4j2 的异步日志，然而如果 RingBuffer 满了输入日志还是会导致业务线程阻塞）。从而 导致同一微服务中其余原本失常的业务，也变得不失常了。

并且，咱们发现

为何 JVM 参数中退出 -XX:-OmitStackTraceInFastThrow

为了防止这个问题可能首先想到的是，JVM 参数中去掉 -XX:-OmitStackTraceInFastThrow。这个 OmitStackTraceInFastThrow 默认是启用的，其作用是，当某个 JDK 内置异样通过某一个办法抛出过多次数时（常见是 NullPointerException），主动省略异样堆栈，其实就是 Throwable.getOurStacktrace() 返回空数组。底层实现的形式是当这些异样被抛出时，会记录在办法的 method_data 中。当这些异样被抛出时，查看对应办法的 method_data 是否有过多次数的这些异样被抛出，如果有，则应用不含堆栈的异样对象替换原有异样对象从而实现异样堆栈被疏忽。对应源码：

graphKit.cpp

  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 的，这样咱们能够在任何中央调用。并且将其中黑名单判断取反，改成白名单：

残缺源码参考：https://github.com/JoJoTec/sp…

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

微信搜寻“我的编程喵”关注公众号，每日一刷，轻松晋升技术，斩获各种 offer：

退出移动版