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