Zenn
🧚

Grafana Pyroscope を用いて Go のアプリケーションで継続的プロファイルしてみた

2023/09/16に公開
Kubernetes
Go
#
profile
#
observability
#
pyroscope
tech

■ はじめに

こんにちは 👋 みなさんプロファイルしてますか？
プロファイルはオブザーバビリティの主要なテレメトリーの一つです。（主要なテレメトリーはログ・トレース・メトリクスだけではないですよ！）

この記事では Go のサンプルアプリケーションを用いてプロファイルを計測し、アプリケーションの性能改善を行う方法を紹介します。稼働中のサービスを継続的にプロファイルすることで、CPU 使用率やメモリ割り当てなどの情報を収集し、自分のサービスのパフォーマンスに関する理解を深めることができとても有用です。
プロファイルの分析にはオープンソースの継続的プロファイルツールである Grafana Pyroscope （最近 v1.0.0 がリリースされました 🎉 ）を用い、これらを Kubernetes 上に展開していきます。

また本記事は、CNDF2023 の @ymotongpoo さんの "継続的プロファイルによる大規模アプリケーションの性能改善" にインスパイアされています（セッションでは Google Cloud の Cloud Profiler を使った性能改善について紹介されています）。プロファイルとは何か、なぜ継続的プロファイルが必要なのか、はセッション内で詳しく説明されているので是非ご参考ください！

■ プロファイルと継続的プロファイルについて

□ 簡単に プロファイル について

プロファイルは、プログラム実行時に取得できる様々なリソースのデータです。これらのデータは一定期間でサンプリングされた統計的な情報になります。Go であれば runtime/pprof というプロファイラー（プロファイルを計測するツール）を使用してアプリケーションを計装し、CPU 時間 / メモリ割当 / ロック/ etc ... [1]などのプロファイルを計測できます。

収集したプロファイルは、Flame Graph（フレームグラフ）を用いて描画することがメジャーです。以下は Grafana Pyroscope（以下、Pyroscope）で可視化したプロファイル（CPU 時間）です。
横軸にサンプリングされたリソース量、縦軸にリソース消費している関数がコールスタックとして示されています。見慣れた方は一目瞭然ですが、このサンプルアプリケーションでは main.count 関数で全体の 70 % 程度の CPU 時間を消費しており改善の余地がありそうです。後半で、実際にサンプルアプリケーションの性能改善をおこなっていきます。


サンプルアプリケーションから計測したプロファイルを Pyroscope で可視化

□ 簡単に 継続的プロファイル について

次に、"継続的" プロファイルについて触れます。
オブザーバビリティにおいて、テレメトリーを継続的に取得し、一元的に集約し、必要なときによしなに取り出し解析できる状態にしておくことが大変重要です。プロファイルも同様で、特定の時間パフォーマンス測定をするだけでは（それでも示唆は得られるとは思いますが！）、突然過負荷になったサービスを調査したい際に、気づいたときプロファイルを始めても遅いケースがあります。
従って、サービスのプロファイルを計測し続け、一元的に集約することが大事です。これにより、知りたいスナップショットでアプリケーションのパフォーマンスをいつでも見れ、現在と過去のプロファイルを比較し性能を深掘りするなどの恩恵を受けることができます。[2]

アプリケーションから継続的に計測したプロファイルは、モニタリングサービスで一元的に集約し、分析されます。Google Cloud の Cloud Profiler, Datadog の Continuous Profiler など多くの継続的プロファイラーサービスがあります。OSS だと今回使った Pyroscope があります。継続的プロファイラーについての歴史の変遷については CNCF のブログでわかりやすく語られていて面白いので気になる方は参考にしてください。（冒頭紹介したセッション内でも詳しく話されています。）
https://www.cncf.io/blog/2022/05/31/what-is-continuous-profiling/

■ 実際に継続的プロファイルをしてみる

□ 今回の構成図

Go アプリケーションと Pyroscope を使って継続的プロファイルを行ってみます。構成は以下！

□ Go アプリへのプロファイル計装

まず Go のアプリでプロファイルを計測できるように計装をしていきます。
計装自体はめっちゃ簡単で、Grafana Pyroscope が提供しているプロファイラー pyroscope-go を使っていきます。内部的には runtime/pprof を使って Go ランタイムから各種プロファイルを計測し、Pyroscope サーバーへ POST します。

Go アプリのプロファイル計装
func main() {
	// 環境変数からアプリバージョンを取得
	appVersion := os.Getenv("APP_VERSION")

	// profiling 設定
	/* Mutex Profile 設定（オプション）
	mutexProfileRate は Mutex Profile の収集される頻度です。
	mutexProfileRate = 1 のとき全ての Mutex Event が収集されます。
	mutexProfileRate > 1 のとき mutexProfileRate 回のうち 1 回 Mutex Profile が収集されます。
	*/
	mutexProfileRate := 1
	runtime.SetMutexProfileFraction(mutexProfileRate) // ・・・(1)
	/* Block Profile 設定（オプション）
	blockProfileRate は Block Profile をサンプルする際の Block 時間（ns）です。
	blockProfileRate = 0 のとき Block Profile が無効になります。
	blockProfileRate > 0 のとき blockProfileRate n秒単位で Block ごとに Block Profile が収集されます。
	*/
	blockProfileRate := 1
	runtime.SetBlockProfileRate(blockProfileRate) // ・・・(2)
	
	pyroscope.Start(pyroscope.Config{
		ApplicationName: "calculator",
		// Pyroscope のエンドポイントを設定
		ServerAddress:   "http://pyroscope.pyroscope.svc.cluster.local:4040",
		Logger:          pyroscope.StandardLogger,

		// タグを設定することで、タグ指定でのプロファイル表示や、タグ間のプロファイル比較ができ便利です
		Tags: map[string]string{
			"hostname": "calculator",
			"version":  appVersion,
		},

		ProfileTypes: []pyroscope.ProfileType{
			// デフォルトで取得するプロファイル
			pyroscope.ProfileCPU,
			pyroscope.ProfileAllocObjects,
			pyroscope.ProfileAllocSpace,
			pyroscope.ProfileInuseObjects,
			pyroscope.ProfileInuseSpace,
			
			// オプショナルで取得するプロファイル
			pyroscope.ProfileGoroutines,
			// ・・・(1) の設定が必要
			pyroscope.ProfileMutexCount,
			pyroscope.ProfileMutexDuration,
			// ・・・(2) の設定が必要
			pyroscope.ProfileBlockCount,
			pyroscope.ProfileBlockDuration,
		},
	})
	...

これでプロファイルを計測して Pyroscope 上で収集・分析ができます。簡単です🥳

□ Pyroscope でプロファイルを分析（Single View）

Locust から数時間負荷をかけて得たプロファイル（今回のデモでは CPU 時間を分析していきます。）の Pyroscope で表示した結果が以下です。
Pyroscope の UI は 4040 port にアクセスすることで確認できます。


サンプルアプリケーションから計測したプロファイルを Pyroscope で可視化（再掲）

これを見ると main.count で全体の約 70 % の CPU 時間の消費があり、性能改善の余地がありそうです。では、main.count のソースコード（便宜上、v1.0.0 とします）を確認してみましょう。

v1.0.0 の count 関数（ダメダメパターン）
func count(dummyData []int, appVersion string) (total int) {
	n := len(dummyData)
	for i := 0; i < n; i++ {
		for j := 0; j < n-i-1; j++ {
			if dummyData[j] > dummyData[j+1] {
				dummyData[j], dummyData[j+1] = dummyData[j+1], dummyData[j]
			}
		}
	}
	index := sort.SearchInts(dummyData, 1)
	fmt.Println("index: ", index)

	return len(dummyData) - index
}

dummyData で [0,1,0,0,1,0,0,0,1...,0,1] のような、要素が 0 or 1 のスライスを受け取って 1 の要素数を返しています。このロジックではバブルソートを使って 0 と 1 を並び替えて、1 の最初のインデックスを計算することで要素数を取得していることがわかります。

言うまでもないですがここでバブルソートをするのは効率が悪いです🙅‍♂️
Go にはソート関数 sort.Ints がありますので、これを使うように改修しましょう。（便宜上 v2.0.0 とします）。

v2.0.0 の count 関数（↑ より効率良いパターン）
func count(dummyData []int, appVersion string) (total int) {
	sort.Ints(dummyData)
	index := sort.SearchInts(dummyData, 1)
	fmt.Println("index: ", index)

	return len(dummyData) - index
}

□ 再度、Pyroscope でプロファイルを分析（Comparison View と Diff View）

Pyroscope ではプロファイルに設定した Tag でプロファイルの比較をする機能があり、パフォーマンス改善を確認する上で便利です（おそらく他のプロファイリングツールでも同様の機能はありそうです）。Tag は Pyroscope の Config で設定していました。
CI などでできちんとバージョンを埋め込んだりしてあげることで、バージョン間のプロファイルの比較も見ることができます。

pyroscope.Start(pyroscope.Config{
	...
	// タグを設定することで、タグ指定でのプロファイル表示や、タグ間のプロファイル比較ができ便利です
	Tags: map[string]string{
		"hostname": "calculator",
		"version":  appVersion, // <= 今回はこっちの Tag で比較
	},
...

□ Comparison Veiw で可視化

左図が v1.0.0 のプロファイル、右図が v2.0.0 のプロファイルです。
左図で CPU 時間の大部分を占めていた main.count のフレームが、右図では存在感が無くなり当該部分の性能改善ができたことがわかります。

□ Diff View で可視化

Diff View では、v1.0.0 のプロファイルをベースラインとして、v2.0.0 のプロファイルが全体に対して増減したかどうかをヒートマップで可視化することができます。
これを見ると、main.count が大幅に減少していることがわかります。このフレームが小さくなったことにより、相対的に他のフレームの CPU 時間が全体に対して大きくなり赤くなっていることも確認できます。
main.count をやっつけたことで、次に性能改善としてアクションすべき対象が詳になりますが、倒すかどうかは費用対効果と相談すれば良いと思います！

このように Tag 間のプロファイル同士を簡単に計算できるのは、profile.proto というスキーマに基づいてプロファイルを収集している恩恵です。Diff View はとても視覚的にわかりやすく今後ともパフォーマンス改善の際に使っていきたいです。

補足：検証に使ったバージョン

まとめ

Go のアプリケーションで継続的プロファイルを簡単に行いました。
計装の手間もほとんどなく、手軽にサービスの性能分析ができることを紹介しました。

継続的プロファイルはオブザーバビリティにおける重要なテレメトリーの一つです。ぜひ有効活用し、パフォーマンス改善をしていきましょう！

参考資料

脚注

  1. runtime/pprof で計測できるプロファイルの詳細はこちらを参考ください。
    https://go.dev/doc/diagnostics#profiling ↩︎

  2. プロファイルを継続的に計測し続けるオーバーヘッドはありますが、サンプリング間隔を短くすることで十分抑えることが可能です。また、https://go.dev/doc/diagnostics#profiling の "Can I profile my production services?" を参照ください。 ↩︎

Discussion