フロントエンドとバックエンドをトレースでつないで原因特定を簡単に！

この記事では、Mackerel APMとOpenTelemetryを用いて、フロントエンド・バックエンド間の一気通貫な分散トレーシングを実現し、パフォーマンス調査を迅速化する手法を解説します。ユーザー操作に紐づくコンテキスト伝搬と属性による集計を活用することで、具体的なソースコードを読み解かなくてもボトルネックを特定するプロセスを紹介します。

こんにちは、Webアプリケーションエンジニアの id:momochi29 です。

Webアプリケーションを運用していると、「この画面が遅い」とお客様からお問い合わせをいただくケースは少なくないと思います。そういったときには、そのお客様の環境固有の問題なのか、特定の画面だけで発生しているのか、あるいはバックエンドのどこかに問題があるのかなど、影響範囲や原因を調査する必要があります。

そこでこの記事では、Mackerel APMを利用して、フロントエンドとバックエンドを1つのトレースで一気通貫に見る方法についてご紹介します。ここではISUCON9の予選問題を題材に、ユーザーがクリックしてから結果が返されるまでに発生するフロントエンドとバックエンドの処理をトレースで見ることで、どこに・誰に問題があるのかを明らかにします。

シナリオとして「マイページをクリックして表示されるまでもっさりしている（「重い」状態になっている）」というお問い合わせを受けたと仮定します。ISUCON9の予選問題は「椅子を売りたい人／買いたい人をつなげるフリマアプリ」というテーマです。マイページでは、出品商品と取引一覧を確認することができます。

github.com

フロントエンドとバックエンドの計装

フロントエンドおよびバックエンドからMackerel APMにトレースを送れるよう、アプリケーションに計装します。

フロントエンドには @opentelemetry/auto-instrumentations-web を使い、ブラウザ上で発生するクリック操作とfetchを捕捉できるように計装します。

※ OpenTelemetryのブラウザへの計装はexperimental（実験段階）なので、ここに記載している内容が変更される可能性は大いにあります。

opentelemetry.io

フロントエンドからMackerelにトレースを送信するには、MackerelのAPIキーではなく、クライアントトークンを利用します。クライアントトークンはスコープがトレースの投稿に限定されており、露出時のセキュリティリスクを低減できます。また、1分あたりのスパン数のレートリミットも設定できます。

クライアントトークンは、オーガニゼーションの「クライアントトークン」タブから作成できます。

mackerel.io

計装の準備として以下のコードをフロントエンドに追加します。ここでは、クリックイベントのスパンに app.ui_action という属性を追加して、どのクリック操作か識別できるようにしています。また、ユーザーIDも app.user_id という属性で追加して、誰の操作か識別できるようにしています。

import {getWebAutoInstrumentations} from '@opentelemetry/auto-instrumentations-web';
import {ZoneContextManager} from '@opentelemetry/context-zone';
import {W3CTraceContextPropagator} from '@opentelemetry/core';
import {OTLPTraceExporter} from '@opentelemetry/exporter-trace-otlp-proto';
import {registerInstrumentations} from '@opentelemetry/instrumentation';
import {resourceFromAttributes} from '@opentelemetry/resources';
import {
    BatchSpanProcessor,
    WebTracerProvider,
} from '@opentelemetry/sdk-trace-web';

const exporter = new OTLPTraceExporter({
    url: 'https://otlp-vaxila.mackerelio.com/v1/traces',
    headers: {
        'X-Mackerel-Client-Token': 'YOUR_CLIENT_TOKEN_HERE',
    },
});
const provider = new WebTracerProvider({
    resource: resourceFromAttributes({
        'service.name': serviceName,
    }),
    spanProcessors: [new BatchSpanProcessor(exporter)],
});

provider.register({
    contextManager: new ZoneContextManager(),
    propagator: new W3CTraceContextPropagator(),
});

// 計装の登録
registerInstrumentations({
    instrumentations: [
        getWebAutoInstrumentations({
            '@opentelemetry/instrumentation-user-interaction': {
                eventNames: ['click'],
                shouldPreventSpanCreation: annotateUserActionClick,
            },
        }),
    ],
});

// クリック時のコールバック関数。追加の属性を付与できる
const annotateUserActionClick = (
    eventType: string,
    element: HTMLElement,
    span: Span,
) => {
    if (eventType !== 'click') {
        return;
    }

    const actionElement = element.closest('[data-otel-action]');
    const action = actionElement?.getAttribute('data-otel-action');
    if (!action) {
        return;
    }

    // フィルタリング用に属性を追加
    span.setAttribute('app.ui_action', action);

    const userId = actionElement?.getAttribute('data-otel-user-id');
    if (userId) {
        // どのユーザーで発生したトレースか識別するために追加
        span.setAttribute('app.user_id', userId);
    }
};

バックエンドの計装方法については省略しますが、otelhttpおよびotelsqlを利用しています。

フロントエンドとバックエンドを1つのトレースとして見られるようにするには、コンテキスト伝搬を行う必要があります。もっとも、今回導入したような自動計装ライブラリを利用していれば、自動でコンテキスト伝搬が行われる場合が多いので、さほど意識することはないでしょう。

少し解説すると、コンテキスト伝搬は次のような流れで行われます。

@opentelemetry/instrumentation-fetch がfetch時に traceparent ヘッダーを付与してリクエストする
otelhttp が propagation.HeaderCarrier を利用して traceparent ヘッダーからコンテキストを読み取る

トレースからどこに・誰に問題があるのかを調べる

Mackerel APMの「トレース一覧」の画面で「フィルター」ボタンをクリックし、フィルタリング用に追加した app.ui_action 属性で絞った一覧を取得します。

取得したトレースのレイテンシーの分布を見ると、500ms以下、1s、2.5s付近に散らばっていることがわかります¹。

これだけではユーザーの偏り具合はわかりません。そこで「集計」ボタンを押して集計してみます。集計結果を見ると3ユーザーぶんのトレースがあり、各ユーザーがどのくらいマイページを開いたかがわかります。

それでは、レイテンシーを最も遅い2.5s付近に絞って検索してみます。さらに、集計してユーザーの偏りをチェックします。

集計結果を見ると user_id=1 が100%であることがわかります。

お問い合わせいただいたお客様は user_id=1 だったので、「もっさりしている」という感覚と合っていそうですね。

では、原因を調べるためにトレースを見てみましょう。click（フロントエンドのクリック操作）のスパンは1msと高速ですが、バックエンドの GET /users/transactions.json で2sほどかかっており、ここがボトルネックになっていることがわかります。

比較のために1s付近のトレースも見てみます。トレースの形はuser_id=1のものと似ていますが、 GET /users/transactions.json が851msとなっており、半分以下の時間であることがわかります。

では、GET /users/transactions.json のどこで時間がかかっているのでしょうか。トレースを見ると、同じような HTTP GET が繰り返されているようです。

この HTTP GET のスパンを見てみましょう。すると、/status (配送ステータスの取得) に200ms程度かかっていることがわかります。そして、これが取引している商品数ぶん、直列に実行されるために遅くなっていました。

以上から、フロントエンド側には問題がなく、原因はバックエンド側にありました。/status の呼び出しが取引商品数ぶんだけ直列に実行されており、取引数の多いuser_id=1で特に顕著な遅延となって現れていたことがわかりました。

まとめ

フロントエンドとバックエンドのオブザーバビリティを高めることで、具体的なコードを見なくても、誰に・どこに問題があるのかを明らかにすることができました。

最後に、今回初めてフロントエンドの計装をしてみた筆者の感想ですが、気を付けて実装しないとトレースが思ったとおりに1つにつながってくれず、分裂してしまってちょっと難しいなと感じました。フロントエンド実装でのコンテキストの引き回しが、サーバーサイド実装よりも自明ではないことが理由として考えられるかもしれません。

もう「なんか遅い」で悩まない！開発者のためのAPM入門

アプリケーションを開発・運用していると、特定の処理が遅い、リクエストごとに応答時間がばらつくなど、「なんか遅い」と感じる場面があります。本資料では、こうした「なんか遅い」と感じる状況に対して、どこから調べればよいのか、何を手がかりにすればよいのかという観点から、APM（アプリケーションパフォーマンスモニタリング）が調査の進め方をどう変えるのかを解説します。

ダウンロードはこちら

シナリオの準備のために適当なユーザーで適当な回数、マイページを開きました。↩

ブログ

#mackerelio

フロントエンドとバックエンドをトレースでつないで原因特定を簡単に！

フロントエンドとバックエンドの計装

トレースからどこに・誰に問題があるのかを調べる

まとめ

もう「なんか遅い」で悩まない！開発者のためのAPM入門

セールスに関するお問い合わせ

無料トライアル