オブザーバビリティー?

“observability” という言葉をよく聞くようになりました。以前よりは、ですが。長くて、カタカナで書いても正しく書けたか自信がないです。上に書いたのも、変換をミスったりして二度ほど書き直しました。そもそも手元の IME で変換できていないような気がしています。Internationalization を i18n と書くように、o11y という表現もあるようですが、もう何がなんだかです。

意味合いとしては、システムの “見える化” を進めようよ、ということと捉えています。サーバーで動くシステムが複雑になると、どんどん内在する問題が見えにくくなっています。様々なデータを集めて可視化することで問題の早期発見やパフォーマンスの改善に活用していきたいところです。

マイクロサービスのボトルネック…?

機能を細分化するメリットももちろんありつつ、問題が起きたときにその調査が難しくなるようなことも多いです。 たとえばある API が妙に時間がかかっているというときに、API 処理の CPU 時間が原因なのか、そこからの DB 処理待ちなのか、ファイル書き込みが遅いのか、… などなど、原因特定に時間がかかることがあります。本番環境でしか発生しないようなことも多く、そういった要素が絡み合ってデバッグの難易度を高くします。

今回は、Open Telemetry の Trace 機能を使って、どの処理にどれくらいの時間がかかっているのかをどのように視覚化できるか見てみようと思います。今回 GCP は使いますが Cloud Run などの GCP で利用可能なものに限ったものではなく、オンプレ等で動くカスタムアプリケーションにも仕込める想定でやってみます。プログラムへの組み込みが必要になってはしまいますが。

そして相変わらずわたしの都合で例は nodejs です。注意点として、node 向けの Open Telemetry の library は完成度が他言語に比べてイマイチな印象で、かつ変更も早いようです。ともあれ言語の選択要件はシステムによってさまざまですので、ここでの例は “例” としてご参照いただければと思います。

サンプル！

忙しい人のためにしては前置きが長くなりすぎました。ここで一気にスピードを上げて、いなきりサンプルコードを出して完結したいと思います。

const opentelemetry = require("@opentelemetry/api");
const { NodeTracerProvider } = require("@opentelemetry/sdk-trace-node");
const { SimpleSpanProcessor } = require("@opentelemetry/sdk-trace-base");
const { TraceExporter } = require("@google-cloud/opentelemetry-cloud-trace-exporter");

const provider = new NodeTracerProvider();
const exporter = new TraceExporter();
provider.addSpanProcessor(new SimpleSpanProcessor(exporter));
opentelemetry.trace.setGlobalTracerProvider(provider);
const tracer = opentelemetry.trace.getTracer("basic");


async function delay(time) {
  return new Promise(resolve => setTimeout(resolve, time));
}

(async () => {
  const s0 = tracer.startSpan('Root span');
  s0.setAttribute("kind", "http"); // GCP Trace 画面では label として表示される
  const c0 = opentelemetry.trace.setSpan(opentelemetry.context.active(), s0); // span に親子関係をつけるための context

  const s1 = tracer.startSpan('Child span 1', undefined, c0);
  delay(700).then(() => {
    s1.end();
  });

  const s2 = tracer.startSpan('Child span 2', undefined, c0);
  await delay(100);
  s2.end();

  const s3 = tracer.startSpan('Child span 3', undefined, c0);
  await delay(200);
  s3.end();

  s0.end();
  console.log('done');
})();

ちょっと長いですが、これで全部です。後ほどの画像で見るとわかりやすいですが、ちょっと欲張って親子関係のある span を使っているので後半がすこし長くなっています。サンプルとして GCP document のこのへん を参照しています。

GCP に Trace data を送信するために、実行環境に権限付与が必要です。GCE instance であればその service account に、“Cloud Trace Agent” role を付与しておきましょう。手元やオンプレサーバーで実行する場合は、key file を生成して環境変数 $GOOGLE_APPLICATION_CREDENTIALS にその path を入れておくなどの準備が必要です。いずれにしても一般的な手順なので、ここでは省略します。

あっ、そして忘れかけていました。上記コードでもだいたいわかりますが、node module の install が必要です。今回確認した際の package.json も載せておきます。これを置いて npm install することで必要なものが揃うと思います。ちなみに node は v17.7.2 を使用しました。

{
  "dependencies": {
    "@google-cloud/opentelemetry-cloud-trace-exporter": "^1.1.0",
    "@opentelemetry/api": "^1.0.4",
    "@opentelemetry/sdk-trace-base": "^1.0.1",
    "@opentelemetry/sdk-trace-node": "^1.0.1"
  }
}

取れた Trace を見てみる

Open Telemetry で送信した Trace データは、GCP Operation Suite 内 Trace のところで視覚的に利用することができます。

非常にわかりやすいです。API ひとつの処理の中で、http 通信や DB 処理など大きめの単位の前後にそれとわかるように名前をつけておくとよいでしょう。これを使わず、log に " —- DB 通信開始 —- " などと出力したものを後で検索するのとを比べると雲泥の差があります。

データ量が少ないのでイマイチですが、時系列での分散具合もわかりやすく視覚化されます。

注意点

今回、JavaScript + Open Telemetry + GCP という組み合わせでやってみましたが、実は、span を親子で組み合わせて記録する方法の例が少なく、見つけるのに苦労しました。

library の version up でやり方が変わったりしているのが原因のひとつでもあるらしく、今後もそういった状況が続く可能性があります。Python や Go などでは状況がもう少しマシなのかな… とは思いつつ、確認はできていません。

まとめ

今回は「個別に実装は必要ですが、処理の内容を細分化して、どの部分にどれくらい時間がかかっているか、それぞれの処理タイミングがどう影響しているかを可視化する」方法を試しました。

継続的な運用から Trace データがある程度の量蓄積されると、統計的な観点からの重要な発見というのも期待できます。このような手段をどんどん取り入れて、システムの効率向上や問題の早期発見を目指しましょう。