1. Caveman調(diào)試到底在說什么被低估了三十年的基本功1.1 從一次線上事故說起上個(gè)月我們有個(gè)服務(wù)線上偶發(fā)卡頓P99延遲每隔半小時(shí)就飆一下持續(xù)時(shí)間不長也就兩三秒但下游投訴不斷。我們一群人圍著監(jiān)控面板看了兩個(gè)小時(shí)懷疑了GC、懷疑了連接池、懷疑了網(wǎng)絡(luò)抖動(dòng)甚至準(zhǔn)備讓運(yùn)維重啟節(jié)點(diǎn)。最后是我一個(gè)同事擠過來說了句讓一讓在那個(gè)方法里加了三條print重新部署了一臺(tái)測(cè)試機(jī)壓了二十分鐘問題直接定位到了——一個(gè)被吞掉的異常引發(fā)了一連串重試堆積。那一刻我突然意識(shí)到一件事不管我們平時(shí)用多少高級(jí)工具遇到真正難搞的問題時(shí)最原始、最笨的辦法往往是最后那個(gè)管用的。這個(gè)最笨的辦法在程序員圈子里有個(gè)很直白的名字——caveman debugging原始人調(diào)試法。所謂caveman字面意思就是穴居人你可以理解成一個(gè)什么都不講究、拿最基礎(chǔ)的家伙事兒解決問題的原始人。在編程領(lǐng)域它特指那種最樸素的排查手段往代碼里加print、echo、console.log把關(guān)鍵狀態(tài)打到標(biāo)準(zhǔn)輸出或者文件里然后靠肉眼觀察行為、推斷原因。聽起來特別沒技術(shù)含量對(duì)吧但相信我這個(gè)沒技術(shù)含量的東西是每個(gè)工程師都該重新?lián)炱饋淼幕竟?。這篇文章我想認(rèn)真聊聊caveman調(diào)試法。它到底是什么、為什么在2020年代依然好用、以及怎么用它同時(shí)避免踩坑。文章里會(huì)有一次真實(shí)的排查復(fù)盤、一套我用了很多年的輸出方法論以及一張什么時(shí)候該當(dāng)原始人、什么時(shí)候該上現(xiàn)代工具的決策清單。不管你是剛?cè)腴T的新人還是被各種可觀測(cè)性平臺(tái)繞暈的老兵應(yīng)該都能在里面找到點(diǎn)用得上的東西。1.2 caveman調(diào)試法的本質(zhì)是最小可觀測(cè)閉環(huán)很多年輕同事一聽到用print調(diào)試就皺眉覺得這是沒有IDE、沒有調(diào)試器時(shí)代的老古董做法。但我得說他們誤解了caveman的本質(zhì)。caveman調(diào)試的核心不叫打印信息而叫親手制造一個(gè)觀測(cè)點(diǎn)。普通的工作方式是這樣的代碼跑出問題你在腦海里推演一遍覺得可能某個(gè)環(huán)節(jié)出了岔子于是去看那個(gè)環(huán)節(jié)的代碼用邏輯去證明它沒壞。這種模式靠的是靜態(tài)推理推理鏈條一旦長了就容易斷在某個(gè)假設(shè)上。caveman的方式完全反過來代碼跑到某個(gè)位置時(shí)我親手塞進(jìn)去一個(gè)觀測(cè)點(diǎn)讓它把當(dāng)時(shí)的真實(shí)狀態(tài)吐出來。這個(gè)觀測(cè)點(diǎn)不是別人幫我埋的也不是框架自動(dòng)生成的而是我此刻根據(jù)當(dāng)前懷疑點(diǎn)現(xiàn)做的。它只回答一個(gè)問題在當(dāng)前這個(gè)時(shí)間點(diǎn)、這條路徑上程序到底經(jīng)歷了什么。有輸出說明這個(gè)分支確實(shí)執(zhí)行了沒有輸出說明執(zhí)行路徑和你想的根本不一樣——不管結(jié)果是哪一種你都拿到了一份新的證據(jù)。這就是為什么它可靠。它依賴的東西少得可憐只需要一個(gè)能從代碼里輸出文字的機(jī)制。在Python里是print在Go里是fmt.Println在JavaScript里是console.log在C里是printf。這些函數(shù)幾乎是語言誕生第一天就在的東西不會(huì)因?yàn)榘姹旧?jí)而改變不會(huì)因?yàn)槟硞€(gè)SDK出bug而失效。你寫下的每個(gè)探針都直接連接著當(dāng)前進(jìn)程最真實(shí)的狀態(tài)。1.3 它和寫日志完全是兩碼事這里必須澄清一個(gè)容易混淆的地方caveman調(diào)試不等于寫日志。很多人說我系統(tǒng)里日志打得挺全的為什么還要用print——好問題。日志是面向長期運(yùn)行的它需要分級(jí)、需要結(jié)構(gòu)化、需要考慮性能開銷、需要設(shè)計(jì)字段結(jié)果往往是把大量信息扔進(jìn)一個(gè)中心化平臺(tái)里等出問題時(shí)再去搜。但caveman調(diào)試是面向當(dāng)下戰(zhàn)斗的它只做三件事臨時(shí)加、快速看、完事刪。日志是廣譜的、被動(dòng)記錄的像是給整個(gè)系統(tǒng)裝了一圈監(jiān)控?cái)z像頭caveman是焦點(diǎn)式的、主動(dòng)刺探的像是你蹲在某個(gè)關(guān)鍵路口專門等那個(gè)嫌疑對(duì)象經(jīng)過。你排查問題時(shí)系統(tǒng)里現(xiàn)有的日志往往不能回答你最想知道的那個(gè)問題——這個(gè)函數(shù)執(zhí)行到這行之前那個(gè)變量到底變成了什么——因?yàn)闆]人知道你會(huì)關(guān)心這個(gè)變量。而一條臨時(shí)加的輸出恰好就能回答它。明白了這個(gè)前提之后我想接著聊聊為什么很多時(shí)候高級(jí)工具反而不如這原始一招。這不是情懷而是工程上的現(xiàn)實(shí)。2. 為什么調(diào)試器和日志框架有時(shí)真的不如一行print2.1 斷點(diǎn)調(diào)試的失效場(chǎng)景說實(shí)話我平時(shí)用得最多的還是調(diào)試器。單步、斷點(diǎn)、watch表達(dá)式這些在寫單元測(cè)試、追本地邏輯問題時(shí)效率很高。但一旦問題跑到特定的環(huán)境里調(diào)試器會(huì)成建制成地失效。第一類是多線程和并發(fā)問題。你在一處斷點(diǎn)停下來你看到的是這個(gè)線程此刻的局部狀態(tài)但問題往往出在另一個(gè)線程的時(shí)序上。你一停在斷點(diǎn)上整個(gè)程序的執(zhí)行節(jié)奏就被改變了本來能復(fù)現(xiàn)的競態(tài)條件可能就此消失了。這跟海森堡測(cè)不準(zhǔn)原理有點(diǎn)像——觀測(cè)動(dòng)作本身干擾了被觀測(cè)對(duì)象。第二類是分布式環(huán)境。服務(wù)有幾十個(gè)實(shí)例負(fù)載均衡隨機(jī)轉(zhuǎn)發(fā)你用調(diào)試器attach到其中一個(gè)實(shí)例可下一次請(qǐng)求可能根本不經(jīng)過它。你得在多臺(tái)機(jī)器上反復(fù)跳出跳入效率低到讓人想砸鍵盤。第三類是偶現(xiàn)問題。問題跑幾個(gè)小時(shí)才出現(xiàn)一次你總不能盯著調(diào)試器等它跳斷點(diǎn)而且斷點(diǎn)一命中程序就暫停了后續(xù)的時(shí)間窗口早過去了。在這些場(chǎng)景里print式的觀測(cè)反而有它獨(dú)特的價(jià)值它不影響執(zhí)行節(jié)奏不需要交互式環(huán)境只要代碼跑到那里輸出就自然產(chǎn)生。你可以讓它在全量實(shí)例上跑跑幾個(gè)小時(shí)最后把日志拉回來對(duì)比——這是調(diào)試器做不到的。2.2 日志框架的過度設(shè)計(jì)帶來的坑再來說說日志框架。現(xiàn)代的日志框架確實(shí)強(qiáng)大異步寫入、級(jí)別過濾、鏈路追蹤、自動(dòng)采集。但強(qiáng)大是有代價(jià)的代價(jià)就是你能看到的永遠(yuǎn)只是框架愿意讓你看到的那部分。我印象很深的一次有個(gè)服務(wù)用了一個(gè)挺流行的日志庫開了異步刷盤平時(shí)日志秒出但壓測(cè)時(shí)發(fā)現(xiàn)最新的一條日志丟了。原因是異步緩沖區(qū)滿了舊的日志沒來得及落盤新的日志直接被丟棄。我當(dāng)時(shí)追了很久最后發(fā)現(xiàn)那一行關(guān)鍵的錯(cuò)誤信息恰恰就是被丟的那條。如果當(dāng)時(shí)用的是print直接同步寫到文件或者終端絕不至于這樣。還有日志級(jí)別的問題。線上環(huán)境為了控制磁盤占用info級(jí)別的日志通常是關(guān)掉的。但你排查問題時(shí)真正需要的就是那幾條info——它們記錄了關(guān)鍵節(jié)點(diǎn)的進(jìn)去和出來。你急著想看卻發(fā)現(xiàn)日志級(jí)別配置在環(huán)境變量里、在配置中心里、在一層層封裝后面改起來還要走變更流程。caveman式的輸出呢它不跟你講級(jí)別不跟你講異步不跟你講采樣率。它就是一個(gè)同步寫入你寫了就有沒寫就是沒有。有時(shí)候這種直白粗暴反而是最大的優(yōu)點(diǎn)。2.3 讀代碼和看行為之間的鴻溝還有一個(gè)深層原因解釋了為什么這原始的一招一直有效靜態(tài)讀代碼和動(dòng)態(tài)看行為之間永遠(yuǎn)存在一條認(rèn)知鴻溝。一個(gè)系統(tǒng)跑起來之后真正執(zhí)行的路徑、時(shí)序、數(shù)據(jù)分布可能和你在代碼里腦補(bǔ)出來的完全不同。你以為某個(gè)分支永遠(yuǎn)不會(huì)進(jìn)但實(shí)際生產(chǎn)數(shù)據(jù)里它就是會(huì)進(jìn)你以為兩個(gè)操作是原子的但實(shí)際上線程調(diào)度把它們打得七零八落你以為一個(gè)第三方庫會(huì)拋異常但它好像在某些情況下會(huì)靜默吞掉。代碼是靜態(tài)的行為是動(dòng)態(tài)的兩者之間的鴻溝靠讀代碼填不平只能靠觀測(cè)填。caveman調(diào)試法就是最直接、最符合直覺的觀測(cè)方式。它不依賴你對(duì)框架的理解不依賴你對(duì)工具的熟練度只依賴一行輸出和你的眼睛。這個(gè)門檻低到幾乎每個(gè)人都會(huì)用但也正因?yàn)樘头炊缓芏嗳撕雎浴?. 一次真實(shí)事件復(fù)盤三行輸出定位線上周期性卡頓3.1 問題表現(xiàn)與最初的手忙腳亂回到開頭那個(gè)線上事故。我們平臺(tái)有個(gè)任務(wù)調(diào)度服務(wù)用的技術(shù)棧是Python gunicorn 多線程下游依賴MySQL和Redis。現(xiàn)象很規(guī)律每隔大概30分鐘P99延遲從平時(shí)的80ms飆到3秒持續(xù)兩三秒后恢復(fù)。業(yè)務(wù)方天天來催說任務(wù)堆積下游超時(shí)。剛開始我們的排查思路完全是散彈槍式的。第一輪懷疑是GC停頓把gc日志拉出來看了看并沒有明顯的長停頓第二輪懷疑是Redis連接池耗盡慢查詢指標(biāo)翻了一圈也沒有異常第三輪懷疑是網(wǎng)絡(luò)抖動(dòng)翻了一大圈基礎(chǔ)設(shè)施監(jiān)控還是沒找到證據(jù)。那是一段特別磨人的時(shí)間——指標(biāo)都是正常的但服務(wù)就是卡。你也遇到過這種情況吧所有常規(guī)指標(biāo)都正常但用戶感知就是很差。這種時(shí)候常規(guī)手段已經(jīng)不夠用了必須把觀測(cè)粒度從系統(tǒng)級(jí)下沉到代碼級(jí)。3.2 決定做減法只留最小化輸出探針當(dāng)時(shí)是我那個(gè)同事拉住了準(zhǔn)備重啟節(jié)點(diǎn)的我們。他說了句讓我一直記到現(xiàn)在的話我們還沒證明哪段代碼慢為什么要重啟然后他打開代碼那個(gè)請(qǐng)求處理入口長這樣先取任務(wù)再調(diào)下游最后寫結(jié)果。他直接在三個(gè)步驟前后加了三行輸出import time def process_task(task_id): t0 time.time() print(f[TRACE-A] task{task_id} start at {t0}, flushTrue) task get_task(task_id) # 第一步從DB拉任務(wù)數(shù)據(jù) print(f[TRACE-B] got task, spent {time.time() - t0:.3f}s, flushTrue) result call_downstream(task) # 第二步調(diào)用下游接口 print(f[TRACE-C] downstream done, spent {time.time() - t0:.3f}s, flushTrue) save_result(task_id, result) # 第三步寫結(jié)果 print(f[TRACE-D] saved, total {time.time() - t0:.3f}s, flushTrue)注意他走了兩個(gè)關(guān)鍵的細(xì)節(jié)。第一個(gè)是flushTrue保證print不是只往緩沖區(qū)里一放而是立刻刷到日志文件否則突然崩潰時(shí)最后幾行就丟了。第二個(gè)是給每行輸出加了一個(gè)固定前綴TRACE-A、TRACE-B這樣的標(biāo)識(shí)方便后面用grep一把過濾出來。這三行輸出不需要改動(dòng)任何業(yè)務(wù)邏輯也幾乎沒有性能開銷。我們把改了代碼的版本發(fā)到那臺(tái)有問題的實(shí)例上——注意只發(fā)一臺(tái)不全部發(fā)——然后等著那個(gè)30分鐘的周期出現(xiàn)。3.3 關(guān)鍵發(fā)現(xiàn)與根因一場(chǎng)被吞掉的異常等了一個(gè)周期日志出來了。我們拉了那段時(shí)間的三行輸出結(jié)果很有意思[TRACE-A] task10221 start at 14:30:01.201 [TRACE-B] got task, spent 0.012s [TRACE-C] downstream done, spent 0.013s [TRACE-D] saved, total 0.021s一切正?？偣膊?1毫秒。那卡頓到底在哪我們又把日志多拉了一段仔細(xì)看了下時(shí)間線突然發(fā)現(xiàn)了一個(gè)被忽略的細(xì)節(jié)那三秒的空白不在任何TRACE標(biāo)記之間而是在整個(gè)請(qǐng)求入口的最前面。也就是說進(jìn)程從收到任務(wù)到執(zhí)行process_task的第一行print中間隔了整整2.7秒。順著這個(gè)線索往前查問題很快水落石出。gunicorn在接受連接之后、調(diào)用worker處理之前有一段任務(wù)是優(yōu)先處理積壓的重試任務(wù)而那個(gè)重試邏輯有一個(gè)異常處理塊用了一個(gè)特別寬泛的except Exception把錯(cuò)誤全吞了。某些定時(shí)任務(wù)失敗后會(huì)自動(dòng)進(jìn)入重試隊(duì)列重試又失敗又被塞回隊(duì)列形成惡性循環(huán)。每隔30分鐘重試隊(duì)列里剛好堆積了一批任務(wù)這個(gè)循環(huán)要一次性把它們處理完于是那幾秒的停頓就出現(xiàn)了。而因?yàn)樗旬惓Ｍ塘顺Ｒ?guī)的錯(cuò)誤日志里什么都看不到。如果沒有那三行print我們恐怕還在盯著GC和Redis猜來猜去。排查鏈路從系統(tǒng)指標(biāo)一路收窄到入口之前的某段代碼靠的正是最小化的、帶明確標(biāo)記的輸出探針。3.4 修復(fù)與驗(yàn)證確認(rèn)病灶之后才能下刀根因明確了修復(fù)反而簡單把那個(gè)寬泛的except Exception改成精確捕獲具體的異常類型并給重試邏輯加上最大重試次數(shù)和退避時(shí)間杜絕無限循環(huán)堆積。改完之后我們把三行TRACE輸出保留在那一臺(tái)上跑了兩小時(shí)周期性的卡頓消失了區(qū)間拉長再也沒有出現(xiàn)那個(gè)2.7秒的空白。這個(gè)項(xiàng)目給我留下的收獲比一次故障本身大得多。我后來把這次排查的套路拆成了可重復(fù)使用的方法論下面具體說。4. 讓原始輸出變得好用我的printf排查方法論4.1 一切從給輸出編號(hào)開始如果你去網(wǎng)上搜到處都會(huì)有人教育你不要亂加print。但我要說的是另一面亂加print確實(shí)沒價(jià)值但有方法地加print是效率極高的排查手段。問題的關(guān)鍵不在要不要用print而在怎么用print。我的第一條經(jīng)驗(yàn)是每個(gè)探針都要有唯一標(biāo)識(shí)。在多人協(xié)作的代碼庫里大家的輸出很可能混在一起你打了一百行print結(jié)果別人的排查和業(yè)務(wù)日志也混在里面根本沒法看。所以我習(xí)慣用一個(gè)統(tǒng)一的前綴比如TRACE-A、TRACE-B或者帶上當(dāng)前所在函數(shù)的名稱比如[process_task]。這樣做有兩個(gè)好處一是用grep一搜就能把所有探針輸出拉出來二是輸出順序本身就是執(zhí)行路徑的一種可視化。一個(gè)典型的標(biāo)記格式長這樣# 推薦格式[模塊/函數(shù)名] [步驟標(biāo)識(shí)] 關(guān)鍵變量內(nèi)容 print(f[worker.process_task][A] task{task_id} received, flushTrue)有了統(tǒng)一前綴刪除探針這件事也變得安全可控。排查結(jié)束后搜一下TRACE或者你的前綴所有該刪的地方一目了然不用擔(dān)心漏掉哪個(gè)。4.2 帶上不可變上下文別怕信息冗余第二條經(jīng)驗(yàn)輸出里一定要帶上定位上下文最好包括時(shí)間戳和請(qǐng)求ID。很多人只打印一個(gè)start或者end然后看著輸出發(fā)呆——這行日志到底是誰打的是哪個(gè)請(qǐng)求觸發(fā)的發(fā)生在什么時(shí)候全都對(duì)不上號(hào)。時(shí)間戳的精度也有講究。排查性能問題時(shí)毫秒級(jí)都嫌粗糙我習(xí)慣用到微秒特別是在Python里import time print(f[process_task][A] task{task_id} ts{time.time():.6f}, flushTrue)(time.time())返回的是帶小數(shù)部分的秒.6f就是微秒級(jí)精度。在對(duì)比兩個(gè)探針之間的耗時(shí)差時(shí)這個(gè)精度能讓你看到毫秒以下的波動(dòng)把那些十幾毫秒的小延遲也找出來。請(qǐng)求ID就更好用了。在Web服務(wù)里入口處通常能拿到一個(gè)trace_id或者request_id把它放進(jìn)每一行輸出里你就能精確地把某個(gè)請(qǐng)求的完整路徑從一堆并發(fā)日志中切出來。哪怕沒有框架幫你傳遞trace_id你也可以在函數(shù)入?yún)⑸舷曼c(diǎn)功夫手動(dòng)把它傳進(jìn)去——這在本地排查時(shí)成本很低但帶來的信息增量極高。4.3 條件輸出只在狀態(tài)變化時(shí)說話第三個(gè)原則是控制噪音。如果一段代碼會(huì)被調(diào)用十萬次你在里面無腦加print輸出文件瞬間就被打爆了你要找的線索也會(huì)淹沒在無數(shù)相同的行里。我的做法是加條件。只有滿足特定條件時(shí)才打輸出比如if task.priority high or elapsed_ms 500: print(f[scheduler][skip] task{task.id} waited{elapsed_ms}ms, flushTrue)這樣不光是邏輯分支被覆蓋到性能異常路徑也被覆蓋到了。排查偶發(fā)卡頓時(shí)這種只在超預(yù)期情況下才說話的探針效果比每行都打強(qiáng)得多——它把注意力直接拉到了異常點(diǎn)上。還有一種很實(shí)用的形式是計(jì)數(shù)器配合循環(huán)。在循環(huán)里加一個(gè)累加變量每1000次才打一行既能看到進(jìn)度又不會(huì)刷屏for i, item in enumerate(item_list): process(item) if i % 1000 0: print(f[batch_worker] progress{i}/{len(item_list)} last_batch_cost{time.time() - batch_start:.3f}s, flushTrue) batch_start time.time()4.4 一套現(xiàn)成的排查手段清單把上面的經(jīng)驗(yàn)整理成一張表你在實(shí)戰(zhàn)中可以直接照著用場(chǎng)景探針寫法要點(diǎn)關(guān)注什么確認(rèn)某段代碼是否執(zhí)行打印唯一標(biāo)記 關(guān)鍵參數(shù)值有沒有這行輸出定位性能瓶頸在每相鄰步驟間打時(shí)間戳精確到微秒相鄰時(shí)間差哪段最大捕捉偶發(fā)異常在異常except塊里打印完整堆棧異常被吞后仍有記錄判斷分支走向在每個(gè)if分支末尾打標(biāo)記走了哪條分支排查并發(fā)超時(shí)輸出請(qǐng)求ID 時(shí)間戳多線程各打各的同一請(qǐng)求ID各階段時(shí)間線反向確認(rèn)循環(huán)是否卡住每N輪打一次進(jìn)度循環(huán)是否在推進(jìn)這個(gè)清單是我自己在重溯、排障時(shí)會(huì)對(duì)照著選型的。選對(duì)了探針形態(tài)一次排查很可能就能少掉一半彎路。不過caveman調(diào)試法也不是萬能的。長期用過之后我慢慢摸清了它的邊界——什么時(shí)候上它什么時(shí)候應(yīng)該果斷換工具。5. 什么時(shí)候該當(dāng)原始人什么時(shí)候該上現(xiàn)代工具5.1 caveman調(diào)試適合的五個(gè)場(chǎng)景根據(jù)我的實(shí)際經(jīng)驗(yàn)下面這幾類場(chǎng)景里caveman式的輸出探針幾乎是最優(yōu)解。第一種是低概率復(fù)現(xiàn)的bug。問題跑幾小時(shí)才出現(xiàn)一次你不能開著調(diào)試器干等但你可以加好探針讓它運(yùn)行著等它自然撞上。這像是布了個(gè)捕獸夾而不是派人站崗。第二種是多線程/異步亂序問題。時(shí)序錯(cuò)了、某個(gè)共享狀態(tài)被改亂了套你很難用斷點(diǎn)抓住那個(gè)作案的瞬間。但你就需要裸的fmt.Println把每個(gè)線程進(jìn)入退出關(guān)鍵區(qū)的時(shí)間打出來人眼一看亂序就出來了。第三種是沒有日志也沒有監(jiān)控的老系統(tǒng)。這種系統(tǒng)你不可能要求它接上APM但加幾行輸出還是可以做到的——不過在線上老系統(tǒng)加輸出前要先確認(rèn)改動(dòng)是納秒級(jí)開銷而且能隨時(shí)刪。第四種是分布式環(huán)境初篩。整個(gè)請(qǐng)求鏈路跨了好幾個(gè)服務(wù)問題到底出在哪個(gè)環(huán)節(jié)都不知道。與其先鋪一堆全鏈路追蹤不如在懷疑的幾個(gè)邊界點(diǎn)各打一行輸出先把范圍縮小到一個(gè)服務(wù)再用專業(yè)工具深入。這種方式成本最低見效最快。第五種是你完全陌生的代碼庫。接手一個(gè)項(xiàng)目不知道該從哪看起加一行print確認(rèn)程序走到了哪一步比在那兒瞎猜這個(gè)入口到底通不通要靠譜得多。這也算是我這些年快速上手新項(xiàng)目的一個(gè)心法。5.2 不該用caveman的三個(gè)場(chǎng)景反過來也有幾個(gè)場(chǎng)景是我明確不建議用原始辦法硬扛的。第一是內(nèi)存泄漏的定位。泄漏往往發(fā)生在你沒在關(guān)注的角落你需要的是用profiler對(duì)堆快照做對(duì)比分清哪些對(duì)象在持續(xù)增長。print加在這類場(chǎng)景里只能在宏觀上告訴你內(nèi)存漲了但漲的那些對(duì)象是誰、從哪里來探針根本無從得知。第二是復(fù)雜的調(diào)用鏈追蹤。跨服務(wù)、跨消息隊(duì)列、跨定時(shí)任務(wù)的調(diào)用鏈靠文本輸出是拼不出來的這時(shí)候該用帶traceId的鏈路追蹤系統(tǒng)讓系統(tǒng)自動(dòng)把各環(huán)節(jié)串起來。第三是生產(chǎn)環(huán)境的長期可觀測(cè)性建設(shè)。caveman是臨時(shí)工不是正式員工。生產(chǎn)上要建的是結(jié)構(gòu)化日志、聚合告警、監(jiān)控大盤。拿print當(dāng)長期日志寫的話過兩周你就得面對(duì)一堆沒人看得懂的臨時(shí)輸出。團(tuán)隊(duì)協(xié)作時(shí)尤其忌諱這個(gè)——你加的臨時(shí)輸出過了三個(gè)月別人還在看到會(huì)怎么想這個(gè)邊界在實(shí)戰(zhàn)中是動(dòng)態(tài)的。我的習(xí)慣是懷疑不明確、范圍未收窄時(shí)先用caveman快速放探針一旦鎖定方向再切換到對(duì)應(yīng)的專業(yè)工具做深入分析。兩種手段不是對(duì)立關(guān)系而是接力關(guān)系。6. 除了排查問題caveman精神還能在哪些地方發(fā)力6.1 極簡腳本勝過重型框架Caveman精神其實(shí)不只在調(diào)試時(shí)好用。它背后那種用最原始、最可控的手段解決眼前的問題的思路在很多地方都能遷移。我自己感觸最深的是寫自動(dòng)化腳本。很多人一上來就搭框架、引依賴、設(shè)計(jì)抽象層一套小工具的代碼量比真正的業(yè)務(wù)邏輯還多。但很多時(shí)候一個(gè)需求只是每周把某個(gè)目錄下的臨時(shí)文件清一下或者從接口拉個(gè)數(shù)據(jù)存下來。這種場(chǎng)景我用純Python標(biāo)準(zhǔn)庫或者一組shell命令就能寫完不加任何額外依賴。減少依賴就是減少未來的坑。腳本這樣寫之后維護(hù)它的人也會(huì)感謝你——所有邏輯都明明白白地?cái)傇谀抢餂]有藏在框架層后面。6.2 shell命令組合拳比想象中的更強(qiáng)大這里的caveman式自動(dòng)化我指的是多用系統(tǒng)的原生命令做組合和管道。就拿排查問題時(shí)的常用操作來說吧# 看最近一分鐘內(nèi)進(jìn)程的CPU情況 top -b -n 1 | head -n 20 # 從一堆日志里按關(guān)鍵字找出帶有時(shí)間戳的行并排序 grep ERROR app.log | sed s/^\[\(.*\)\].*/\1 / | sort | head -n 30 # 統(tǒng)計(jì)某個(gè)狀態(tài)碼在五分鐘內(nèi)的分布并實(shí)時(shí)刷新 tail -F access.log | awk {print $9} | sort | uniq -c這些命令看起來原始但組合起來之后的表達(dá)能力遠(yuǎn)超想象。我有的同事傾向于引入一堆專門的日志分析工具但在排查初期一個(gè)grep加一個(gè)awk往往就能把問題范圍縮小到一行代碼里。這不叫退步這叫掌握了事物底層之后的自如選擇。6.3 簡單直接的方式做監(jiān)控預(yù)警還有一個(gè)讓我特別受益的用法是最原始的監(jiān)控模板。有些指標(biāo)我不想為了它去搭一套完整的監(jiān)控系統(tǒng)這時(shí)候幾行shell加一個(gè)系統(tǒng)內(nèi)置定時(shí)任務(wù)就夠了# 每5分鐘檢查一次服務(wù)健康狀態(tài)異常時(shí)記錄時(shí)間戳 */5 * * * * curl -sf http://localhost:8080/health /tmp/health_ok.txt || date /tmp/health_fail_times.txt甚至你可以在關(guān)鍵腳本里加一個(gè)請(qǐng)求耗時(shí)超限的判斷超了就寫一行到某個(gè)文件配合定時(shí)查看。這種監(jiān)控強(qiáng)度當(dāng)然比不了專業(yè)系統(tǒng)但勝在零成本、零依賴、可移植。你放在任何一臺(tái)機(jī)器上它都能馬上開始干活。如果這種caveman式的基礎(chǔ)監(jiān)控已經(jīng)能覆蓋絕大多數(shù)場(chǎng)景你就可以把更重的工具留給那些真正需要它們的少數(shù)問題。說到底這些做法的共同點(diǎn)是當(dāng)情況足夠明確時(shí)不要被工具本身絆住手腳。工具是拿來幫你解決問題的不是拿來證明你用得多高級(jí)的。最后再分享一個(gè)小技巧吧。我每次加臨時(shí)探針時(shí)都會(huì)在輸出前后加一條特別顯眼的分隔線比如連續(xù)打十幾個(gè)號(hào)。這樣做有兩個(gè)好處一是排查時(shí)一眼就能從海量日志里把探針段落框出來二是收尾時(shí)搜索分隔線就能把所有探針一網(wǎng)打盡不會(huì)留坑在代碼里。別小看這個(gè)習(xí)慣——我見過太多人因?yàn)闆]加標(biāo)記最后臨時(shí)輸出混入正式版本被運(yùn)維追著問這是什么鬼日志。原始人debugging這件事說到底不是讓你放棄現(xiàn)代工具而是讓你始終保有那個(gè)最簡單的抓手。手里拿著錘子看什么都是釘子固然不好但只認(rèn)工具箱里那套高級(jí)裝備、把最趁手的基本功丟了那才真的是撿了芝麻丟了西瓜。