Stackdriver Traceの導入とCustom Tracing APIによる分析の詳細化

リクルートテクノロジーズの高尾です。

Recruit Engineers Advent Calendar 2019 – Adventar の17日目(12/17)のエントリーです。

Stackdriver Trace の導入と、さらに踏み込んだ利用方法について、まとめました。

Stackdriver Traceとは

Google Cloud が提供する分散トレースシステムです。

Stackdriver Trace の説明は、本記事では割愛します。

詳細は以下のサイトをご参照ください。

導入メリットについて

Stackdriver Trace を導入するメリットとして、以下のものが挙げられます。

どこで問題が発生したかの調査が容易
各処理の処理時間を俯瞰できる

1.については、障害発生時に大きなアドバンテージになりますし、2.についてもパフォーマンス問題が発生した時に重要な手がかりとなります。

サービスの継続のために入れて損のない、仕組みかと思います。

Stackdriver Traceの導入

ここからは、Stackdriver Traceの導入方法について説明していきます。

導入にあたって必要な手順は大まかに2つの作業が必要です。

Stackdriver Trace APIの有効化
各言語毎のAgentの導入

1.について

Google Cloud Console 上から、 API を有効にします。

2.について

公式で用意されている実装は、以下の8つです。(2019/12/10現在)

C# ASP.NET Core
C# ASP.NET
Go
Java
PHP
Python
Ruby

詳細は以下をご参照ください。

今回は、この中から Node.js の導入方法について、ピックアップして説明していきます。

@google-cloud/trace-agent を依存関係に追加

npm install --save @google-cloud/trace-agent

1	npm install --save @google-cloud/trace-agent

エントリーポイントに @google-cloud/trace-agent の呼び出し処理を追加

require('@google-cloud/trace-agent').start();

1	require('@google-cloud/trace-agent').start();

基本的には、上記 2 Step で導入は完了します。

@google-cloud/trace-agent を導入すると自動的に以下 Framework や各種RPC のイベントをトレースしてくれます。

導入時の注意点

基本的に導入が簡単な、 @google-cloud/trace-agent ですが、 Node.js の資産を Webpack などで bundle する際は注意が必要です。

先に述べたとおり、 @google-cloud/trace-agent は自動的に各種イベントをトレースします。つまり、依存関係の解決を動的に実行しています。

そのため、webpack などで bundle を実行した時点では依存関係の解決ができておらず、トレース処理の実装が Tree Shaking で落とされてしまいます。

この問題を回避するためには、以下のような対策が必要です。

@google-cloud/trace-agent を bundle 対象から外す
bundle した JS ファイルを起動する別の JS ファイルを用意する

Custom Tracing API について

Stackdriver Trace 導入するだけで様々な情報をトレースすることができますが、既存の設定だけでは少し不便な点が出てきます。

例えば、以下のような処理毎の時間は既存の設定だけでは取得することができません。

DNS Lookup
TCP 接続
Rendering 処理 (SSR(Server Side Rendering) をしている場合のみ)

これらの情報は Custom Tracing API を利用することで、トレースすることが可能です。

必ずしも必須の情報ではありませんが、パフォーマンスボトルネックの特定を容易にすることが出来るようになります。

Custom Tracing API の利用方法

Custom Tracing API の利用方法はシンプルです。

ChildSpan の作成
endSpan() の呼び出し

例えば、SSR(Server Side Rendering)の実行時間を測定したい場合は、以下のように記述します。

const tracer = require('@google-cloud/trace-agent').start();
// ...
const ssrSpan = tracer.createChildSpan({ name: 'renderToString' });
const content = renderToString(jsx);
ssrSpan.endSpan();

const tracer = require('@google-cloud/trace-agent').start();

// ...

const ssrSpan = tracer.createChildSpan({ name: 'renderToString' });

const content = renderToString(jsx);

ssrSpan.endSpan();

基本的には、計測したい処理を span で囲めば詳細なトレースが可能となります。

ただし、 DNS Lookup や TCP 接続の時間などを計測したい場合は、少し工夫が必要です。

具体的には shimmer というライブラリを利用して、 http パッケージにモンキーパッチを当てる必要があります。

一からモンキーパッチを当てることは少し骨が折れますが、幸いなことに Google が @google-cloud/trace-agent 用の plugin を公開してくれています。

こちらのコードに30行ほどのパッチを当てることで DNS Lookup や TCP接続の処理時間を計測することが可能となります。

※処理時間の計測ロジックは、古川さんの httpstat を参考にさせていただきました。

// ...

    res.on('end', () => {
        if (transferSpan != null) transferSpan.endSpan();
        span.addLabel(api.labels.HTTP_RESPONSE_SIZE_LABEL_KEY, numBytes);
        span.addLabel(api.labels.HTTP_RESPONSE_CODE_LABEL_KEY, res.statusCode);
        span.endSpan();
    });
    if (callback) {
        return callback(res);
    }
});

// DNS Lookup / TCP接続 / SSL Handshake の処理時間計測

let dnsSpan = api.createChildSpan({ name: 'DNS Lookup' });
let tcpConnectionSpan;
let sslHandshakeSpan;
api.wrapEmitter(req);
req.on('socket', (socket) => {
    api.wrapEmitter(socket);
    socket.on('lookup', () => {
        if (dnsSpan != null) {
            dnsSpan.endSpan();
            dnsSpan = null;
        }
        tcpConnectionSpan = api.createChildSpan({ name: 'TCP Connection' });
    });
    socket.on('connect', () => {
        if (tcpConnectionSpan != null) {
            tcpConnectionSpan.endSpan();
            tcpConnectionSpan = null;
        }
        if (protocol === "https:") sslHandshakeSpan = api.createChildSpan({ name: 'SSL Handshake' });
    });
    socket.on('secureConnect', () => {
        if (sslHandshakeSpan != null) {
            sslHandshakeSpan.endSpan();
            sslHandshakeSpan = null;
        }
    });
});

// ...

// ...

res.on('end', () => {

if (transferSpan != null) transferSpan.endSpan();

span.addLabel(api.labels.HTTP_RESPONSE_SIZE_LABEL_KEY, numBytes);

span.addLabel(api.labels.HTTP_RESPONSE_CODE_LABEL_KEY, res.statusCode);

span.endSpan();

});

if (callback) {

return callback(res);

}

});

// DNS Lookup / TCP接続 / SSL Handshake の処理時間計測

let dnsSpan = api.createChildSpan({ name: 'DNS Lookup' });

let tcpConnectionSpan;

let sslHandshakeSpan;

api.wrapEmitter(req);

req.on('socket', (socket) => {

api.wrapEmitter(socket);

socket.on('lookup', () => {

if (dnsSpan != null) {

dnsSpan.endSpan();

dnsSpan = null;

}

tcpConnectionSpan = api.createChildSpan({ name: 'TCP Connection' });

});

socket.on('connect', () => {

if (tcpConnectionSpan != null) {

tcpConnectionSpan.endSpan();

tcpConnectionSpan = null;

}

if (protocol === "https:") sslHandshakeSpan = api.createChildSpan({ name: 'SSL Handshake' });

});

socket.on('secureConnect', () => {

if (sslHandshakeSpan != null) {

sslHandshakeSpan.endSpan();

sslHandshakeSpan = null;

}

});

// ...

plugin の実装は TypeScript で記述されているので、取り込むプロジェクトの構成によって適宜 JavaScript に読み替える必要があります。
パッチを当てた plugin は Stackdriver Trace の起動処理で plugins の引数として渡せば有効化することができます。

const path = require("path");
const tracer = require('@google-cloud/trace-agent').start({
    plugins: [
        // パッチを当てた plugin
        http: path.join(__dirname, "plugins", "http.js"),
    ]
});