萬(wàn)萬(wàn)沒(méi)想到！ logger.info() 還能導(dǎo)致線上故障？

事故代碼

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

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

先做個(gè)小調(diào)查，你覺(jué)得這段代碼會(huì)不會(huì)有問(wèn)題。

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

原因分析

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

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

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

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

public void info(String format, Object arg);

解決方案

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

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

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

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

- END -

關(guān)注我回復(fù)「加群」，加入Spring技術(shù)交流群