はじめに
Go はシンプルな構文ながら複雑な処理を行えるプログラミング言語です。エラーも自らがハンドリングするスタイルなので割とバグが入り込みにくいのが特徴です。しかし時には Go 本体のソースを見ないと動きが確認できない事もあります。とは言えオープンソースだからといって全ての挙動が簡単に探れるものではありません。
コンパイラの動きであったり、ランタイムの動きであったりで良く分からない物があった場合に、ソースを変更して print デバッグする事が良い方法とは言えません。
幸運にも Go ではランタイム、標準パッケージにデバッグのヒントを出せる仕組みが用意されています。GODEBUG や GOGC、GOTRACEBACK という環境変数が用意されており、設定を行う事で挙動を変更できたり色々なデバッグ情報を出力できたりします。
本記事ではこれらの環境変数に設定可能な値を、筆者の知見を交えて紹介したいと思います。
GODEBUG
GODEBUG は Go でコンパイルされたプログラムの動作を設定値に従って変更する為のオプションです。多くの式は GODEBUG=xxx=1,yyy=2 の様に設定可能です。
runtime
allocfreetrace
allocfreetrace=1 を設定すると全てのメモリ確保がプロファイルされ、オブジェクトのメモリ確保と解放がスタックトレースとして表示されます。
tracealloc(0xc000088000, 0x900, main.Foo)
goroutine 1 [running]:
runtime.mallocgc(0x900, 0x4ba040, 0x1, 0x0)
c:/dev/go/src/runtime/malloc.go:1074 +0x515 fp=0xc0000856b0 sp=0xc000085610 pc=0x40b2b5
runtime.convT2E(0x4ba040, 0xc000085738, 0x0, 0x0)
c:/dev/go/src/runtime/iface.go:319 +0x3f fp=0xc0000856e8 sp=0xc0000856b0 pc=0x408e6f
main.main()
c:/dev/go-sandbox/a1.go:13 +0x6b fp=0xc000085f60 sp=0xc0000856e8 pc=0x496a9b
runtime.main()
c:/dev/go/src/runtime/proc.go:203 +0x21e fp=0xc000085fe0 sp=0xc000085f60 pc=0x42dbde
runtime.goexit()
c:/dev/go/src/runtime/asm_amd64.s:1357 +0x1 fp=0xc000085fe8 sp=0xc000085fe0 pc=0x453af1
メモリの確保を行った箇所、サイズ、シンボル名と言った情報が、環境変数を設定するだけで簡単にトレース出来ます。
なお Go のコンパイラは Go で書かれているので、この環境変数を設定して Go のコンパイラを起動すると大量にスタックトレースが表示されます。コンパイル時にはオフにしておく事をオススメします。
またこれらのフラグはランタイムの初期化時に設定されるので、以下の様に関数内で局所的にトレースを有効にする事は出来ません。
func foo() {
os.Setenv("GODEBUG", "allocfreetrace=1")
defer os.Setenv("GODEBUG", "")
var a = 1
println(a)
}
これは以下に示すフラグも同じです。
clobberfree
clobberfree=1 を設定すると GC がオブジェクトの解放時にオブジェクトのメモリコンテンツに変な値(0xdeadbeef)を埋め込みます。
これにより解放したはずのメモリを参照して不正なまま動作を継続してしまう様なバグが起きにくくなり、即時で panic してくれる事を期待出来ます。多くの場合、このフラグは Go 本体のデバッグで使用されます。
cgocheck
cgo は Go からC言語のシンボルを扱う為の機能です。Go ではバージョン 1.6 で go16pointer と呼ばれる変更が入り、Go で生成したメモリのポインタをC言語に渡す事が禁止されました。
この変更はそれまでに書かれていた cgo のコードの多くに影響しました。
void
gtk_tree_selection_set_select_function
(GtkTreeSelection *selection,
GtkTreeSelectionFunc func,
gpointer data,
GDestroyNotify destroy);
例えば go-gtk は GTK の binding ですが、上記の様な GTK の API もサポートしています。この例ではユーザデータとしてポインタを渡せる仕組みになっています。go16pointer が入るまでは Go のポインタをそのままC言語に渡して動いていましたが、go16pointer が入った事によりこれらの呼び出し全てが panic で落ちる様になってしまいました。
これは Go が Go 自身を守る為に必要なチェックである為、致し方ない変更でした。回避策としては go-pointer があります。
どうしても変更が出来ない場合は、この cgocheck を 0 に設定する事でチェックを無効にする事が出来ます。デフォルト値は 1 (単純なチェック)、2 を設定すると writeBarrier を有効にしつつ厳密なチェックが実行されます。その為2を設定するとパフォーマンスが急激に落ちます。
efence
efence=1 を設定するとアロケータは全てのオブジェクトに対してユニークなページを割り当て、再利用されないモードとして動作する様になります。
こちらも Go 本体のデバッグで使用されます。
gccheckmark
gccheckmark=1 を設定すると GC 停止中(Stop The World)に非同期に行われる GC マークフェーズにおいて、2回のマークを行って検証を行う機能を有効にします。
この非同期による2回のマークで到達可能なオブジェクトを見つけられなかった場合は、GC は panic します。
こちらも Go 本体のデバッグで使用されます。
gcpacertrace
gcpacertrace=1 を設定すると非同期タイミング管理の内部情報を表示します。
gcshrinkstackoff
gcshrinkstackoff=1 を設定すると小さいスタックの goroutine を別の goroutine に移動する機能を無効にします。
このモードでは goroutine 内のスタックが増大していく可能性があります。
gcstoptheworld
gcstoptheworld=1 を設定すると非同期 GC を無効にします。Go でデバッグする際に何かしらの処理の経過を見てメモリの状態を確認する事になるのですが、その間に非同期で GC が行われてしまい、期待した順にメモリが解放されない事象が発生します。
このフラグを使うと非同期に GC されなくなるので確認が楽になります。ただし全ての GC は処理を一旦停止させます。gcstoptheworld=2 は GC 終了後の非同期スウィープも無効にします。
gctrace
gctrace=1 を設定すると GC 毎に回収されたメモリと停止時間を1行にして標準エラーで出力します。
この行フォーマットは変更される可能性もあります。
現在は以下の通り:
gc # @#s #%: #+#+# ms clock, #+#/#/#+# ms cpu, #->#-># MB, # MB goal, # P
フィールドは以下の通り:
gc # GC の番号(GC 毎に増える)
@#s プログラムが起動してからの秒数
#% プログラムが起動してから GC に費やされた割合
#+...+# GC の各種フェーズの実行時間
#->#-># MB GC が開始した際のヒープサイズ、終了時のサイズ、現在のサイズ
# MB goal 目標とするヒープサイズ
# P 使用しているプロセッサの数
フェーズとは、処理の停止(Stop The World: STW) 、非同期マークとスキャン、そして STW マークの終了を指します。
mark と scan の CPU 実行時間は、進む時間(メモリ割り当てに従って実行される GC)、バックグラウンドでの GC の時間、アイドル状態での GC の時間、という内訳になります。
行が "(forced)" で終わっている場合は、この GC が runtime.GC() の呼び出しにより強制実行された事を意味します。
gc 3 @1.814s 0%: 0+17+0 ms clock, 0+0.99/17/0+0 ms cpu, 4->4->0 MB, 5 MB goal, 4 P
この例ではプログラムが起動してから 1.81 秒後にマークとスキャンが実行され 4 MB のメモリが解放された事になります。
gctrace を 1 以上の任意の値に設定すると、GC はシステムにメモリが返却される時にサマリを送信する様になります。尚システムにメモリを返却するこのプロセスは scavenging と呼ばれます。
この行フォーマットは変更される可能性もあります。
現在は以下の通り:
scvg#: # MB released printed only if non-zero
scvg#: inuse: # idle: # sys: # released: # consumed: # (MB)
フィールドは以下の通り:
scvg# scavenge の番号(循環し scavenge 毎に増える)
inuse: # 使用量または部分的な使用量
idle: # 保留中 scavenging の量
sys: # システムから割り当てられた量
released: # システムに返却された量
consumed: # システムから確保された量
scvg: inuse: 3, idle: 4, sys: 7, released: 2, consumed: 4 (MB)
この例では処理中に 3MB、アイドル中に 4MB、システムから 7MB 割り当てられ、2MB をシステムに返却し、4MB システムから確保した、という事になります。
madvdontneed
madvdontneed=1 は Linux 上でメモリをカーネルに返却する際に MADV_FREE の代わりに MADV_DONTNEED を使う様になります。それほど効率的ではありませんが、RSS (Resident Set Size: 仮想メモリの中で実際に使われているサイズ) の数をもっと早く落とします。
-
MADV_DONTNEED中身は置いておく -
MADV_FREE中身は消しちゃう
memprofilerate
memprofilerate=X は runtime.MemProfileRate の値を更新します。0 が設定された場合、プロファイルは無効になります。デフォルト値に関しては MemProfileRate の説明を参照してください。
invalidptr
デフォルトの invalidptr=1 は、ポインタが指す不正な位置(例えば 1)が見付かった場合に GC とスタックのコピーでクラッシュさせます。
invalidptr=0 はこのチェックを無効にします。
これはバギーなコードの診断をするといった様な暫定的な処置としてのみ使われます。本来修正すべき問題は、ポインタの位置として int を格納しないという事です。
sbrk
sbrk=1 を設定するとメモリアロケータと GC は、OS からメモリを取得するけれど回収されない単純なアロケータに置き換えられます。Go 1.13 から導入されました。
このモードは、現在 Russ Cox が作業を進めている、32bit アーキテクチャで64bit の値が正しくアライメントされていない(データの移動が多い)問題を確認する為のデバッグモードです。 1
現状はこのモードで動作させるとメモリは一方的に増え続けます。
scavenge
scavenge=1 を設定するとヒープの後片付けに関するデバッグを有効にします。gctrace と併用します。
scheddetail
scheddetail=X そして scheddetail=1 を設定するとスケジューラは X ミリ秒毎にスケジューラ、プロセス、スレッド、goroutine といった複数の情報を出力します。schedtrace と併用します。
SCHED 0ms: gomaxprocs=4 idleprocs=3 threads=6 spinningthreads=0 idlethreads=3 runqueue=0 gcwaiting=0 nmidlelocked=0 stopwait=0 sysmonwait=0
P0: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
P1: status=2 schedtick=3 syscalltick=11 m=-1 runqsize=0 gfreecnt=0
P2: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
P3: status=0 schedtick=0 syscalltick=0 m=-1 runqsize=0 gfreecnt=0
M5: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M4: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M3: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=true lockedg=-1
M2: p=-1 curg=-1 mallocing=0 throwing=0 preemptoff= locks=1 dying=0 spinning=false blocked=false lockedg=-1
M1: p=-1 curg=17 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=17
M0: p=1 curg=1 mallocing=0 throwing=0 preemptoff= locks=0 dying=0 spinning=false blocked=false lockedg=1
G1: status=3(chan receive) m=0 lockedm=0
G17: status=6() m=1 lockedm=1
G2: status=4(force gc (idle)) m=-1 lockedm=-1
G3: status=4(GC sweep wait) m=-1 lockedm=-1
内容は runtime のソースのデバッグ情報に過ぎません。
schedtrace
schedtrace=X を設定するとスケジューラは X ミリ秒毎にスケジューラの状態を標準エラーへ1行で出力します。
tracebackancestors
tracebackancestors=N を設定すると goroutine が作られたスタックでの tracebacks が拡張され、N を限界値とする世代分の groutine における tracebacks がレポートされます。これは runtime.Stack によって返される情報も拡張されます。祖先となる goroutine の ID は作成時の goroutine の ID として参照されます。この ID は別の goroutine として再利用される可能性もあります。N を 0 に設定すると、世代に関する情報は報告されません。スタックトレースが出力される gctrace と併用します。
パッケージ
net
net パッケージでは以下のように GODEBUG 環境変数を設定する事でリゾルバによる名前解決の動作を変更出来ます。
GODEBUG=netdns=go # pure Go を強制で使う
GODEBUG=netdns=cgo # cgo を強制で使う
Go の名前解決はデフォルトで pure Go が使われます。ただし pure Go では /etc/nsswtich.conf や /etc/resolv.conf による指定が一部実装されていません。cgo の方は正しく扱われます。何かしらの用途で go による名前解決を使いたくない場合には netdns=cgo を設定する事で問題が解決する場合があります。
また GODEBUG=netdns=1 の様に数値を指定する事ででデバッグレベルが設定ですが、go や cgo と併用する場合は GODEBUG=netdns=go+1 の様に + を使う事が出来ます。
net/http
Go 1.6 以降、http パッケージは HTTP/2 プロトコルを透過的にサポートする様になっています。意図的に HTTP/2 を無効にしなければならないプログラムは Transport.TLSNextProto (クライアント用) または Server.TLSNextProto (サーバー用) を nil ではない空のマップに設定することで無効にできます。または以下の GODEBUG 環境変数で設定が可能です。
GODEBUG=http2client=0 # HTTP/2 クライアントサポートを無効
GODEBUG=http2server=0 # HTTP/2 サーバサポートを無効
GODEBUG=http2debug=1 # HTTP/2 詳細デバッグログを有効
GODEBUG=http2debug=2 # フレームダンプ等さらに詳細を有効
以前 twitter.com は HTTP/2 を優先的に扱いながらも、クライアントから送られる Accept-Encoding を無視して gzip なバイナリを返却していたので、ブラウザでない HTTP クライアントの多くで問題が発生しました。筆者が開発していた twty 2 という Twitter クライアントでも問題が発生したため、その時はワークアラウンドで以下のコードを設定していました。
os.Setenv("GODEBUG", os.Getenv("GODEBUG")+",http2client=0")
net/http パッケージに関しては接続時にプロトコル判定が行われます。
crypt/tls
多くのウェブサーバでは既に TLS 1.3 はサポートされていますが、中にはサポートしていないウェブサーバも存在します。tls13=0 を設定すると、HTTPS で通信する際に TLS 1.3 を無効(他のバージョンで実行)にして通信する様になっています。
キャッシュ
gocacheverify
Go 1.11 からモジュールという概念が導入され、ビルドした結果はキャッシュとして保存される様になりました(デフォルトではありません)。キャッシュが原因と思われる問題に遭遇した場合は GOCACHE=off を指定してコマンドを再実行する事で、キャッシュの確認や更新を回避することが出来ます(注意: GOCACHE=off は go build の様なキャッシュに書き込むコマンドでは失敗します)。GOCACHE の値は変更せずに、代わりに GODEBUG=gocacheverify=1 を設定する事でキャッシュに関する問題をデバッグする事が出来ます。これはキャッシュからの読み込みを回避する事はしませんが、すでに存在するキャッシュへの書き戻しがビット毎に一致することを再確認します。
gocachehash
gocachehash=1 を設定すると go コマンドはキャッシュの問い合わせを行う際のキーの生成としてとして使われるコンテンツハッシュの詳細を表示します。出力は膨大になりますが、キャッシュのデバッグに便利です。
HASH[link github.com/itchyny/gojq/cmd/gojq]: "packagefile internal/race=0XxZj_m_OpEChJHHcNPn\n"
HASH[link github.com/itchyny/gojq/cmd/gojq]: "packagefile internal/syscall/windows/sysdll=kvEmbwMXKGaz5DKD04_1\n"
HASH[link github.com/itchyny/gojq/cmd/gojq]: "packagefile internal/syscall/windows/registry=G29f5AmqZdtPM2IF4EAI\n"
HASH[link github.com/itchyny/gojq/cmd/gojq]: "packagefile encoding/binary=FVNalIOD9PsNK-2DXQCq\n"
HASH[link github.com/itchyny/gojq/cmd/gojq]: "packagefile math/bits=gRqt6LSKXq7S_1jRjeh0\n"
HASH[link github.com/itchyny/gojq/cmd/gojq]: "packagefile regexp/syntax=7p8tU11q5MCBoqIbrlHU\n"
HASH[link github.com/itchyny/gojq/cmd/gojq]: 837e0b1ad2bd2293b80d43990ea11c35ea340a03c4c8d3f2a1128b119f476b89
HASH subkey 14395a7f1243b7435c39e9fbdbfdbcf5d3974d63a2988e32ace7a0f8eb7e5ec4 "link-stdout" = ba9eca72c81bfd2b7b3f124db92d7ab911d5204280fc187866c7f90c6f401c40
gocachetest
gocachetest=1 を設定すると go test コマンドはキャッシュされたテスト結果を再利用しているかどうかの詳細を表示します。
testcache: caching disabled in local directory mode
ちなみに go test が結果をキャッシュしてしまうと色々と問題が起きてしまいます。go test -count=1 としてキャッシュを無効化するか、go clean -testcache を実行してキャッシュを消すと良いでしょう。
cpu
以下のフラグはそれぞれ SSE2、SSE3、全ての CPU 拡張命令を無効にします。
cpu.sse2=off
cpu.sse3=off
cpu.all=off
特に意図的に無効にする用途はないと思いますが、パフォーマンス計測で SSE3 の効果を計るには便利です。
GOGC
GOGC は Go で書かれたプログラムの GC の動作を変更出来ます。デフォルトは前回の回収から 100% になった際に GC が発動する 100 という値です。200 を設定すれば GC が発動する頻度が下がり、20 を設定すると頻繁に GC が発動します。off を設定すると GC を発動しなくする事が出来ます。
こちらは運用に使えるかもしれません。検証はしていません。
GOTRACEBACK
Go で書かれたプログラムが panic した際は、トレースバックが表示されます。
package main
func foo() {
panic("boom!")
}
func main() {
foo()
}
例えばこのコードを実行すると以下の様に表示されます。(GOTRACEBACK=1)
panic: boom!
goroutine 1 [running]:
main.foo(...)
C:/dev/go-sandbox/a4.go:4
main.main()
C:/dev/go-sandbox/a4.go:8 +0x40
GOTRACEBACK=0 で実行すると以下になります。
panic: boom!
GOTRACEBACK=1 はデフォルト値です。GOTRACEBACK=2 では全 goroutine のトレースバックが表示されます。GOTRACEBACK=crash を設定すると許可されているシステムではコアダンプする様になります。Windows では以下の様に出力されます。
panic: boom!
goroutine 1 [running]:
panic(0x45d2c0, 0x47eec0)
C:/go/src/runtime/panic.go:706 +0x2d0 fp=0xc000031f40 sp=0xc000031eb0 pc=0x426ce0
main.foo(...)
C:/dev/go-sandbox/a4.go:4
main.main()
C:/dev/go-sandbox/a4.go:8 +0x40 fp=0xc000031f60 sp=0xc000031f40 pc=0x451c50
runtime.main()
C:/go/src/runtime/proc.go:203 +0x21e fp=0xc000031fe0 sp=0xc000031f60 pc=0x428a3e
runtime.goexit()
C:/go/src/runtime/asm_amd64.s:1357 +0x1 fp=0xc000031fe8 sp=0xc000031fe0 pc=0x44b8e1
意図的にコアダンプさせてデバッガで確認するのに便利です。
おわりに
Go を再コンパイルする事なくデバッグする為の環境変数を紹介しました。メモリが少しずつ増え続ける様なリークが、いったいどの様にして発生しているのかを知るのに便利だと思います。print デバッグでも良いですが、一度これらのオプションで動作を確認してみてはどうでしょうか。