近期業務大量突增微服務性能優化總結-2.開發日誌輸出異常堆棧的過濾插件

• 2021 年 11 月 2 日
• 筆記
• log4j2, 微服務, 微服務設計模式, 問題定位

最近，業務增長的很迅猛，對於我們後台這塊也是一個不小的挑戰，這次遇到的核心業務接口的性能瓶頸，並不是單獨的一個問題導致的，而是幾個問題揉在一起：我們解決一個之後，發上線，之後發現還有另一個的性能瓶頸問題。這也是我經驗不足，導致沒能一下子定位解決；而我又對我們後台整個團隊有着固執的自尊，不想通過大量水平擴容這種方式挺過壓力高峰，導致線上連續幾晚都出現了不同程度的問題，肯定對於我們的業務增長是有影響的。這也是我不成熟和要反思的地方。這系列文章主要記錄下我們針對這次業務增長，對於我們後台微服務系統做的通用技術優化，針對業務流程和緩存的優化由於只適用於我們的業務，這裡就不再贅述了。本系列會分為如下幾篇：

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 的，這樣我們可以在任何地方調用。並且將其中黑名單判斷取反，改成白名單：

完整源碼參考：//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

微信搜索「我的編程喵」關注公眾號，每日一刷，輕鬆提升技術，斬獲各種offer：