オブザーバビリティにおけるプロファイルの重要性　pprofを活用するメリットをGoogle CloudのDeveloper Advocateが語る

Observabilityにおけるプロファイルの重要性

山口能迪氏（以下、ymotongpoo）：山口です。Google CloudでDeveloper Advocateをしていて、担当はObservabilityとGoです。

つい最近までは「Stackdriver」と呼ばれている製品群があったのですが、名前が変わりまして「Cloud Operations」という名前になっています。「Stackdriver」というブランドが消えてその下にあるいろんな、例えばロギングとかモニタリングとかいうのが今までは「Stackdriver Logging」とか「Stackdriver Monitoring」とかだったんですけど、全部「Cloud Logging」とか「Cloud Monitoring」とかそういう名前になりました。それらを担当しています。あと、オープンソースだとOpenTelemetryとかをやっています。

今日話すことは、先ほどのセッションでObservabilityの3本柱みたいな話が出てきたと思うんですけど、「このObservabilityというのはシステムの状態を見える化するためのものです」みたいな話があるなかで、「そのためにはログとメトリクスと分散トレースが必要ですね」ということがよく言われています。

Googleの製品だと「Cloud Logging」「Cloud Monitoring」「Cloud Trace」があって、それぞれ（ログ、メトリクス、分散トレースに）対応しています。

それらを実際そのログとかトレースとかメトリクスがどこをカバーしているかを見て行こうと思います。

左側はアプリケーションを動かしてるときの各レイヤーです。一番左は分散トレースですけど、分散トレースは、基本的にはアプリケーション間・サービス間の通信とか、あるいはサービス内での関数とか、そういう処理のレベルでのレイテンシーを見るために使っているので、一番カバーしている領域、レイヤーが浅いです。

ログは、アプリケーションログやランタイムログを見ることが、アプリケーションを運用する上、多いです。あるとしたら、コンテナランタイム取ればDockerでもいいですしKubernetesでもいいですけど、コンテナランタイムのログとかは運用の上では見るけれども、アプリケーションのパフォーマンスとかそういったところではあんまり見ない部分ではあるかなと思います。

メトリクスに関して言うと、アプリケーションレイヤーで必要なメトリクスありますよね。例えばECサイトを運用してたら「カートの中に入ったアイテムがいくつか？」みたいなレベルから「ユーザーがどのくらい来ました」というようなものです。

そういうアプリケーションレイヤーのものあれば、アプリケーションランタイム、JavaとかPythonとか、 VMベースのプログラムもそうですし、Cだと下のレベルになりますが、そういったところで特有の「ヒープサイズどれぐらいかな？」とか、あるいは「CPU timeはどれぐらい使っているのかな？」ということも取得するので、幅が広いです。

Metricsとプロファイラーの違い

今日お話しするのはプロファイラーの話なんですけど、プロファイラーがどこをカバーしているかというと、アプリケーションのレベルからコンテナのランタイム、普通にベアメタルで動かしているんだったらOSのレベルまで全部見ています。プロファイラーとメトリクスは同じような領域をカバーしているけど、じゃあ実際に何が違うかについて話します。

メトリクスというのは自分でだいたい定義するわけですよね。例えば、これはECサイトの注文のハンドラのサンプルコードをGoで書いてみたんですけど、metricsパッケージというのがどこかメトリクスのバックエンドにデータを送っているとして、ItemCountみたいのがあって、ハンドラの中で自分で書いてあげないといけません。

例えば、ある処理がどれぐらい時間かかったかというのも自分で測って送るとか、ミドルウェア的なものが測ってくれることもありますけど、自分で何か意思を持って「こういうデータが欲しい」というものを自分で計装（instrument）して送るみたいな感じです。　そうやって送ってあげると、時系列データ（time series data）がこういう右側のようなかたちでグラフで出ます。あるいは、ある程度バケットにデータをバーっと入れて分散を見ると、なにかヒートマップのようなものが出ます。基本的には時系列データですよね。

プロファイルは何かというと、Goの場合はpprofというのが標準のパッケージでありますし、JavaとかだったらJFRがありますが、基本的には全部ランタイムで動いているなかで、そのなかでこのランタイムの中のスタックトレースをサンプリングして、それをある程度の長い時間取って、そのいくつか取ったプロファイルのデータをパッとまとめて、統計データとしてスナップショット的に表示するというのがプロファイルの使い方です。

なので、違いはなにかというと、メトリクスは自分が取りたいと決めた任意のデータを取っていくものです。インターバルに関しても、時系列でバーっと並べていくようなことが多いので、サンプルする期間はかなり短いです。長くても1分とか数分ぐらいの単位かなと思います。あと、そのデータの扱い方にしても、時系列データを扱います。

一方、プロファイルは基本的にはランタイムの中のスタックトレースを見ていくようなかたちになるので、そのスタックトレースを並べるときにどういう基準で並べるかは事前に定義されていて、CPUの使用率、メモリの使用率、あとスレッドの数とか、そういうものを使うことが多いと思います。プロファイルは（取得する内容を）自分で決めることはあまりありません。

サンプリングする期間は、統計的にデータをスナップショットして扱わなきゃいけないので、かなり長い時間計測することが多いかなと思います。だいたい10分ぐらい取ることが多くて、それ以上長く取ることもあると思います。データの表示の扱い方としては、統計データとしてスタックトレース等を使ってバッと1枚の絵で並べるという感じになると思います。

katzchang：ごめん。これは、プロファイラーはもしかしてサンプルで取ったやつの統計値なんだ？

ymotongpoo：そうです。別に一発流して取ることも多いですけど。一発その……例えばなんだろうな。

バッチファイルみたいなものを動かして、そのバッチが動いている間のデータを取るというのはあるかもしれないけど、そのデータを取るにしても、基本的には中で動いているので、例えば一番下のレベルまでいくと同じ関数が何回も呼ばれているはずなので、それを全部合計値取ったりとかするというのはパフォーマンス的に問題が出る場合もあるので、サンプルで取ったりします。

1回しか動かないんだったらもちろん最初から最後まで動かしてそれでおしまいってするかもしれないけど、いわゆるWebサービスとかだとデーモン的に動いているので、その時その時のサンプルデータを取って、あとで平均というか。

katzchang：まとめて。

ymotongpoo：統計データとしてまとめてとる感じになります。

プロファイラーを使うと、パフォーマンスの原因を探りやすい

ymotongpoo：なぜプロファイラーを使うかというと、結局メトリクスは自分で「このデータ取りたいです」というのを決めなきゃいけないし、それから漏れたものに関しては自分ではわからなくなります。

あと、メトリクスは前後関係がわからないですよね。例えば、あるリクエストが来たときに、ある処理をする時間を測っているようなメトリクスがあったとします。そのメトリクスが時間がかかりましたといったときに、なんで時間がかかったかというのはわからない。だから、そこから数字を見たあとに「じゃあ中を調べてみましょう」という感じでソースコード全部見たりとか、いろんな情報とつなぎ合わせないとわからない。

一方で、プロファイラーはもうやることは決まっていて、CPUの使用時間、ヒープのサイズとかスレッドの数、そういう決まりきったメトリクスしか見ることができません。でもその代わりに、「そのメトリクスがなんで遅くなったか？」みたいな前後関係はプログラムの中で全部表示してくれます。なので、何が原因で処理が遅いか特定する用途で使うときにはすごく使いやすいです。

だから、何かパフォーマンス的に問題があるみたいなときに、その原因を探すのにはすごく使いやすいのがプロファイラーですね。

pprofの紹介

今日紹介するのはpprofというものです。GitHubの「google/pprof」というところでOSSとして公開されているプロファイラーがこのpprofです。主にデータのビジュアライズとアナライズをするためのツールです。

よくGoで同梱されているので、pprofはデータの収集とかプロファイルデータを取ってくるのもやってくれると思っている人が多いんですが、pprofはただ単にデータの可視化と解析をすることしかしてくれません。

じゃあそのデータを取ってくる場合ってどういうふうに取ってくるのかというと、protoファイルがもう定義されていてprofile.protoというprotoの型が定義されているので、その型どおりにデータを吐きさえすればどんな言語でも使えます。実際にサードパーティで、RubyとかPerlとかで自分のランタイムとかのプロファイル情報を吐き出すツールを書いている人がいます。

さっきも言いましたけど、Goはpprofを標準に同梱した状態で配布されているので、Goユーザーはプロファイルをするといったら、だいたいのパターンがpprofをそのまま使うというかたちになっています。

pprofの使い方

pprofを使うのはすごく簡単で、デーモンとかWebサーバを動かす場合のプロファイルを取る場合はこの「net/http/pprof」が使えます。どうやって使うかというと、1行インポートのところに「net/http/pprof」を空にしてimportしてくださいというふうにすれば、勝手にいろいろよしなにやってくれます。

それをインポートしてビルドしてそのアプリケーションを動かしたら、HTTP GETで「[root]/debug/pprof/profile」というところに例えばアクセスすると、CPUプロファイルのデータが取れると。URLパラメータとか指定すると、その取得する時間が例えば30秒とか1分とか、そういうふうに長い時間データが取れます。

katzchang：これはエンドポイントを叩くことによってプロファイルを開始する、みたいな感じ？

ymotongpoo：そう、エンドポイントを勝手に生やしてくれるので、エンドポイントを叩けば勝手にプロファイルのデータを取得して、そのプロファイルのデータを返してくれます。

katzchang：へえ、おもしろい。

netmarkjp：自分で仕込んでおいて、スイッチをしないといけないですね。。

ymotongpoo：はい。その差し込むのはこれだけでできるという話ですね。「net/http/pprof」をインポートするだけでできます。

netmarkjp：ISUCONのときに使いました。

katzchang：（笑）。

ymotongpoo：それでは取得したデータをどうやって解析するか説明します。CLIで解析する方法もあるんですけど、Web UIを使うと非常に見やすいのでWeb UIを使います。このgo toolの中、go tool pprofに-httpというオプションをつけて、さっき取ってきたプロファイルデータを引数として与えてあげると、Web UIが起動して出てきます。

Web UIのメニューは6種類ぐらいあって、TopとGraphとFlame GraphとPeekとSourceとDisassembleというのがあるんですけど、今日は時間の都合上Graphだけ紹介します。

プログラムのパフォーマンスの悪い箇所を素早く特定できる

これはCPU Profile図です。どうやって見るかというと、基本的には赤くてでかい箱が（パフォーマンスが）悪いところです。

なので、赤くてでかい箱を見たら、こいつが原因で遅くなってるとか、こいつがなんか余計なリソース食ってるということがすぐにわかります。

例えばこの図でいうと、右下のjsonのDecoderというstructのポインタのメソッドのreadValueというのがでかいじゃないですか。この見方でいうと、これCPU Profileなんですけど、「18.53秒 of 48.11秒」って書いてあって、これ「48.11秒」というのが、上から、jsonの矢印の元ですね、jsonのDecoderのポインタのメソッドのDecodeというのが使っている時間のうち、「48.11秒」がそのjsonのDecoder readValueが使っています。その「48.11秒」のうち「18.53秒」が、このメソッドの中、要はブロックなし、呼び出していない、Flatというんですけど、その中で実装されているコードが原因で遅くなっていることがわかります。

「41.8秒－18.5秒」の残りの30秒ぐらいはどこかほかの関数を呼び出してて、そのブロックして待っている時間が30秒ぐらいあるというのが見方なんですね。だから、これがjson Decoder readValueをいっぱい呼んでるから、この呼んでるやつを倒していけばいいというのが見方です。

これ別の資料で発表しているので、それを見てもらえればいいと思うんですけど、これ（CPU Profileの図）が見えるようになるとどうなるかというと、プログラムのどこが遅いのかがわかるので、その遅いところを見ていけば早くプログラムの遅いところを修正することができます。

バージョン、リビジョン間のパフォーマンスの変化がつかめる

これを一発、単発でやっても仕方ないので、継続的にpprofをしましょうというのが今日の話です。

継続的にpprofをするということは、定期的にpprofのエンドポイントを生やしたサービスに対してリクエストを投げて、プロファイルデータを定期的に取ってこなければいけません。そのために、比較のためにどのバージョンで動いてたときはこのプロファイルで、どのバージョンで動いていたときはこのプロファイルなのかわかるようにします。そのためのバージョンとかリビジョンとかをちゃんとアプリケーション内にエンベッドしてあげましょう、というのが提案です。

例えばリビジョン番号をビルドする際に埋め込んであげると。オプションでldflagで-Xというのをやると、プログラム内の変数に外から値を渡せるので、値を渡した状態でビルドができるので、こういう感じでバージョンとかリビジョン番号とかをプログラムの中に埋め込んだ状態で起動します。

実際今動いているバージョンとかを返すようなエンドポイントを用意してあげれば、外からどのバージョンが動いているかの情報が取れるので、こういう仕組みを用意しておきましょう。

これを1回叩いてバージョンとかリビジョンを取得した状態で、今度はプロファイルのエンドポイントに対して、そのバージョンとリビジョンのプロファイルデータをファイル名で返してくださいという感じで投げてあげると、そのとき、そのバージョン、そのリビジョンのプロファイルデータが取得できます。

ただ単に各バージョンとリビジョンのプロファイルデータを並べておいてもしょうがないので、改善されているかどうかを比較するのがこの-baseオプションです。

この-baseオプションを使うと何が起きるかというと、さっきのGraphでプロファイルデータを表示したときに、速くなっているところと改善されたところは緑になるんです。ダメになったところ、遅くなったところ、例えばメモリだったらメモリをもっといっぱい食うようになったところとかは、赤く表示されます。なので、2個並べて、常に緑だけがいっぱいになるようにすれば常に改善が起きているのがひと目でわかるのがこの図です。

katzchang：便利だ。

ymotongpoo：さっきの図だと単純に前の四角から次の四角にどれだけリソースが食われているかというのが遷移図しかなかったんですけど、比較バージョンで使うと、こうやって前のプロファイルに比べてどのぐらいリソースが使われなくなったかが一目瞭然でわかるようになるので、「おお、改善しているな」というのが可視化されます。

今までのpprofの使い方だと、全部ただ単にwgetしたりだとか、ビルド時にバージョンを埋め込んだりとかするだけなので、これは機械的にできるはずです。なので、これをCI/CDのプロセスに組み込んであげれば、あとは人間が特定の、常に1個前のバージョンと今の最新バージョンでのプロファイルの比較データを見れるような簡単なWebサーバを手元に用意しておいてあげると、すごく効率よく改善ができるというのがContinuous pprofの考え方です。

pprofはGoogleの社内でもバンバン動いている

katzchang：あっ、ちょっと1個聞いていい？　pprofって、CI/CDだと当然人工的な環境で動かすことになると思うけど、本番系でこれを動かすという運用も想定してたりする？

ymotongpoo：想定しています。実際にContinuous pprofというのは、外向きにはあまり言ってないですけど、Googleの社内でバンバン動いています。

katzchang：おお、すごい。

ymotongpoo：本番用に使ってるサービスでも普通にこのpprofと同じものを使って、ちょっとForkしてますけど、基本的にはこのpprofと同じものが動いていて、ばんばんプロファイルデータを取ってきて、常にプロファイルデータを比較しています。

katzchang：ポートを分けてるから基本的には外から見えないようになってるし、みたいなのも……。

ymotongpoo：それは外からは見えない。普通に外向きには、GFE（Google Front End）があって、そこからしかアクセスできないようになっているので、塞がれているけれども、社内的にはプロファイルを取るためのエンドポイントみたいのは開けてあって、常に定期的にヘルスチェックみたいなかたちでプロファイルデータを取りにいっています。

katzchang：おもしろい。

ymotongpoo：pprofを使ったことがある人は「Flame Graphのほうが便利じゃないの？」と思うと思うんですけど、残念ながらオープンソースのpprofではFlame Graphでのバージョン間の比較はできないようになっています。

katzchang：あらー。オープンソースでは（笑）。

netmarkjp：（今見せているスライドは）ちょっといじってるってやつですね。

ymotongpoo：なので、Graphでも十分便利なので……。

katzchang：いやでも、さっきの緑の箱だけでもぜんぜんいいと思うよ、これ。

ymotongpoo：これ（緑の箱）を見られれば普通にいろいろなパフォーマンスチューニングできると思うし、実際にISUCONとかでもパッと見て、Flame Graphも同じなんですけど、見方はどっちも得手不得手の部分があるんですけど、箱の読み方がわかれば、かなりパフォーマンスチューニングが楽になると思います。

katzchang：うん。

ymotongpoo：宣伝になっちゃうんですけど、Flame Graphでバージョン比較したいじゃないですか。なので、Cloud Profilerというのがありまして（笑）。

katzchang：（笑）。

ymotongpoo：これを使うと、使い方は普通にpprofを使うときとほとんど変わらないんですけど、やると値がバージョン間で比較したときに、値が小さくなったやつが青くなって大きくなったやつが赤くなるので「改善したね」とわかります。こういうUIをはじめから用意しているので、自分でWebサーバを用意しなくてもいいのが利点です。

別にこれCloud Profilerだけじゃなくて、最近Datadogとかもプロファイラーというのを出したんですね。Datadog Profilerというのを出していて、やっぱり同じようなプロダクトになってます。

katzchang：やっぱり各社、AWSもプロファイラー、けっこういろいろ出してきたし。

ymotongpoo：そうですね。出しましたね。

katzchang：もう戦国時代ですよ。

Observabilityにおけるプロファイルを取得することの大切さ

ymotongpoo：これが、最後のリファレンスです。結局、最近「3 Pillars of Observability」みたいな「とりあえず、ログとメトリクスとトレースだけ取っておけばいい」みたいなことを言う人がたまにいるのですが、僕はそれ違うなと思っています。その3つでも取れないデータはあって、そのうちの1つがプロファイルだと思います。

そういう感じで、何かをしようと思ったときに必要なデータがちゃんと取れるような状態にするというのがObservabilityだと思うので、今日はそのためにプロファイラーという非常に有効なツールが最近ありますよという話をしました。

katzchang：なるほど。

ymotongpoo：Javaとかやってる人だとJFR（Java Flight Recorder）がすごく有名なのでみなさん使っていると思います。僕の周りでは、ほかの言語だとあんまりプロファイルをちゃんとやっているという話を聞かないので、もっとプロファイラーが広まってみんなが使ってくれるといいなと思ったので、今日紹介しました。

katzchang：なるほど。ありがとうございます。

ymotongpoo：以上です。