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

乾貨滿滿張雜湊發表於2021-11-02
微服務優化

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

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

image

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

相關文章