打印優質日志的十條軍規
前言
去年雙十一大促,我面對監控大屏上瘋狂跳動的紅色指標,顫抖著打開服務器日志,看到的卻是這樣的畫面:
用戶登錄失敗
訂單創建出錯 null
ERROR 非法參數
那一刻我突然頓悟:寫不好日志的程序員,就像不會寫病歷的醫生。
這篇文章跟大家一起聊聊打印優質日志的10條軍規,希望對你會有所幫助。
第1條:格式統一
反例(管理看到會扣錢):
log.info("start process");
log.error("error happen");
無時間戳,無上下文。
正解代碼:
<!-- logback.xml核心配置 -->
<pattern>
%d{yy-MM-dd HH:mm:ss.SSS}
|%X{traceId:-NO_ID}
|%thread
|%-5level
|%logger{36}
|%msg%n
</pattern>
在logback.xml中統一配置了日志的時間格式、tradeId,線程、等級、日志詳情都信息。
日志的格式統一了,更方便點位問題。
圖片
第2條:異常必帶堆棧
反例(同事看了想打人):
try {
processOrder();
} catch (Exception e) {
log.error("處理失敗");
}
出現異常了,日志中沒打印任何的異常堆棧信息。
相當于自己把異常吃掉了。
非常不好排查問題。
正確姿勢:
log.error("訂單處理異常 orderId={}", orderId, e); // e必須存在!
日志中記錄了出現異常的訂單號orderId和異常的堆棧信息e。
第3條:級別合理
反面教材:
log.debug("用戶余額不足 userId={}", userId); // 業務異常應屬WARN
log.error("接口響應稍慢"); // 普通超時屬INFO
接口響應稍慢,打印了error級別的日志,顯然不太合理。
正常情況下,普通超時屬INFO級別。
級別定義表:
級別 | 正確使用場景 |
FATAL | 系統即將崩潰(OOM、磁盤爆滿) |
ERROR | 核心業務失敗(支付失敗、訂單創建異常) |
WARN | 可恢復異常(重試成功、降級觸發) |
INFO | 關鍵流程節點(訂單狀態變更) |
DEBUG | 調試信息(參數流水、中間結果) |
第4條:參數完整
反例(讓運維罵娘):
log.info("用戶登錄失敗");
上面這個日志只打印了“用戶登錄失敗”這個文案。
誰在哪登錄失敗?
偵探式日志:
log.warn("用戶登錄失敗 username={}, clientIP={}, failReasnotallow={}",
username, clientIP, "密碼錯誤次數超限");
登錄失敗的業務場景,需要記錄哪個用戶,ip是多少,在什么時間,登錄失敗了,失敗的原因是什么。
時間在logback.xml中統一配置了格式。
這樣才方便快速定位問題:
圖片
第5條:數據脫敏
血淚案例:某同事打印日志泄露用戶手機號被投訴。
我在記錄的日志中,需要對一下用戶的個人敏感數據做脫敏處理。
例如下面這樣:
// 脫敏工具類
public class LogMasker {
public static String maskMobile(String mobile) {
return mobile.replaceAll("(\\d{3})\\d{4}(\\d{4})", "$1****$2");
}
}
// 使用示例
log.info("用戶注冊 mobile={}", LogMasker.maskMobile("13812345678"));
第6條:異步保性能
問題復現某次秒殺活動中直接同步寫日志,導致大量線程阻塞:
log.info("秒殺請求 userId={}, itemId={}", userId, itemId);
高并發下IO阻塞。
致命傷害分析:
- 同步寫日志導致線程上下文切換頻繁
- 磁盤IO成為系統瓶頸
- 高峰期日志打印耗時占總RT的25%
正確示范(三步配置法)
步驟1:logback.xml配置異步通道
<!-- 異步Appender核心配置 -->
<appender name="ASYNC" class="ch.qos.logback.classic.AsyncAppender">
<!-- 不丟失日志的閾值:當隊列剩余容量<此值時,TRACE/DEBUG級別日志將被丟棄 -->
<discardingThreshold>0</discardingThreshold>
<!-- 隊列深度:建議設為 (最大并發線程數 × 2) -->
<queueSize>4096</queueSize>
<!-- 關聯真實Appender -->
<appender-ref ref="FILE"/>
</appender>
步驟2:日志輸出優化代碼
// 無需前置判斷,框架自動處理
log.debug("接收到MQ消息:{}", msg.toSimpleString()); // 自動異步寫入隊列
// 不應做復雜計算后再打印(異步前仍在業務線程執行)
// 錯誤做法:
log.debug("詳細內容:{}", computeExpensiveLog());
流程圖如下:
圖片
步驟3:性能關鍵參數公式
最大內存占用 ≈ 隊列長度 × 平均單條日志大小
推薦隊列深度 = 峰值TPS × 容忍最大延遲(秒)
例如:10000 TPS × 0.5s容忍 ? 5000隊列大小
風險規避策略:
- 防隊列堆積:監控隊列使用率,達80%觸發告警
- 防OOM:嚴格約束大對象toString()的調用
- 緊急逃生:預設JMX接口用于快速切換同步模式
第7條:鏈路追蹤
混沌場景:跨服務調用無法關聯日志。
我們需要有鏈路追蹤方案。
全鏈路方案:
// 攔截器注入traceId
MDC.put("traceId", UUID.randomUUID().toString().substring(0,8));
// 日志格式包含traceId
<pattern>%d{HH:mm:ss} |%X{traceId}| %msg%n</pattern>
可以在MDC中設置traceId。
后面可以通過traceId全鏈路追蹤日志。
流程圖如下:
圖片
第8條:動態調參
半夜重啟的痛:線上問題需要臨時開DEBUG日志,比如:查詢用戶的某次異常操作的日志。
熱更新方案:
@GetMapping("/logLevel")
public String changeLogLevel(
@RequestParam String loggerName,
@RequestParam String level) {
Logger logger = (Logger) LoggerFactory.getLogger(loggerName);
logger.setLevel(Level.valueOf(level)); // 立即生效
return "OK";
}
有時候我們需要臨時打印DEBUG日志,這就需要有個動態參數控制了。
否則每次調整打印日志級別都需要重啟服務,可能會影響用戶的正常使用。
journey
title 日志級別動態調整
section 舊模式
發現問題 --> 修改配置 --> 重啟應用 --> 丟失現場
section 新模式
發現問題 --> 動態調整 --> 立即生效 --> 保持現場
第9條:結構化存儲
混沌日志:
用戶購買了蘋果手機 訂單號1001 金額8999
上面的日志拼接成了一個字符串,雖說中間有空格分隔了,但哪些字段對應了哪些值,看起來不是很清楚。
我們在存儲日志的時候,需要做結構化存儲,方便快速的查詢和搜索。
機器友好式日志:
{
"event": "ORDER_CREATE",
"orderId": 1001,
"amount": 8999,
"products": [{"name":"iPhone", "sku": "A123"}]
}
這里使用了json格式存儲日志。
日志中的數據一目了然。
第10條:智能監控
最失敗案例:某次用戶開通會員操作,錯誤日志堆積3天才被發現,黃花菜都涼了。
我們需要在項目中引入智能監控。
ELK監控方案:
圖片
報警規則示例:
ERROR日志連續5分鐘 > 100條 → 電話告警
WARN日志持續1小時 → 郵件通知
總結
研發人員的三大境界:
- 青銅:System.out.println("error!")
- 鉆石:標準化日志 + ELK監控
- 王者:
日志驅動代碼優化
異常預測系統
根因分析AI模型
最后的靈魂拷問:下次線上故障時,你的日志能讓新人5分鐘定位問題嗎?