萬萬沒想到 logger.info() 還能出導(dǎo)致線上故障

事故代碼

直入主題，生產(chǎn)環(huán)境日志級別為warn，請看如下這行代碼：

LOGGER.info("the?DTO?info:?{}",?JSON.toJSONString(DTO));

先做個小調(diào)查，你覺得這段代碼會不會有問題。

如果你的答案為“有問題”，并且你有充足的理由，那么這篇文章已經(jīng)沒有往下看的必要了，因?yàn)槟阋呀?jīng)掌握了筆者此文要傳達(dá)的知識點(diǎn)。如果你的答案為“沒有問題”或者“無法分辨”，那么，請繼續(xù)往下看。

原因分析

這段代碼主要有兩個需要注意的地方：

1. 日志級別為info，而線上環(huán)境是warn級別。我們可以得出結(jié)論，線上環(huán)境肯定不會輸出這行日志。
2. 打印日志的行為中有JSON序列化動作。

第二點(diǎn)是此文的關(guān)鍵。我們假設(shè)DTO是一個很小的對象，JSON序列化時間以及開銷可以忽略不計(jì)，那么這行代碼依然沒有問題。但是，如果DTO是一個很大的對象，比如10k，甚至100k，即使快如fastjson，其耗時依然高達(dá)數(shù)百毫秒，并且非常消耗CPU。如果是在高并發(fā)的系統(tǒng)中，這么大的開銷完全不可接受，甚至可能就會拖垮整個系統(tǒng)。

有同學(xué)就會說了，我不是info日志么，為什么還會執(zhí)行這行代碼？請繼續(xù)往下看。我們首先看一下slf4j中l(wèi)ogger.info()這個方法是如何申明的：第二個參數(shù)為Object類型。我們的代碼中傳遞給第二個參數(shù)的值為：JSON.toJSONString(DTO)，很明顯這行代碼是傳遞一個String類型的字段給Object arg。那么String如何來呢？答案也很明顯，必須先執(zhí)行JSON序列化才能得到String。那么logger.info這個info在什么時候起作用呢？答案是它只能在輸出日志這個動作時起作用：

public?void?info(String?format,?Object?arg);

解決方案

如何解決這個問題？很簡單，在輸入日志時加個級別判斷（需要說明的是，這種規(guī)范很容易被忽略，比如項(xiàng)目成員更替時，很容易引入有問題的代碼。所以筆者寫了一段腳本：掃描所有Java代碼，如果logger.info()中有JSON序列化動作，那么必須判斷優(yōu)先級后才能輸出日志。即可以簡單的認(rèn)為它的前一行代碼必須是logger.isInfoEnabled()。如果你的項(xiàng)目有CICD環(huán)境，那么把這段腳本集成到掃描規(guī)范中，才是解決這個問題最完美的方案）：

if(LOGGER.isInfoEnabled())?{
????LOGGER.info("the?DTO?info:?{}",?JSON.toJSONString(DTO));
}

當(dāng)然，需要說明的是，通過上面的分析，如果我們的打印日志那行代碼中沒有JSON序列化等耗時動作的話，那么日志級別判斷就沒必要了，比如下面這行代碼：

String?reqId?=?"...";
String?msg?=?"...";
LOGGER.info("the?DTO?info:?{}",?msg);

-?END?-