Span Metrics Connector で SQL のクエリの処理時間を計測する

この記事は Mackerel Advent Calendar 2024 の 13日目の記事です。

Web アプリケーションのパフォーマンスの指標としてレスポンスタイムあげられます。レスポンスタイムは SQL の処理時間がボトルネックになることも多いです。 Web アプリケーションの SQL の処理時間を計測する手法は多くあります。

このブログでは OpenTelemetry Collector の Connector として提供されている Span Metrics Connector を活用し Mackerel で SQL のクエリごとの処理時間を計測し、さらに監視設定を設定する方法を説明します。

Span Metrics Connector とはトレースのスパンの情報から次のメトリックを計算する Connector です。

スパンの数 calls
スパンの処理時間のヒストグラム duration

例えば次のようなトレースを計測したとしましょう。

この例では POST /api/register のスパンが1個、db.Begin が1個、 db.Prepare が（表示では省略されているが）2個、　stmt.Exec が2個あります。Span Metrics Connector は計測された全てのトレースのスパンの数を通して足し合わせて call、そしてこれらのスパンの処理時間のヒストグラムを duration のメトリックにします。

次のブログでは Span Metrics Connector についてはさらに詳しく解説されています。 zenn.dev

今回は Span Metrics Connector の実用的な例として SQL のクエリの処理時間を計測してみましょう。

このブログでは Web Application の例として ISUCON13 を使います。Go で記述されたサーバーを使います。コードの大半はそのままで Trace だけ導入します。

github.com

DB のクエリのトレースを取得する

まずはSQLの処理時間をトレースとして計測しましょう。 ISUCON13 は DB のライブラリとして jmoiron/sqlx を使っています。 jmoiron/sqlx に対応した OpenTelemetry 計装ライブラリ uptrace/opentelemetry-go-extra/otelsqlx があるので、これをアプリケーションに組み込みます。

go get github.com/uptrace/opentelemetry-go-extra/otelsqlx

差分としては次のようになります。パッケージのインポート文の差分を除くと一行ですね。

@@ -93,7 +100,7 @@ func connectDB(logger echo.Logger) (*sqlx.DB, error) {
                conf.ParseTime = parseTime
        }
 
-       db, err := sqlx.Open("mysql", conf.FormatDSN())
+       db, err := otelsqlx.Open("mysql", conf.FormatDSN())
        if err != nil {
                return nil, err
        }

さらに OpenTelemetry の Trace の exporter を設定します。これはボイラープレートコードのため省略します。トレースの Export 先は OpenTelemetry Collector です。

Span Metrics Connector の設定

次に Span Metrics Connector の設定をします。 Span Metrics Connector の設定だけ引用すると次のようになります。ブログの最後に設定全文を載せました。

  spanmetrics/exponential:
    histogram:
      exponential:
        max_size: 160
    dimensions:
      - name: db.statement
    aggregation_temporality: "AGGREGATION_TEMPORALITY_DELTA"
    metrics_flush_interval: 60s

注目する点として dimensions に db.statement があります。 Span Metrics Connector が生成するメトリックはデフォルトの設定だと service.name, span.name, span.kind, status.code の属性しかありません。デフォルトの設定ではSQL の処理スパンからメトリックを生成してもクエリの情報は含めてくれません。今回はクエリごとの処理時間を計測したいですから dimensions に db.statement を設定します。db.statement は実行した SQL のクエリを表す span の属性です。

SpanMetrics Connector は events という設定もあり、こちらでメトリックに db.statement を追加するようにしても良いかもしれません。私は未検証です。

さらにヒストグラムの種類として exponential ヒストグラムにしました。 exponential ヒストグラムについては僕のブログを参照ください。

blog.rmatsuoka.org

メトリックの送信先は Mackerel です。

さて実行してみましょう

ISUCON 13 のベンチマーカーを実行しました。

Mackerel のメトリックエクスプローラ

さて投稿したメトリックを Mackerel のメトリックエクスプローラで見てみましょう。ベンチマーカーは数分しか起動しないので、メトリックもそのぶんだけです。

calls と duration のメトリックがあります。処理時間は duration のメトリックです。注目するメトリックは処理時間の最大値 duration.max や XX パーセントタイルである duration.XXp です。

SQL の処理時間のメトリックだけに限定する

今回は DB のスパンだけ計測したので、表示されるメトリックは DB のものだけです。通常のアプリケーションでは HTTPやカスタムなど DB 以外の span も計測していることがほとんどだと思います。SQL の処理時間のメトリックだけ見たい時は db.statment のラベルを持つメトリックだけを見えるようにしましょう。ラベルフィルターに db.statment = * と指定すればできます。

グラフの凡例を変更してみる

デフォルトの凡例は見にくいので変更してみましょう。凡例設定で span.name, db.statment と設定しましょう。

これによって SELECT * FROM livestream_tags WHERE livestream_id = ? というクエリの 90 パーセントタイルが 3.84ms であることがよくわかります。

遅いクエリがあったときにアラートを発報させる

クエリによる監視をつかって遅いアラートが発生した時にアラートを発報させるようにしてみましょう。今回は時間がかかっているクエリを調べたいのでクエリの処理時間の最大値である duration.max を監視します。

さらにちょっとした隠し機能ですが監視設定の名前にラベルにテンプレートを使って、属性を含めることができます。便利ですね。画像では監視設定の名前を {{span.name}} {{db.statement}} にしてみました。

アラートが発報する次のように表示されます。テンプレートが評価されてアラートの名前が db.Prepare SELECT * FROM livestream_tags WHERE livestream_id = ? となっています。

最後に

Span Metrics Connector と Mackerel のメトリックエクスプローラを駆使して SQL のクエリ処理時間を計測する方法を解説しました。そこそこお手軽で計測できると思います。

おまけ Collector の config 全文

---
receivers:
  otlp:
    protocols:
      http:
        endpoint: 0.0.0.0:4318
exporters:
  debug:
    verbosity: basic
  otlp/michizane:
    endpoint: otlp.mackerelio.com:4317
    compression: gzip
    headers:
      mackerel-api-key: "${env:MACKEREL_APIKEY}"

processors:
  batch:

connectors:
  spanmetrics/exponential:
    histogram:
      exponential:
        max_size: 160
    dimensions:
      - name: db.statement
    aggregation_temporality: "AGGREGATION_TEMPORALITY_DELTA"
    metrics_flush_interval: 60s

service:
  pipelines:
    traces:
      receivers:
        - otlp
      processors:
        - batch
      exporters:
        - debug
        - spanmetrics/exponential
    metrics:
      receivers:
        - spanmetrics/exponential
      processors:
        - batch
      exporters:
        - otlp/michizane
        - debug