實(shí)踐)
1. 項(xiàng)目靈感與整體設(shè)計(jì)思路1.1 “hindsight”這個(gè)名字背后的含義hindsight 直譯過(guò)來(lái)是“后見之明”我第一眼看到這個(gè)標(biāo)題腦子里想到的是另外一個(gè)詞fore sight事前遠(yuǎn)見。這兩個(gè)詞放在一起正好構(gòu)成了一個(gè)完整的閉環(huán)——事前預(yù)判事后復(fù)盤。作為一個(gè)搞后端和穩(wěn)定性相關(guān)工作的人我經(jīng)常遇到一種很尷尬的處境系統(tǒng)半夜報(bào)警了服務(wù)重啟了等我睜開眼打開監(jiān)控面板一切指標(biāo)都恢復(fù)了看起來(lái)“什么都沒發(fā)生”。但用戶確實(shí)受到了影響故障確實(shí)存在問(wèn)題只是沒有被看見。這就是 hindsight 的價(jià)值我們無(wú)法永遠(yuǎn)事先預(yù)知所有問(wèn)題但我們可以保證在事情發(fā)生之后能像看回放一樣把當(dāng)時(shí)發(fā)生的每一個(gè)事件、每一次調(diào)用、每一行關(guān)鍵日志重新拉出來(lái)找到那個(gè)真正的原因。我決定把它做成一個(gè)真實(shí)的系統(tǒng)實(shí)踐項(xiàng)目目標(biāo)很明確搭建一套具備“事后全鏈路追溯”能力的分析體系讓任何一次線上事故都能被快速還原、定位、復(fù)盤。我當(dāng)時(shí)給自己定的方向不是做一個(gè)炫酷的監(jiān)控大屏而是做一套以日志和鏈路數(shù)據(jù)為核心的回溯系統(tǒng)。它能解決三個(gè)核心問(wèn)題數(shù)據(jù)要全、關(guān)聯(lián)要準(zhǔn)、回溯要快。第二個(gè)和第三個(gè)問(wèn)題往往被忽略很多人覺得有日志就夠了可真到了排查的時(shí)候日志格式亂七八糟trace id 斷在服務(wù)邊界時(shí)間戳對(duì)不上完全沒法串起來(lái)。所以這整套設(shè)計(jì)必須從數(shù)據(jù)源頭開始抓。1.2 系統(tǒng)設(shè)計(jì)目標(biāo)與方案選型項(xiàng)目立項(xiàng)的時(shí)候我先把目標(biāo)拆成了四個(gè)硬性要求采集范圍覆蓋所有核心服務(wù)的日志、調(diào)用鏈和關(guān)鍵事件不能有黑洞數(shù)據(jù)之間必須能按 trace_id、時(shí)間戳、服務(wù)維度快速關(guān)聯(lián)不靠人工拼從發(fā)現(xiàn)異常到定位根因整個(gè)回溯過(guò)程可以交互式完成不是寫一堆腳本慢慢擼復(fù)盤結(jié)果要能自動(dòng)導(dǎo)出成報(bào)告省去每次手動(dòng)整理的時(shí)間。帶著這四個(gè)要求我對(duì)技術(shù)選型做了好幾輪對(duì)比。存儲(chǔ)層我最終選了 ClickHouse而不是繼續(xù)用 Elasticsearch。不是說(shuō) ES 不好而是這套系統(tǒng)的核心查詢場(chǎng)景和 ES 的主場(chǎng)不一樣。我的查詢模式非常固定按 trace_id 查全部 span按時(shí)間范圍和服務(wù)名做多維聚合算 P99 耗時(shí)、錯(cuò)誤率。這種高基數(shù)、大規(guī)模、偏分析型的查詢ClickHouse 的列式存儲(chǔ)和向量化執(zhí)行優(yōu)勢(shì)非常明顯。我實(shí)測(cè)下來(lái)同樣數(shù)據(jù)量下一個(gè)帶條件的 trace 查詢?cè)?ClickHouse 里比 ES 快上一個(gè)數(shù)量級(jí)。采集和傳輸層用了 Kafka。原因很簡(jiǎn)單削峰填谷。線上流量不可能平穩(wěn)白天高峰時(shí)日志產(chǎn)生的速度可能是低峰的十倍如果讓采集服務(wù)直接寫入 ClickHouse連接池和寫入并發(fā)很容易被打爆。Kafka 放在中間做緩沖生產(chǎn)端只管往里扔消費(fèi)端按照自己的節(jié)奏批量寫入穩(wěn)定得很。鏈路追蹤的嵌入用的是 OpenTelemetry 的標(biāo)準(zhǔn)協(xié)議好處是語(yǔ)言無(wú)關(guān)不管是 Java 服務(wù)還是 Go、Python 服務(wù)都能用同一套規(guī)范把 trace 數(shù)據(jù)打出來(lái)。整個(gè)架構(gòu)是這么串起來(lái)的應(yīng)用服務(wù)通過(guò) SDK 采集日志和 span發(fā)送到 KafkaClickHouse 消費(fèi) Kafka 數(shù)據(jù)并及時(shí)落庫(kù)查詢層通過(guò) HTTP 接口對(duì) ClickHouse 做檢索最后用自定義 Web 面板和 Grafana 做可視化展示。聽起來(lái)不復(fù)雜但里面值得摳的細(xì)節(jié)非常多后面我一個(gè)個(gè)講。2. 核心模塊拆解與實(shí)現(xiàn)要點(diǎn)2.1 數(shù)據(jù)采集層讓“后見之明”有據(jù)可依我在這個(gè)項(xiàng)目里最深的體會(huì)是沒有干凈的數(shù)據(jù)后面所有分析都是空中樓閣。采集層是整個(gè)系統(tǒng)的地基這里偷懶后面排查問(wèn)題的時(shí)候會(huì)加倍還債。采集層要解決的第一件事是統(tǒng)一格式。原來(lái)很多服務(wù)的日志是自由輸出的有人在日志里打[INFO] xxx有人用log_format %(message)s還有人直接把異常堆棧和管理員備注混在一起。統(tǒng)一格式后所有的日志行必須是 JSON至少包含以下幾個(gè)字段service、timestamp、level、trace_id、span_id、message、duration_ms、host、env。這樣做的好處是到了 ClickHouse 里可以直接按字段檢索不需要在查詢時(shí)做字符串解析。我在某個(gè)服務(wù)的改造里光是讓所有開發(fā)統(tǒng)一字段名就花了兩個(gè)迭代但效果立竿見影——后續(xù)查詢沒有任何一個(gè)地方需要靠正則去刨日志。統(tǒng)一時(shí)間戳是第二個(gè)關(guān)鍵點(diǎn)。日志要記錄的時(shí)間是事件發(fā)生的時(shí)間不是采集器收到的時(shí)間。如果時(shí)間戳混用鏈路回放的時(shí)候整個(gè)時(shí)間線就會(huì)錯(cuò)亂。我要求所有服務(wù)統(tǒng)一用 UTC 時(shí)間精確到毫秒并且把時(shí)區(qū)信息干脆徹底拿掉只存 UTC。為什么非要這樣因?yàn)榭绶?wù)調(diào)用時(shí)A 服務(wù)在北京B 服務(wù)在美西如果不轉(zhuǎn)成 UTC同一個(gè) trace 里的時(shí)間戳一會(huì)兒東八區(qū)一會(huì)兒西七區(qū)回放時(shí)間線會(huì)差出十幾個(gè)小時(shí)。第三件事是鏈路上下文穿透。采集層必須把 trace_id 和 span_id 從入口一路傳遞到下游在 HTTP 場(chǎng)景里就是通過(guò) header 透?jìng)髟谙㈥?duì)列場(chǎng)景里就是塞進(jìn)消息頭。沒有這個(gè)穿透日志之間就是孤立的根本沒法做關(guān)聯(lián)回放。下面是一段我用 Python 實(shí)現(xiàn)的采集器示例核心邏輯是承接 OpenTelemetry 的 span 上下文把 trace_id 注入到日志字段中然后批量發(fā)送到 Kafka。這段代碼看起來(lái)簡(jiǎn)單但它是整個(gè)體系能跑起來(lái)的基礎(chǔ)。import json import logging import time from opentelemetry import trace from kafka import KafkaProducer logger logging.getLogger(hindsight-collector) producer KafkaProducer( bootstrap_serverskafka:9092, value_serializerlambda v: json.dumps(v).encode(utf-8), ) def emit_event(event_type: str, message: str, duration_ms: float 0): span trace.get_current_span() trace_id format(span.get_span_context().trace_id, 032x) if span else span_id format(span.get_span_context().span_id, 016x) if span else record { service: order-service, timestamp: int(time.time() * 1000), level: INFO, trace_id: trace_id, span_id: span_id, event_type: event_type, message: message, duration_ms: duration_ms, host: host-01, env: prod, } producer.send(app-logs, valuerecord) logger.debug(enqueue record with trace_id%s, trace_id) # 使用示例 def create_order(user_id: str): start time.time() try: # 業(yè)務(wù)邏輯... pass finally: emit_event(create_order, fuser_id{user_id}, (time.time() - start) * 1000)注意這段代碼里的trace.get_current_span()它是從當(dāng)前線程的 OpenTelemetry Context 中拿上下文所以調(diào)用鏈里的 span 必須被正確設(shè)定。如果業(yè)務(wù)代碼里手動(dòng)開了新線程但沒有做 context 傳遞這里拿到的 trace_id 就是空字符串整個(gè)鏈路就斷了。我當(dāng)時(shí)在線程池場(chǎng)景里踩過(guò)這個(gè)坑回頭在排查模塊里細(xì)說(shuō)。2.2 事件關(guān)聯(lián)與鏈路回放采集上來(lái)的數(shù)據(jù)就像一張張小卡片混沌地散落在地板上。Rediscovery 的含義就是把這些卡片按線索串回電影膠片。鏈路回放是這個(gè)系統(tǒng)最核心的能力串起這段膠片的就是 trace_id 和 span_id。我特別喜歡用“電影膠片”來(lái)類比這套機(jī)制。一個(gè)完整的請(qǐng)求鏈路就是一部電影電影里每一個(gè)畫面就是一幀在這一幀里記錄了某個(gè)服務(wù)處理某段邏輯的信息。trace_id是這部片子的唯一編號(hào)說(shuō)明這些畫面出自同一個(gè)故事span_id是每一幀的序列號(hào)標(biāo)定它在時(shí)間上的位置parent_span_id則像是剪輯時(shí)的前后續(xù)接關(guān)系說(shuō)明這一幀是從哪一個(gè)畫面上延續(xù)下來(lái)的。把這些幀按時(shí)間順序排列起來(lái)把前后的邏輯引用關(guān)系用樹形結(jié)構(gòu)畫出來(lái)我們就得到了一個(gè)瀑布圖——也就是一條請(qǐng)求從入口到各個(gè)依賴服務(wù)之間完整的調(diào)用軌跡。要保證這種關(guān)聯(lián)成立必須在調(diào)用下游服務(wù)時(shí)把上下文信息傳過(guò)去。HTTP 一般用 header自定義的 RPC 協(xié)議則通過(guò)協(xié)議字段攜帶。我給大家一個(gè)標(biāo)準(zhǔn)的 header 傳播表做參考Header 字段說(shuō)明示例值traceparentW3C 標(biāo)準(zhǔn) trace 上下文格式為版本號(hào)-traceid-spanid-標(biāo)記00-863b464a71a4418ba1c712f10f7f9c21-0f3f2d8e9a1c4b56-01tracestate供應(yīng)商擴(kuò)展字段攜帶額外的業(yè)務(wù)標(biāo)簽vendorhigh_risk_orderx-request-id用于接入層網(wǎng)關(guān)記錄入口 ID與 traceparent 映射req-1087-afde92當(dāng)時(shí)我們有個(gè)支付回調(diào)服務(wù)對(duì)接的是第三方渠道第三方只認(rèn)自己生成的 request_id。我就在接入層做了一個(gè)映射表渠道的 request_id 對(duì)應(yīng)內(nèi)部生成的 trace_id。排查渠道回調(diào)問(wèn)題時(shí)拿著渠道給我們的單號(hào)就能反查出內(nèi)部完整調(diào)用鏈這個(gè)映射設(shè)計(jì)對(duì)事后的第三方問(wèn)題溯源幫助極大。鏈路回放的實(shí)現(xiàn)本質(zhì)上是按照 trace_id 把所有相關(guān) span 和日志拉出來(lái)然后按時(shí)間排列、按層級(jí)縮進(jìn)展示。這里有一個(gè)關(guān)鍵設(shè)計(jì)日志內(nèi)容必須依附于某個(gè) span而不是單獨(dú)游離在 trace 之外。否則日志就算有 trace_id也很難準(zhǔn)確地放到瀑布圖中某個(gè)節(jié)點(diǎn)旁邊。我的做法是日志記錄時(shí)引用當(dāng)前 span_id落庫(kù)后通過(guò)(trace_id, span_id)把日志關(guān)聯(lián)到具體節(jié)點(diǎn)。2.3 查詢與分析層從追查到還原數(shù)據(jù)進(jìn)來(lái)之后查詢層負(fù)責(zé)把“追查”變成“還原”。這層直接決定了系統(tǒng)好不好用。我見過(guò)很多數(shù)據(jù)平臺(tái)數(shù)據(jù)可能全有但查詢接口難用得一塌糊涂每次想撈一條鏈路得像寫畢業(yè)論文一樣拼 SQL這肯定不行。ClickHouse 表結(jié)構(gòu)設(shè)計(jì)我反復(fù)調(diào)了幾版。最終的核心表 schema 如下CREATE TABLE app_trace_events ( service String, timestamp DateTime64(3, UTC), trace_id String, span_id String, parent_span_id String, operation String, duration_ms UInt64, status_code UInt16, error_msg String, host String, env String, tags Map(String, String), INDEX idx_trace_id trace_id TYPE bloom_filter GRANULARITY 1 ) ENGINE MergeTree PARTITION BY toYYYYMMDD(timestamp) ORDER BY (timestamp, trace_id, span_id) TTL timestamp INTERVAL 90 DAY;PARTITION BY toYYYYMMDD(timestamp)讓每一天的數(shù)據(jù)落在一個(gè)分區(qū)查詢時(shí)如果帶上時(shí)間范圍條件可以快速跳過(guò)不是目標(biāo)日期的分區(qū)。ORDER BY (timestamp, trace_id, span_id)是整個(gè)查詢效率的關(guān)鍵——按 trace_id 查詢時(shí)ClickHouse 可以在稀疏索引中定位到對(duì)應(yīng)數(shù)據(jù)塊而不是全表掃描。我還對(duì) trace_id 建了 bloom filter 索引遇到高頻 trace 檢索時(shí)效率還能再上一個(gè)臺(tái)階。建表時(shí)我特意加了TTL timestamp INTERVAL 90 DAY線上日志保存三個(gè)月超過(guò)之后自動(dòng)清理。這個(gè)設(shè)計(jì)很有價(jià)值有次和另一個(gè)團(tuán)隊(duì)協(xié)作他們說(shuō)要“長(zhǎng)期保存”我提醒他們即使 ClickHouse 壓縮比很高但 90 天的數(shù)據(jù)量也足夠讓 TTL 機(jī)制發(fā)揮價(jià)值否則磁盤滿了以后所有人的查詢都會(huì)變慢。查詢層我封裝了三個(gè)核心接口。第一個(gè)是按 trace_id 拉全鏈路這是排障的入口。拿到一個(gè) trace_id通過(guò)下面的 SQL 把整條鏈路的所有 span 都取出來(lái)按時(shí)間排序再根據(jù) parent_span_id 構(gòu)造樹形結(jié)構(gòu)返回給前端SELECT service, timestamp, span_id, parent_span_id, operation, duration_ms, status_code, error_msg FROM app_trace_events WHERE trace_id {trace_id:String} ORDER BY timestamp ASC;第二個(gè)是服務(wù)維度聚合用來(lái)快速看某個(gè)服務(wù)在某個(gè)時(shí)間窗的負(fù)載和錯(cuò)誤率配合 Grafana 做熱力圖和趨勢(shì)線。第三個(gè)是慢調(diào)用分析通過(guò)duration_ms分位數(shù)函數(shù)算 P50、P95、P99判斷哪些接口需要優(yōu)化。我實(shí)際排查過(guò)一個(gè)訂單超時(shí)問(wèn)題通過(guò)慢調(diào)用分析發(fā)現(xiàn) P99 集中在某個(gè)下游服務(wù)一查是該服務(wù)連接池配置太小鏈路圖把整個(gè)過(guò)程暴露得清清楚楚。3. 實(shí)操落地從零搭建一套hindsight分析流程3.1 環(huán)境搭建與關(guān)鍵配置這一節(jié)說(shuō)說(shuō)從零開始怎么把整套系統(tǒng)跑起來(lái)。我在本地開發(fā)時(shí)用的是 Docker Compose把 ClickHouse、Kafka、Kafka UI、Grafana 全部編排起來(lái)。下面是我用的服務(wù)編排文件關(guān)鍵內(nèi)容version: 3.8 services: clickhouse: image: clickhouse/clickhouse-server:23.8 container_name: hindsight-clickhouse ports: - 8123:8123 - 9000:9000 volumes: - ./clickhouse/data:/var/lib/clickhouse - ./clickhouse/init.sql:/docker-entrypoint-initdb.d/init.sql:ro ulimits: nofile: soft: 262144 hard: 262144 kafka: image: bitnami/kafka:3.6 container_name: hindsight-kafka ports: - 9092:9092 environment: KAFKA_CFG_NODE_ID: 0 KAFKA_CFG_PROCESS_ROLES: controller,broker KAFKA_CFG_CONTROLLER_QUORUM_VOTERS: 0kafka:9093 KAFKA_CFG_LISTENERS: PLAINTEXT://:9092,CONTROLLER://:9093 KAFKA_CFG_ADVERTISED_LISTENERS: PLAINTEXT://localhost:9092 KAFKA_CFG_AUTO_CREATE_TOPICS_ENABLE: true啟動(dòng)之后第一步不是立刻寫采集器而是先建表。我把上一節(jié)那一段建表 SQL 放到初始化目錄里ClickHouse 在第一次啟動(dòng)時(shí)就會(huì)自動(dòng)執(zhí)行省得手工敲。接著手動(dòng)創(chuàng)建 Kafka 的 topic。我用的命令是docker exec hindsight-kafka kafka-topics.sh \ --create \ --topic app-logs \ --partitions 6 \ --replication-factor 1 \ --bootstrap-server localhost:9092分片數(shù)設(shè)置了 6這個(gè)數(shù)字不是隨手定的。我的線上環(huán)境有三臺(tái)消費(fèi)節(jié)點(diǎn)每個(gè)節(jié)點(diǎn)開兩個(gè)線程消費(fèi)6 個(gè)分區(qū)剛好能讓每個(gè)線程處理一個(gè)分區(qū)的消息既不浪費(fèi)也不爭(zhēng)搶。有個(gè)項(xiàng)目把分區(qū)數(shù)設(shè)成 12但消費(fèi)端只有兩個(gè)實(shí)例導(dǎo)致大部分消費(fèi)者線程空閑浪費(fèi)了 Kafka 的順序讀能力。Grafana 我是在最后才接入的。先單獨(dú)驗(yàn)證 ClickHouse 里的數(shù)據(jù)是否正確再配置數(shù)據(jù)源最后畫面板這樣可以避免“系統(tǒng)跑起來(lái)了但數(shù)據(jù)是臟的”這種問(wèn)題。3.2 核心采集與回放代碼示例整套系統(tǒng)落地中的核心代碼包含采集器、寫入 ClickHouse 的消費(fèi)腳本以及回放查詢的 API。采集器端大家可以直接沿用 2.1 節(jié)那段 Python 代碼。需要注意生產(chǎn)環(huán)境采集器通常不會(huì)和業(yè)務(wù)代碼耦合在同一個(gè)進(jìn)程里而是通過(guò) filebeat / otel collector 這種獨(dú)立進(jìn)程做無(wú)侵入采集。我推薦先用 otel-collector 來(lái)做統(tǒng)一接入因?yàn)樗?kafka exporter 和 debug exporter 可以很方便地幫你看數(shù)據(jù)到底有沒有發(fā)出去。我在啟動(dòng) collector 之后經(jīng)常會(huì)跑一條測(cè)試請(qǐng)求然后立刻去 Kafka UI 里確認(rèn) topic 消息數(shù)有沒有增加。如果沒增加先排查 collector 的 exporter 配置再排查業(yè)務(wù) SDK 的 endpoint。這一步花費(fèi)時(shí)間最少卻是很多新手最頭疼的環(huán)節(jié)。消費(fèi)端我寫了一個(gè) Go 程序從 Kafka 拉取消息批量寫入 ClickHouse。核心邏輯是并發(fā)消費(fèi) 每 2000 條或每 5 秒批量 flush 一次避免小批量寫入造成 ClickHouse 大量 merge:package main import ( context database/sql fmt time github.com/ClickHouse/clickhouse-go/v2 github.com/segmentio/kafka-go ) func main() { clickhouseDSN : clickhouse://user:passclickhouse:9000/observability db, _ : sql.Open(clickhouse, clickhouseDSN) reader : kafka.NewReader(kafka.ReaderConfig{ Brokers: []string{kafka:9092}, Topic: app-logs, GroupID: clickhouse-writer, MinBytes: 1e6, MaxBytes: 10e6, MaxWait: 500 * time.Millisecond, }) var batch []LogRecord for { msg, err : reader.ReadMessage(context.Background()) if err ! nil { continue } batch append(batch, LogRecordFromJSON(msg.Value)) if len(batch) 2000 { flushToClickHouse(db, batch) batch batch[:0] } } } func flushToClickHouse(db *sql.DB, batch []LogRecord) { tx, _ : db.Begin() stmt, _ : tx.Prepare( INSERT INTO app_trace_events (service, timestamp, trace_id, span_id, parent_span_id, operation, duration_ms, status_code, error_msg, host, env, tags) VALUES (?,?,?,?,?,?,?,?,?,?,?,?) ) for _, r : range batch { _, _ stmt.Exec(r.Service, r.Timestamp, r.TraceID, r.SpanID, r.ParentSpanID, r.Operation, r.DurationMS, r.StatusCode, r.ErrorMsg, r.Host, r.Env, r.Tags) } _ tx.Commit() }這段代碼的巧妙之處在于MinBytes、MaxBytes和MaxWait三個(gè)參數(shù)。MaxWait: 500ms表示即使消息沒攢夠 2000 條最多等 500 毫秒也要 flush 一次。這樣既保證了吞吐又避免消息在緩沖區(qū)里停留太久才入庫(kù)影響故障排查時(shí)的實(shí)時(shí)性。我實(shí)測(cè)下來(lái)消費(fèi)端每秒能處理幾萬(wàn)條簡(jiǎn)單日志對(duì)絕大多數(shù)中小規(guī)模業(yè)務(wù)來(lái)說(shuō)綽綽有余。3.3 數(shù)據(jù)可視化與報(bào)告輸出數(shù)據(jù)進(jìn)了 ClickHouse回放查詢也通了之后整套系統(tǒng)的最后一步是可視化與報(bào)告輸出。可視化我用 Grafana 做了幾個(gè)核心面板。第一個(gè)是全局流量大盤每秒請(qǐng)求數(shù)、錯(cuò)誤率、P50/P95/P99 耗時(shí)曲線。這個(gè)面板放在最頂端用于發(fā)現(xiàn)“有沒有問(wèn)題”。第二個(gè)是服務(wù)依賴拓?fù)渫ㄟ^(guò) span 里的 parent 關(guān)系用 NodeGraph 插件畫出服務(wù)之間的調(diào)用關(guān)系每個(gè)節(jié)點(diǎn)顯示平均耗時(shí)和錯(cuò)誤率。這個(gè)面板非常直觀有一次我一下就看到新上線的推薦服務(wù)把核心訂單服務(wù)的 QPS 拉高了 30%拓?fù)鋱D上那根線條紅得刺眼。第三個(gè)是 Trace 瀑布圖專門用于單個(gè) trace 的回放。我實(shí)現(xiàn)在 Web 面板上輸入 trace_id就能按時(shí)間軸渲染出完整的調(diào)用瀑布每個(gè) span 下面會(huì)附加對(duì)應(yīng)的日志條數(shù)點(diǎn)擊即可下鉆。報(bào)告輸出這一塊是我覺得最實(shí)用也最容易被忽視的功能。每一次線上事故排查完都需要提交一份復(fù)盤文檔。以前是手動(dòng)截圖加拼湊時(shí)間線效率極低。我在項(xiàng)目中預(yù)設(shè)了一套 Markdown 模板查詢層返回以下結(jié)構(gòu)化信息故障時(shí)間范圍、影響服務(wù)列表、根因 trace_id 鏈路、異常日志摘要、關(guān)鍵指標(biāo)前后對(duì)比、改進(jìn)建議。后端接口一次性把這些數(shù)據(jù)返回前端自動(dòng)填充到 Markdown 模板里一鍵導(dǎo)出成文件。最終生成的內(nèi)容可以直接作為復(fù)盤附件省去了大量寫文檔的時(shí)間。4. 常見問(wèn)題與排查技巧實(shí)錄4.1 日志量太大存儲(chǔ)扛不住這是一個(gè)必然會(huì)出現(xiàn)的問(wèn)題。系統(tǒng)剛上線的時(shí)候大家熱情高漲什么樣的日志都往里打一天能產(chǎn)生幾個(gè) TB 的數(shù)據(jù)。我一開始也天真地以為 ClickHouse 壓縮比高扛得住結(jié)果一周過(guò)去磁盤空間告急。解決思路根據(jù)日志的價(jià)值分了三層。第一層是采樣策略核心服務(wù)訂單、支付、登錄全量采集邊緣服務(wù)推薦、營(yíng)銷按 10% 的比例采樣采樣時(shí)按 trace_id 做到全鏈路一致否則會(huì)出現(xiàn)一半鏈路有日志一半沒有的尷尬。第二層是數(shù)據(jù)分層熱數(shù)據(jù)在 ClickHouse 保留 7 天用于日常排查冷數(shù)據(jù)通過(guò) TTL 移動(dòng)到對(duì)象存儲(chǔ)需要時(shí)按 trace_id 回?fù)?。第三層是字段裁剪業(yè)務(wù)日志里的冗余大字段如 request body 全文、響應(yīng)報(bào)文在采集端就做截?cái)喑^(guò) 512 字節(jié)的部分只保留長(zhǎng)度和 hash 值。這個(gè) hash 很有用對(duì)比兩次請(qǐng)求的參數(shù)是否一致時(shí)不需要完整報(bào)文對(duì)比 hash 就行。4.2 時(shí)間戳不同步導(dǎo)致鏈路錯(cuò)亂鏈路回放最怕時(shí)間戳錯(cuò)位?？鐓^(qū)域部署時(shí)如果各機(jī)房的機(jī)器沒有做統(tǒng)一時(shí)鐘同步A 服務(wù)記錄的事件時(shí)間早于 B 服務(wù)瀑布圖就會(huì)變成一團(tuán)亂麻。我在一個(gè)跨境電商項(xiàng)目上就吃過(guò)這個(gè)虧。機(jī)房在美國(guó)和新加坡兩邊服務(wù)器的系統(tǒng)時(shí)間差了幾百毫秒一個(gè) trace 的 span 排序錯(cuò)亂看起來(lái)像先響應(yīng)后請(qǐng)求。排查手段是先批量檢查日志中的時(shí)間戳單調(diào)性如果發(fā)現(xiàn)同一 trace 里 span 的時(shí)間出現(xiàn)回退就找到具體兩個(gè)服務(wù)所在的機(jī)器用下面的命令檢查時(shí)鐘偏移chronyc tracking | grep -E System time|Clock offset ntpdate -q time.google.com解決方式分兩步第一步所有機(jī)器配置 NTP 自動(dòng)同步這是基礎(chǔ)第二步也是最關(guān)鍵的采集端在發(fā)送日志時(shí)把“本地時(shí)間戳”和“采集端接收時(shí)間戳”并列記錄。這樣哪怕系統(tǒng)時(shí)鐘被業(yè)務(wù)進(jìn)程誤改我們依然可以通過(guò)接收時(shí)間戳反推真實(shí)事件順序。僅這一步就解決了 90% 的鏈路亂序問(wèn)題。4.3 定位到問(wèn)題但找不到根因有一種非常折磨人的排查場(chǎng)景鏈路很快定位到了某個(gè)服務(wù)但這個(gè)服務(wù)內(nèi)部的日志太稀無(wú)法進(jìn)一步定位到具體邏輯。比如一次請(qǐng)求的鏈路圖顯示評(píng)論服務(wù)耗時(shí) 5 秒但打開評(píng)論服務(wù)的日志只看到“開始處理”和“結(jié)束處理”兩條中間干了什么完全不知道。這時(shí)候就需要“回放式埋點(diǎn)”也就是在關(guān)鍵邏輯路徑上插入更有信息量的事件。我的經(jīng)驗(yàn)是凡是涉及外部調(diào)用的地方必須記錄 target、method、請(qǐng)求摘要、返回狀態(tài)和耗時(shí)凡是涉及數(shù)據(jù)庫(kù)讀寫的地方必須記錄表名、主鍵和影響行數(shù)凡是出現(xiàn) catch 分支必須把原始異常類型和消息完整打出來(lái)。還有一個(gè)很容易被忽略的坑線程池中的上下文丟失。業(yè)務(wù)里經(jīng)常用ExecutorService提交異步任務(wù)如果線程池沒有使用 OpenTelemetry 的上下文傳播包裝那么任務(wù)內(nèi)部拿到的 trace_id 就會(huì)為空日志“游離”了。我寫了一個(gè)簡(jiǎn)單的包裝類提交任務(wù)時(shí)顯式把當(dāng)前 TraceContext 快照傳到子線程里這個(gè)操作成本很低卻是異步場(chǎng)景鏈路完整的救命藥。4.4 從hindsight場(chǎng)景延伸到日常復(fù)盤做到這里hindsight 已經(jīng)不是一個(gè)單純的日志系統(tǒng)它變成了一種思維方式。我在迭代過(guò)程中慢慢體會(huì)到回溯能力不只在故障排查時(shí)有用。每次發(fā)布新版本之后我都會(huì)調(diào)出對(duì)應(yīng)版本的流量曲線和錯(cuò)誤率曲線對(duì)照回放當(dāng)時(shí)的發(fā)布窗口日志看看有沒有潛在的異常被隱藏。每個(gè)季度做性能優(yōu)化時(shí)我也會(huì)直接拉出 P99 耗時(shí)最高的幾個(gè)鏈路逐個(gè)展開瀑布圖找到真正拖慢系統(tǒng)的瓶頸——這些優(yōu)化工作以前靠估現(xiàn)在靠數(shù)據(jù)。有一次團(tuán)隊(duì)開復(fù)盤會(huì)聊一個(gè)功能上線后用戶投訴增多的問(wèn)題本來(lái)是業(yè)務(wù)邏輯的爭(zhēng)議結(jié)果我順手拉了該功能上線前后的 trace 對(duì)比發(fā)現(xiàn)有一個(gè)新的下游服務(wù)調(diào)用在特定參數(shù)下會(huì)返回大量超時(shí)錯(cuò)誤是調(diào)用方?jīng)]有做好重試和降級(jí)導(dǎo)致的。如果沒有“回放”能力這一輪爭(zhēng)論可能又要僵持很久?？傊甴indsight 就是給這個(gè)流程配了一臺(tái)“事件回放儀”讓所有決策都建立在對(duì)真實(shí)發(fā)生的每一幀數(shù)據(jù)的理解之上。結(jié)尾一些落地后的真實(shí)體會(huì)如果讓我用一個(gè)詞總結(jié)這套系統(tǒng)對(duì)我團(tuán)隊(duì)的影響我會(huì)選“確定性”。以前排查線上問(wèn)題很多時(shí)候靠猜、靠回憶、靠某個(gè)老員工拍胸脯現(xiàn)在不用了——任何一次事故只要能拿到一個(gè) trace_id就能在幾分鐘內(nèi)把現(xiàn)場(chǎng)完整還原出來(lái)根因分析從玄學(xué)變成了流水線作業(yè)。最后分享兩個(gè)我踩過(guò)的最深的坑。第一個(gè)是不要過(guò)早優(yōu)化采樣策略。項(xiàng)目剛上線時(shí)我為了省存儲(chǔ)設(shè)置了一套復(fù)雜的動(dòng)態(tài)采樣規(guī)則結(jié)果后來(lái)排查問(wèn)題時(shí)發(fā)現(xiàn)該采的日志沒采到。后來(lái)我把規(guī)則簡(jiǎn)化為無(wú)腦全量運(yùn)行一周后看數(shù)據(jù)量再調(diào)整反而更穩(wěn)。第二點(diǎn)是要重視數(shù)據(jù)質(zhì)量測(cè)試。每次采集 SDK 升級(jí)或者新增日志格式我都會(huì)往測(cè)試環(huán)境跑一批模擬流量專門驗(yàn)證 trace_id 是否連貫、時(shí)間戳格式是否符合預(yù)期、字段映射是否正確。這套校驗(yàn)機(jī)制看著不起眼實(shí)打?qū)嵄苊膺^(guò)好幾次線上數(shù)據(jù)的靜默損壞。hindsight 這個(gè)名字我一直很喜歡人很難做到事事預(yù)見但至少可以在事情過(guò)后誠(chéng)實(shí)、完整、高效地把它重新看清楚。希望這篇文章能給正在建設(shè)可觀測(cè)性體系的你一些思路。 基于ClickHouse與Kafka的分布式鏈路日志回溯系統(tǒng)實(shí)踐
1. 項(xiàng)目靈感與整體設(shè)計(jì)思路1.1 “hindsight”這個(gè)名字背后的含義hindsight 直譯過(guò)來(lái)是“后見之明”我第一眼看到這個(gè)標(biāo)題腦子里想到的是另外一個(gè)詞fore sight事前遠(yuǎn)見。這兩個(gè)詞放在一起正好構(gòu)成了一個(gè)完整的閉環(huán)——事前預(yù)判事后復(fù)盤。作為一個(gè)搞后端和穩(wěn)定性相關(guān)工作的人我經(jīng)常遇到一種很尷尬的處境系統(tǒng)半夜報(bào)警了服務(wù)重啟了等我睜開眼打開監(jiān)控面板一切指標(biāo)都恢復(fù)了看起來(lái)“什么都沒發(fā)生”。但用戶確實(shí)受到了影響故障確實(shí)存在問(wèn)題只是沒有被看見。這就是 hindsight 的價(jià)值我們無(wú)法永遠(yuǎn)事先預(yù)知所有問(wèn)題但我們可以保證在事情發(fā)生之后能像看回放一樣把當(dāng)時(shí)發(fā)生的每一個(gè)事件、每一次調(diào)用、每一行關(guān)鍵日志重新拉出來(lái)找到那個(gè)真正的原因。我決定把它做成一個(gè)真實(shí)的系統(tǒng)實(shí)踐項(xiàng)目目標(biāo)很明確搭建一套具備“事后全鏈路追溯”能力的分析體系讓任何一次線上事故都能被快速還原、定位、復(fù)盤。我當(dāng)時(shí)給自己定的方向不是做一個(gè)炫酷的監(jiān)控大屏而是做一套以日志和鏈路數(shù)據(jù)為核心的回溯系統(tǒng)。它能解決三個(gè)核心問(wèn)題數(shù)據(jù)要全、關(guān)聯(lián)要準(zhǔn)、回溯要快。第二個(gè)和第三個(gè)問(wèn)題往往被忽略很多人覺得有日志就夠了可真到了排查的時(shí)候日志格式亂七八糟trace id 斷在服務(wù)邊界時(shí)間戳對(duì)不上完全沒法串起來(lái)。所以這整套設(shè)計(jì)必須從數(shù)據(jù)源頭開始抓。1.2 系統(tǒng)設(shè)計(jì)目標(biāo)與方案選型項(xiàng)目立項(xiàng)的時(shí)候我先把目標(biāo)拆成了四個(gè)硬性要求采集范圍覆蓋所有核心服務(wù)的日志、調(diào)用鏈和關(guān)鍵事件不能有黑洞數(shù)據(jù)之間必須能按 trace_id、時(shí)間戳、服務(wù)維度快速關(guān)聯(lián)不靠人工拼從發(fā)現(xiàn)異常到定位根因整個(gè)回溯過(guò)程可以交互式完成不是寫一堆腳本慢慢擼復(fù)盤結(jié)果要能自動(dòng)導(dǎo)出成報(bào)告省去每次手動(dòng)整理的時(shí)間。帶著這四個(gè)要求我對(duì)技術(shù)選型做了好幾輪對(duì)比。存儲(chǔ)層我最終選了 ClickHouse而不是繼續(xù)用 Elasticsearch。不是說(shuō) ES 不好而是這套系統(tǒng)的核心查詢場(chǎng)景和 ES 的主場(chǎng)不一樣。我的查詢模式非常固定按 trace_id 查全部 span按時(shí)間范圍和服務(wù)名做多維聚合算 P99 耗時(shí)、錯(cuò)誤率。這種高基數(shù)、大規(guī)模、偏分析型的查詢ClickHouse 的列式存儲(chǔ)和向量化執(zhí)行優(yōu)勢(shì)非常明顯。我實(shí)測(cè)下來(lái)同樣數(shù)據(jù)量下一個(gè)帶條件的 trace 查詢?cè)?ClickHouse 里比 ES 快上一個(gè)數(shù)量級(jí)。采集和傳輸層用了 Kafka。原因很簡(jiǎn)單削峰填谷。線上流量不可能平穩(wěn)白天高峰時(shí)日志產(chǎn)生的速度可能是低峰的十倍如果讓采集服務(wù)直接寫入 ClickHouse連接池和寫入并發(fā)很容易被打爆。Kafka 放在中間做緩沖生產(chǎn)端只管往里扔消費(fèi)端按照自己的節(jié)奏批量寫入穩(wěn)定得很。鏈路追蹤的嵌入用的是 OpenTelemetry 的標(biāo)準(zhǔn)協(xié)議好處是語(yǔ)言無(wú)關(guān)不管是 Java 服務(wù)還是 Go、Python 服務(wù)都能用同一套規(guī)范把 trace 數(shù)據(jù)打出來(lái)。整個(gè)架構(gòu)是這么串起來(lái)的應(yīng)用服務(wù)通過(guò) SDK 采集日志和 span發(fā)送到 KafkaClickHouse 消費(fèi) Kafka 數(shù)據(jù)并及時(shí)落庫(kù)查詢層通過(guò) HTTP 接口對(duì) ClickHouse 做檢索最后用自定義 Web 面板和 Grafana 做可視化展示。聽起來(lái)不復(fù)雜但里面值得摳的細(xì)節(jié)非常多后面我一個(gè)個(gè)講。2. 核心模塊拆解與實(shí)現(xiàn)要點(diǎn)2.1 數(shù)據(jù)采集層讓“后見之明”有據(jù)可依我在這個(gè)項(xiàng)目里最深的體會(huì)是沒有干凈的數(shù)據(jù)后面所有分析都是空中樓閣。采集層是整個(gè)系統(tǒng)的地基這里偷懶后面排查問(wèn)題的時(shí)候會(huì)加倍還債。采集層要解決的第一件事是統(tǒng)一格式。原來(lái)很多服務(wù)的日志是自由輸出的有人在日志里打[INFO] xxx有人用log_format %(message)s還有人直接把異常堆棧和管理員備注混在一起。統(tǒng)一格式后所有的日志行必須是 JSON至少包含以下幾個(gè)字段service、timestamp、level、trace_id、span_id、message、duration_ms、host、env。這樣做的好處是到了 ClickHouse 里可以直接按字段檢索不需要在查詢時(shí)做字符串解析。我在某個(gè)服務(wù)的改造里光是讓所有開發(fā)統(tǒng)一字段名就花了兩個(gè)迭代但效果立竿見影——后續(xù)查詢沒有任何一個(gè)地方需要靠正則去刨日志。統(tǒng)一時(shí)間戳是第二個(gè)關(guān)鍵點(diǎn)。日志要記錄的時(shí)間是事件發(fā)生的時(shí)間不是采集器收到的時(shí)間。如果時(shí)間戳混用鏈路回放的時(shí)候整個(gè)時(shí)間線就會(huì)錯(cuò)亂。我要求所有服務(wù)統(tǒng)一用 UTC 時(shí)間精確到毫秒并且把時(shí)區(qū)信息干脆徹底拿掉只存 UTC。為什么非要這樣因?yàn)榭绶?wù)調(diào)用時(shí)A 服務(wù)在北京B 服務(wù)在美西如果不轉(zhuǎn)成 UTC同一個(gè) trace 里的時(shí)間戳一會(huì)兒東八區(qū)一會(huì)兒西七區(qū)回放時(shí)間線會(huì)差出十幾個(gè)小時(shí)。第三件事是鏈路上下文穿透。采集層必須把 trace_id 和 span_id 從入口一路傳遞到下游在 HTTP 場(chǎng)景里就是通過(guò) header 透?jìng)髟谙㈥?duì)列場(chǎng)景里就是塞進(jìn)消息頭。沒有這個(gè)穿透日志之間就是孤立的根本沒法做關(guān)聯(lián)回放。下面是一段我用 Python 實(shí)現(xiàn)的采集器示例核心邏輯是承接 OpenTelemetry 的 span 上下文把 trace_id 注入到日志字段中然后批量發(fā)送到 Kafka。這段代碼看起來(lái)簡(jiǎn)單但它是整個(gè)體系能跑起來(lái)的基礎(chǔ)。import json import logging import time from opentelemetry import trace from kafka import KafkaProducer logger logging.getLogger(hindsight-collector) producer KafkaProducer( bootstrap_serverskafka:9092, value_serializerlambda v: json.dumps(v).encode(utf-8), ) def emit_event(event_type: str, message: str, duration_ms: float 0): span trace.get_current_span() trace_id format(span.get_span_context().trace_id, 032x) if span else span_id format(span.get_span_context().span_id, 016x) if span else record { service: order-service, timestamp: int(time.time() * 1000), level: INFO, trace_id: trace_id, span_id: span_id, event_type: event_type, message: message, duration_ms: duration_ms, host: host-01, env: prod, } producer.send(app-logs, valuerecord) logger.debug(enqueue record with trace_id%s, trace_id) # 使用示例 def create_order(user_id: str): start time.time() try: # 業(yè)務(wù)邏輯... pass finally: emit_event(create_order, fuser_id{user_id}, (time.time() - start) * 1000)注意這段代碼里的trace.get_current_span()它是從當(dāng)前線程的 OpenTelemetry Context 中拿上下文所以調(diào)用鏈里的 span 必須被正確設(shè)定。如果業(yè)務(wù)代碼里手動(dòng)開了新線程但沒有做 context 傳遞這里拿到的 trace_id 就是空字符串整個(gè)鏈路就斷了。我當(dāng)時(shí)在線程池場(chǎng)景里踩過(guò)這個(gè)坑回頭在排查模塊里細(xì)說(shuō)。2.2 事件關(guān)聯(lián)與鏈路回放采集上來(lái)的數(shù)據(jù)就像一張張小卡片混沌地散落在地板上。Rediscovery 的含義就是把這些卡片按線索串回電影膠片。鏈路回放是這個(gè)系統(tǒng)最核心的能力串起這段膠片的就是 trace_id 和 span_id。我特別喜歡用“電影膠片”來(lái)類比這套機(jī)制。一個(gè)完整的請(qǐng)求鏈路就是一部電影電影里每一個(gè)畫面就是一幀在這一幀里記錄了某個(gè)服務(wù)處理某段邏輯的信息。trace_id是這部片子的唯一編號(hào)說(shuō)明這些畫面出自同一個(gè)故事span_id是每一幀的序列號(hào)標(biāo)定它在時(shí)間上的位置parent_span_id則像是剪輯時(shí)的前后續(xù)接關(guān)系說(shuō)明這一幀是從哪一個(gè)畫面上延續(xù)下來(lái)的。把這些幀按時(shí)間順序排列起來(lái)把前后的邏輯引用關(guān)系用樹形結(jié)構(gòu)畫出來(lái)我們就得到了一個(gè)瀑布圖——也就是一條請(qǐng)求從入口到各個(gè)依賴服務(wù)之間完整的調(diào)用軌跡。要保證這種關(guān)聯(lián)成立必須在調(diào)用下游服務(wù)時(shí)把上下文信息傳過(guò)去。HTTP 一般用 header自定義的 RPC 協(xié)議則通過(guò)協(xié)議字段攜帶。我給大家一個(gè)標(biāo)準(zhǔn)的 header 傳播表做參考Header 字段說(shuō)明示例值traceparentW3C 標(biāo)準(zhǔn) trace 上下文格式為版本號(hào)-traceid-spanid-標(biāo)記00-863b464a71a4418ba1c712f10f7f9c21-0f3f2d8e9a1c4b56-01tracestate供應(yīng)商擴(kuò)展字段攜帶額外的業(yè)務(wù)標(biāo)簽vendorhigh_risk_orderx-request-id用于接入層網(wǎng)關(guān)記錄入口 ID與 traceparent 映射req-1087-afde92當(dāng)時(shí)我們有個(gè)支付回調(diào)服務(wù)對(duì)接的是第三方渠道第三方只認(rèn)自己生成的 request_id。我就在接入層做了一個(gè)映射表渠道的 request_id 對(duì)應(yīng)內(nèi)部生成的 trace_id。排查渠道回調(diào)問(wèn)題時(shí)拿著渠道給我們的單號(hào)就能反查出內(nèi)部完整調(diào)用鏈這個(gè)映射設(shè)計(jì)對(duì)事后的第三方問(wèn)題溯源幫助極大。鏈路回放的實(shí)現(xiàn)本質(zhì)上是按照 trace_id 把所有相關(guān) span 和日志拉出來(lái)然后按時(shí)間排列、按層級(jí)縮進(jìn)展示。這里有一個(gè)關(guān)鍵設(shè)計(jì)日志內(nèi)容必須依附于某個(gè) span而不是單獨(dú)游離在 trace 之外。否則日志就算有 trace_id也很難準(zhǔn)確地放到瀑布圖中某個(gè)節(jié)點(diǎn)旁邊。我的做法是日志記錄時(shí)引用當(dāng)前 span_id落庫(kù)后通過(guò)(trace_id, span_id)把日志關(guān)聯(lián)到具體節(jié)點(diǎn)。2.3 查詢與分析層從追查到還原數(shù)據(jù)進(jìn)來(lái)之后查詢層負(fù)責(zé)把“追查”變成“還原”。這層直接決定了系統(tǒng)好不好用。我見過(guò)很多數(shù)據(jù)平臺(tái)數(shù)據(jù)可能全有但查詢接口難用得一塌糊涂每次想撈一條鏈路得像寫畢業(yè)論文一樣拼 SQL這肯定不行。ClickHouse 表結(jié)構(gòu)設(shè)計(jì)我反復(fù)調(diào)了幾版。最終的核心表 schema 如下CREATE TABLE app_trace_events ( service String, timestamp DateTime64(3, UTC), trace_id String, span_id String, parent_span_id String, operation String, duration_ms UInt64, status_code UInt16, error_msg String, host String, env String, tags Map(String, String), INDEX idx_trace_id trace_id TYPE bloom_filter GRANULARITY 1 ) ENGINE MergeTree PARTITION BY toYYYYMMDD(timestamp) ORDER BY (timestamp, trace_id, span_id) TTL timestamp INTERVAL 90 DAY;PARTITION BY toYYYYMMDD(timestamp)讓每一天的數(shù)據(jù)落在一個(gè)分區(qū)查詢時(shí)如果帶上時(shí)間范圍條件可以快速跳過(guò)不是目標(biāo)日期的分區(qū)。ORDER BY (timestamp, trace_id, span_id)是整個(gè)查詢效率的關(guān)鍵——按 trace_id 查詢時(shí)ClickHouse 可以在稀疏索引中定位到對(duì)應(yīng)數(shù)據(jù)塊而不是全表掃描。我還對(duì) trace_id 建了 bloom filter 索引遇到高頻 trace 檢索時(shí)效率還能再上一個(gè)臺(tái)階。建表時(shí)我特意加了TTL timestamp INTERVAL 90 DAY線上日志保存三個(gè)月超過(guò)之后自動(dòng)清理。這個(gè)設(shè)計(jì)很有價(jià)值有次和另一個(gè)團(tuán)隊(duì)協(xié)作他們說(shuō)要“長(zhǎng)期保存”我提醒他們即使 ClickHouse 壓縮比很高但 90 天的數(shù)據(jù)量也足夠讓 TTL 機(jī)制發(fā)揮價(jià)值否則磁盤滿了以后所有人的查詢都會(huì)變慢。查詢層我封裝了三個(gè)核心接口。第一個(gè)是按 trace_id 拉全鏈路這是排障的入口。拿到一個(gè) trace_id通過(guò)下面的 SQL 把整條鏈路的所有 span 都取出來(lái)按時(shí)間排序再根據(jù) parent_span_id 構(gòu)造樹形結(jié)構(gòu)返回給前端SELECT service, timestamp, span_id, parent_span_id, operation, duration_ms, status_code, error_msg FROM app_trace_events WHERE trace_id {trace_id:String} ORDER BY timestamp ASC;第二個(gè)是服務(wù)維度聚合用來(lái)快速看某個(gè)服務(wù)在某個(gè)時(shí)間窗的負(fù)載和錯(cuò)誤率配合 Grafana 做熱力圖和趨勢(shì)線。第三個(gè)是慢調(diào)用分析通過(guò)duration_ms分位數(shù)函數(shù)算 P50、P95、P99判斷哪些接口需要優(yōu)化。我實(shí)際排查過(guò)一個(gè)訂單超時(shí)問(wèn)題通過(guò)慢調(diào)用分析發(fā)現(xiàn) P99 集中在某個(gè)下游服務(wù)一查是該服務(wù)連接池配置太小鏈路圖把整個(gè)過(guò)程暴露得清清楚楚。3. 實(shí)操落地從零搭建一套hindsight分析流程3.1 環(huán)境搭建與關(guān)鍵配置這一節(jié)說(shuō)說(shuō)從零開始怎么把整套系統(tǒng)跑起來(lái)。我在本地開發(fā)時(shí)用的是 Docker Compose把 ClickHouse、Kafka、Kafka UI、Grafana 全部編排起來(lái)。下面是我用的服務(wù)編排文件關(guān)鍵內(nèi)容version: 3.8 services: clickhouse: image: clickhouse/clickhouse-server:23.8 container_name: hindsight-clickhouse ports: - 8123:8123 - 9000:9000 volumes: - ./clickhouse/data:/var/lib/clickhouse - ./clickhouse/init.sql:/docker-entrypoint-initdb.d/init.sql:ro ulimits: nofile: soft: 262144 hard: 262144 kafka: image: bitnami/kafka:3.6 container_name: hindsight-kafka ports: - 9092:9092 environment: KAFKA_CFG_NODE_ID: 0 KAFKA_CFG_PROCESS_ROLES: controller,broker KAFKA_CFG_CONTROLLER_QUORUM_VOTERS: 0kafka:9093 KAFKA_CFG_LISTENERS: PLAINTEXT://:9092,CONTROLLER://:9093 KAFKA_CFG_ADVERTISED_LISTENERS: PLAINTEXT://localhost:9092 KAFKA_CFG_AUTO_CREATE_TOPICS_ENABLE: true啟動(dòng)之后第一步不是立刻寫采集器而是先建表。我把上一節(jié)那一段建表 SQL 放到初始化目錄里ClickHouse 在第一次啟動(dòng)時(shí)就會(huì)自動(dòng)執(zhí)行省得手工敲。接著手動(dòng)創(chuàng)建 Kafka 的 topic。我用的命令是docker exec hindsight-kafka kafka-topics.sh \ --create \ --topic app-logs \ --partitions 6 \ --replication-factor 1 \ --bootstrap-server localhost:9092分片數(shù)設(shè)置了 6這個(gè)數(shù)字不是隨手定的。我的線上環(huán)境有三臺(tái)消費(fèi)節(jié)點(diǎn)每個(gè)節(jié)點(diǎn)開兩個(gè)線程消費(fèi)6 個(gè)分區(qū)剛好能讓每個(gè)線程處理一個(gè)分區(qū)的消息既不浪費(fèi)也不爭(zhēng)搶。有個(gè)項(xiàng)目把分區(qū)數(shù)設(shè)成 12但消費(fèi)端只有兩個(gè)實(shí)例導(dǎo)致大部分消費(fèi)者線程空閑浪費(fèi)了 Kafka 的順序讀能力。Grafana 我是在最后才接入的。先單獨(dú)驗(yàn)證 ClickHouse 里的數(shù)據(jù)是否正確再配置數(shù)據(jù)源最后畫面板這樣可以避免“系統(tǒng)跑起來(lái)了但數(shù)據(jù)是臟的”這種問(wèn)題。3.2 核心采集與回放代碼示例整套系統(tǒng)落地中的核心代碼包含采集器、寫入 ClickHouse 的消費(fèi)腳本以及回放查詢的 API。采集器端大家可以直接沿用 2.1 節(jié)那段 Python 代碼。需要注意生產(chǎn)環(huán)境采集器通常不會(huì)和業(yè)務(wù)代碼耦合在同一個(gè)進(jìn)程里而是通過(guò) filebeat / otel collector 這種獨(dú)立進(jìn)程做無(wú)侵入采集。我推薦先用 otel-collector 來(lái)做統(tǒng)一接入因?yàn)樗?kafka exporter 和 debug exporter 可以很方便地幫你看數(shù)據(jù)到底有沒有發(fā)出去。我在啟動(dòng) collector 之后經(jīng)常會(huì)跑一條測(cè)試請(qǐng)求然后立刻去 Kafka UI 里確認(rèn) topic 消息數(shù)有沒有增加。如果沒增加先排查 collector 的 exporter 配置再排查業(yè)務(wù) SDK 的 endpoint。這一步花費(fèi)時(shí)間最少卻是很多新手最頭疼的環(huán)節(jié)。消費(fèi)端我寫了一個(gè) Go 程序從 Kafka 拉取消息批量寫入 ClickHouse。核心邏輯是并發(fā)消費(fèi) 每 2000 條或每 5 秒批量 flush 一次避免小批量寫入造成 ClickHouse 大量 merge:package main import ( context database/sql fmt time github.com/ClickHouse/clickhouse-go/v2 github.com/segmentio/kafka-go ) func main() { clickhouseDSN : clickhouse://user:passclickhouse:9000/observability db, _ : sql.Open(clickhouse, clickhouseDSN) reader : kafka.NewReader(kafka.ReaderConfig{ Brokers: []string{kafka:9092}, Topic: app-logs, GroupID: clickhouse-writer, MinBytes: 1e6, MaxBytes: 10e6, MaxWait: 500 * time.Millisecond, }) var batch []LogRecord for { msg, err : reader.ReadMessage(context.Background()) if err ! nil { continue } batch append(batch, LogRecordFromJSON(msg.Value)) if len(batch) 2000 { flushToClickHouse(db, batch) batch batch[:0] } } } func flushToClickHouse(db *sql.DB, batch []LogRecord) { tx, _ : db.Begin() stmt, _ : tx.Prepare( INSERT INTO app_trace_events (service, timestamp, trace_id, span_id, parent_span_id, operation, duration_ms, status_code, error_msg, host, env, tags) VALUES (?,?,?,?,?,?,?,?,?,?,?,?) ) for _, r : range batch { _, _ stmt.Exec(r.Service, r.Timestamp, r.TraceID, r.SpanID, r.ParentSpanID, r.Operation, r.DurationMS, r.StatusCode, r.ErrorMsg, r.Host, r.Env, r.Tags) } _ tx.Commit() }這段代碼的巧妙之處在于MinBytes、MaxBytes和MaxWait三個(gè)參數(shù)。MaxWait: 500ms表示即使消息沒攢夠 2000 條最多等 500 毫秒也要 flush 一次。這樣既保證了吞吐又避免消息在緩沖區(qū)里停留太久才入庫(kù)影響故障排查時(shí)的實(shí)時(shí)性。我實(shí)測(cè)下來(lái)消費(fèi)端每秒能處理幾萬(wàn)條簡(jiǎn)單日志對(duì)絕大多數(shù)中小規(guī)模業(yè)務(wù)來(lái)說(shuō)綽綽有余。3.3 數(shù)據(jù)可視化與報(bào)告輸出數(shù)據(jù)進(jìn)了 ClickHouse回放查詢也通了之后整套系統(tǒng)的最后一步是可視化與報(bào)告輸出。可視化我用 Grafana 做了幾個(gè)核心面板。第一個(gè)是全局流量大盤每秒請(qǐng)求數(shù)、錯(cuò)誤率、P50/P95/P99 耗時(shí)曲線。這個(gè)面板放在最頂端用于發(fā)現(xiàn)“有沒有問(wèn)題”。第二個(gè)是服務(wù)依賴拓?fù)渫ㄟ^(guò) span 里的 parent 關(guān)系用 NodeGraph 插件畫出服務(wù)之間的調(diào)用關(guān)系每個(gè)節(jié)點(diǎn)顯示平均耗時(shí)和錯(cuò)誤率。這個(gè)面板非常直觀有一次我一下就看到新上線的推薦服務(wù)把核心訂單服務(wù)的 QPS 拉高了 30%拓?fù)鋱D上那根線條紅得刺眼。第三個(gè)是 Trace 瀑布圖專門用于單個(gè) trace 的回放。我實(shí)現(xiàn)在 Web 面板上輸入 trace_id就能按時(shí)間軸渲染出完整的調(diào)用瀑布每個(gè) span 下面會(huì)附加對(duì)應(yīng)的日志條數(shù)點(diǎn)擊即可下鉆。報(bào)告輸出這一塊是我覺得最實(shí)用也最容易被忽視的功能。每一次線上事故排查完都需要提交一份復(fù)盤文檔。以前是手動(dòng)截圖加拼湊時(shí)間線效率極低。我在項(xiàng)目中預(yù)設(shè)了一套 Markdown 模板查詢層返回以下結(jié)構(gòu)化信息故障時(shí)間范圍、影響服務(wù)列表、根因 trace_id 鏈路、異常日志摘要、關(guān)鍵指標(biāo)前后對(duì)比、改進(jìn)建議。后端接口一次性把這些數(shù)據(jù)返回前端自動(dòng)填充到 Markdown 模板里一鍵導(dǎo)出成文件。最終生成的內(nèi)容可以直接作為復(fù)盤附件省去了大量寫文檔的時(shí)間。4. 常見問(wèn)題與排查技巧實(shí)錄4.1 日志量太大存儲(chǔ)扛不住這是一個(gè)必然會(huì)出現(xiàn)的問(wèn)題。系統(tǒng)剛上線的時(shí)候大家熱情高漲什么樣的日志都往里打一天能產(chǎn)生幾個(gè) TB 的數(shù)據(jù)。我一開始也天真地以為 ClickHouse 壓縮比高扛得住結(jié)果一周過(guò)去磁盤空間告急。解決思路根據(jù)日志的價(jià)值分了三層。第一層是采樣策略核心服務(wù)訂單、支付、登錄全量采集邊緣服務(wù)推薦、營(yíng)銷按 10% 的比例采樣采樣時(shí)按 trace_id 做到全鏈路一致否則會(huì)出現(xiàn)一半鏈路有日志一半沒有的尷尬。第二層是數(shù)據(jù)分層熱數(shù)據(jù)在 ClickHouse 保留 7 天用于日常排查冷數(shù)據(jù)通過(guò) TTL 移動(dòng)到對(duì)象存儲(chǔ)需要時(shí)按 trace_id 回?fù)?。第三層是字段裁剪業(yè)務(wù)日志里的冗余大字段如 request body 全文、響應(yīng)報(bào)文在采集端就做截?cái)喑^(guò) 512 字節(jié)的部分只保留長(zhǎng)度和 hash 值。這個(gè) hash 很有用對(duì)比兩次請(qǐng)求的參數(shù)是否一致時(shí)不需要完整報(bào)文對(duì)比 hash 就行。4.2 時(shí)間戳不同步導(dǎo)致鏈路錯(cuò)亂鏈路回放最怕時(shí)間戳錯(cuò)位?？鐓^(qū)域部署時(shí)如果各機(jī)房的機(jī)器沒有做統(tǒng)一時(shí)鐘同步A 服務(wù)記錄的事件時(shí)間早于 B 服務(wù)瀑布圖就會(huì)變成一團(tuán)亂麻。我在一個(gè)跨境電商項(xiàng)目上就吃過(guò)這個(gè)虧。機(jī)房在美國(guó)和新加坡兩邊服務(wù)器的系統(tǒng)時(shí)間差了幾百毫秒一個(gè) trace 的 span 排序錯(cuò)亂看起來(lái)像先響應(yīng)后請(qǐng)求。排查手段是先批量檢查日志中的時(shí)間戳單調(diào)性如果發(fā)現(xiàn)同一 trace 里 span 的時(shí)間出現(xiàn)回退就找到具體兩個(gè)服務(wù)所在的機(jī)器用下面的命令檢查時(shí)鐘偏移chronyc tracking | grep -E System time|Clock offset ntpdate -q time.google.com解決方式分兩步第一步所有機(jī)器配置 NTP 自動(dòng)同步這是基礎(chǔ)第二步也是最關(guān)鍵的采集端在發(fā)送日志時(shí)把“本地時(shí)間戳”和“采集端接收時(shí)間戳”并列記錄。這樣哪怕系統(tǒng)時(shí)鐘被業(yè)務(wù)進(jìn)程誤改我們依然可以通過(guò)接收時(shí)間戳反推真實(shí)事件順序。僅這一步就解決了 90% 的鏈路亂序問(wèn)題。4.3 定位到問(wèn)題但找不到根因有一種非常折磨人的排查場(chǎng)景鏈路很快定位到了某個(gè)服務(wù)但這個(gè)服務(wù)內(nèi)部的日志太稀無(wú)法進(jìn)一步定位到具體邏輯。比如一次請(qǐng)求的鏈路圖顯示評(píng)論服務(wù)耗時(shí) 5 秒但打開評(píng)論服務(wù)的日志只看到“開始處理”和“結(jié)束處理”兩條中間干了什么完全不知道。這時(shí)候就需要“回放式埋點(diǎn)”也就是在關(guān)鍵邏輯路徑上插入更有信息量的事件。我的經(jīng)驗(yàn)是凡是涉及外部調(diào)用的地方必須記錄 target、method、請(qǐng)求摘要、返回狀態(tài)和耗時(shí)凡是涉及數(shù)據(jù)庫(kù)讀寫的地方必須記錄表名、主鍵和影響行數(shù)凡是出現(xiàn) catch 分支必須把原始異常類型和消息完整打出來(lái)。還有一個(gè)很容易被忽略的坑線程池中的上下文丟失。業(yè)務(wù)里經(jīng)常用ExecutorService提交異步任務(wù)如果線程池沒有使用 OpenTelemetry 的上下文傳播包裝那么任務(wù)內(nèi)部拿到的 trace_id 就會(huì)為空日志“游離”了。我寫了一個(gè)簡(jiǎn)單的包裝類提交任務(wù)時(shí)顯式把當(dāng)前 TraceContext 快照傳到子線程里這個(gè)操作成本很低卻是異步場(chǎng)景鏈路完整的救命藥。4.4 從hindsight場(chǎng)景延伸到日常復(fù)盤做到這里hindsight 已經(jīng)不是一個(gè)單純的日志系統(tǒng)它變成了一種思維方式。我在迭代過(guò)程中慢慢體會(huì)到回溯能力不只在故障排查時(shí)有用。每次發(fā)布新版本之后我都會(huì)調(diào)出對(duì)應(yīng)版本的流量曲線和錯(cuò)誤率曲線對(duì)照回放當(dāng)時(shí)的發(fā)布窗口日志看看有沒有潛在的異常被隱藏。每個(gè)季度做性能優(yōu)化時(shí)我也會(huì)直接拉出 P99 耗時(shí)最高的幾個(gè)鏈路逐個(gè)展開瀑布圖找到真正拖慢系統(tǒng)的瓶頸——這些優(yōu)化工作以前靠估現(xiàn)在靠數(shù)據(jù)。有一次團(tuán)隊(duì)開復(fù)盤會(huì)聊一個(gè)功能上線后用戶投訴增多的問(wèn)題本來(lái)是業(yè)務(wù)邏輯的爭(zhēng)議結(jié)果我順手拉了該功能上線前后的 trace 對(duì)比發(fā)現(xiàn)有一個(gè)新的下游服務(wù)調(diào)用在特定參數(shù)下會(huì)返回大量超時(shí)錯(cuò)誤是調(diào)用方?jīng)]有做好重試和降級(jí)導(dǎo)致的。如果沒有“回放”能力這一輪爭(zhēng)論可能又要僵持很久?？傊甴indsight 就是給這個(gè)流程配了一臺(tái)“事件回放儀”讓所有決策都建立在對(duì)真實(shí)發(fā)生的每一幀數(shù)據(jù)的理解之上。結(jié)尾一些落地后的真實(shí)體會(huì)如果讓我用一個(gè)詞總結(jié)這套系統(tǒng)對(duì)我團(tuán)隊(duì)的影響我會(huì)選“確定性”。以前排查線上問(wèn)題很多時(shí)候靠猜、靠回憶、靠某個(gè)老員工拍胸脯現(xiàn)在不用了——任何一次事故只要能拿到一個(gè) trace_id就能在幾分鐘內(nèi)把現(xiàn)場(chǎng)完整還原出來(lái)根因分析從玄學(xué)變成了流水線作業(yè)。最后分享兩個(gè)我踩過(guò)的最深的坑。第一個(gè)是不要過(guò)早優(yōu)化采樣策略。項(xiàng)目剛上線時(shí)我為了省存儲(chǔ)設(shè)置了一套復(fù)雜的動(dòng)態(tài)采樣規(guī)則結(jié)果后來(lái)排查問(wèn)題時(shí)發(fā)現(xiàn)該采的日志沒采到。后來(lái)我把規(guī)則簡(jiǎn)化為無(wú)腦全量運(yùn)行一周后看數(shù)據(jù)量再調(diào)整反而更穩(wěn)。第二點(diǎn)是要重視數(shù)據(jù)質(zhì)量測(cè)試。每次采集 SDK 升級(jí)或者新增日志格式我都會(huì)往測(cè)試環(huán)境跑一批模擬流量專門驗(yàn)證 trace_id 是否連貫、時(shí)間戳格式是否符合預(yù)期、字段映射是否正確。這套校驗(yàn)機(jī)制看著不起眼實(shí)打?qū)嵄苊膺^(guò)好幾次線上數(shù)據(jù)的靜默損壞。hindsight 這個(gè)名字我一直很喜歡人很難做到事事預(yù)見但至少可以在事情過(guò)后誠(chéng)實(shí)、完整、高效地把它重新看清楚。希望這篇文章能給正在建設(shè)可觀測(cè)性體系的你一些思路。