OpenTelemetry の Trace を中心としたパフォーマンス改善

by rmatsuoka

Slide 1

Slide 1 text

OpenTelemetry の Trace を中心としたパフォーマンス改善 id:rmatsuoka Hatena Engineer Seminar #27 2023-11-16

Slide 2

Slide 2 text

自己紹介 ● id:rmatsuoka ● 2023年新卒 ● Mackerel チーム ● アプリケーションエンジニア ● 母語は Go

Slide 3

Slide 3 text

Mackerel

Slide 4

Slide 4 text

Mackerel の特徴

Slide 5

Slide 5 text

Mackerel は OpenTelemetry の Metric に対応します

Slide 6

Slide 6 text

OpenTelemetry とは？ ● テレメトリー (メトリック、トレース、ログなど) の標準仕様を定めている ● 仕様に基づいた計装ライブラリの開発 ○ Go, Java, PHP, … ● OpenTelemetry Collector の開発

Slide 7

Slide 7 text

テレメトリーを計装するアプリケーションやミドルウェア ● 計装ライブラリをアプリケーションに埋め込む ● 一部のミドルウェアは OpenTelemetry Collector をつかってテレメトリーを計装できる https://opentelemetry.io/docs/ OpenTelemetry の領域

Slide 8

Slide 8 text

OpenTelemetry Collector ● テレメトリーの受信、処理、送信を行うエージェント

Slide 9

Slide 9 text

テレメトリーを受信して保存、表示するモニタリングサービス ● Prometheus (metric) ● Jaeger (tracer) ● AWS X-Ray (trace) ● Mackerel (metric) など

Slide 10

Slide 10 text

Mackerel の Otel 対応 ● OpenTelemetry が策定した Telemetry 送受信プロトコル OTLP によってメトリックを受信 ● PromQL によってメトリックをクエリしてグラフに描画画面は開発中のものです

Slide 11

Slide 11 text

PromQL ● Prometheus に実装されているメトリックをクエリする言語（式） ● たとえば ○ http_request_total{job=”prometheus”} ■ jobをキー, ”prometheus” を値に持つ属性を持った http_request_total のメトリックをすべて取得する ○ filesystem_usage / filesystem_capacity ■ ファイルシステムの使用率を計算する ● Mackerel では今回 PromQL エンジンを独自に実装して提供します

Slide 12

Slide 12 text

新卒初の仕事として… OpenTelemetry 対応へ向けてコンポーネントの開発・改善をしています ● OpenTelemetry のメトリックを受信して DB へ保存 (writer) ● リクエストの PromQL を評価してメトリックを取り出す (reader)

Slide 13

Slide 13 text

開発しているのはこのコンポーネント RDB Time Series DB Otel metric Reader (ECS) Otel metric Writer (ECS) Otel Collector Web Browser Mackerel あなたの server あなたメトリックのメタデータを保存メトリックの時系列データを保存 OTLP によってメトリックを受信 PromQL を評価してメトリックを DB から取得

Slide 14

Slide 14 text

今回のお話する仕事 ● もともとこのコンポーネントは PoC であった ○ 実装の方針が正しいか調べるため ○ あまりパフォーマンスを意識した実装にはなっていなかった ● 実際のサーバーからメトリックを送信してブラウザから見ようとすると重くて使い物にならない ○ 一つのダッシュボードを開くだけで Reader コンポーネントの CPU 使用率が 100 % になった ● 「コンポーネントのパフォーマンスを改善しよう！」

Slide 15

Slide 15 text

パフォーマンス改善で大切なこと ● 計測 ○ ボトルネックを改善しなければ意味がない！ ○ 推測するな、計測せよ ● どうやってボトルネックを見つける？ ○ ツールは色々ある

Slide 16

Slide 16 text

Trace を中心に計測してみた！ ● Trace をする。さらにTrace で見つかったボトルネックを他のツールを使うことによって掘り下げていくトップダウンの方法で計測 ● コンポーネント Writer / Reader どちらも Trace を使ってパフォーマンス改善したが、今回の話は Reader に焦点をあてる ● 「Trace を入れよう」とは id:luﬁabb が言った ○ 曰く「タスクとしては Trace を入れて終わるつもりだったけど、 rmatsuoka がパフォーマンス改善を進められそうだから任せた」

Slide 17

Slide 17 text

分散トレース ● ひとつのリクエストが処理される過程を追跡する方法 ● マイクロサービスやミドルウェアに「分散」している処理を横断して追跡する ○ 今回の話では、横断はできておらず一つのコンポーネントだけ見ています

Slide 18

Slide 18 text

分散トレーストレースは「スパン」の木構造で表すことができる。 Span B は Span A を親に持ち Span C と Span D を子に持つ Span A (例: http Handler など) Span B (use case) Span C (database access) Span D

Slide 19

Slide 19 text

Go で trace を計装するのは 3 ステップ！ 1. Tracer の initialize を追加 2. http.Handler を otelhttp でラップ 3. 計測したい関数に trace start/end の2行追加

Slide 20

Slide 20 text

1. Tracer の initialize を追加 // main 関数あたりに trace の送り先を指定する traceExporter, err := otlptracegrpc.New(ctx, ...) ... -- nicepkg/tracer.go -- // pkg ごとに tracer を初期する var tracer = otel.Tracer("example.com/proj/nicepkg")

Slide 21

Slide 21 text

2. http.Handler を otelhttp でラップ // リクエスト処理全体のスパンを生成してくれる。 // metric reader コンポーネントは net/http と互換性のある // github.com/go-chi/chi によって書かれている - handler := newNiceHandler() + handler := otelhttp.NewHandler(newNiceHandler(), “servername”, ...)

Slide 22

Slide 22 text

1. 3. 計測したい関数に2行追加 // スパンを生成する func NiceFunction(ctx context.Context) { + ctx, span := tracer.Start(ctx, "SpanName") + defer span.End() + // function body }

Slide 23

Slide 23 text

モニタリングサービスへ送信 ● 今回、トレーシングデータは AWS X-Ray へ送信した。 ○ AWS Open Distro for OpenTelemetry https://aws-otel.github.io/ ● ECS にあるコンポーネントのサイドカーにAWS が提供している ADOT Collector (AWS Distro の OpenTelemetry Collector) を立てた。

Slide 24

Slide 24 text

こんな結果が得られる！スパン緑の線: 実行時間

Slide 25

Slide 25 text

結果を観察してみよう同じ関数がループで呼ばれている

Slide 26

Slide 26 text

N + 1 問題 ● データベースへの問い合わせに発生する問題 ● 取り出すメトリック一覧を取得する RDB へのアクセスを1回 ● それぞれのメトリックの時系列データを Time Series DB から取り出すことをループで N 回実行 ● まとめて取得をするように変更して N+1 問題は解決

Slide 27

Slide 27 text

一度に取得できる数に上限を入れる ● PoC では検索結果の数の上限がなかった。 ● 数百, 千件ものメトリックを一気に取り出そうとして CPU を食い潰していた。

Slide 28

Slide 28 text

N+1 問題は解決したが… db.Query がなぜか遅かったりする

Slide 29

Slide 29 text

DB への特定のリクエストが遅いことを発見 ● 特定の条件のリクエストだけが遅い ● 大抵のリクエストはそんなに遅くない ● テーブルはふたつある ○ メトリック (Mackerel のオーガニゼーションの ID やメトリックのタイプなど) ○ メトリックのメタデータ (メトリックの属性のテーブル、メトリックに従属している)

Slide 30

Slide 30 text

DB へのインデックスを追加 ● DB の実行計画を`EXPLAIN ANALYZE` コマンドで見る ● メタデータテーブルの index の貼り方がマズかったことがわかった ● 高速化のためメタデータテーブルを非正規化してオーガニゼーションID のカラムを追加した + ALTER TABLE <メタデータテーブル> ADD COLUMN "org_id" BIGINT; + CREATE INDEX on <メタデータテーブル> ("org_id", ...);

Slide 31

Slide 31 text

PromQL への評価が遅い

Slide 32

Slide 32 text

クエリによっては PromQL の評価が遅い ● Trace では PromQL を評価する関数が遅いことしかわからない ● Go のプロファイラー pprof を使って調査

Slide 33

Slide 33 text

(time.Time).Equal が遅い？ ● 時間を表す構造体 time.Time が等しいかを調べる関数 ● CPU の使用時間を多く占めている ● この関数単体では遅くないはず

Slide 34

Slide 34 text

(time.Time).Equal を沢山呼んでいた ● スライスの中から特定の時間をもつ構造体を探すときに、ループで探していたことがわかった。 ● Equal メソッドを何度も呼んでいる。 - for _, dataPoint := range metric.DataPoint { - if dataPoint.Time.Equal(at) { - ...

Slide 35

Slide 35 text

二分探索をする ● 構造体は時間でソートされていたので二分探索をするようにコードを変更 + idx := sort.Search(len(metric.DataPoints), func (i int) bool { + return metric.DataPoints[i].Time.Compare(at) >= 0 + })

Slide 36

Slide 36 text

メモリの確保が激しい ● メモリを確保/解放する関数mallocgc, や madvise なども CPU 使用時間を多く占めていた ● メモリのプロファイラも調査した

Slide 37

Slide 37 text

メモリの確保を回避する入力のバリデーションのたびに毎回正規表現をコンパイルしていた - regexp.Match("[\x00-\x08\x0B\x0C\x0E-\x1F\x7F]", input)

Slide 38

Slide 38 text

改善策 ● 正規表現を一度だけコンパイルする ○ 一般的な選択肢 ● 正規表現を使わない ○ 今回はこっち。制御文字がないか調べるだけなので正規表現を使わずに済ました + strings.ContainsAny(input, invalidChars)

Slide 39

Slide 39 text

こうした改善のおかげで * 改善前の遅いリクエストと全く同じものではないので参考程度に

Slide 40

Slide 40 text

トレースを計装するときのヒント 1 トレースを自動計装してくれるミドルウェアを使う ● github.com/uptrace/opentelemetry -go-extra/otelsql ○ DB へのクエリを保存してくれる

Slide 41

Slide 41 text

トレースを計装するときのヒント 2 // フィールドを追加する // トレースにリクエストの情報を追加して、トレースの詳細に見る時に // 参考にすることができる。 // この例ではリクエストされた PromQL をフィールドに追加している。 ctx, span := tracer.Start(ctx, "eval", trace.WithAttributes( attribute.String("query", query), attribute.Int64("start", start.Unix()), attribute.Int64("end", end.Unix()), ))

Slide 42

Slide 42 text

まとめ ● アプリケーションにトレーシングを導入するのは3ステップでできる ● タイムラインの図によってボトルネックが発見しやすい ● Trace の結果から DB の実行計画や pprof などの細かい情報を見にいくトップダウンに改善ができた

Slide 43

Slide 43 text

OpenTelemetry の Mackerel の beta 参加者募集！ ● Mackerel「ラベル付きメトリック機能」ベータ版テストお申し込みフォームからお申し込みください ○ ブログ記事 [ なぜ Mackerel は OpenTelemetry のラベル付きメトリックをサポートするのか - Mackerel お知らせ #mackerelio https://mackerel.io/ja/blog/entry/why-does-mackerel-support-open-telemet ry-labeled-metrics ] からフォームに飛べます