1
異なるヒープオブジェクト数に対して、最大STW GCの休止時間をベンチマークしようとしています。私はGODEBUG=gctrace=1でこれを実行して、私のマシン上で出力されているなぜ「同時」Go GCフェーズが世界的に停止しているように見えますか？
package main
type message []byte
type channel map[int]message
const (
windowSize = 200000
msgCount = 1000000
)
func mkMessage(n int) message {
m := make(message, 1024)
for i := range m {
m[i] = byte(n)
}
return m
}
func pushMsg(c *channel, highID int) {
lowID := highID - windowSize
m := mkMessage(highID)
(*c)[highID] = m
if lowID >= 0 {
delete(*c, lowID)
}
}
func main() {
c := make(channel)
for i := 0; i < msgCount; i++ {
pushMsg(&c, i)
}
}
：
gc 1 @0.004s 2%: 0.007+0.44+0.032 ms clock, 0.029+0.22/0.20/0.28+0.12 ms cpu, 4->4->3 MB, 5 MB goal, 4 P
gc 2 @0.009s 3%: 0.007+0.64+0.042 ms clock, 0.030+0/0.53/0.18+0.17 ms cpu, 7->7->7 MB, 8 MB goal, 4 P
gc 3 @0.019s 1%: 0.007+0.99+0.037 ms clock, 0.031+0/0.13/1.0+0.14 ms cpu, 13->13->13 MB, 14 MB goal, 4 P
gc 4 @0.044s 2%: 0.009+2.3+0.032 ms clock, 0.039+0/2.3/0.30+0.13 ms cpu, 25->25->25 MB, 26 MB goal, 4 P
gc 5 @0.081s 1%: 0.009+9.2+0.082 ms clock, 0.039+0/0.32/9.7+0.32 ms cpu, 49->49->48 MB, 50 MB goal, 4 P
gc 6 @0.162s 0%: 0.020+10+0.078 ms clock, 0.082+0/0.28/11+0.31 ms cpu, 93->93->91 MB, 96 MB goal, 4 P
gc 7 @0.289s 0%: 0.020+27+0.092 ms clock, 0.080+0/0.95/28+0.37 ms cpu, 178->178->173 MB, 182 MB goal, 4 P
gc 8 @0.557s 1%: 0.023+38+0.086 ms clock, 0.092+0/38/10+0.34 ms cpu, 337->339->209 MB, 346 MB goal, 4 P
gc 9 @0.844s 1%: 0.008+40+0.077 ms clock, 0.032+0/5.6/46+0.30 ms cpu, 407->409->211 MB, 418 MB goal, 4 P
gc 10 @1.100s 1%: 0.009+43+0.047 ms clock, 0.036+0/6.6/50+0.19 ms cpu, 411->414->212 MB, 422 MB goal, 4 P
gc 11 @1.378s 1%: 0.008+45+0.093 ms clock, 0.033+0/6.5/52+0.37 ms cpu, 414->417->213 MB, 425 MB goal, 4 P
は、上記のリンクを参照してください。これを行うには、私はmapからメッセージをプッシュしてポップシンプルなベンチマークを書かれていますこの出力に関するドキュメント
行くの私のバージョンは次のとおりです。以上の結果から
$ go version
go version go1.7.1 darwin/amd64
、最長の壁時計STWの一時停止時間が0.093 msです。すばらしいです！
start := time.Now()
m := mkMessage(highID)
elapsed := time.Since(start)
でmkMessageをラップすることによって作成するために、新しいmessageを取り、最も遅いelapsed時間を印刷どのくらいタイムアウトしました。私がこれを得る時間は38.573036msでした！
これはおそらく並行マーク/スキャンフェーズで、そして「アイドルGC時間」と、特に壁時計時間と強く相関しているので、私は即座に不審でした。
私の質問は：なぜGCのこのおそらく同時相はミューテータをブロックするように見えるのでしょうか？
GCを定期的に実行すると、手動で計算された一時停止時間が< 1msになります。そのため、ライブ以外のヒープオブジェクトの制限があるようです。もしそうなら、私はその限界が何であるか分からず、なぜGCの同時フェーズがミューテータをブロックするように見えるのか？
特定の回答が必要な場合、goメーリングリストはおそらくより適切なフォーラムです（まだ行っていない場合は、現在のmasterブランチでこれをテストする必要があります） – JimB
これを見ると、ここでは大まかな相関が見られますが、小さな入力でしか見られません。 'mkMessage'の大部分の時間は、スライスを変更するのではなく、GC中の割り当てを待つのに費やされます。ポインタの数を1桁増加させると、それに応じて同時フェーズで費やされる時間が増えますが、スライスの割り当てや変更に要する時間は大幅に増加しません。 – JimB
これには巨大なマップがあり、一時停止の原因となるバグがあります。インクリメンタルな「ミューテータアシスト」 - コードが中断されてわずかな作業が行われ、マイクロ秒単位で実行されることがあり、マップ全体をスキャンすることがあります。 https://groups.google.com/forum/#!topic/golang-codereviews/kIqdlqEZ47M、https://github.com/golang/go/issues/16432、https://github.com/golang/goをご覧ください。/issues/14812、およびhttps://github.com/golang/go/issues/9477を参照してください。 Goのヒントがうまくいくかもしれません。古いバージョンの場合は1.7です。 – twotwotwo