Mackerel で開発中のマイクロサービスを OpenTelemetry のトレースを活用してパフォーマンス改善した

Mackerel Advent Calendar 2023 の2日目の id:rmatsuoka です。

私は今年に新卒としてはてなに入社し、 Mackerel のアプリケーションエンジニアとして開発に携わっています。さて Mackerel では OpenTelemetry のメトリックに対応することが発表されました。詳しくは次のページをご覧ください。

mackerel.io

私はこの OpenTelemetry を受け取ったり、取り出したりするコンポーネントの開発をしています。入社して最初の仕事として OpenTelemetry のトレースを活用し、コンポーネントのパフォーマンスを改善を行いました。トレース導入を提案したのは id:lufiabb さんです。最初、私のタスクは OpenTelemetry のトレースをアプリケーションに仕込んで終わりだったのですが、id:lufiabb 曰く「パフォーマンス改善まで rmatsuoka ができそうだから任せた」と言われて頑張りました。

ソフトウェアのパフォーマンスを改善するとき、大切なのが計測をすることです。ソフトウェアエンジニアはどこかで「推測するな、計測せよ」という格言を聞いたことがあるかもしれません。ソフトウェアの処理時間の大半はプログラムの中の数%のボトルネックに集中すると言われています。この部分を見つけることがパフォーマンスの改善の第一歩になります。しかしながらどのように見つければ良いのでしょうか。このブログは OpenTelemetry のトレースを使ってボトルネックを発見し、パフォーマンス改善を進めた体験を書きます。

OpenTelemetry とは

公式のウェブサイトでは次のように説明されています。

OpenTelemetry is an Observability framework and toolkit designed to create and manage telemetry data such as traces, metrics, and logs. Crucially, OpenTelemetry is vendor- and tool-agnostic, meaning that it can be used with a broad variety of Observability backends, including open source tools like Jaeger and Prometheus, as well as commercial offerings. OpenTelemetry is a Cloud Native Computing Foundation (CNCF) project.

opentelemetry.io

OpenTelemetry が提供しているライブラリやコレクターは GitHub のリポジトリから見ることができます。Go や JavaScript など主要な言語でテレメトリーを計装するライブラリが用意されています。このブログの後半で Go アプリケーションをトレースを導入する方法を紹介します。

取得したテレメトリーは Prometheus (metric)や Mackerel (metric), AWS X-Ray (trace)といったモニタリングサービスへ直接送ることもできますが、 OpenTelemetry Collector を経由して送ることが推奨されています。これによってアプリケーションにモニタリングサービスに依存したコードを書く必要がなくなります。さらに collector 自体にもリトライや、テレメトリーをバッチしてモニタリングサービスへおくったり、不要なテレメトリーを除くフィルタリングするといった機能が兼ね備えられていて便利だからです。

Mackerel の OpenTelemetry メトリック対応

PromQL によってメトリックをクエリしている様子。https://mackerel.io へのレスポンスタイムのメトリックをクエリしている。

Mackerel では現在、主に次の機能を開発しています。

OTLP/gRPC によるメトリックの受信
PromQL によってメトリックをクエリしてグラフに描画

OTLP は OpenTelemetry が策定したテレメトリーを送受信するプロトコルです。 PromQL は OpenSource のメトリックモニタリングツール Prometheus で使われているクエリ言語です。たとえば

httpcheck.duration{http.url="https://mackerel.io"}

といった式によるクエリが可能です。 Mackerel では独自のメトリックデータベースを利用しているため PromQL エンジンを独自に実装して提供します。

これらの機能はマイクロサービスとして設計されています。Go で記述され AWS ECS へデプロイされます。それぞれのサービスの関係は次の図で表すことができます。この図でメトリックは左から右へ流れます。ユーザーのメトリックは OpenTelemetry Collector を経由して、緑色の四角形で表された Otel metric Writer へ送信されデータベースへ保存されます。ユーザーの PromQL によるクエリは Otel metric Reader に送られます。reader は PromQL を評価してメトリックをデータベースから取り出し、レスポンスをユーザーへ返します。

Mackerel の OpenTelemetry 対応のコンポーネントの構成図

もともとこれらのマイクロサービスは設計の方針を確認する PoC で、あまりパフォーマンスを意識した実装ではありませんでした。実際のサーバーから送信されたメトリックの一覧のダッシュボードを見ようとするも重くて使いものになりません。一つのダッシュボードを開くだけでマイクロサービスの CPU が 100%になることもありました。そういうわけでパフォーマンス改善のタスクを行うことになりました。writer と reader のどちらもパフォーマンス改善しましたが、このブログでは reader に焦点を当てて説明します。

Go のアプリケーションでトレースを計装する

つぎのようにして Go のアプリケーションでトレースを計装しました。

1. Tracer の initialize を追加

main 関数あたりでトレースの exporter を初期化します。これによって計装したテレメトリーを外部へ送信する先を指定します。今回は ECS のサイドカーにおいた otel-collector に送信をするので、 otlptracegrpc を exporter としました。

+ traceExporter, err := otlptracegrpc.New(ctx, ...)
+ if err != nil {
+         ...
+ }
+ tp := trace.NewTracerProvider(...)
+ otel.SetTracerProvider(tp)

2. http.Handler を otelhttp でラップ

otelhttp はリクエスト全体のスパンを生成してくれます。reader マイクロサービスは net/http と互換性のある chi によって書かれています。

- handler := newHandler()
+ handler := otelhttp.NewHandler(newHandler(), “servername”, ...)

3. 計装したい関数で span を生成する

処理に時間がかかると思われる関数に span を生成して、処理時間を測定します。

まずはパッケージごとに固有の tracer をグローバル変数で定義します。これによってパッケージとスパンを結びつけることができます。私はパッケージごとに次のようなコードである trace.go を置きました。

package nicepkg

var tracer = otel.Tracer("example.com/proj/nicepkg")

そして span を生成したい関数に次の2行を追加します。

  func NiceFunction(ctx context.Context) {
+        ctx, span := tracer.Start(ctx, "NiceFunction")
+        defer span.End()
+
          // function body
  }

どの関数で span を生成するかは悩みます。初めはデータベースをクエリしている部分、 PromQL を評価している部分など重いと思われるとこに全部に span を生成して、不要と思った部分を削る方針で進めました。

アプリケーションのトレースは ADOT を用いて AWS X-Ray へと送信しました。

aws-otel.github.io

トレース結果を見て発見した課題と解決方法

トレース結果は X-Ray の画面から上のように見ることができます。この結果は一つのリクエストが処理を完了するまでを表しています。一番上の緑の帯はリクエストを受け取る http のハンドラーがかかったのスパンです。幅が処理時間を表しています。このハンドラーが呼び出した関数のスパンが次の行の緑色の帯であり、さらにその関数が呼んだ関数が下に…といったようになっています。

データベースへのクエリの改善

N+1 問題

このトレース結果をみると、同じ関数が何度も呼ばれてその処理に時間がかかっていることがわかります。これはデータベースへの問い合わせに発生する典型的な問題で N+1問題と呼ばれています。取り出すメトリック一覧を取得する RDB へのアクセスを1回。それぞれのメトリックの時系列データを Time Series DB から取り出すことをループで N 回実行しています。

これらはまとめて取得をするように変更して N+1 問題は解決しました。

特定のリクエストが遅いことを発見

トレースを眺めていると特定の条件のリクエストだけが遅いことを発見しました。メトリックのメタデータを記録した RDB のテーブルはふたつあります。

メトリック (Mackerel のオーガニゼーションの ID やメトリックのタイプなど)
メトリックのラベル (メトリックに従属している)

RDBの実行計画をEXPLAIN ANALYZE コマンドで見ると、ラベルテーブルの index の貼り方がマズかったことがわかったので index を修正しました。さらに高速化のためラベルデータのテーブルを非正規化してオーガニゼーションID のカラムを追加しました。

+ ALTER TABLE <ラベルテーブル> ADD COLUMN "org_id" BIGINT;
+ CREATE INDEX <index_name> on <ラベルテーブル> ("org_id", ...);

PromQL の評価が遅い

さらにクエリによっては PromQL を評価する関数が遅いがわかりました。更なる調査でメトリックを長い期間つまりたくさんのデータポイントがあるようなリクエストを発行した時は PromQL の評価が異常に遅くなることがわかりました。トレースの結果ではなぜこの eval 関数が遅いのかわからないのでGo のプロファイラー pprof を使って更なる調査を行いました。

ループで探していたことを二分探索へ変更

取得したpprof を眺めるとちょっと変わった点を発見しました。時刻の構造体が等しいことを調べる関数 time.(Time).Equal がとても CPU 時間を使っています。この処理自体は重い処理ではないはずです。さらに詳しく調べたところ、時刻を含む構造体 (dataPoint) のスライス dataPoints から at と一致する時刻をもつ要素を探す時、ループで探していたことを見つけました。この構造体は時刻でソートしていたため、二分探索で行い探索にかかる処理を削減しました。

- for _, dataPoint := range dataPoints {
-         if dataPoint.Time.Equal(at) {
-                 ...
+ idx := sort.Search(len(dataPoints), func(i int) bool {
+         return dataPoints[i].Time.Compare(at) >= 0
+ })

メモリの確保が激しかった

pprof の結果をみるとメモリの確保や解放などのシステムコールを呼び出していることが多いことがわかりました。更なる調査で入力のたびに毎回正規表現をコンパイルしてバリデーションしていました。正規表現を毎回バリデーションするのをやめる手もありますが、今回のケースでは単純なバリデーションだったため、正規表現自体の利用をやめました

  // 制御文字を取り除く
- matched, err := regexp.Match("[ -- set of invalid charactor -- ]", input)
+ matched := strings.ContainsAny(input, invalidChars) // invalidChars = "\x00\x01\x02..."