対象読者
この連載では以下の読者を想定しています。
- オブザーバビリティやOpenTelemetryに興味がある人
- SREやDevOps、Platform Engineeringに取り組んでいるエンジニア
- バックエンド開発者、クラウドエンジニア、インフラエンジニア
テレメトリーデータとは
オブザーバビリティの文脈で活用されるテレメトリーデータとして代表的なものを「オブザーバビリティの3本柱」と言うことがあります。 今回はこの3本に加えて、OpenTelemetryが最近サポートを宣言した新たな4種類目のデータも扱おうと思います。その4種類のデータとは、以下です。
- メトリクス：一定間隔の期間内で取得された測定値を統計的に処理したもの
- ログ：発生したイベント・事象について記録したもの
- トレース：サービスを構成する複数のコンポーネントをまたぐ一連の処理を順に記録したもの
- プロファイル：一定間隔の期間内で取得されたスタックトレースを統計的に処理したもの
この中で多くの人に馴染みがあるのは、メトリクスとログではないでしょうか。この2つは既に多くのIT運用の現場でも利用されています。
まずは、イメージを持ってもらいやすいこれらから扱っていきましょう。
メトリクス
メトリクスは、一定の時間間隔で取得された測定値を統計的に処理したものです。例えば、CPUやメモリの使用率、アプリケーションでのリクエスト処理数・エラー率・処理時間（一般にREDメトリクスと呼ばれます）、CDNでのキャッシュヒット率やDBコネクション数など、あらゆる種類のメトリクスがあります。
メトリクスは、問題の発生有無や問題傾向などを理解することに役立ちます。一方、メトリクスによって問題の原因を理解できることはそれほど多くありません。例えば、あるサーバーでCPU使用率が急騰し100%で張り付いてしまっているのを見た時「何か問題が起きていそう」ということはわかりますが、何故それが起きたかは分かりません。その時点における全体概況を把握するために利用するのがメトリクスです。
最もシンプルなメトリクスは以下のようなものです。
http_requests_total 1027
この http_requests_total というメトリクスは、その名の通りHTTPリクエストの総数を表しますが、HTTPリクエストには、例えばGET, POSTなどのメソッド別、ハンドラーのパス別など、さまざまな切り口に基づいて詳細に理解したくなるかもしれません。その切り口ごとにメトリクス名を分けていくということも考えられますが、メトリクスにディメンションを設けることで以下のように表現することができます。
http_requests_total{method="GET", handler="/home"} 527
http_requests_total{method="POST", handler="/api"} 123
http_requests_total{method="GET", handler="/about"} 377
こういった key-value 形式のラベルを付与することで、メトリクスの分析力を高めることができます。つまり、あるディメンションを持つメトリクスだけを検索したり、ディメンション別に集計したりできるわけです。ディメンションが豊富であるほど、きめ細かくシステムの状態を理解できるようになります。
ログ
さて、次にログです。ログは、発生したあるイベント・事象をタイムスタンプと共に記録したものです。
システムに関わる方であれば、ログに触れたことがない人はいないでしょう。LinuxやWindowsのシステムログ、アプリケーションが出力するアプリログ、ミドルウェアでのGCログ……など、例に困りません。
ログは、フォーマットが柔軟で、人間にとって読みやすいように内容や詳細度などを調整して出力させることが可能です。発生した事象を理解し、問題の原因を調査・確定するのに役立てることができます。
一方で、ログ自体はさまざまな場所に分散しています。ログごとにフォーマットも異なるので、機械的な検索・分析などには不都合が生じることもあります（ログ検索ソフトウェアを利用する場合は、データの構造化を試みたり、スキーマを定義したりする必要がある場合があります）。また、ログサイズ自体が大きくなりがちです。そのため、出力されたログの保管・転送・加工・分析に係るコストは高くなる傾向にあります。
Jun 27 09:34:42 CDZNSMPL systemd-resolved[122]: Clock change detected. Flushing caches. Jun 27 09:34:42 CDZNSMPL systemd[1]: Starting Daily apt upgrade and clean activities... Jun 27 09:34:43 CDZNSMPL systemd[1]: dpkg-db-backup.service: Deactivated successfully. Jun 27 09:34:43 CDZNSMPL systemd[1]: Finished Daily dpkg database backup service. Jun 27 09:34:44 CDZNSMPL systemd[1]: logrotate.service: Deactivated successfully. Jun 27 09:34:44 CDZNSMPL systemd[1]: Finished Rotate log files. Jun 27 09:34:52 CDZNSMPL systemd[1]: ua-timer.service: Deactivated successfully. Jun 27 09:34:52 CDZNSMPL systemd[1]: Finished Ubuntu Advantage Timer for running repeated jobs. Jun 27 09:34:58 CDZNSMPL systemd[1]: man-db.service: Deactivated successfully. Jun 27 09:34:58 CDZNSMPL systemd[1]: Finished Daily man-db regeneration. Jun 27 09:35:23 CDZNSMPL dbus-daemon[143]: [system] Activating via systemd: service name='org.freedesktop.PackageKit' unit='packagekit.service' requested by ':1.14' (uid=0 pid=7752 comm="/usr/bin/gdbus call --system --dest org.freedeskto") Jun 27 09:35:23 CDZNSMPL systemd[1]: Reached target Network is Online. Jun 27 09:35:23 CDZNSMPL systemd[1]: Starting PackageKit Daemon... Jun 27 09:35:23 CDZNSMPL PackageKit: daemon start Jun 27 09:35:24 CDZNSMPL dbus-daemon[143]: [system] Activating via systemd: service name='org.freedesktop.PolicyKit1' unit='polkit.service' requested by ':1.16' (uid=0 pid=7755 comm="/usr/libexec/packagekitd ") Jun 27 09:35:24 CDZNSMPL systemd[1]: Starting Authorization Manager... Jun 27 09:35:24 CDZNSMPL polkitd[7760]: started daemon version 0.105 using authority implementation `local' version `0.105' Jun 27 09:35:24 CDZNSMPL dbus-daemon[143]: [system] Successfully activated service 'org.freedesktop.PolicyKit1' Jun 27 09:35:24 CDZNSMPL systemd[1]: Started Authorization Manager. Jun 27 09:35:24 CDZNSMPL dbus-daemon[143]: [system] Successfully activated service 'org.freedesktop.PackageKit' Jun 27 09:35:24 CDZNSMPL systemd[1]: Started PackageKit Daemon. Jun 27 09:35:51 CDZNSMPL systemd[1]: apt-daily-upgrade.service: Deactivated successfully. Jun 27 09:35:51 CDZNSMPL systemd[1]: Finished Daily apt upgrade and clean activities. Jun 27 09:36:46 CDZNSMPL kernel: [ 1891.167151] mini_init (175): drop_caches: 1
トレース
次にトレースを見ていきましょう。
トレースは、あるサービスを構成する複数のコンポーネントをまたぐ処理を、その順に記録していったものです。特に分散環境においては分散トレース（Distributed Tracing）などと呼ばれることもあります。
例えば、あるユーザーが「商品を検索・閲覧」→「カートに追加」→「購入」→「支払い」→……と処理が実施されていったとします。それぞれの処理ごとにアプリケーション内の特定のコードが呼び出されますが、この処理の一つ一つを「スパン」と呼び、スパンの集合体のことを「トレース」として記録するのです。
以下は、OpenTelemetry Collectorでのトレースの処理に関する詳細ログの一例です。
2024-06-27T06:20:45.027Z info TracesExporter {"kind": "exporter", "data_type": "traces", "name": "debug", "resource spans": 1, "spans": 8}
2024-06-27T06:20:45.027Z info ResourceSpans #0
Resource SchemaURL: https://opentelemetry.io/schemas/1.6.1
Resource attributes:
-> service.name: Str(cartservice)
-> deployment.environment: Str(o11y-demo-jp0)
-> k8s.pod.ip: Str(10.42.0.71)
-> k8s.pod.name: Str(cartservice-67f75fb495-88g69)
-> k8s.namespace.name: Str(default)
-> k8s.pod.uid: Str(5973a638-e14f-4ed5-9eae-54538964dd4a)
-> k8s.node.name: Str(ip-10-0-0-14)
-> k8s.pod.labels.app: Str(cartservice)
-> host.name: Str(ip-10-0-0-14.us-east-2.compute.internal)
-> os.type: Str(linux)
-> k8s.cluster.name: Str(o11y-demo-jp0-k3s)
ScopeSpans #0
ScopeSpans SchemaURL:
InstrumentationScope
Span #0
Trace ID : 189e441788a6264d39a2c5204ffbc64a
Parent ID :
ID : 5944405df606e974
Name : grpc.request
Kind : Server
Start time : 2024-06-27 06:20:42.762399 +0000 UTC
End time : 2024-06-27 06:20:42.764177 +0000 UTC
Status code : Unset
Status message :
Attributes:
-> grpc.method.path: Str(/grpc.health.v1.Health/Check)
-> grpc.method.service: Str(Health)
-> grpc.status.code: Str(0)
-> signalfx.tracing.version: Str(0.2.4.0)
-> component: Str(Grpc)
-> grpc.method.name: Str(Check)
-> signalfx.tracing.library: Str(dotnet-tracing)
-> grpc.method.package: Str(grpc.health.v1)
-> grpc.method.kind: Str(unary)
Span #1
Trace ID : 189e441788a6264d39a2c5204ffbc64a
Parent ID : 5944405df606e974
ID : 1083e428c8f7d683
Name : Clear local DB
Kind : Client
Start time : 2024-06-27 06:20:42.763998 +0000 UTC
End time : 2024-06-27 06:20:42.764003 +0000 UTC
Status code : Unset
Status message :
Attributes:
-> peer.service: Str(mysql:LxvGChW075)
-> db.system: Str(mysql)
-> db.statement: Str(DELETE FROM 'cart' WHERE 'cartid' = ($1))
Span #2
Trace ID : 189e441788a6264d39a2c5204ffbc64a
Parent ID : 5944405df606e974
ID : 2b85ddd74b887ded
Name : Cache_Hit
Kind : Client
Start time : 2024-06-27 06:20:42.76399 +0000 UTC
End time : 2024-06-27 06:20:42.763996 +0000 UTC
Status code : Unset
Status message :
Attributes:
-> db.system: Str(mysql)
-> db.statement: Str(SELECT 'products'.* FROM 'products' WHERE 'productid' = ($1))
-> peer.service: Str(mysql:LxvGChW075)
じっくり読み解けば、同一のトレースIDのもとに複数のスパンが取得されており、親子関係があることなどを理解できるのですが、視覚的にはなかなか理解しづらいものです。そのため、こういったトレースを以下のようなウォーターフォールチャートの形で可視化するのが一般的です。
いわゆるAPM（Application Performance Monitoring）ソリューションを利用して「計装（Instrumentation）」を行うと、これらのトレース情報を取得することができるようになります。アプリケーションの言語によってはAPMエージェントをアプリケーションと一緒に起動するだけで情報取得が開始できます（自動計装と言います）。まずは手軽に自動計装から始めて、更に緻密な情報が欲しくなってきたら、アプリケーションのコード内でスパンを生成するなどの工夫を加えていく（手動計装と言います）のが一般的なアプローチです。
トレースは、イベントの記録という意味ではログの一種とも言えます。
分散的な環境では、サーバーやアプリケーションごとに散在したログを集めてきて突き合わせていく必要がありましたが、トレースは一連の処理の順に記録し可視化・分析に利用できるものなので、サービス間の依存関係を理解でき、一連の処理の中でどこで問題が発生したか、どこに処理時間がかかったかなどを理解するのには非常に有用です。
一方で、トレースデータ取得に際して手動計装を行う場合、アプリケーションのコードに手を加える必要が出てきます。ログ出力のコードを埋め込むイメージではあるのですが、ハードルを感じてしまう方がいるのも事実です。また、取得されたデータの取り扱い、分析手法などについても、まだまだIT運用の世界に定着したものとは言えません。少しずつ利用者や活用事例が増えていくその最中にあるのがトレースデータであるとも言えるでしょう。
プロファイル
最後にプロファイルです。OpenTelemetryは、2023年にログ、メトリクス、トレースに関する仕様の安定化を発表しましたが、2024年3月にプロファイリングについてもサポートを発表しました。同年中の実装安定化を目指して取り組みが続いています（OpenTelemetry announces support for profiling | CNCF）。
プロファイルは、一定の期間におけるスタックトレースを統計的に処理したものを指します。アプリケーションに含まれる関数やメソッドのレベルでその実行回数や実行所要時間、CPU使用率、メモリ使用量、I/O操作などを取得・分析することで、コードレベルでのパフォーマンス特性を理解できるようになります。
プロファイリングデータは一般的にはフレームグラフによって可視化します。各メソッドや関数が一つの枠（スタックフレーム）として表示され、その枠の大小によって処理時間の長さが表されます。また、あるメソッドや関数を呼び出している元のメソッド・関数がスタックとして積み上げられていきます。こうしたできた「高原」と「塔」に着目し、パフォーマンス特性を解析していきます。大きな高原になっている部分は、その関数が呼び出された回数が多いか、その関数の処理時間が長いことを表します。また、高い塔はスタックの深さを示し、上下のフレームを辿っていくことでパフォーマンス問題がどのように伝搬されていくかを理解することに役立ちます。
プロファイルは、パフォーマンス問題が起きた時間のデータがないとボトルネック特定には役立ちません。昨今では継続的プロファイリングとして、短い間隔で定期的にプロファイルデータを取得することでアプリケーションへのオーバーヘッドを抑えつつ、過負荷時のプロファイルを遡って確認できるようにする実装が行われています。一方、トレースと同様、プロファイルデータの取得や分析・解釈手法などは普及の途上であり、実用的なインサイトを得られるようになるには一定の学習が必要になる場合があります。
