この記事は Go Advent Calendar 2016 の3日目の記事です。
はじめに
今回は gops という Google 製のツールを紹介したいと思います。
gops は ps コマンドの様に動作しますが、golang で書かれたプロセスに限って以下の機能を提供します。
- スタックトレースの表示
- メモリ状態の表示
- ランタイム状態の表示
- メモリのプロファイルを取り pprof を起動
- CPUのプロファイルを取り pprof を起動
- 強制GC
以下一つずつ説明していきます。
golang プロセスの一覧
まず引数を何も指定せずに起動します。
$ gops
10224 go (/opt/go/bin/go)
10244* main (/tmp/go-build638808727/command-line-arguments/_obj/exe/main)
10257 gops (/opt/godev/bin/gops)
139 processes left undetermined
ここで * の付いているプロセスがあるのに気付くかと思います。
これは以下に説明する gops の各種機能が実行可能なプロセスである事を示しています。実は gops で各種機能を実行する為には、対象プロセスの main 関数に一手間入れる必要があります。
以下は修正前のコード
package main
import (
"log"
"time"
)
func main() {
m := make(map[int]int, 500000)
for i := 0; i < 500000; i++ {
m[i] = i
}
time.Sleep(time.Hour)
}
次に修正後のコード
package main
import (
"log"
"time"
"github.com/google/gops/agent"
)
func main() {
if err := agent.Listen(nil); err != nil {
log.Fatal(err)
}
m := make(map[int]int, 500000)
for i := 0; i < 500000; i++ {
m[i] = i
}
time.Sleep(time.Hour)
}
agent.Listen(nil) でエージェントを起動しています。この修正によりバックグラウンドでプロセスの監視と制御が行える様になりました。
gops コマンドでは golang でコンパイルされたプロセスの一覧が表示されますが、上記の例は go run コマンドを実行した結果になっています。
ご存じの様に golang はセルフホストされているので、コンパイラ(およびランチャー)自身と、ビルドして起動されたプロセス、あと gops プロセス自身が表示されているのが分かるかと思います。面白いですね。
以下に述べる機能はこの細工を入れた物だけ有効となります。
スタックトレースの表示
* の付いたプロセスIDを指定して以下の様に実行します。
$ gops stack 10244
goroutine 5 [running]:
github.com/google/gops/agent.handle(0x7f5da627a440, 0xc82002a000, 0xc82000a1f0, 0x1, 0x1, 0x0, 0x0)
/opt/godev/src/github.com/google/gops/agent/agent.go:86 +0xd9
github.com/google/gops/agent.Start.func2(0x7f5da76b80a8, 0xc82002a008)
/opt/godev/src/github.com/google/gops/agent/agent.go:72 +0x41e
created by github.com/google/gops/agent.Start
/opt/godev/src/github.com/google/gops/agent/agent.go:78 +0x525
goroutine 1 [sleep]:
time.Sleep(0x34630b8a000)
/usr/local/go/src/runtime/time.go:59 +0xf9
main.main()
/home/spoteye/main.go:20 +0x208
goroutine 17 [syscall, locked to thread]:
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1721 +0x1
goroutine 20 [syscall]:
os/signal.loop()
/usr/local/go/src/os/signal/signal_unix.go:22 +0x18
created by os/signal.init.1
/usr/local/go/src/os/signal/signal_unix.go:28 +0x37
goroutine 3 [select, locked to thread]:
runtime.gopark(0x602500, 0xc820026f28, 0x5b81a0, 0x6, 0x42d618, 0x2)
/usr/local/go/src/runtime/proc.go:185 +0x163
runtime.selectgoImpl(0xc820026f28, 0x0, 0x18)
/usr/local/go/src/runtime/select.go:392 +0xa64
runtime.selectgo(0xc820026f28)
/usr/local/go/src/runtime/select.go:212 +0x12
runtime.ensureSigM.func1()
/usr/local/go/src/runtime/signal1_unix.go:227 +0x353
runtime.goexit()
/usr/local/go/src/runtime/asm_amd64.s:1721 +0x1
goroutine 4 [chan receive]:
github.com/google/gops/agent.Start.func1(0xc82001c060, 0xc82000e200, 0x20)
/opt/godev/src/github.com/google/gops/agent/agent.go:55 +0x36
created by github.com/google/gops/agent.Start
/opt/godev/src/github.com/google/gops/agent/agent.go:58 +0x4f3
いま実行中の生のスタックトレースが、goroutine 分全て表示されます。プロセスから応答がないといった場合に使えるかと思います。
メモリ状態の表示
同じくプロセスIDを指定します。
$ gops memstats 10244
alloc: 19267968 bytes
total-alloc: 19393560 bytes
sys: 23939320 bytes
lookups: 11
mallocs: 2518
frees: 104
heap-alloc: 19267968 bytes
heap-sys: 20578304 bytes
heap-idle: 983040 bytes
heap-in-use: 19595264 bytes
heap-released: 0 bytes
heap-objects: 2414
stack-in-use: 393216 bytes
stack-sys: 393216 bytes
next-gc: when heap-alloc >= 28678953 bytes
last-gc: 1481194106621190296 ns
gc-pause: 455534 ns
num-gc: 2
enable-gc: true
debug-gc: false
各メモリの状態とヒープの使用状況が表示されています。mallocs/frees は履歴の個数ですので、現在確保されている個数ではありません。
ランタイム状態の表示
goroutines: 13
OS threads: 8
GOMAXPROCS: 2
num CPU: 2
実行すると、goroutine の数、OSスレッドの数、GOMAXPROCS の値、実際の CPU コア数が表示されます。
メモリのプロファイルを取り pprof を起動
瞬間的なヒープのプロファイルを取得して、pprof が起動します。以下では pprof の list コマンドを実行し、各行でのメモリ確保量を表示しています。
(pprof) list
Total: 19MB
ROUTINE ======================== main.main in /home/spoteye/main.go
18.50MB 18.50MB (flat, cum) 97.37% of Total
. . 10:func main() {
. . 11: if err := agent.Start(); err != nil {
. . 12: log.Fatal(err)
. . 13: }
. . 14:
18MB 18MB 15: m := make(map[int]int, 500000)
. . 16: for i := 0; i < 500000; i++ {
512.07kB 512.07kB 17: m[i] = i
. . 18: }
. . 19:
. . 20: time.Sleep(time.Hour)
. . 21:}
ROUTINE ======================== runtime.goexit in /usr/local/go/src/runtime/asm_amd64.s
0 18.50MB (flat, cum) 97.37% of Total
Error: open /usr/local/go/src/runtime/asm_amd64.s: no such file or directory
ROUTINE ======================== runtime.main in /usr/local/go/src/runtime/proc.go
0 18.50MB (flat, cum) 97.37% of Total
Error: open /usr/local/go/src/runtime/proc.go: no such file or directory
ROUTINE ======================== runtime.malg in /usr/local/go/src/runtime/proc1.go
512.19kB 512.19kB (flat, cum) 2.63% of Total
Error: open /usr/local/go/src/runtime/proc1.go: no such file or directory
ROUTINE ======================== runtime.mcommoninit in /usr/local/go/src/runtime/proc1.go
0 512.19kB (flat, cum) 2.63% of Total
Error: open /usr/local/go/src/runtime/proc1.go: no such file or directory
ROUTINE ======================== runtime.mpreinit in /usr/local/go/src/runtime/os1_linux.go
0 512.19kB (flat, cum) 2.63% of Total
Error: open /usr/local/go/src/runtime/os1_linux.go: no such file or directory
ROUTINE ======================== runtime.rt0_go in /usr/local/go/src/runtime/asm_amd64.s
0 512.19kB (flat, cum) 2.63% of Total
Error: open /usr/local/go/src/runtime/asm_amd64.s: no such file or directory
ROUTINE ======================== runtime.schedinit in /usr/local/go/src/runtime/proc1.go
0 512.19kB (flat, cum) 2.63% of Total
Error: open /usr/local/go/src/runtime/proc1.go: no such file or directory
(pprof)
pprof コマンドはとても機能が豊富です。この記事では全てを説明できないので、詳しくは Go Official Blog の記事を参照して下さい。
CPUのプロファイルを取り pprof を起動
30秒間のCPUプロファイルを取得して pprof コマンドを起動します。同じく上記のリンクを参照して下さい。
強制GC
gops コマンドが agent に対してガベージコレクションの実行を指示し、完了するまでブロックします。
GC の効果が分かりやすい様にソースコードを以下に修正しています。
package main
import (
"log"
"time"
"github.com/google/gops/agent"
)
func main() {
if err := agent.Start(); err != nil {
log.Fatal(err)
}
m := make(map[int]int, 500000)
for i := 0; i < 500000; i++ {
m[i] = i
}
m = nil
time.Sleep(time.Hour)
}
※ m に nil を代入しています。
以下は gc コマンドを実行する前の memstats。
alloc: 19376928 bytes
total-alloc: 19445104 bytes
sys: 24594680 bytes
lookups: 9
mallocs: 3473
frees: 662
heap-alloc: 19376928 bytes
heap-sys: 20840448 bytes
heap-idle: 942080 bytes
heap-in-use: 19898368 bytes
heap-released: 0 bytes
heap-objects: 2811
stack-in-use: 131072 bytes
stack-sys: 131072 bytes
next-gc: when heap-alloc >= 38035568 bytes
last-gc: 1481455449599960600 ns
gc-pause: 0 ns
num-gc: 1
enable-gc: true
debug-gc: false
この状態で以下のコマンドを実行します。
$ gops gc 10244
再度 memstats を表示します。
alloc: 19335216 bytes
total-alloc: 19447008 bytes
sys: 24660216 bytes
lookups: 13
mallocs: 3510
frees: 734
heap-alloc: 19335216 bytes
heap-sys: 20840448 bytes
heap-idle: 1032192 bytes
heap-in-use: 19808256 bytes
heap-released: 0 bytes
heap-objects: 2776
stack-in-use: 131072 bytes
stack-sys: 131072 bytes
next-gc: when heap-alloc >= 38671024 bytes
last-gc: 1481455475620465600 ns
gc-pause: 0 ns
num-gc: 2
enable-gc: true
debug-gc: false
GCが実行され、幾らかヒープオブジェクトが解放されているのが分かります。
まとめ
筆者が運用しているサービスの管理コンソールアプリでは既に gops の agent を取り込み運用していますが、特に問題は発生しておらず安定動作しています。ただ、現状対象のアプリケーションにてメモリが徐々に増加するといった兆候もない為 gc コマンドの使い道が現状ありませんが、もしあれば使ってみたいと思います。
余談
本来 @Nirma さんがアサインされていましたが、記事が書かれていなかったので代行する事にしました。
@Nirmaさん、もし記事を書かれておられたならすみません。