Apollo Server に OpenTracing を導入してみたいけど・・・？

今回は OpenTracing の一例として、Apollo Server の GraphQL API のトレースログを出してみたいと思います。

Apollo にはありがたいことに OpenTracing 対応のモジュール "Apollo Opentracing" というモジュールがあるので、OpenTracing 仕様のログを出力するのは非常に簡単です。
先日の記事(【2019年10月版】TypeGraphQL なら ORM は TypeORM でしょう。)で作成いたしました Apollo Server とテスト用の docker-compose を改造して、Jeager, Zipkin でトレースログを出力してみたいと思います!

Jaeger でのトレースログ出力

それではまず、Jaeger へのログ出力を行ってみましょう。
以下の記事が非常に参考になるので(ほぼそのまま)、こちらの記事を参考に、Jaegerへの出力を行ってみたいと思います。

Apollo Server Integrated Performance Monitoring

1. モジュールの追加

以下のコマンドにてモジュールを追加します。

$ npm i apollo-opentracing jaeger-client @types/jaeger-client

apollo-opentracing と、今回は Jaegerを使うので、 jaeger-client を使用します。また、jaeger-client の型定義、@types/jaeger-client を追加しました。

2. Tracer の作成

先ほどの記事を丸パクリして tracer を作成します。

tracer.ts

import { initTracer } from 'jaeger-client';

const config = {
  serviceName: 'apollo-typeorm-opentracing',
  sampler: {
    type: 'const',
    param: 1,
  },
  reporter: {
    logSpans: true,
    collectorEndpoint: 'http://localhost:14268/api/traces',
  },
}

const options = {
  logger: {
    info(msg: string) {
      console.log('INFO ', msg)
    },
    error(msg: string) {
      console.log('ERROR', msg)
    },
  },
}

export const tracer = initTracer(config, options)

今回は Jaeger は docker-composeでサクッと起動しますので、接続先は localhost:14268 とします。

3. プラグインの投入

続いて Apollo Server のプラグインとして上記で作った tracer を登録します。apollo-opentracing 本家リポジトリの README にあるようにとりあえずシンプルなOpentracing 用 Extension を作成し、ApolloServer のコンストラクタで組み込みます。

server.ts

...
import { default as OpentracingExtension } from "apollo-opentracing";
...

  const server = new ApolloServer({
    schema, playground: true, introspection: true,
    extensions: [
      () => new OpentracingExtension({
        server: tracer,
        local: tracer
      })
    ]
  });
...

コードの対応は…なんとこれだけです！

4. Jaeger コンテナの追加

テスト用のコンテナ群に、Jaeger のコンテナを追加します。

今回は Jaeger のイメージは以下の AllInOneイメージを使用してしまいます。

https://www.jaegertracing.io/docs/1.14/getting-started/#all-in-one

test/docker-compose.yml

...(前回の続き)
  jaeger:
    image: jaegertracing/all-in-one
    environment:
      - COLLECTOR_ZIPKIN_HTTP_PORT=9411
    ports:
      - 5775:5775/udp
      - 6831:6831/udp
      - 6832:6832/udp
      - 5778:5778
      - 16686:16686
      - 14268:14268
      - 9411:9411

はい、以上です！

5. 動作確認

まず、例によって docker-compose でテスト用の関連サーバー群を立ち上げます。

$ cd test

$ docker-compose up

ログを垂れ流して、MySQL がちゃんと3306ポートを待ち受け開始したか確認してくださいね！

MySQL ポートが開かれたら、新しいターミナルから、以下のコマンドでApollo Serverを起動します。

$ npm start

ブラウザから Http://localhost:4000 を開き、立ちあがった PlayGrooundからGRaphQLのクエリをいくつか発行してみましょう。

そして、ブラウザから http://localhost:16686 にアクセスしてください。

Services に上記の Tracer作成で指定した、apollo-typeorm-opentracing を選択し、"Find Traces" をクリックしてください。

以下のようにいくつかのアクセストレースログが表示されるかと思います。

なかなかグラフィカルでいいですね！そして何より簡単！

ただし TypeORMの対応がまだ なので MySQL へ投げるクエリのOpentracing対応のログなどは自力でガリガリ実装する必要があるようです。。。

Zipkin 対応

TypeORM は OpenTracing 対応していませんが、Zipkin には SQL のログなどが出せるようなので Zipkin でもトレースログの出力を試してみます。

対象のソースコードは上記の Jaeger の続き…ではなく、前回の記事の続きからとなります。

1. モジュールのインストール

今回は以下のモジュールを追加いたしました。

apollo-opentracing
opentracing
zipkin-javascript-opentracing
zipkin
zipkin-transport-http

以下のコマンドでごっそりと投入いたします。

$ npm i apollo-opentracing opentracing zipkin-javascript-opentracing zipkin zipkin-transport-http

2. Tracer の作成

続いて Zipkin 用の tracer を作成いたします。

非常に簡易な Tracer ですが、以下の zipkin-javascript-opentracing 本家リポジトリのサンプルをそのまま拝借いたします。

https://github.com/DanielMSchmidt/zipkin-javascript-opentracing/tree/master/examples/vanillajs

src/tracer.ts

import { BatchRecorder } from "zipkin";
import { HttpLogger } from "zipkin-transport-http";
const ZipkinJavascriptOpentracing = require("zipkin-javascript-opentracing");

const recorder = new BatchRecorder({
  logger: new HttpLogger({
    endpoint: "http://localhost:9411/api/v1/spans"
  })
});

// Setup the tracer to use http and implicit trace context
export const tracer = new ZipkinJavascriptOpentracing({
  serviceName: "TypeGraphQL TypeORM Sample",
  recorder,
  kind: "client"
});

zipkin-javascript-opentracing は TypeScript の対応が出来ていないようなので require してしまいます。

エンドポイントは後ほど docker-compose.yml で作成いたしますが、localhost:9411 といたします。

3. TypeORM への仕込み

Zipking の TypeORM 用トレースログ流し込みプラグインとして zipkin-instrumentation-typeorm がありますが、今回はこれを使用したいと・・・思ったのですがバージョンが古くて現在の Zipkin には対応できていませんでした。
ちょっとした修正を行いましたので本家ではなく私のリポジトリを参照します。

以下のように dependencies に git のパスを直指定しておきます。

package.json

...
  "dependencies": {
  ...
    "zipkin": "^0.19.1",
    "zipkin-instrumentation-typeorm": "git:https://github.com/Yoshinori-Koide-PRO/zipkin-instrumentation-typeorm.git",
    "zipkin-javascript-opentracing": "^2.0.1", 
  ...
  }
...

で、 npm i を実行してください。

続いて以下のように TypeORM のコネクションをハイジャックいたします。

Database.ts

import { createConnection } from "typeorm";
import { TypeOrmInstrumentation } from "zipkin-instrumentation-typeorm";

import { tracer } from "./tracer"

export const connection = createConnection("local").then(con => TypeOrmInstrumentation.proxyConnection(con, { tracer: tracer._zipkinTracer, serviceName: "TypeGraphQL TypeORM Sample" }))

tracer は import したままだと Opentracing 用の Tracer なので内部オブジェクトの_zipkinTracerを使用します。

これで Zipkin に SQL のログが流れます。

4. Opentracing 用 Extension の作成

続いて、Jeagerの場合と同様に Extension を作成し、ApolloServer に組み込みます。

src/server.ts

import { tracer } from "./tracer";
import { default as OpentracingExtension } from "apollo-opentracing";

...

  const server = new ApolloServer({
    schema, playground: true, introspection: true,
    extensions: [
      () => new OpentracingExtension({
        server: tracer,
        local: tracer
      })
    ]
  });
...

OpentracingExtension でいろいろやってくれるようですね～。

5. Zipkin サーバーの準備

テスト環境用の docker-compose.yml に zipkin を追加します。以下の docker-compose-slim.ymlを使ってみました。

https://github.com/openzipkin-attic/docker-zipkin/blob/master/docker-compose-slim.yml

docker-compose.yml

...(前回の続き)
  zipkin:
    image: openzipkin/zipkin-slim
    container_name: zipkin
    # Environment settings are defined here https://github.com/openzipkin/zipkin/blob/master/zipkin-server/README.md#environment-variables
    environment:
      - STORAGE_TYPE=mem
      # Uncomment to enable self-tracing
      # - SELF_TRACING_ENABLED=true
      # Uncomment to enable debug logging
      - JAVA_OPTS=-Dorg.slf4j.simpleLogger.log.zipkin2=debug
    ports:
      # Port used for the Zipkin UI and HTTP Api
      - 9411:9411
    depends_on:
      - storage

  # Fake services allow us to compose with docker-compose-elasticsearch.yml
  # BusyBox is pinned to prevent repetitive image pulls for no-op services
  storage:
    image: busybox:1.31.0
    container_name: fake_storage

  dependencies:
    image: busybox:1.31.0
    container_name: fake_dependencies

6.実行と動作確認

例によって以下のコマンドで docker-compose を立ち上げます。

$ cd test

$ docker-compose up

ログを垂れ流して、MySQL がちゃんと3306ポートを待ち受け開始したか確認してくださいね！

MySQL ポートが開かれたら、新しいターミナルから、以下のコマンドでApollo Serverを起動します。

$ npm start

ブラウザから Http://localhost:4000 を開き、立ちあがった PlayGrooundからGRaphQLのクエリをいくつか発行してみましょう。

そして、ブラウザから http://localhost:9441 にアクセスしてください。検索ボタンをクリックしてデータのロードをすると、以下のようにアクセスログが表示されいると思います。

一つをクリックしてみると、内容が展開されて詳細が見れます。

こちらはAPIのインタフェース = Resolve のメソッドが呼び出されたログですね。

また、SQLの場合は以下のような感じで表示されます。

Zipkin はドリルダウンでどこにどれだけ時間がかかっているかがわかるのが魅力ですが、Apollo 用の Tracer と TypeORM用の Tracer がうまく連携できていないので別々のトレーサーとしてログが表示されています。う～ん、ちゃんと連携させるにはもう一工夫必要なようです。。。

とはいえAPIのアクセスログとSQLのトレースログが簡単に取れるので、これまでよりはボトルネックの割り出しが簡単にできそうです。
開発作業が収束してから重めの性能問題が発覚するのはキツイので、実装フェーズから積極的に Jaeger or Zipkin でのAPI性能チェックを開発作業に組み込めるようにしていきたいとおもいました。

Githubに上げました。

上記のサンプルですが、github に上げました！

Jaeger 版: https://github.com/Yoshinori-Koide-PRO/apollo-typeorm-functions/tree/jaeger
Zipkin 版: https://github.com/Yoshinori-Koide-PRO/apollo-typeorm-functions

ご参考にどうぞ～。