フレームグラフを活用したトレースパフォーマンス分析¶

本ドキュメントでは、分散型トレーシング（Trace）の基本概念と、トレース内のパフォーマンスボトルネックを分析するためのツールの使用方法について説明します。

基本概念とツール¶

• 分散型トレーシング（Trace）
• 分析ツール
  • フレームグラフ（Flame Graph）
  • 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）を表します。1つのマスの幅が大きいほど、その Span の開始から終了までの継続時間が長く、パフォーマンスボトルネックの原因である可能性が高いことを示します。

表示説明¶

フレームグラフ

• フレームグラフ上の各 Span のマスの色は、そのサービス（service）の色に対応します。

そのため、フレームグラフからは、現在の Trace にどのようなサービスリクエストが実行されているかを直感的に把握できます。（サービスの色の生成ロジック：ユーザーがワークスペースにログインしてアプリケーションパフォーマンスモニタリング（APM）モジュールにアクセスすると、Guanceはサービス名に基づいて自動的に色を生成します。この色の統合は、トレースエクスプローラーなどの分析ページにも引き継がれます）

• Span ブロックのデフォルト表示：現在の Span のリソース（resource）またはオペレーション（operation）、継続時間（duration）、およびエラーの有無（status = error）
• 各 Span のツールチップには、現在の Span に対応するリソース（resource）、継続時間（duration）、および全体の所要時間に占める割合が表示されます。

サービスリスト

フレームグラフ右側のサービスリストには、現在の Trace 内でリクエスト呼び出しが発生したサービスの名前、色、およびそのサービスの実行が総実行時間に占める割合が表示されます。

注意：サービス名が None と表示される場合、現在のトレースにおいて parent_id = 0 のトップレベルスパンが見つからなかったことを示します。

インタラクション説明¶

1. 全画面表示 / デフォルトサイズに戻す：トレース詳細右上の全画面表示アイコンをクリックすると、トレースフレームグラフが横方向に拡大表示されます。デフォルトサイズに戻すアイコンをクリックすると、詳細ページが元のサイズに戻ります。
2. ミニマップの表示 / 非表示：トレース詳細左側のミニマップ表示/非表示アイコンをクリックすると、ミニマップ上で範囲選択、ドラッグ、スクロール操作を行い、フレームグラフを素早く確認できます。
3. グローバル Trace の表示：トレース詳細左側のグローバル Trace 表示アイコンをクリックすると、フレームグラフで全体のトレースを確認できます。
4. 下部 Tab 詳細の非表示：折りたたみボタンをクリックすると、下部の Tab 詳細表示エリアが非表示になります。
5. Span のダブルクリック：フレームグラフ上で該当の Span が中央に拡大表示され、その前後のコンテキストにある Span を素早く特定して確認できます。
6. 右側のサービス名をクリック：対応する Span がハイライト表示されます。もう一度サービス名をクリックすると、デフォルトの全 Span 選択状態に戻ります。サービス名をクリックすることで、対応するサービスに関連する Span を素早くフィルタリングして確認できます。

特記事項¶

マルチスレッドや非同期タスクの存在などにより、フレームグラフの実際の描画時には、Span 間の関係が以下のようになる場合があります。

• 同じ parent に属する兄弟 Span 間で時間が重複する可能性がある

Span の重複が存在するため、各 Span とその子 Span の実行状況をより直感的に確認できるよう、フレームグラフ描画時にフロントエンドで表示処理を行っています。これは、時間 + 空間の次元に基づいて、Span と子 Span が完全に重ならない位置を計算して表示するものです。

例1：

正常な Trace で、同じ階層の Span の時間は重複していませんが、その下位の子 Span の時間と重複している場合、線で結ぶことで親子 Span の関係を関連付けます。下の子 Span に線が存在する場合も、同様のロジックで描画処理を行います。

例2：

異常な Trace で、同じ階層の Span の時間が依然として重複している場合。これは、実際のデータにおいて、Trace のトップレベルスパン（parent_id = 0）の開始時間（start）が子 Span の開始時間よりも大きいためです。

分析ロジック：

プログラム実行の親子関係に基づくトレース内の判断では、親 Span の開始時間は必ず子 Span の開始時間よりも小さくなります。そのため、このフレームグラフの表示を見て、親 Span と子 Span のサービスが異なる場合、2つのサービスが存在するサーバーのシステム時間に不一致がある可能性が考えられます。まずは時刻同期を確認・校正した上で、実際のパフォーマンスボトルネックを分析する必要があります。

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 の実行時間が総実行時間に占める割合を表示

インタラクション説明¶

• 検索：リソース名（resource）によるあいまい検索に対応
• Span を選択後、フレームグラフに切り替えて、対応する Span のコンテキスト関係を確認可能

サービス呼び出し関係図¶

表示説明¶

現在のトレースにおけるサービス間の呼び出し関係トポロジを表示します。

• リソース名（resource）によるあいまい一致検索に対応し、特定のリソースの上流・下流サービス呼び出し関係を特定できます。
• サービスにホバーすると、現在のサービスに属する Span の数、サービスの実行時間、およびその割合が表示されます。

継続時間¶

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 の実際の実行時間には一部重複があるため、この重複部分は2つの 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 コレクターを有効にしてください。

コード例¶

以下のコードは、ファイルオープン操作のトレースデータ収集を示しています。

main() のエントリーコードで、基本的なトレースパラメータを設定し、トレースを開始します。

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

プログラムをしばらく実行すると、Guanceで以下のようなトレースデータが確認できます。

Golang プログラムのトレースデータ表示

サポートされている環境変数¶

以下の環境変数は、プログラム起動時に ddtrace の設定パラメータを指定するために使用できます。基本的な形式は以下の通りです。

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

注意事項：これらの環境変数は、コード内で WithXXX() を使用して注入された対応するフィールドによって上書きされます。そのため、コードで注入された設定の優先順位が高く、これらの ENV はコードで対応するフィールドが指定されていない場合にのみ有効となります。

実際のトレースデータ分析¶

1.Guanceのワークスペースにログインし、APM モジュールのサービスリストを確認します。サービスページから、browser サービスの P90 応答時間が比較的長いことがわかります。

2.browser サービス名をクリックし、そのサービスの概要分析ビューを確認します。現在のサービスの応答時間に最も影響を与える重要なリソースは query_data というインターフェースであることがわかります。このインターフェースは Guance のデータクエリインターフェースであるため、次にこのインターフェースのクエリ処理中に、何が原因で所要時間が長くなっているのかを確認します。

3.リソース名をクリックしてエクスプローラーに移動し、[継続時間] を降順でクリックして、応答時間の最大値を確認します。

4.Span データをクリックし、現在の Span のトレース全体における実行パフォーマンスとその他の関連情報を確認・分析します。

5.右上の [全画面表示] モードボタンをクリックし、フレームグラフの関連情報を拡大表示します。トレース全体を確認すると、browser サービスの実行時間がトレース全体の実行時間に占める割合は 96.26% にも上ることがわかります。この結論は Span リストからも導き出せます。フレームグラフの割合と対応するトレース詳細情報を組み合わせると、browser のこの query_data Span の実行全体において、resource_ttfb（リソース読み込み要求応答時間）が 400 ミリ秒以上、resource_first_byte（リソース読み込み初回パケット時間）が 1.46 秒かかっていることがわかります。さらに、province の地理的位置情報が Singapore（シンガポール）であるのに対し、当社のサイトは杭州ノードにデプロイされていることから、地理的な問題によりデータ転送時間が長くなり、全体の所要時間に影響を与えていると結論付けることができます。