昨天結案的時候有一條「查不到的」：pricing 的 WARN 跟 gateway 的 checkout 之間沒有共同欄位，我知道兩邊各發生幾次，就是對不起來。今天開始的 Traces 區塊就是在補這個洞。

今天不裝東西，先講清楚 trace 在解什麼問題。因為它是三根支柱裡唯一需要改程式碼的，動手之前要知道為什麼值得。

今天的故障開關：全部關閉

kubectl set env deploy/pricing BUG_SILENT_DISCOUNT=false LEAK_KB_PER_REQUEST=0
kubectl set env deploy/catalog BUG_N_PLUS_ONE=false

第二個故障長什麼樣

先回顧一下。Day 10 開著故障二畫過 P50 / P95 / P99 三條線：

一半的人完全沒感覺，最慢的 5% 慢了八到十倍，錯誤率是 0。metrics 只能告訴我「有一群人很慢」，log 只能告訴我「每一筆都成功」。我知道慢，不知道慢在哪。

log 為什麼拼不起來

我有三個服務，每個都有 log，而且都是結構化的。理論上把它們的 log 按時間排在一起，應該就能還原一筆請求走過的路。

我真的去 Loki 撈了三秒鐘的資料，三個服務一起看：

17:12:17.032 pricing  request  /prices    64.0ms
17:12:17.033 catalog  request  /items     65.7ms
17:12:17.034 gateway  request  /checkout  67.3ms
17:12:17.209 pricing  request  /prices    69.4ms
17:12:17.210 catalog  request  /items     72.2ms
17:12:17.212 gateway  request  /checkout  74.9ms
17:12:17.388 pricing  request  /prices    68.4ms
17:12:17.391 catalog  request  /items     73.7ms
17:12:17.394 gateway  request  /checkout  78.2ms

看起來很整齊，三行一組，每組就是一筆訂單。但這是假象，有三個原因。

第一，順序是倒的。 每個服務是在請求「處理完」的時候印那行 log，所以最裡面的 pricing 最先印，最外面的 gateway 最後印。log 記的是結束時間，不是呼叫順序。

第二，這三行之間沒有任何東西說它們屬於同一筆。 我是靠「時間很接近」猜的。這個猜測在我的環境成立，是因為 loadgen 一次只送一筆、等回來才送下一筆，每筆之間隔 175 毫秒，剛好排得開。

第三，真實系統不是這樣。 請求是並行的，每秒幾百筆交錯進來，pricing 的一行 log 前後各有幾十行別人的，時間相近的不只一組。而且一旦故障二打開，一個大購物車會讓 catalog 對 pricing 連打十幾次，pricing 那邊會堆出十幾行，哪幾行是哪個購物車的，完全看不出來。

有人會說，那在 log 裡加一個請求編號就好了。對，這就是 trace 的第一個原理。差別在於 trace 把這件事做完整了：它不只給一個共同編號，還記錄每一段的父子關係和精確耗時。

trace 的資料模型

只有三個概念。

span：一段工作。「gateway 處理這個請求」是一個 span，「catalog 呼叫 pricing」是一個 span，「pricing 查一次資料庫」也是一個 span。每個 span 記名字、開始和結束時間、狀態、一組任意的鍵值對（叫 attributes，像 http.status_code=200），還有最重要的——它的父 span 是誰。

trace：一筆請求產生的所有 span 合起來，因為有父子關係，會形成一棵樹。

trace_id：整棵樹共用的編號。Day 14 講欄位的時候預留的那個 trace_id，就是它。

畫成圖大概像這樣，橫軸是時間。這是故障二打開、一個 12 件的購物車會長的樣子：

gateway  POST /checkout  ████████████████████████████████  0.92s
  catalog  POST /items    ██████████████████████████████    0.88s
    pricing  GET /price     ███                            0.06s
    pricing  GET /price        ███                         0.06s
    pricing  GET /price           ███                      0.06s
    ...（共 12 次，一次接一次）

一眼就看得出時間花在哪：catalog 對 pricing 打了 12 次，每次 60 毫秒，而且是一次接一次串著打。這種圖叫火焰圖或瀑布圖，是 trace 的標準呈現方式。

我第一次看到這種圖的感覺是：這跟 debugger 的呼叫堆疊很像，但它不用暫停程式，而且跨了三個程序。debugger 是你在一台機器上停下來往裡看；trace 是系統自己把每一段記下來，你事後跨機器往回看。

關鍵機制：上下文傳遞

這是我覺得 trace 最需要理解的一件事。

gateway 產生了 trace_id，但 catalog 是另一支程式、另一個 Pod，它怎麼知道自己屬於哪個 trace？

靠 HTTP header 傳過去。gateway 呼叫 catalog 的時候，在請求裡多塞一個標頭：

traceparent: 00-4bf92f3577b34da6a3ce929d0e0e4736-00f067aa0ba902b7-01
             │  └──────── trace_id ────────┘ └─ 父 span id ─┘ └ 旗標
             └ 版本

catalog 收到後解析它，知道「我是這個 trace 的一部分，我的父親是那個 span」，然後它呼叫 pricing 時再往下傳。這個格式叫 W3C Trace Context，是正式標準，所以不同語言、不同廠商的系統可以互相接得起來。

上下文傳遞斷了，trace 就斷了。 只要有一段程式沒把 header 傳下去，那條 trace 就在那裡斷成兩截，前半段不知道後半段的存在。而且不會有任何錯誤訊息——你只會在畫面上看到一條莫名其妙很短的 trace，以為那個服務真的很快。這是後面埋 trace 的時候最常踩的坑。

抽樣：不可能全都記

trace 的資料量很大。每筆請求跨三個服務、每個服務兩三個 span，就是七八筆記錄，每筆都帶著屬性。故障二那種一筆請求 14 個 span 的更不用說。

正式環境會抽樣（sampling），只留一部分。兩種做法：

我在本機全部都記，因為量小。但要知道這件事：正式環境找不到某筆請求的 trace，很可能只是它沒被抽中。

Tail-based 是很多團隊真正想要的——正常的丟掉，慢的和失敗的全留——但它需要一個中間層來做，明天會講到。

trace 不能取代另外兩根支柱

免得誤會，講一下它的限制。

trace 很貴，所以要抽樣，所以不能拿來算比例。 「錯誤率多少」要問 metrics，因為 metrics 是全量的。昨天算的那個六分之一，用 trace 算會因為抽樣而不準。

trace 只在請求路徑上。 背景排程、批次工作、定時任務不在裡面。故障三那個記憶體洩漏就不是 trace 能看的東西。

trace 要改程式碼。 這是它門檻最高的地方。metrics 和 logs 我到現在改的都是 common.py 那十幾行，trace 要碰到每一個對外呼叫。

所以三者的分工又更清楚一點：metrics 說有事，trace 說在哪一段，log 說那一段裡發生了什麼。

回到第二個故障

有了這個模型，第二個故障的偵辦路線已經很明確：

1. 從 P99 的圖上找一個慢的時間點
2. 找到那個時間點的一條慢 trace
3. 看它的火焰圖，找出哪一段佔了最多時間

第 1 步到第 2 步之間有一個缺口。P99 是聚合值，圖上那個點是幾百筆請求算出來的，它不記得自己是由哪些請求組成的——我怎麼從一張圖上的點，跳到「那一筆」的 trace？

這個缺口有解，等把 trace 埋進去之後再講。

小結

• log 就算整齊也拼不起來：順序是倒的、行與行之間沒有關聯欄位
• trace 只有三個概念：span、trace、trace_id；靠 HTTP header 傳遞，斷了不報錯
• metrics 說有事，trace 說在哪一段，log 說那一段發生了什麼

明天講 OpenTelemetry——這套標準為什麼存在，以及它的 Collector 在做什麼。