More than 5 years have passed since last update.

LOBAdvent Calendar 2018

@yoppe(Okubo Yohei)in

Anyflow株式会社

稼働中のWebサービスを継続プロファイリングする by Stackdriver Profiler（GAE/SE Go 1.11）

Posted at 2018-12-17

※この記事は LOB のアドベントカレンダーの17日目の記事になります。

こんにちは。

LOBで開発業務を手伝わせてもらっている大久保です。

最近はGCP触ったりRailsを触ったりと、インフラとアプリの境で~~彷徨ってる~~精進してるのですが、今後の開発でもGoでWebアプリを開発したりGCPでSRE的なタスクを進めたりといった業務が増えそうなので、Goの学習も兼ねて最近リリースされたStackdriver Profilerについて調査しました。

Stackdriver Profilerとは

Stackdriver Profilerの管理画面

Stackdriver Profilerは、GCPのStackdriver系サービスの１つで、2018/3にベータ公開された新しめのサービスになります。
公式の要約になりますが、継続的な開発を続けるサービスにおいて、大きくなり続けるサービスは徐々にパフォーマンスが悪化していきます。Stackdriver Profilerでは、実行中のアプリケーション全体に対して定期的なプロファイリングを実施し、CPUやメモリといったリソースの消費量をビジュアライズすることができます。Stackdriver Profilerの情報をもとにサービスのボトルネックをチェックし、継続的なサービスパフォーマンスの改善＆安定化に役立たせることができます。
またStackdriver Profilerでは、プロファイリングの実施によるサービスのパフォーマンス劣化を起こすことなく、統計的な計測を可能にします。

今月始め(2018/12)に Go 1.11のGoogleAppEngine/SEでのサポートが開始されましたが、まだサポートされてる言語も少なくこれからといった感じですね。
サポート状況

Stackdriver Profiler: https://cloud.google.com/profiler/

本記事では、Stackdriver Profilerを試すためのテストアプリを作成し、実際にどんなプロファイリングデータを確認できるのかを見ていきます。

実行環境の整備

※GCPのアカウントを持っている&Mac PC前提で進めます。

各種インストール

Cloud SDK のインストールは公式通りに ⇛ Cloud SDK のインストール

go は brew とかで適当にインストールを ⇛ Golang Macへのインストール〜Homebrewを使って〜

$ gcloud version
Google Cloud SDK 228.0.0

$ go version
go version go1.11.2 darwin/amd64

サンプルアプリ作成

Ginインストール

$ go get -u github.com/gin-gonic/gin

web framework https://github.com/gin-gonic/gin
（なんとなくGin使ってるだけなので、net/http でもよいかと）

サンプルコード

hello.go

package main

import "github.com/gin-gonic/gin"

func main() {
	r := gin.Default()
	r.GET("/", func(c *gin.Context) {
		c.JSON(200, gin.H{
			"message": "hello world",
		})
	})
	r.Run() // listen and serve on 0.0.0.0:8080
}

実行

$ go run hello.go

実行結果

かなりシンプルなWebアプリができました！
Stackdriver Profilerを使うためにはGCPにデプロイする必要があるため、これをGAE/SE用に修正していきます。

GAE/SE上で動くサンプルアプリに変更

ここのGAE/SEで動くアプリを作るあたりで結構ハマりました。。
GAE用のapp.yamlや起動用の関数が、 Go 1.9 と Go 1.11では大きく違います。
GAE/SEでStackdriver Profilerを試すには、 Go 1.11 を使う必要があり、公式にもこうあります。

App Engine standard environment (requires Go 1.11 or later)

ただこのGo 1.11、最近リリースされたものでGoのGAEデプロイ周りの記事はほとんど Go 1.9 対象なので注意が必要です。
Go 1.11に関してはこの記事がとてもわかりやすかったです。 ⇛ GAE/Go アプリケーションを Go 1.11 に移行するためにやったこと - えいのうにっき

Go用のappengineモジュールをインストール

$ go get -u google.golang.org/appengine

先程のサンプルコードを Go 1.11 対応のコードにすると下記のようになります。

hello.go

package main

import (
	"github.com/gin-gonic/gin"
	"google.golang.org/appengine" // 追加
	"net/http"
)

func main() {  // G0 1.9ではinitだがmainのままでいい
	r := gin.Default()
	r.GET("/", func(c *gin.Context) {
		c.JSON(200, gin.H{
			"message": "hello world",
		})
	})
	http.Handle("/", r) // r.Run()では動かないので、net/httpを使用
	appengine.Main()    // 追加
}

デプロイのためのapp.yaml作成

app.yaml

runtime: go111
env: standard

env_variables:
  GIN_MODE: release

instance_class: F1 # FはFrontendの略だがautomatic_scalingを使う場合は、Fを指定
automatic_scaling:
  target_cpu_utilization: 0.6 # default value
  target_throughput_utilization: 0.6 # default value
  min_instances: 1
  max_instances: 5
  min_idle_instances: 1
  max_idle_instances: automatic  # default value
  min_pending_latency: automatic
  max_pending_latency: automatic
  max_concurrent_requests: 80

handlers:
- url: /.*
  script: auto

Automatic Scaling周りの設定参考: App Engine Scaling Config - Qiita

GoのModulesを導入

$ GO111MODULE=on go mod init hello
go: creating new go.mod: module hello
$ cat go.mod
module hello

go mod init を実行すると、ほぼ空の go.mod ファイルが生成され、ビルドかアプリの実行をすることで、モジュールの依存情報が自動で書き込まれる（らしい）

最終的にディレクトリ直下には以下のファイルが置かれている状態

sample/
|-- app.yaml
|-- go.mod
|-- go.sum
`-- hello.go

動作確認

$ python -V
Python 2.7.15 :: Anaconda, Inc. // dev_appserver.pyはPython 2.7でないと動かない

$ dev_appserver.py app.yaml
INFO     2018-12-16 09:46:06,538 devappserver2.py:278] Skipping SDK update check.
INFO     2018-12-16 09:46:06,705 api_server.py:275] Starting API server at: http://localhost:63221
INFO     2018-12-16 09:46:06,707 instance_factory.py:170] Building with dependencies from GOPATH.
INFO     2018-12-16 09:46:06,785 dispatcher.py:256] Starting module "default" running at: http://localhost:8080
INFO     2018-12-16 09:46:06,788 admin_server.py:150] Starting admin server at: http://localhost:8000

（※そもそもローカルでの動作確認にdev_appserver.pyなどのツールを使いたくなかったが、GAE/SE でGoを動かくならdev_appserver.py か goapp を使うのがデフォらしい、、）

http://localhost:8080 で先ほどと同じ実行結果になることを確認。

http://localhost:8000/instances にアクセスすることで管理画面のようなものも確認できる。

デプロイ

$ gcloud components install app-engine-go  // Go用のGAEコンポーネントをインストール
$ gcloud app deploy app.yaml
Services to deploy:

descriptor:      [path/sample/app.yaml]
source:          [path/sample]
target project:  [southern-list-619]
target service:  [default]
target version:  [20181216t192647]
target url:      [https://southern-list-619.appspot.com]


Do you want to continue (Y/n)?  Y

Beginning deployment of service [default]...
#============================================================#
#= Uploading 4 files to Google Cloud Storage                =#
#============================================================#
File upload done.
Updating service [default]...done.
Setting traffic split for service [default]...done.
Deployed service [default] to [https://southern-list-619.appspot.com]

You can stream logs from the command line by running:
  $ gcloud app logs tail -s default

To view your application in the web browser run:
  $ gcloud app browse

確認

プロファイリング（本題）

（前段が長くなりましたが、）テスト用アプリができたので、Stackdriver Profilerでプロファイリングできるようにしていく。

Profiler APIの有効化

$ gcloud services enable cloudprofiler.googleapis.com

プロファイリング用の設定をコードに追加

Goのprofilerモジュールを追加

$ go get -u cloud.google.com/go/profiler

ソースコードの修正

基本的にmainにprofilerの設定を追加するのみです。

hello.go

package main

import (
	"cloud.google.com/go/profiler"
	"github.com/gin-gonic/gin"
	"google.golang.org/appengine"
	"log"
	"net/http"
	"os"
)

func main() {

	project := os.Getenv("GOOGLE_CLOUD_PROJECT")
	if project != "" {  // profiler.Startをそのままmainに書くとAPIエラーでローカル実行できなくなるので、GAE上のみで有効化
		err := profiler.Start(profiler.Config{  // profilerの設定
			Service:        "hello-profiler",
			DebugLogging:   true,
			MutexProfiling: true,
		})
		if err != nil {
			log.Fatalf("failed to start the profiler: %v", err)
		}
	}

	r := gin.Default()
	r.GET("/", func(c *gin.Context) {
		c.JSON(200, gin.H{
			"message": "hello world",
		})
	})
	http.Handle("/", r)
	appengine.Main()
}

profiler.Configに指定できる項目

Service: プロファイルを区別するためのサービス名。GAEの場合、未指定だとGAE_SERVICEがデフォルトで入る。
ServiceVersion：オプション。バージョンを指定することで前のバージョンとの比較とかができる（っぽい）。（GAEの場合、未指定だとデフォルトでGAE_VERSIONが入る）。
DebugLogging：プロファイリング実行時にログが出るようになる
MutexProfiling：同期処理時のロック（競合）による待機時間をプロファイルしたい場合に指定。デフォルトはfalse。
NoAllocProfiling：割当（スタック?）メモリをプロファイルしない場合指定。デフォルトはfalse。
AllocForceGC：ヒーププロファイルの前に強制的にGCを実行する場合（GCした方が精度が上がる）に指定。にデフォルトはfalse。
NoHeapProfiling：ヒーププロファイルを無効にしたい場合は指定。デフォルトはfalse。
NoGoroutineProfiling：ゴルーチンのプロファイルを無効にしたい場合は指定。デフォルトはfalse。
ProjectID： GCPの場合はデフォルトでGOOGLE_CLOUD_PROJECTが指定される

※ profiler設定追加後の初回のbuildや起動は、結構時間かかるので気長に待つ必要あり

デプロイ&確認

$ gcloud app deploy app.yaml

プロファイリング結果

https://console.cloud.google.com/profiler
ざっとこんな感じの結果になる。

プロファイリングは１分に１回実行されるため、10分の期間指定では、11回のプロファイルの平均値を出力するようになっている。

負荷の高い処理をサンプルアプリに追加

上記のサンプルアプリではシンプルすぎて負荷のかかる箇所がなくプロファイリングしてもあまり見れる情報がないので、公式のサンプルコードを参考に負荷の高い処理を追加します。

hello.go

package main

import (
	"cloud.google.com/go/profiler"
	"github.com/gin-gonic/gin"
	"google.golang.org/appengine"
	"log"
	"net/http"
	"os"
	"time"
)

func busyloop() {
	for i := 0; i < 1000; i++ {
		foo(1000)
	}
}

func foo(scale int) {
	bar(scale)
	baz(scale)
}

func bar(scale int) {
	load(scale)
}

func baz(scale int) {
	load(scale)
}

func load(scale int) {
	for i := 0; i < scale*(1<<16); i++ {
	}
}

func heavyWorld() func(c *gin.Context) {
	return func(c *gin.Context) {
		busyloop()
		c.JSON(200, gin.H{
			"message": "heavy world",
		})
	}
}

func sleepWorld() func(c *gin.Context) {
	return func(c *gin.Context) {
		time.Sleep(600 * time.Second)
		c.JSON(200, gin.H{
			"message": "sleep world",
		})
	}
}


func main() {
	project := os.Getenv("GOOGLE_CLOUD_PROJECT")

	if project != "" {
		err := profiler.Start(profiler.Config{
			Service:        "hello-profiler",
			DebugLogging:   true,
			MutexProfiling: true,
		})
		if err != nil {
			log.Fatalf("failed to start the profiler: %v", err)
		}
	}

	r := gin.Default()
	r.GET("/heavy", heavyWorld())
	r.GET("/sleep", sleepWorld())
	http.Handle("/", r)
	appengine.Main()
}

/heavy: CPUが100%に張り付くような負荷の高い処理を実行するエンドポイント
/sleep: 負荷は高くないがsleepが発生し、ブロックされてしまうような処理を実行するエンドポイント

プロファイリング結果

/heavy の結果

この結果では、CPUの使用割合がbusyloopにほぼ全て専有されており、そのなかでもbazとbarで半分ずつCPUリソースが浪費されていることがわかります

/sleep の結果

この結果では、sleep(futex?)が発生しており、大部分の処理が待機状態になってしまっていることがわかります

その他のプロファイル項目

サンプルアプリではCPU時間のみのプロファイルを見てきましたが、他にも以下のような項目を確認することができます

参考

まとめ（感想）

GoのGAE/SEのアプリに対してStackdriver Profilerを導入してみたが適用自体はかなり楽だったので、今後パフォーマンスが求められるアプリを開発するときには試しに使ってみるのもありだと感じました。（ただ、そもそものGoの処理系を理解してないとレポートを見てもいまいちピンと来なかったりはするので、Goにもある程度精通している必要がありそう）

課題としては、Stackdriver Profilerの対応言語が現状ほぼGoだけなので利用シーンは限られる上に、個人的に利用ケースがあまりイメージできていない（バッチ処理などは手元でプロファイリングすればよいし、Webサービスが常時プロファイリングされたとしての運用イメージが湧いていない）。そのため今後GCPで触りながらユースケースを見出していきたい。

このStackdriver Profilerに限らず、Stackdriver Trace、Stackdriver ErrorReport、Stackdriver DeguggerなどStackdriver系のサービスでは使いこなせていないサービスが多くあるので、今後運用ベースで知見深めないといけないなと感じました。

（チュートリアル以外でGo書いたの初めてなので、変な箇所あるかもですがご了承くださいmm）

株式会社 LOB では「流通のケタを変える、広告プラットフォームを創る」仲間を募集しています。
https://lob-inc.com/recruit/

You get articles that match your needs
You can efficiently read back useful information
You can use dark theme

What you can do with signing up