この記事はNikkei Advent Calendar 2021の24日目の記事です。

こんにちは。エンジニアの成田です。 API・バックエンドチームとして日本経済新聞LINE公式アカウントのバックエンドサーバやレコメンドAPIなどの開発などを担当しています。

今回はSentryのパフォーマンス監視機能について概要を紹介したあと、Pythonで使用する場合の便利な設定、そして 実際に社内でチューニングの際にどのような使用したかの簡単な例を紹介をします。

概要

Sentryといえばエラー監視ツールとしての印象が強い方が多いと思います。2020年7月からJavascriptとPython向けにパフォーマンス監視機能を提供し、その後も対応言語や機能を増やしています。 日経でも、バックエンド・フロント問わず多くのプロジェクトがSentry導入しており、主にエラーを検知してSlackにアラートを送る運用をしていますが、 一部プロジェクトではこのパフォーマンス監視機能を有効にして、パフォーマンス改善のために使用しています。

Sentryでは分散トレーシングを行います。各マイクロサービスでの処理を Transaction とし、各マイクロサービスの一連の処理の集合が Trace となります。 Transactionは Span と呼ばれる関数実行や外部通信といったタスクのツリーで構成されます。

例えば、あるLambdaがAPIサーバにリクエストし、さらにその中で別のサーバにリクエストした場合は以下のようになります。

3つのTransactionによってTraceが形成されています。親子関係が出来ていますね。真ん中のTransactionを詳しく見てみると以下のようになっています。

より細かくパフォーマンスを見ることが出来ます。django.middlewareの処理や、httpリクエスト、DBへのクエリのレイテンシが計測されており、これがSpanです。 httpリクエストを3回していますが、この中でSentryを導入している内部サーバへのリクエストは最後の1つだけだったので、 上のTraceにはその1つのTransactionしか記録されていません。

このTransactionがパフォーマンス監視の際には基本単位となります。Transaction名（APIサーバならpath、Lambdaなら関数名）で集計し、 レイテンシのパーセンタイルやApdexなどの指標を計算し詳しく確認できます。レイテンシが高かったTransactionも確認できます。

パフォーマンスの改善を行なう際は、まず改善したいpathを決め、レイテンシが高いTransactionのパフォーマンスを見てボトルネックの処理を探すことが多いです。 httpリクエストが遅ければTraceを見て、リクエスト先のTransactionを更に調べる... といった流れになります。

参考: https://docs.sentry.io/product/sentry-basics/tracing/、https://docs.sentry.io/product/performance/

Pythonでの便利設定について

ここでは、Pythonのバックエンドサービスでの導入方法と、使うと便利な機能を紹介します。 Sentryによるエラー監視を行っていない場合は、まずトライアルに申し込む必要がありますが、ここではすでに使える状態を想定します。

初期設定

SDKの導入方法は公式ドキュメントに各言語、各ライブラリごとに解説されています。 例えば、PythonのDjangoだと以下のようなコードになります。DSNはコンソールの設定から取得します。 すでにエラー監視でSentryを導入している場合は traces_sample_rate を引数に追加するだけですね（プランがTeams以上の場合）。 もし、エラー監視はしたくないという場合はsample_rate=0を追加して下さい。

sentry_sdk.init(
    integrations=[DjangoIntegration()],
    environment="development",
    dsn="xxx",
    traces_sample_rate=0.2,
)

他にも、AWS Lambdaで動かしていたら、AwsLambdaIntegrationが使えますし、 FastAPIなどのASGI Web フレームワークには SentryAsgiMiddleware というmiddlewareが提供されています。 SQLAlchemyを使用していたら SqlalchemyIntegration、Redisをキャッシュサーバに使用していたら RedisIntegration など データベースへのアクセスの監視も簡単です（Djangoを使用している場合は DjangoIntegration だけでSQLの監視が出来ます）。

pathごとのサンプリングレート調整

全てのリクエストでパフォーマンスを計測してしまうと、料金プランの上限にもすぐ達してしまいますし、負荷もかかります。 そこでサンプリングレートを決め、ランダムな一部リクエストのみを計測することが推奨されています。

上の例では、traces_sample_rate=0.2 として一括で決めていましたが、重要なところを重点的に監視したいなどpathごとにレートを変えたいケースはあると思います。 このように動的にサンプリングレートを定義する場合は traces_sample_rateの代わりに traces_sampler を定義します

今回は、healthcheck用のpathはサンプリングせず、他は20％サンプリングする設定を考えます。フレームワークはDjangoです。 traces_sampler は sampling_context というオブジェクトを元にレートを決定するのですが、 Djangoの場合は wsgi_environ というオブジェクトがここに入っており、PATH_INFO が更にその中に入っています （フレームワークによって対応は異なり、ASGIでは asgi_scope が代わりに入っているのでこれを使います）。 このpathで条件分岐させればOKです。

また、分散トレーシングのために、Traceの始めのTransactionで決定されたサンプルするかしないかは、それ以後のトランザクションに継承されるべきです。 デフォルトではそのような設定となっていますが、traces_sampler を自分で定義する場合はこの処理も書く必要があります。 といっても sampling_context の中に parent_sampled として入っているので、それをそのまま返すだけです。

参考: https://docs.sentry.io/platforms/python/guides/django/configuration/sampling/#sampling-context-data

from django.urls import resolve


def traces_sampler(sampling_context):
    # 親transactionのsample設定を引き継ぐ
    if sampling_context["parent_sampled"] is not None:
        return sampling_context["parent_sampled"]

    # pathがhealthcheck用ならばsamplingしない
    if wsgi_environ := sampling_context.get("wsgi_environ")
      if wsgi_environ.get("PATH_INFO") == "/healthcheck"
        return 0

    return 0.2

sentry_sdk.init(
    # ...

    traces_sampler=traces_sampler,
)

関数単位の計測

対応するintegrationを導入することで、httpリクエストやDBへのクエリはSpanとして計測出来ますが、 その他の処理がボトルネックになっていないか調べたいケースも多いと思います。

公式ドキュメントに、現在のSpanの子Spanを作るコードが載っています。 これをもとに、関数やメソッドをSpanとして計測できるデコレータを作ると便利です。

def monitoring(func):
    @functools.wraps(func)
    def wrapped(*args, **kwargs):
        span = sentry_sdk.Hub.current.scope.span
        if span:
            description = f"{func.__module__}.{func.__qualname__}"
            with span.start_child(op="function", description=description):
                return func(*args, **kwargs)
        else:
            return func(*args, **kwargs)

    return wrapped

@monitoring
def some_function():
    ...

class SomeClass:

  @monitoring
  def some_method(self):
      ...

このように使用すると、下のように関数がSpanとして計測されます。 descriptionとしては関数名と（メソッドの場合はクラス名と）モジュール名を定義しています。 全ての関数にこのデコレータをつけること現実的ではないので、負荷的に気になる箇所に設定するのが良いでしょう。

実際のパフォーマンス監視の利用例

最後に、サーバの負荷試験時の際に、Sentryのパフォーマンス監視機能を使ってボトルネックを調査した例を紹介します。

あるサーバの負荷テストをしたところ、想定よりもCPU使用率が高くなり、レイテンシが増大してしまいました。 そこでボトルネックを探すためにパフォーマンスを見てみると見てみると、httpリクエストの間に謎の空白が存在していました。

コードを読む限りだと重くなりそうな処理が無いので、上で説明したデコレータで関数ごとに計測を行いました。

from urllib.parse import parse_qsl

@monitoring
def parse_postback(data: str) -> dict[str, str]:
    # parse_qlだと dict[str, list[str]]になってしまう
    return dict(parse_qsl(data))

すると、上の parse_postback という関数が重いことがわかりました。 これはクエリ文字列をdictに変換する（例: a=1&b=2 -> {"a": "1", "b": "2"} ）だけの関数です。 ローカルで5μsほどの処理が50msかかっています。

※ 処理が重くなった原因は現在も解明出来ておらず、特定の条件でしか発生しないようです。

そこで、この処理を以下のようにコードを書き換えました。これはURLエンコードする処理などを除いて単純化したものです。これでも今回は機能要件を満たすことが出来ます。

@monitoring
def parse_postback(data: str) -> dict[str, str]:
    result = {}
    for d in data.split("&"):
        k, v = d.split("=")
        result[k] = v
    return result

関数を置き換え計測すると、負荷をあげてもレイテンシが増えないことが確認出来たので、これでチューニング終了です。 このようにローカルでは確認出来ないボトルネックをパフォーマンス監視機能で発見出来ました。

最後に

本記事では、Sentryのパフォーマンス監視機能の概要やPythonでの設定方法、実際の利用例を紹介しました。 Sentryのパフォーマンス監視機能のようなAPMはDatadogやNew Relic、AWS X-Rayなどがあり、大体似たようなことができると思います（日経でもDatadaogを使用するプロジェクトも多いです）が、 エラー監視に合わせて、少し設定を加えるだけで気軽に使えるのが利点かなと思います。この記事が参考になれば幸いです。