日志快速定位根因:WeClaw 日志分析收斂實(shí)戰(zhàn))
凌晨 1 點(diǎn) 47 分值班群被一條告警刷屏訂單服務(wù)可用率掉到 91%用戶支付頁反復(fù)報(bào)“系統(tǒng)繁忙”。我打開 WeClaw 日志平臺(tái)目標(biāo)索引最近 24 小時(shí)已經(jīng)積累了 3.8 億條日志屏幕上滾動(dòng)最快的那個(gè) “error” 檢索結(jié)果膨脹到幾十萬條。這個(gè)場(chǎng)面相信做后端的人都不陌生日志不是沒有而是多到讓你不知道從哪一條看起。我后來總結(jié)出一個(gè)結(jié)論海量日志定位根因靠的不是“看得多”而是“收斂得快”。這篇文章就寫一寫我用 WeClaw 做日志分析的一套實(shí)戰(zhàn)打法從億級(jí)日志里快速把候選范圍壓到幾十條再順著鏈路把根因揪出來。適合正在做服務(wù)排障、穩(wěn)定性建設(shè)或者剛開始搭日志平臺(tái)的同學(xué)參考。1. 先想清楚日志分析的目的是收斂不是翻日志1.1 為什么日志越多越難定位日志本來是系統(tǒng)的黑匣子但把它接入統(tǒng)一平臺(tái)之后黑匣子變成了洪流。以前單機(jī)幾百萬條日志人工 grep 還能接受現(xiàn)在微服務(wù)一拆、副本一拉正常業(yè)務(wù)流量就能每天產(chǎn)出幾十億條日志單個(gè)服務(wù)一晚上的 ERROR 就有好幾萬條。問題不是沒有信號(hào)而是信號(hào)被噪音按在地上摩擦。我見過不少同事在 WeClaw 里排障從頭到尾都在做一件事?lián)Q關(guān)鍵詞。搜“Exception”看幾條搜“timeout”再看幾條又搜“error code”循環(huán)幾輪半小時(shí)過去還在原始日志里打轉(zhuǎn)。這種做法的核心誤區(qū)是把“日志分析”理解成了“搜關(guān)鍵詞”。真正的日志分析是三條動(dòng)作的循環(huán)過濾、聚合、關(guān)聯(lián)。過濾做減法聚合找模式關(guān)聯(lián)串因果。三條動(dòng)作循環(huán)幾輪根因自然浮出水面。1.2 一條可以復(fù)制的黃金分析路線我自己這幾年用過不少日志工具最后固定下來一條排障路線先鎖時(shí)間窗口再定服務(wù)范圍用聚合壓掉重復(fù)噪音最后用鏈路 ID 串因果。每一步做的事都是把候選集合縮小億級(jí)日志先壓到百萬級(jí)再壓到千級(jí)然后從幾百條可疑記錄里挑出幾條關(guān)鍵 trace打開鏈路視圖確認(rèn)真兇。這條路線的關(guān)鍵不是某個(gè)單點(diǎn)技巧而是“不能跳步”的順序感。對(duì)應(yīng)到 WeClaw 上四個(gè)動(dòng)作分別會(huì)用到四類能力檢索頁做過濾統(tǒng)計(jì)圖表做聚合日志看板做觀測(cè)鏈路檢索做串聯(lián)。很多人只會(huì)用檢索頁等于只發(fā)揮了 WeClaw 四分之一的能力。2. 分析前的準(zhǔn)備工作接入、索引與字段規(guī)劃2.1 日志接入與采集配置別以為日志分析是故障發(fā)生后才做的事真正的分水嶺在接入階段就決定了。如果日志格式亂七八糟后面再?gòu)?qiáng)的工具也幫不上忙。我現(xiàn)在的做法是所有業(yè)務(wù)服務(wù)統(tǒng)一輸出 JSON 格式日志把關(guān)鍵信息暴露成獨(dú)立字段。一份典型的日志長(zhǎng)這樣{ time: 2025-04-17T01:47:23.123Z, level: ERROR, service: order-svc, trace_id: 6f8c9d2e1a4b, message: invoke pay timeout, cost_ms: 3021, code: PAY_TIMEOUT }JSON 的好處是字段天然結(jié)構(gòu)化WeClaw 采集端可以直接把 key 解析成獨(dú)立字段后續(xù)檢索就能寫code:PAY_TIMEOUT而不是在 message 里做文本匹配。如果你還在用純文本日志至少也要通過分隔符、正則等方式把 service、level、trace_id、code 這幾個(gè)關(guān)鍵字段解析出來。接入時(shí)還有幾個(gè)細(xì)節(jié)值得注意日志統(tǒng)一用 UTC 時(shí)間避免跨時(shí)區(qū)聚合錯(cuò)位采集路徑要精確到目錄避免把無關(guān)系統(tǒng)日志也采進(jìn)來編碼統(tǒng)一 UTF-8不然中文日志會(huì)變成亂碼。這些在故障時(shí)全都會(huì)變成致命干擾項(xiàng)。2.2 索引如何設(shè)計(jì)直接決定了查詢快不快很多人在 WeClaw 上排障慢不是工具慢而是索引設(shè)計(jì)沒做對(duì)。索引不是把所有字段都建上就叫好而是只給“會(huì)用來篩選和聚合的字段”建索引。常規(guī)做法是給高頻過濾字段做成 keyword 類型例如service: keyword level: keyword trace_id: keyword code: keyword host: keyword time: date帶時(shí)區(qū) cost_ms: long message: text開啟分詞用于模糊檢索keyword 和 text 的區(qū)別很關(guān)鍵。keyword 適合精確匹配、范圍過濾、分組聚合速度快text 適合模糊搜索但檢索開銷大聚合也不太方便。如果把 service 誤配成 text查詢時(shí)可能查得到但group by service的時(shí)候會(huì)得到你完全想不到的分桶結(jié)果因?yàn)榉衷~把字段拆碎了。保留策略也不能忽略。熱數(shù)據(jù)近幾天在 SSD 上冷數(shù)據(jù)轉(zhuǎn)入歸檔存儲(chǔ)既省錢又保證熱查詢速度。如果所有索引都按 180 天全量保留光掃描范圍就能把查詢拖慢一個(gè)數(shù)量級(jí)。2.3 這些配置坑我?guī)缀趺總€(gè)項(xiàng)目都見過接入和索引配置踩過的坑我基本都能背出來了。第一個(gè)是時(shí)間字段時(shí)區(qū)錯(cuò)亂。有些服務(wù)上報(bào)本地時(shí)間有些上報(bào) UTC混在一起后在 WeClaw 里看到的日志時(shí)間線是扭曲的聚合出的高峰期根本對(duì)不上真實(shí)故障窗口。解決辦法就是接入規(guī)范里強(qiáng)制要求統(tǒng)一 UTC 時(shí)間戳或者在采集端做一次時(shí)區(qū)歸一。第二個(gè)是采集路徑導(dǎo)致日志體積虛高。之前有次排障明明只查訂單服務(wù)結(jié)果檢索結(jié)果里混進(jìn)了一堆全鏈路健康檢查日志。后來查出來是采集器把整個(gè)根目錄都掃了健康檢查日志全部灌進(jìn)索引。日志量翻了三倍查詢自然變慢。第三個(gè)是多行日志被拆散。Java 異常堆棧天生是多行的默認(rèn)按行采集會(huì)把一個(gè)異常拆成幾十條獨(dú)立日志聚合時(shí) count 出來的不是“異常次數(shù)”而是“堆棧行數(shù)”。WeClaw 這類平臺(tái)一般都有多行合并配置按堆棧首行特征把完整異常合并成一條日志。這個(gè)沒配好你后面做的任何堆棧聚合都是錯(cuò)的。3. 檢索篩選從億級(jí)日志中快速收斂到可疑范圍3.1 單條檢索的語法和習(xí)慣WeClaw 的檢索語法和主流日志平臺(tái)類似基礎(chǔ)能力就是布爾表達(dá)式加字段過濾。常用的幾類寫法# 字段精確匹配 service:order-svc # 多個(gè)條件組合 service:order-svc AND level:ERROR # 帶數(shù)值范圍 service:order-svc AND cost_ms:3000 # 排除干擾 service:order-svc AND level:ERROR AND NOT message:health check # 通配符 message:redis * timeout用詞大小寫、引號(hào)規(guī)則不同版本可能略有差異但核心習(xí)慣是一樣的先做字段精確過濾再做內(nèi)容模糊檢索。上來就在 message 里搜一個(gè)不帶引號(hào)的 error結(jié)果匹配的范圍會(huì)比你想的大得多因?yàn)?error 可能是單詞的一部分也可能出現(xiàn)在 URL、響應(yīng)頭等位置。3.2 不要一上來就搜 error這大概是排障里最違反直覺的一條建議先別搜 error。因?yàn)楹芏嘞到y(tǒng)的 ERROR 日志數(shù)量本身就很大而且大部分 ERROR 不是根因而是根因引發(fā)的連鎖反應(yīng)。我之前處理過的一個(gè)案例就能說明問題表面上是支付服務(wù)瘋狂報(bào)“上游連接被拒”搜 error 全線飄紅。順著 error 一條條看都是網(wǎng)關(guān)服務(wù)在重試看起來像是網(wǎng)關(guān)掛了。但追到網(wǎng)關(guān)日志才發(fā)現(xiàn)真正的起因是數(shù)據(jù)庫(kù)連接池被打滿所有請(qǐng)求在數(shù)據(jù)庫(kù)層排隊(duì)超時(shí)網(wǎng)關(guān)只是把超時(shí)錯(cuò)誤翻譯成了連接失敗。如果一開始就盯著 error 細(xì)看很容易把“重試引起的次生錯(cuò)誤”誤判成根因。更合理的起點(diǎn)是“已知的異常信號(hào)”告警里提到的錯(cuò)誤碼、監(jiān)控曲線突變的時(shí)刻、耗時(shí)最高的請(qǐng)求類型。拿這些信號(hào)去構(gòu)造檢索條件比從 error 開頭更接近真相。3.3 排障篩選三連時(shí)間窗口、服務(wù)維度、日志級(jí)別我每次定位都嚴(yán)格按三步做檢索收斂這一步做扎實(shí)后面的聚合和關(guān)聯(lián)才有意義。第一步把時(shí)間窗口縮到故障前后五分鐘。告警是 01:47 觸發(fā)的我就先看 01:42 到 01:52 這十分鐘。半小時(shí)前和半小時(shí)后的日志對(duì)這次事故沒有意義只會(huì)增加噪音。時(shí)間窗口收窄之后檢索速度也能快一個(gè)量級(jí)WeClaw 只需要掃極少的分片即可。第二步用服務(wù)維度固定范圍。故障影響的是訂單服務(wù)就先看service:order-svc不要一開始就全平臺(tái)搜。等確定根因在依賴鏈路后再用 trace_id 跳轉(zhuǎn)到其他服務(wù)。第三步再?zèng)Q定要不要限定日志級(jí)別。業(yè)務(wù)自定義的錯(cuò)誤碼比日志級(jí)別更可靠?jī)?yōu)先用 code 過濾。比如service:order-svc AND code:PAY_TIMEOUT通常比level:ERROR準(zhǔn)確得多。三個(gè)動(dòng)作做完候選集合通常已經(jīng)從百萬級(jí)降到了萬級(jí)以內(nèi)下一步就可以做聚合了。4. 聚合分析讓海量日志自己開口說話4.1 高頻錯(cuò)誤聚合把幾萬條壓成幾個(gè)桶排障最怕的是條條日志長(zhǎng)得都不一樣你看到一萬條錯(cuò)誤卻沒看出它們其實(shí)是同一個(gè)錯(cuò)誤的重復(fù)演繹。聚合就是用來解決這個(gè)問題的。WeClaw 里常見的聚合操作是按字段分組后統(tǒng)計(jì)次數(shù)。比如先查service:order-svc AND level:ERROR然后按 code 分組統(tǒng)計(jì)service:order-svc AND level:ERROR | group by code, top 10出來的結(jié)果大概率是一個(gè) code 占比 70%另一個(gè)占比 20%剩下的是零散異常。最占優(yōu)勢(shì)的那個(gè) code就是你后面要重點(diǎn)追的方向。這一步至關(guān)重要它把幾萬條錯(cuò)誤收斂成了幾個(gè)可數(shù)的統(tǒng)計(jì)桶。4.2 趨勢(shì)與時(shí)間切片對(duì)齊操作和故障時(shí)間線聚合不僅看數(shù)量還要看時(shí)間分布。WeClaw 的統(tǒng)計(jì)圖表功能可以按分鐘、按小時(shí)做直方圖把錯(cuò)誤數(shù)畫成一條時(shí)間線。這條時(shí)間線的用途是讓你的大腦把“故障”和“某個(gè)操作”關(guān)聯(lián)起來。有一次排障錯(cuò)誤聚合結(jié)果一直指向空指針但場(chǎng)景怎么都說不通。我把錯(cuò)誤數(shù)量按分鐘拉成圖表后發(fā)現(xiàn)某個(gè) NPE 是在下午 2 點(diǎn)零幾分突然出現(xiàn)且持續(xù)增長(zhǎng)而下午 2 點(diǎn)恰好是某次發(fā)布窗口。順著發(fā)布變更回溯代碼定位到一次參數(shù)校驗(yàn)邏輯被改漏了。如果沒有時(shí)間切片對(duì)齊就永遠(yuǎn)停留在“代碼為什么空指針”的靜態(tài)層面根本不會(huì)想到去看發(fā)布操作。時(shí)間分布還有一個(gè)用法是和正?;€對(duì)比??茨硹l錯(cuò)誤碼曲線相對(duì)前一天同時(shí)段是否陡增能快速區(qū)分“積壓性的慢性問題”和“突然爆發(fā)的急性問題”。慢性問題看趨勢(shì)急性問題找尖刺排障策略完全不一樣。4.3 從聚合結(jié)果里識(shí)別“異常模式”而不是看單條日志做聚合分析時(shí)我會(huì)刻意做一個(gè)操作把 message 里的動(dòng)態(tài)部分抽象成模板。比如原始日志是2025-04-17 01:47:23 ERROR order-svc 請(qǐng)求 /api/order/12345 處理超時(shí), cost3021ms 2025-04-17 01:47:25 ERROR order-svc 請(qǐng)求 /api/order/67890 處理超時(shí), cost2876ms兩條日志的 message 看起來是兩條不同的但把訂單號(hào)替換成{orderId}后模式完全一致。WeClaw 里有些版本支持按表達(dá)式提取模式或者你可以在檢索時(shí)手動(dòng)用通配符message:請(qǐng)求 /api/order/* 處理超時(shí)來歸并同類日志。這一步就是在把“離散日志”變成“類型視圖”。排障時(shí)你應(yīng)該關(guān)注的是類型而不是單條文本。等到你看到“某個(gè)類型占 90% 的錯(cuò)誤量”時(shí)根因方向往往已經(jīng)很明確了。5. 關(guān)聯(lián)分析從可疑片段連出完整因果鏈5.1 用 trace_id 把散落的日志串成一條鏈日志分析做到聚合這步基本能鎖定“哪個(gè)錯(cuò)誤類型最可疑”但還差最后一擊搞清楚這條錯(cuò)誤在調(diào)用鏈中處于什么位置是誰調(diào)誰才觸發(fā)出來的。這就輪到 trace_id 上場(chǎng)了。trace_id 是貫穿整個(gè)調(diào)用鏈路的唯一標(biāo)識(shí)。你在 WeClaw 里直接輸入trace_id:6f8c9d2e1a4b得到的不是一條日志而是從入口網(wǎng)關(guān)到下游服務(wù)的完整鏈路日志按時(shí)間排序后一眼就能看出每個(gè)環(huán)節(jié)的耗時(shí)和狀態(tài)。這是把“一條可疑錯(cuò)誤”升級(jí)為“一段完整因果”的關(guān)鍵動(dòng)作。如果項(xiàng)目里還沒有打 trace_id我建議盡快在網(wǎng)關(guān)或 RPC 中間件統(tǒng)一生成并在日志上下文里帶上。沒有 trace_id 的日志平臺(tái)排障能力至少砍掉一半因?yàn)樗腥罩径际腔ハ喙铝⒌乃槠肋h(yuǎn)拼不出整張圖。5.2 跨服務(wù)上下文檢索與上下游判斷鏈路日志變多后怎么判斷問題出在哪一環(huán)我的判斷標(biāo)準(zhǔn)是三個(gè)維度耗時(shí)、狀態(tài)碼、依賴資源。耗時(shí)維度看哪一環(huán)的時(shí)間占比最大。比如 trace_id 展開后網(wǎng)關(guān)耗時(shí) 3000ms 里3900ms 花在調(diào)數(shù)據(jù)庫(kù)那數(shù)據(jù)庫(kù)基本就是瓶頸。狀態(tài)碼維度看哪個(gè)下游返回了 5xx 或?qū)?yīng)超時(shí)碼。依賴資源維度則是看 DB、Redis、MQ 這些外部組件的連接數(shù)、慢查詢指標(biāo)有沒有同步異常。有一次排障支付服務(wù)調(diào)用訂單服務(wù)一直超時(shí)order-svc 自身報(bào)錯(cuò)不過兩三條。我拿 trace_id 一查發(fā)現(xiàn)所有請(qǐng)求都卡在 sso-cache 這個(gè)中間環(huán)節(jié)。再往下追是緩存服務(wù)連接池被異常請(qǐng)求打滿連接獲取等了 4 秒。如果只看 order-svc 一家的日志這個(gè)問題根本定位不了因?yàn)檎鎯丛谏嫌蔚木彺鎸印?.3 一個(gè)實(shí)戰(zhàn)推演日志表象到根因的距離拿一次完整的排障推演來演示整條鏈路。某跨平臺(tái)系統(tǒng)在 00:00 左右開始出現(xiàn)訂單創(chuàng)建失敗告警規(guī)則觸發(fā)后我按前面三步走第一步鎖定 00:02 到 00:12 這個(gè)時(shí)間窗口查詢service:order-svc AND level:ERROR。第二步按 code 聚合發(fā)現(xiàn)DB_CONN_TIMEOUT占比突破 80%。第三步隨便挑一條該 code 的高頻 trace_id在 WeClaw 鏈路視圖里展開00:03:01.204 gateway DEBUG 收到創(chuàng)建訂單請(qǐng)求, trace_id7f3a... 00:03:01.210 order-svc INFO 調(diào)用訂單服務(wù) 00:03:02.502 order-svc INFO 嘗試獲取數(shù)據(jù)庫(kù)連接, pool_wait4120ms 00:03:02.503 order-svc ERROR 獲取數(shù)據(jù)庫(kù)連接超時(shí), codeDB_CONN_TIMEOUT問題很快就浮出水面不是 SQL 慢不是業(yè)務(wù)邏輯錯(cuò)而是應(yīng)用拿不到數(shù)據(jù)庫(kù)連接連接池在 00:00 之后被耗盡了。繼續(xù)看數(shù)據(jù)庫(kù)監(jiān)控發(fā)現(xiàn)大量慢查詢把連接占住不釋放。再回看慢查詢是某條統(tǒng)計(jì)報(bào)表 SQL 在跨天結(jié)算任務(wù)里被打了出來。從“訂單創(chuàng)建失敗”到“跨天慢查詢占滿連接池”中間隔了四層錯(cuò)誤聚合收斂到錯(cuò)誤碼、trace_id 展開定位環(huán)節(jié)、連接池指標(biāo)反映資源瓶頸、慢查詢定位最終 SQL。每一步都通過 WeClaw 的分析能力完成整個(gè)定位過程大約二十分鐘。如果一上來就在日志里搜“訂單失敗”可能到天亮也理不清因果。6. 常見問題與排查技巧實(shí)錄6.1 查詢變慢的幾個(gè)原因與解決思路用 WeClaw 排障時(shí)最煩躁的莫過于檢索轉(zhuǎn)圈。遇到這種情況先別怪平臺(tái)先從自己的查詢習(xí)慣找原因。最常見的問題是時(shí)間范圍開得太大默認(rèn)七天實(shí)際只需要看十分鐘。日志平臺(tái)掃描的數(shù)據(jù)量和時(shí)間范圍成正比把窗口縮到分鐘級(jí)速度立刻不一樣。其次是把模糊查詢當(dāng)成萬能藥。message:超時(shí)這種全文檢索在大型索引上比字段級(jí)過濾慢得多。能寫成code:PAY_TIMEOUT就不要用模糊匹配。還有一個(gè)隱藏因素聚合并發(fā)度。如果你同時(shí)打開多個(gè)聚合圖表后端會(huì)執(zhí)行多路統(tǒng)計(jì)速度自然會(huì)慢。排障時(shí)只保留最必要的聚合圖。6.2 檢索結(jié)果出現(xiàn)偏差的典型坑結(jié)果不準(zhǔn)比結(jié)果慢更可怕它會(huì)直接把你引到錯(cuò)誤方向。我整理幾個(gè)常見的坑都是親手踩過的。第一個(gè)是索引刷新延遲。日志寫入索引后通常不是立即可查有幾十秒到幾分鐘的延遲。剛發(fā)生故障時(shí)查最近一分鐘的日志可能查不到。解決方法是看日志下標(biāo)時(shí)間不要盯著當(dāng)前時(shí)間判斷。第二個(gè)是時(shí)區(qū)錯(cuò)亂導(dǎo)致“看不到日志”。某次查詢最近十分鐘沒有任何結(jié)果以為是采集斷了后來發(fā)現(xiàn)是應(yīng)用日志時(shí)間是 UTC8WeClaw 檢索界面按 UTC 計(jì)算導(dǎo)致時(shí)間窗口整體偏移了八小時(shí)。避免方法是接入時(shí)統(tǒng)一成 UTC或者在檢索界面上把時(shí)區(qū)選項(xiàng)對(duì)齊。第三個(gè)是日志被截?cái)?。超長(zhǎng)日志字段會(huì)被平臺(tái)默認(rèn)截?cái)喽褩.惓S绕淙菀装l(fā)生。排障時(shí)發(fā)現(xiàn)堆棧到一半就沒了先檢查字段長(zhǎng)度限制而不是急著懷疑代碼。第四個(gè)是采樣丟失。對(duì)超大日志量環(huán)境有些平臺(tái)默認(rèn)對(duì) DEBUG、INFO 級(jí)日志做采樣排障時(shí)查不到低級(jí)日志屬于正?,F(xiàn)象。日常排障可以用 ERROR 級(jí)日志但如果要定位低概率問題需要確保關(guān)鍵鏈路的全量日志沒有采樣。6.3 一套“壓箱底”的排查清單最后分享一套我貼在工位上的排查清單每次故障告警來了就照著執(zhí)行打開 WeClaw先把時(shí)間窗縮到告警前后五分鐘用服務(wù)名加錯(cuò)誤碼做第一輪過濾不要直接搜 error對(duì)過濾結(jié)果按 code 聚合找到占比最高的一類錯(cuò)誤如果 code 不能解釋就對(duì) message 做模式提取找出共性模板從聚合結(jié)果里挑一條有 trace_id 的日志打開鏈路視圖在鏈路里對(duì)比各環(huán)節(jié)耗時(shí)和狀態(tài)碼定位最可疑的一環(huán)沿時(shí)間線回溯該環(huán)節(jié)依賴的資源結(jié)合數(shù)據(jù)庫(kù)、緩存、消息隊(duì)列的監(jiān)控看是否同步異常如果一輪找不到就收窄時(shí)間窗把重點(diǎn)從 ERROR 級(jí)放到 INFO 級(jí)日志上還原操作細(xì)節(jié)。這套清單的特點(diǎn)是把“搜索”變成了“排查流程”每一步都在喂給下一步更精確的輸入最終收斂到根因。7. 寫在最后排障之后我最常做的事日志排障其實(shí)是個(gè)可以先苦后甜的活。我在好幾次事故里嘗到過“沒有 trace_id、字段亂配、時(shí)間格式不統(tǒng)一”的苦頭后來才把索引模板、日志規(guī)范和 trace_id 注入這些事當(dāng)成了基礎(chǔ)建設(shè)而不是事故后的補(bǔ)救。如果你剛開始用 WeClaw 做日志分析我建議你先把索引和字段模型打磨好平時(shí)就順手做幾次演練千萬不要等故障發(fā)生了才第一次打開聚合功能。日常排障多體會(huì)“過濾、聚合、關(guān)聯(lián)”這三板斧的順序感熟練之后面對(duì)億級(jí)日志時(shí)心里就有底了。最后再說一個(gè)小技巧每次定位完一個(gè)根因把當(dāng)時(shí)用的檢索語句、聚合圖表和鏈路截圖整理成一份“排障書簽”下次遇到同類問題直接復(fù)用這是用日志平臺(tái)越用越快的秘訣。