NestJS × PrismaのGraphQL APIのボトルネックをOpenTelemetryで調査してみた
2024.05.27CX事業本部@大阪の岩田です
NestJS × Prismaで開発されたGraphQL APIのレスポンスが悪く、ボトルネックを調査する機会があったので調査の過程をご紹介します。ざっとソースを確認して非効率な処理をいくつか見つけたのですが、どこから修正するのが効率的なのか？修正のリスクも鑑みながら優先順位を付けたかったので、OpenTelemetry SDKを使ってトレースを取得して分析しています。
環境
今回利用した環境です
- NodeJS: v20.11.1
- NestJS: 10.2.6
- @opentelemetry/instrumentation-graphql: 0.40.0
- @opentelemetry/instrumentation-http: 0.51.1
- @opentelemetry/sdk-node: 0.51.1
- @prisma/client: 5.4.1
- @prisma/instrumentation: 5.14.0
- otel/opentelemetry-collector: sha256: fe7714849adfd251129be75e39c5c4fa7031d87146645afa5d391ab957845c18
- jaegertracing/all-in-one: sha256:aa3d8eca6edeb84d997af6712b62fc5db8e6217277f95c109d121ea7fe03c291
APIをトレースする準備
ここからAPIをトレースするための準備をしていきます
Dockerコンテナの準備
今回はNestJS -> OpenTelemetry Collector -> Jaegerという流れでトレースデータを送信し、JaegerのUIからトレースデータを分析する構成としました。docker-composeでOpenTelemetry Collector と Jaeger のコンテナをサクっと立ち上げられるように以下の通りdocker-compose.ymlを用意しました。
version: '3.9'
services:
jaeger:
image: jaegertracing/all-in-one
ports:
- '16686:16686'
otel-collector:
image: otel/opentelemetry-collector
ports:
- '4318:4318'
command: ['--config=/etc/otel-collector-config.yaml']
volumes:
- ./otel-collector-config.yaml:/etc/otel-collector-config.yaml
OpenTelemetry Collectorのコンテナにバインドマウントしている設定ファイルotel-collector-config.yamlの中身は以下の通りです。Jaegerのコンテナにトレースデータをエクスポートするだけのシンプルな構成です。
receivers:
otlp:
protocols:
http:
endpoint: 0.0.0.0:4318
processors:
batch/traces:
timeout: 1s
send_batch_size: 50
exporters:
otlp/jaeger:
endpoint: 'jaeger:4317'
tls:
insecure: true
logging:
verbosity: detailed
sampling_initial: 5
sampling_thereafter: 200
service:
pipelines:
traces:
receivers: [otlp]
processors: [batch/traces]
exporters: [otlp/jaeger]
最初ハマったポイントとしてotlp/jaegerの部分をjaegerにするとerror decoding 'exporters': unknown type: "jaeger" for id: "jaeger" (valid values: [nop otlp kafka prometheusremotewrite zipkin debug logging otlphttp file opencensus prometheus])というエラーによってうまくJaegerと連携できませんでした。JaegerがOTLP形式をサポートするようになったため、Opentelemetry Collector v0.85.0 以後はネイティブの Jaeger フォーマットはサポートされなくなったとのことです。
ライブラリの準備
NestJSのコードをインストルメンテーションする準備としてOpen Telemetry関連のライブラリをインストールします。今回は以下のライブラリをインストールしました。
npm install @opentelemetry/sdk-node \
@opentelemetry/instrumentation-http \
@opentelemetry/instrumentation-graphql \
@prisma/instrumentation
必要に応じてOpenTelemetry Express Instrumentation for Node.jsやOpenTelemetry NestJS Instrumentation for Node.jsあたりの導入を検討するのも良いでしょう。
Prismaの処理をトレースする準備
4.2.0以後のPrismaはプレビュー機能としてOpen Telemetry互換のトレース機能がサポートされています。プレビュー機能のため扱いには注意が必要ですが、今回はローカル環境で分析用に利用するだけなので、気にせず有効化していきます。
まずschema.prismaを編集し、previewFeaturesにtracingを追加します。
generator client {
provider = "prisma-client-js"
previewFeatures = ["tracing"]
}
スキーマが更新できたらnpx prisma generateでPrisma Clientを再生成しておきます
npx prisma generate
以下のように出力されればOKです
Environment variables loaded from .env
Prisma schema loaded from schema.prisma
✔ Generated Prisma Client (v5.4.1) to ./node_modules/@prisma/client in 126ms
Start using Prisma Client in Node.js (See: https://pris.ly/d/client)
```
import { PrismaClient } from '@prisma/client'
const prisma = new PrismaClient()
```
or start using Prisma Client at the edge (See: https://pris.ly/d/accelerate)
```
import { PrismaClient } from '@prisma/client/edge'
const prisma = new PrismaClient()
```
See other ways of importing Prisma Client: http://pris.ly/d/importing-client
NestJSをトレースする準備
続いてNestJSをトレースするために以下のコードを準備します。
import * as process from 'process';
import { BatchSpanProcessor } from '@opentelemetry/sdk-trace-base';
import { NodeSDK } from '@opentelemetry/sdk-node';
import { HttpInstrumentation } from '@opentelemetry/instrumentation-http';
import { OTLPTraceExporter } from '@opentelemetry/exporter-trace-otlp-http';
import { Resource } from '@opentelemetry/resources';
import { SEMRESATTRS_SERVICE_NAME } from '@opentelemetry/semantic-conventions';
import { PrismaInstrumentation } from '@prisma/instrumentation';
import { GraphQLInstrumentation } from '@opentelemetry/instrumentation-graphql';
const exporterOptions = {
url: process.env.OTLP_TRACE_ENDPOINT ?? 'http://127.0.0.1:4318/v1/traces',
};
const traceExporter = new OTLPTraceExporter(exporterOptions);
export const otelSDK = new NodeSDK({
resource: new Resource({
[SEMRESATTRS_SERVICE_NAME]: 'NestJS - Prisma - Graphql',
}),
traceExporter,
instrumentations: [
new PrismaInstrumentation(),
new HttpInstrumentation(),
new GraphQLInstrumentation({
depth: 2,
}),
],
spanProcessors: [new BatchSpanProcessor(traceExporter)],
});
export const shutdown = async () => {
await otelSDK
.shutdown()
.then(() => console.log('Tracing terminated'))
.catch((error) => console.log('Error terminating tracing', error))
.finally(() => process.exit(0));
};
NestJSのメイン処理から上記のコードを呼び出してインストルメンテーションします
import { otelSDK, shutdown } from './tracing';
...略
async function bootstrap() {
process.on('SIGINT', shutdown);
process.on('SIGTERM', shutdown);
otelSDK.start();
const app = await NestFactory.create(AppModule);
...略
await app.listen(port);
}
bootstrap();
重そうな処理をトレースする準備
ここまである程度の情報は取得できるのですが、重そうな処理にはすでに当たりがついているのでコードを微修正してスパンをいくつか手動生成します。
import { trace, Span } from '@opentelemetry/api';
// ...略
const tracer = trace.getTracer('手動でインストルメンテーション');
return tracer.startActiveSpan('処理-1-1', async (span: Span) => {
try {
// 重そうな処理
// ...略
} finally {
span.end();
}
});
トレース結果を確認してみる
一通り準備ができたので実際にNestJSのGraphQL APIを呼び出して分析してみましょう。まずDockerコンテナを起動
docker-compose up
NestJSを起動
npx nest start
準備ができたので適当にチューニング対象のAPIを呼び出したあと、`http://localhost:16686`でjaegerのWeb UIにアクセスします。こんな感じでトレース結果が表示されていれば成功です。
トレースの詳細を確認してみましょう。
トレース結果をドリルダウンしていくと「処理-1-3」の中で繰り返し実行されている「処理-1-7」がボトルネックになっていそうなことが分かります。さらに「処理-1-7」をドリルダウンしてみます。
「処理-1-7」の中でPrismaのクエリが大量に発行されていることが分かります。いわゆるN + 1問題が原因で処理が遅くなっていそうですね。チューニングの初手として、まずはN + 1問題を解消するのが良さそうです。
まとめ
やはりJaegerのようなトレース結果をグラフィカルに表示できるツールを使うとボトルネックの特定が捗りますね。今回はローカル環境を用いた調査方法の紹介なのでJaegerを利用しましたが、AWS上で本番のワークロードを稼働させる場合はOpentelemetry Collectorの設定ファイルを微修正するだけで簡単にX-Rayにトレースデータを連携可能です。トレースデータを分析できる環境を用意しておくとパフォーマンス関連のトラブルシューティングが効率化するので、初期開発の段階からトレースデータを分析するための仕込みを入れておくと良いでしょう。
