性能文章>近期业务大量突增微服务性能优化总结-2.开发日志输出异常堆栈的过滤插件>

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

9月前
213904

最近,业务增长的很迅猛,对于我们后台这块也是一个不小的挑战,这次遇到的核心业务接口的性能瓶颈,并不是单独的一个问题导致的,而是几个问题揉在一起:我们解决一个之后,发上线,之后发现还有另一个的性能瓶颈问题。这也是我经验不足,导致没能一下子定位解决;而我又对我们后台整个团队有着固执的自尊,不想通过大量水平扩容这种方式挺过压力高峰,导致线上连续几晚都出现了不同程度的问题,肯定对于我们的业务增长是有影响的。这也是我不成熟和要反思的地方。这系列文章主要记录下我们针对这次业务增长,对于我们后台微服务系统做的通用技术优化,针对业务流程和缓存的优化由于只适用于我们的业务,这里就不再赘述了。本系列会分为如下几篇:

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 官方只是提供了黑名单包的配置,也就是哪些包的异常栈被省略掉;还有关于精简异常栈的就是输出日志的前几行,但是我们无法保证我们关心的日志一定位于日志的前几行,尤其是针对异步响应式代码调用的异常栈的时候。

348834f31231d2a457ecabaa9e63dedb.jpg

不过 Log4j2 的这些配置,是通过 Pattern 插件的方式实现的,我们也可以通过开发自定义的 Pattern 插件实现。

开发自定义 Pattern 插件

首先,Log4j2 官方只是提供了黑名单包的配置,我们可以将黑名单包的配置的判断逻辑取反,其实就变成了白名单,其他的配置格式解析照旧。于是我们将 Log4j2 的代码 ThrowableProxyRenderer 复制出来,命名为我们自定义的 CustomizedThrowableProxyRenderer,同时将其中 package-private 的方法改成 public 的,这样我们可以在任何地方调用。并且将其中黑名单判断取反,改成白名单:

完整源码参考:https://github.com/JoJoTec/spring-cloud-parent/blob/master/spring-cloud-commons/src/main/java/org/apache/logging/log4j/core/impl/CustomizedThrowableProxyRenderer.java

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
请先登录,感受更多精彩内容
快去登录吧,你将获得
  • 浏览更多精彩评论
  • 和开发者讨论交流,共同进步

为你推荐

字符串字面量长度是有限制的
前言 偶然在一次单元测试中写了一个非常长的字符串字面量。 正文 在一次单元测试中,我写了一个很长的字符串字面量,大概10万个字符左右,编译时,编译器给出了异常告警 `java: constant
多次字符串相加一定要用StringBuilder而不用-吗?
今天在写一个读取Java class File并进行分析的Demo时,偶然发现了下面这个场景(基于oracle jdk 1.8.0_144): ``` package test; public c
如何通过反射获得方法的真实参数名(以及扩展研究)
前段时间,在做一个小的工程时,遇到了需要通过反射获得方法真实参数名的场景,在这里我遇到了一些小小的问题,后来在部门老大的指导下,我解决了这个问题。通过解决这个问题,附带着我了解到了很多新的知识,我觉得
高吞吐、低延迟 Java 应用的 GC 优化实践
本篇原文作者是 LinkedIn 的 Swapnil Ghike,这篇文章讲述了 LinkedIn 的 Feed 产品的 GC 优化过程,虽然文章写作于 April 8, 2014,但其中的很多内容和
「每日五分钟,玩转 JVM」:久识你名,初居我心
聊聊 JVMJVM,一个熟悉又陌生的名词,从认识Java的第一天起,我们就会听到这个名字,在参加工作的前一两年,面试的时候还会经常被问到JDK,JRE,JVM这三者的区别。JVM可以说和我们是老朋友了
据说99.99%的人都会答错的类加载的问题
概述首先还是把问题抛给大家,这个问题也是我厂同学在做一个性能分析产品的时候碰到的一个问题。 同一个类加载器对象是否可以加载同一个类文件多次并且得到多个Class对象而都可以被java层使用吗请仔细注意
Java多线程——并发测试
编写并发程序时候,可以采取和串行程序相同的编程方式。唯一的难点在于,并发程序存在不确定性,这种不确定性会令程序出错的地方远比串行程序多,出现的方式也没有固定规则。那么如何在测试中,尽可能的暴露出这些问
Java多线程知识小抄集(一)
本文主要整理笔者遇到的Java多线程的相关知识点,适合速记,故命名为“小抄集”。本文没有特别重点,每一项针对一个多线程知识做一个概要性总结,也有一些会带一点例子,习题方便理解和记忆。 1.interr