近期業務大量突增微服務效能優化總結-2.開發日誌輸出異常堆疊的過濾外掛

乾貨滿滿張雜湊發表於2021-11-02

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

改進客戶端負載均衡演算法
開發日誌輸出異常堆疊的過濾外掛
針對 x86 雲環境改進非同步日誌等待策略
增加對於同步微服務的 HTTP 請求等待佇列的監控以及雲上部署，需要小心達到例項網路流量上限導致的請求響應緩慢
針對系統關鍵業務增加必要的侵入式監控

開發日誌輸出異常堆疊的過濾外掛

我們一般會在異常發生時，列印日誌，同時日誌中帶有異常堆疊。

線上上因為某個基礎元件或者某個儲存慢導致大量超時異常發生時，如果都列印完整的異常棧，則一下子會輸出大量的日誌，導致寫入日誌也會成為瓶頸（雖然我們使用了 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 將其關閉，主要原因是：

OmitStackTraceInFastThrow 這個引數僅針對某些 Java 內建異常（上面原始碼已經列出），對於我們自定義或者框架自定義的異常沒用。
分析是否過多，僅對於丟擲異常的方法，但是是否是同一呼叫路徑，並沒有考慮。
微服務執行緒可能會執行很長時間，我們業務日誌量非常大，每一個小時產生一個新檔案。假設某個方法每天丟擲一定量的 NullPointerException 但是不多，並沒有及時發現。日積月累，某一天突然就沒有堆疊了。之後如果這個方法大量丟擲 NullPointerException，我們卻看不到堆疊，還得去挨個翻之前的日誌，這樣太低效率了。

我們對於異常日誌的需求

由於我們專案中使用了各種框架，有的使用了非同步框架，導致異常棧會非常非常長（有的甚至有 1000 行），所以其實最符合我們需求的是：

每次異常都輸出異常棧
但是異常棧只包括我們關心的包，其他的包都被省略，防止異常棧過長導致輸出大量日誌。

Log4j2 官方關於異常的配置

Log4j2 官方只是提供了黑名單包的配置，也就是哪些包的異常棧被省略掉；還有關於精簡異常棧的就是輸出日誌的前幾行，但是我們無法保證我們關心的日誌一定位於日誌的前幾行，尤其是針對非同步響應式程式碼呼叫的異常棧的時候。

不過 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

微信搜尋“我的程式設計喵”關注公眾號，每日一刷，輕鬆提升技術，斬獲各種offer：

近期業務大量突增微服務效能優化總結-3.針對 x86 雲環境改進非同步日誌等待策略
2021-11-03
微服務優化非同步
近期業務大量突增微服務效能優化總結-4.增加對於同步微服務的 HTTP 請求等待佇列的監控
2021-11-04
微服務優化HTTP佇列
在SpringBoot中使用logback優化異常堆疊的輸出
2022-05-09
Spring Boot優化
Laravel/Lumen 自定義錯誤日誌格式過濾堆疊資訊
2020-03-03
Laravel
使用log4j列印異常堆疊到日誌檔案
2020-11-15
go基於grpc構建微服務框架-結構化日誌輸出
2018-04-21
GoRPC微服務框架
在被線上大量日誌輸出導致效能瓶頸毒打了很多次之後總結出的經驗
2021-10-27
iOS crash 日誌堆疊解析
2018-04-24
iOS
頁面輸出過濾外掛--最新icp備案需要
2019-05-11
常見效能優化策略總結
2016-12-06
優化
如何利用NLog輸出結構化日誌，並在Kibana優雅分析日誌？
2020-08-06
微服務開發系列：如何列印好日誌
2022-11-24
微服務
遊戲開發效能優化經驗總結
2015-05-09
遊戲開發優化
android常見的效能優化方面的總結
2019-02-12
Android優化
C中關於堆疊的總結
2019-05-09
go開發屬於自己的日誌庫-日誌庫優化
2019-02-21
Go優化
NebulaGraph v3.3.0 釋出：支援子圖過濾、和大量效能最佳化
2022-11-29
效能優化總結
2015-09-27
優化
JVM異常不列印堆疊資訊 [ -XX:-OmitStackTraceInFastThrow ]
2020-12-29
JVMMITAST
優化自定義的Exception的日誌列印，設定自定義使用的ApiException extends Exception日誌列印不刷出堆疊資訊配置程式碼ApiException類即可
2020-11-03
優化ExceptionAPI
Java 效能優化之——效能優化的過程方法與求職面經總結
2020-12-25
Java優化求職
前端開發常用的VS Code外掛總結
2019-10-22
前端
啟動tomcat時，日誌裡大量輸出建立資料來源dataSource的日誌
2018-03-16
Tomcat
高手過招「效能優化/純手寫SpringMVC框架/MySql優化/微服務」
2018-12-05
優化SpringMVC框架MySql微服務
MVC使用異常過濾器處理異常
2020-10-22
MVC過濾器
效能優化小冊 - 非同步堆疊追蹤：為什麼 await 勝過 Promise
2020-05-12
優化非同步AIPromise
python 使用 loguru 輸出異常日誌同時列印變數值
2022-01-12
Python變數
Android效能優化——效能優化的難題總結
2021-08-12
Android優化
JAVA異常和日誌
2020-12-11
Java
《跳跳小子》開發日誌——反思與總結
2019-10-14
React 效能優化總結
2019-04-22
React優化
canvas效能優化總結
2021-04-30
Canvas優化
React效能優化總結
2021-08-27
React優化
前端效能優化總結
2019-01-10
前端優化
iOS 效能優化總結
2018-04-11
iOS優化
【Lolttery】專案開發日誌（一）微服務框架搭建
2017-12-14
微服務框架
總結前端效能優化的方法
2019-11-28
前端優化
MySQL的SQL效能優化總結
2019-02-16
MySql優化