巧用 "火焰圖" 快速分析鍊路性能

本文旨在幫助讀者了解什麼是全鍊路追蹤以及如何使用工具來分析鍊路中性能瓶頸。

閱讀前提

鍊路概念和術語

基本概念及工具

• 全鍊路（Trace）追蹤
• 分析工具
• 火焰圖
• Span 清單
• 服務調用關系圖
• 持續時間 / 執行時間

全鍊路追蹤

一般來說，單個追蹤（Trace）由各個 Span 構成，是一棵樹或有向無環圖（DAG），每一個 Span 代表 Trace 中被命名并計時的連續性的執行片段，如下圖所示。因為 Span 的核心是記錄對應程式執行片段的開始時間和結束時間，而程式執行片段之間存在調用的父子關系，因而 Span 邏輯上形成樹狀結構。

注：span 的父子關系可以通過子 span 的 parent_id 等于父 Span 的 span_id 來關聯

火焰圖

火焰圖（Flame Graph）是由 Linux 性能優化大師 Brendan Gregg 發明的用于分析性能瓶頸的可視化圖表，火焰圖以一個全局的視野來看待時間分布，它從頂部往底部列出所有可能導緻性能瓶頸 Span。

繪制邏輯

• 縱軸（Y軸）代表調用 Span 的層級深度，用于表示程式執行片段之間的調用關系：上面的 Span 是下面 Span 的父 Span（資料上也可以通過子 span 的 parent_id 等于父 Span 的 span_id 來關聯來對應）。
• 橫軸（X軸）代表單個 Trace 下 Span 的持續時間（duration），一個格子的寬度越大，越說明該 Span 的從開始到結束的持續時間較長，可能是造成性能瓶頸的原因。

顯示說明

火焰圖

• 火焰圖上的每個 Span 格子的顔色都對應其服務（service）的顔色。

是以從火焰圖上很直覺的可以感覺目前的 Trace 中涉及到有哪些服務請求在執行。（服務的顔色生成邏輯：使用者登入到工作空間通路應用性能監測子產品時，觀測雲會根據服務名稱自動生成顔色，該顔色的內建會繼承到鍊路檢視器等分析頁面）

• Span 塊預設顯示：目前 Span 的資源（resource）或操作（operation）、持續時間（duration）以及是否存在錯誤（status = error）
• 每個 Span 提示都會顯示目前 Span 對應的 資源（resource）、持續時間（duration）以及整體耗時占比

服務清單

火焰圖右側的服務清單顯示目前 Trace 内發生請求調用的服務名稱、顔色及該服務執行占總執行時間的比率。

注意：服務名稱顯示為 None 的情況則表示目前 trace 未找到 parent_id = 0 的頂層 Span

特别說明

由于多線程或者存在異步任務等原因，是以火焰圖在實際繪圖時會遇到 span 之間的關系可以如下：

1. 同屬于一個 parent 的兄弟 span 間可能重疊

因為存在 Span 重疊的情況，為了能更直覺的看到每個 Span 及子 Span的執行情況，我們前端在繪制火焰圖的時候做了一些顯示處理，即根據 時間 + 空間次元計算 Span 及子 Span 在完全不遮擋情況下顯示的位置。

示例1：

正常 Trace，同層級 Span 時間上不重疊，但跟下屬子 Span 時間有重疊，通過連線的形式關聯父子 Span 之間的關系，下面子 Span 存在連線的時候也是按照該邏輯做繪圖處理。

示例 2：

異常 Trace，仍然存在同層級 Span 時間上重疊，但是因為實際資料裡發現 Trace 的 頂層 Span（parent_id = 0）的開始時間（start）大于子 Span 的開始時間。

分析邏輯：按照鍊路中根據程式執行的父子關系判斷，父 Span 的開始時間一定是小于子 Span的開始時間的，是以看到該火焰圖的顯示後，發現父 Span 跟子 Span 的服務不是一個時，可以判斷兩個服務所在伺服器的系統時間可能存在不一緻的情況，需要先去校驗校準後再來分析實際的性能瓶頸。

Span 清單

顯示說明

清單全收起狀态

• 列1：顯示服務類型、服務名稱、服務顔色及目前服務下是否存在 status = error 的 Span
• 列2：顯示目前服務下面的 Span 數量
• 列3：顯示目前服務下 Span 持續時間（duration）的平均值
• 列4：顯示目前服務下 Span 的執行時間總和
• 列5：顯示目前服務的執行時間占總執行時間的比例

服務行展開顯示

• 列1：顯示資源名稱（resource）、對應服務顔色及目前 span 是否存在 status = error
• 列2：空
• 列3：顯示目前 Span 持續時間（duration）
• 列4：顯示目前 Span 的執行時間
• 列5：顯示目前Span 的執行時間占總執行時間的比例

服務調用關系圖

顯示說明

顯示目前 trace 下的服務之間的調用關系拓撲

持續時間

Span 對應程式執行片段的開始時間和結束時間，一般在 Trace 的資料中用 duration 字段來做标記。

執行時間

上述的特别說明中有提及到可能會存在父子 Span 的結束時間不一緻的情況，那麼執行時間則參考以下邏輯計算得出。

Span 執行時間

1. 子 span 可能在父 span 結束後才結束

子 Span 的執行時間 = Children 的 duration

總執行時間 = Children 的結束時間 - Parent 的開始時間

父 Span 的執行時間 = 總執行時間 - 子 Span 的執行時間

1. 子 span 可能在父 span 結束後才開始

子 Span 的執行時間 = Children 的 duration

總執行時間 = Children 的結束時間 - Parent 的開始時間

父 Span 的執行時間 = 總執行時間 - 子 Span 的執行時間

1. 同屬于一個 parent 的兄弟 span 間可能重疊

父 Span 執行時間 = p(1) +p(2)

Children 1 Span 執行時間 = c1(1) + c1(2)

Children 2 Span 執行時間 = c2(1) + c2(2)

注意：因為 Children 1 Span、Children 2 Span 實際執行中時間上存在部分重疊，是以這部分時間由兩個 Span 平分。

示例說明

同步任務情況下，Span 按照 "Span1開始->Span1結束->Span2開始->Span2結束->..."順序執行時，每個 Span 的執行時間及對應父 Span 的執行時間計算如下：

示例1：

父 Span = Couldcare SPAN1

子 Span = MyDQL SPAN2、MyDQL SPAN3、MyDQL SPAN4、MyDQL SPAN5、MyDQL SPAN6、MyDQL SPAN7、MyDQL SPAN8、MyDQL SPAN9、MyDQL SPAN10、MyDQL SPAN11

計算分析：

因為所有的子 Span 都沒有再下層級的子 Span，是以下圖所有的子 Span 的執行時間等于他們的 Span 持續時間。父 Span 因為下面存在子 Span 的調用是以實際父 Span 的執行時間需要通過父 Span 的持續時間減去所有子 Span 的執行時間獲得。

服務執行時間

每個服務的執行時間 = Trace 内所有屬于該服務的 Span 執行時間總和

總執行時間

總執行時間 = Trace 内 Span 最後結束的時間 - Span 最開始的時間

鍊路檢視分析場景示例

采集器配置（主機安裝）

進入 DataKit 安裝目錄下的 conf.d/ddtrace 目錄，複制 ddtrace.conf.sample 并命名為 ddtrace.conf。示例如下：

[[inputs.ddtrace]]
  ## DDTrace Agent endpoints register by version respectively.
  ## Endpoints can be skipped listen by remove them from the list.
  ## Default value set as below. DO NOT MODIFY THESE ENDPOINTS if not necessary.
  endpoints = ["/v0.3/traces", "/v0.4/traces", "/v0.5/traces"]

  ## customer_tags is a list of keys contains keys set by client code like span.SetTag(key, value)
  ## that want to send to data center. Those keys set by client code will take precedence over
  ## keys in [inputs.ddtrace.tags]. DOT(.) IN KEY WILL BE REPLACED BY DASH(_) WHEN SENDING.
  # customer_tags = ["key1", "key2", ...]

  ## Keep rare tracing resources list switch.
  ## If some resources are rare enough(not presend in 1 hour), those resource will always send
  ## to data center and do not consider samplers and filters.
  # keep_rare_resource = false

  ## By default every error presents in span will be send to data center and omit any filters or
  ## sampler. If you want to get rid of some error status, you can set the error status list here.
  # omit_err_status = ["404"]

  ## Ignore tracing resources map like service:[resources...].
  ## The service name is the full service name in current application.
  ## The resource list is regular expressions uses to block resource names.
  ## If you want to block some resources universally under all services, you can set the
  ## service name as "*". Note: double quotes "" cannot be omitted.
  # [inputs.ddtrace.close_resource]
    # service1 = ["resource1", "resource2", ...]
    # service2 = ["resource1", "resource2", ...]
    # "*" = ["close_resource_under_all_services"]
    # ...

  ## Sampler config uses to set global sampling strategy.
  ## sampling_rate used to set global sampling rate.
  # [inputs.ddtrace.sampler]
    # sampling_rate = 1.0

  # [inputs.ddtrace.tags]
    # key1 = "value1"
    # key2 = "value2"
    # ...

  ## Threads config controls how many goroutines an agent cloud start.
  ## buffer is the size of jobs' buffering of worker channel.
  ## threads is the total number fo goroutines at running time.
  # [inputs.ddtrace.threads]
    # buffer = 100
    # threads = 8

  ## Storage config a local storage space in hard dirver to cache trace data.
  ## path is the local file path used to cache data.
  ## capacity is total space size(MB) used to store data.
  # [inputs.ddtrace.storage]
    # path = "./ddtrace_storage"
    # capacity = 5120

           

配置好後，重新開機 DataKit 即可。

HTTP 設定

如果 Trace 資料是跨機器發送過來的，那麼需要設定 DataKit 的 HTTP 設定。

如果有 ddtrace 資料發送給 DataKit，那麼在 DataKit 的 monitor 上能看到：

DDtrace 将資料發送給了 /v0.4/traces 接口

SDK 接入（Go 示例）

安裝依賴

安裝 ddtrace golang library 在開發目錄下運作

go get -v github.com/DataDog/dd-trace-go
           

設定 DataKit

需先安裝、啟動 datakit，并開啟 ddtrace 采集器

代碼示例

以下代碼示範了一個檔案打開操作的 trace 資料收集。

在 main() 入口代碼中，設定好基本的 trace 參數，并啟動 trace：

package main

import (
    "io/ioutil"
    "os"
    "time"

    "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/ext"
    "gopkg.in/DataDog/dd-trace-go.v1/ddtrace/tracer"
)

func main() {
    tracer.Start(
        tracer.WithEnv("prod"),
        tracer.WithService("test-file-read"),
        tracer.WithServiceVersion("1.2.3"),
        tracer.WithGlobalTag("project", "add-ddtrace-in-golang-project"),
    )

    // end of app exit, make sure tracer stopped
    defer tracer.Stop()

    tick := time.NewTicker(time.Second)
    defer tick.Stop()

    // your-app-main-entry...
    for {
        runApp()
        runAppWithError()

        select {
        case <-tick.C:
        }
    }
}

func runApp() {
    var err error
    // Start a root span.
    span := tracer.StartSpan("get.data")
    defer span.Finish(tracer.WithError(err))

    // Create a child of it, computing the time needed to read a file.
    child := tracer.StartSpan("read.file", tracer.ChildOf(span.Context()))
    child.SetTag(ext.ResourceName, os.Args[0])

    // Perform an operation.
    var bts []byte
    bts, err = ioutil.ReadFile(os.Args[0])
    span.SetTag("file_len", len(bts))
    child.Finish(tracer.WithError(err))
}
           

編譯運作

Linux/Mac 環境：

go build main.go -o my-app
DD_AGENT_HOST=localhost DD_TRACE_AGENT_PORT=9529 ./my-app
           

Windows 環境：

go build main.go -o my-app.exe
$env:DD_AGENT_HOST="localhost"; $env:DD_TRACE_AGENT_PORT="9529"; .\my-app.exe
           

程式運作一段時間後，即可在觀測雲看到類似如下 trace 資料：

Golang 程式 trace 資料展示

支援的環境變量

以下環境變量支援在啟動程式的時候指定 ddtrace 的一些配置參數，其基本形式為：

DD_XXX=<env-value> DD_YYY=<env-value> ./my-app
           

注意事項 這些環境變量将會被代碼中用 WithXXX() 注入的對應字段覆寫，故代碼注入的配置，優先級更高，這些 ENV 隻有在代碼未指定對應字段時才生效。

Key	預設值	說明
DD_VERSION	-	設定應用程式版本，如 1.2.3、2022.02.13
DD_SERVICE	-	設定應用服務名
DD_ENV	-	設定應用目前的環境，如 prod、pre-prod 等
DD_AGENT_HOST	localhost	設定 DataKit 的 IP 位址，應用産生的 trace 資料将發送給 DataKit
DD_TRACE_AGENT_PORT	-	設定 DataKit trace 資料的接收端口。這裡需手動指定 DataKit 的 HTTP 端口（一般為 9529）
DD_DOGSTATSD_PORT	-	如果要接收 ddtrace 産生的 statsd 資料，需在 DataKit 上手動開啟 statsd 采集器
DD_TRACE_SAMPLING_RULES	-	這裡用 JSON 數組來表示采樣設定（采樣率應用以數組順序為準），其中 sample_rate 為采樣率，取值範圍為 [0.0, 1.0]。 示例一：設定全局采樣率為 20%：DD_TRACE_SAMPLE_RATE='[{"sample_rate": 0.2}]' ./my-app 示例二：服務名通配 app1.*、且 span 名稱為 abc的，将采樣率設定為 10%，除此之外，采樣率設定為 20%：DD_TRACE_SAMPLE_RATE='[{"service": "app1.*", "name": "b", "sample_rate": 0.1}, {"sample_rate": 0.2}]' ./my-app
DD_TRACE_SAMPLE_RATE	-	開啟上面的采樣率開關
DD_TRACE_RATE_LIMIT	-	設定每個 golang 程序每秒鐘的 span 采樣數。如果 DD_TRACE_SAMPLE_RATE 已經打開，則預設為 100
DD_TAGS	-	這裡可注入一組全局 tag，這些 tag 會出現在每個 span 和 profile 資料中。多個 tag 之間可以用空格和英文逗号分割，例如 layer:api,team:intake、layer:api team:intake
DD_TRACE_STARTUP_LOGS	true	開啟 ddtrace 有關的配置和診斷日志
DD_TRACE_DEBUG	false	開啟 ddtrace 有關的調試日志
DD_TRACE_ENABLED	true	開啟 trace 開關。如果手動将該開關關閉，則不會産生任何 trace 資料
DD_SERVICE_MAPPING	-	動态重命名服務名，各個服務名映射之間可用空格和英文逗号分割，如 mysql:mysql-service-name,postgres:postgres-service-name，mysql:mysql-service-name postgres:postgres-service-name

實際鍊路資料分析

1.登入觀測雲工作空間，檢視應用性能監測子產品的服務清單，從服務頁面已經可以看出 browser 服務的 P90 響應時間是比較長的。

2.點選 browser 服務名稱，檢視該服務的概覽分析視圖，可以看出影響目前服務響應時間的最關鍵的資源是 query_data 這個接口，因為這個接口是觀測雲的一個資料查詢接口，是以接下來我們看下這個接口在查詢過程當中，到底是因為什麼導緻耗時較長。

3.點選資源名稱，跳轉到檢視器，通過點選 持續時間 倒序檢視響應時間的最大值。

4.點選 Span 資料，檢視分析目前 Span 在整個鍊路裡面的執行性能和其他相關資訊。

5.點選右上角 [全屏] 模式按鈕，放大檢視火焰圖相關資訊。結合整體鍊路檢視，可以看出 browser服務在整個鍊路中的執行時間占比高達 96.26%，從 Span 清單也可以得出此結論。根據火焰圖的占比和對應的鍊路詳情資訊，我們可以總和得出 browser 的這個 query_data Span 在整個執行過程中可以看到 resource_ttfb（資源加載請求響應時間）耗時 400 多毫秒， resource_first_byte（資源加載首包時間）耗時 1.46 秒，再結合檢視 province 的地理位置定位是 Singapore（新加坡），而我們的站點部署在杭州節點，則可以得出是因為地理位置問題導緻資料傳輸的時間變長進而影響了整個的耗時。

參考來源：https://www.guance.com/learning/articles/flame_graph01