概要

ludwig125.hatenablog.com

この記事のsync.PoolでのSlice操作の高速化で取り上げた、 BenchmarkReplicateStrNTimesWithPool 関数でメモリアロケーションが0になる理由が解せなかったので自分なりに調べたことをまとめます

appendを使った方法でアロケーション数が0になる理由は？

上の気になる点は、appendを使う方法に変えたにもかかわらず、メモリのアロケーション回数、アロケーションされたバイト数は0のままなことです。

appendをしているので少しは増えるかと思ったのですが、ここが0のままなのはなぜでしょう。。？

gcflags=-m で最適化の確認

goのプログラムが変数を処理するとき、stack割り当てについてはBenchmarkはアロケーションに含めていません。heap割り当てのみが対象になります。

参考：

そのため、アロケーションが0ということは、ReplicateStrNTimesWithPoolはheapではなくすべてstack割り当てをしているか、どこにも割り当てしていないということになってしまいます。

確認するために、上のBenchmark実行時に-gcflags=-mオプションを渡してみました。 -gcflags=-mオプションをつけると、build時、test時に内部の変数がheap割り当てになるかなどの、最適化を確認することができます。ちなみに、-gcflags='-m -m'とmを増やすとより詳細な結果が得られます。

[~/go/src/github.com/ludwig125/sync-pool/replicate_str_revised] $go test -bench . -count=4 -gcflags=-m
# github.com/ludwig125/sync-pool/replicate_str_revised [github.com/ludwig125/sync-pool/replicate_str_revised.test]
./replicate_str_revised_test.go:66:16: inlining call to testing.(*B).ReportAllocs
./replicate_str_revised_test.go:75:16: inlining call to testing.(*B).ReportAllocs
./replicate_str_revised_test.go:11:7: can inline glob..func1
./replicate_str_revised_test.go:16:25: leaking param: s
./replicate_str_revised_test.go:17:12: make([]string, n) escapes to heap
./replicate_str_revised_test.go:29:8: ReplicateStrNTimesWithPool ignoring self-assignment in *ss = (*ss)[:0]
./replicate_str_revised_test.go:24:33: leaking param: s
./replicate_str_revised_test.go:37:29: leaking param: t
./replicate_str_revised_test.go:48:57: leaking param: t
./replicate_str_revised_test.go:54:65: leaking param: t

（以下省略：37行目以降は TestReplicateStrNTimes部分なので見る必要ないです）

これを見ると、ReplicateStrNTimesのmake([]string, n)ではheap割り当てが発生しています。

./replicate_str_revised_test.go:17:12: make([]string, n) escapes to heap

一方でReplicateStrNTimesWithPoolはそれにあたるものが出ていません。もしstack割り当てが発生しているとしたら、does not escapeというheapに変数を退避させなかったメッセージが出るのですが、それも出ていません。

なので、最適化の結果だけを見ると、appendにした場合のsliceについて heapにもstackにも割り当てされている様子が見えない

=> 新たな割り当てが起きていない？

という謎なことになりました。これはおかしいです。

appendの場合のアロケーションが0となってしまう原因の推測

おそらく、appendでcapを拡張するのは毎回行うことではないからでは、という推測をしています。

capは最初0で、次にappendされるたびに1、2、4, 8, 16と倍々に増やされますが、例えば一度capを16まで増やしたら、要素数が9から16まで追加される間はcapがその範囲内なので拡張しません。次に要素数が17になるときにcapは32に拡張されますが、そうなると、要素数18~32の間は同じく拡張されず、次に拡張されるのは33番目を追加するタイミングです。

もしcapが拡張されないタイミングを測定したらアロケーションは0になるはずです。

毎回nilにする場合のアロケーション回数の確認

そこで、試しに以下のように、(*ss) = (*ss)[:0]ではなく、 (*ss) = nilとして、sliceをメモリごと初期化するようにしてみました。

func ReplicateStrNTimesWithPool(s string, n int) []string {
    ss := pool.Get().(*[]string)

    // (*ss) = (*ss)[:0]
    (*ss) = nil
    defer pool.Put(ss)
    for i := 0; i < n; i++ {
        (*ss) = append((*ss), s)
    }
    return *ss
}

これでBenchmarkを取ると、

ReplicateStrNTimesWithPool("12345", 1)のように文字列１個だけのSliceを作る時は

1 allocs/op

ReplicateStrNTimesWithPool("12345", 2)のように文字列２個のSliceを作る時は

2 allocs/op

ReplicateStrNTimesWithPool("12345", 32)は

6 allocs/op

ReplicateStrNTimesWithPool("12345", 33)は

7 allocs/op

となりました。

capの拡張操作は以下の順番で行われるので、32要素のSliceを作るには6回操作 = 6 allocs/op、 33要素のSliceには７回操作 = 7 allocs/opとなることが確認できました。

capの推移

0 -> 1: 1回目
1 -> 2: 2回目
2 -> 4: 3回目
4 -> 8: 4回目
8 -> 16: 5回目
16 -> 32: 6回目
32 -> 64: 7回目

毎回nilする場合は想定通りのメモリアロケーションがありましたが、最初の例で全部 0 allocなのはまだよくわかっていません。

例えば ReplicateStrNTimesWithPool("12345", 5)のときは、 3回目と5回目はcap拡張によるアロケーションがカウントされないので、「カウントしない場合もあるから0と見なそう」とBenchmarkが働いているということならわかりますが、以下のように１回にしたら必ず0->1のcap拡張があるはずです。

func BenchmarkReplicateStrNTimesWithPool(b *testing.B) {
    b.ReportAllocs()
    var r []string
    for n := 0; n < b.N; n++ {
        // r = ReplicateStrNTimesWithPool("12345", 5)
        r = ReplicateStrNTimesWithPool("12345", 1)
    }
    Result = r
}

それでもこの結果は 0 allocs/opになりました。

よくわからないので次に単純なサンプルで確認してみました。

Allocsの確認（AllocsPerRunで確認）

testingパッケージにはAllocsPerRunという関数があります。

https://pkg.go.dev/testing#AllocsPerRun

これは、引数として関数と実行回数を与えると、１実行回数あたりのアロケーション数をカウントする関数です。

試しにこの関数で上と同様にappendをする関数のアロケーションを確認してみます。

以下の関数では、stringではなくintのsliceとなっていますが、検証の過程でintにしただけで挙動に違いはありません

package main

import (
    "fmt"
    "sync"
    "testing"
)

var pool = &sync.Pool{
    New: func() interface{} {
        return &[]int{}
    },
}

func AddNum(n int) []int {
    l := pool.Get().(*[]int)
    defer pool.Put(l)

    (*l) = (*l)[:0]
    (*l) = append((*l), n)

    return (*l)
}

func TestAddNum(t *testing.T) {
    fmt.Println("Allocs:", int(testing.AllocsPerRun(1, func() {
        AddNum(1)
    })))
}

この実行結果は以下のようになりました。

[~/go/src/github.com/ludwig125/sync-pool/check_allocs] $go test -v .
=== RUN   TestAddNum
Allocs: 0
--- PASS: TestAddNum (0.00s)
PASS
ok      github.com/ludwig125/sync-pool/check_allocs     0.002s

やはりBenchmarkのときと同様にアロケーション数0となりました。

ここでこのAllocsPerRunの実装を見てみます。 https://github.com/golang/go/blob/2ebe77a2fda1ee9ff6fd9a3e08933ad1ebaea039/src/testing/allocs.go#L20-L45

func AllocsPerRun(runs int, f func()) (avg float64) {
    defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))

    // Warm up the function
    f()  // <1> warm upで一度実行

    // Measure the starting statistics
    var memstats runtime.MemStats
    runtime.ReadMemStats(&memstats) // <2> runtime.MemStatsで現在のメモリ情報を取得
    mallocs := 0 - memstats.Mallocs

    // Run the function the specified number of times
    for i := 0; i < runs; i++ {
        f() // <3> runの回数だけ関数を実行
    }

    // Read the final statistics
    runtime.ReadMemStats(&memstats) // <4> 再度runtime.MemStatsでメモリ情報を取得
    mallocs += memstats.Mallocs  // <5> run回関数を実行する前のmalloc数との差分を計算

    // Average the mallocs over the runs (not counting the warm-up).
    // We are forced to return a float64 because the API is silly, but do
    // the division as integers so we can ask if AllocsPerRun()==1
    // instead of AllocsPerRun()<2.
    return float64(mallocs / uint64(runs)) // <6> １runあたりのmallocsを計算
}

これを見ると、以下の処理になっています。

<1> 最初に引数として与えた関数を Warm upとして１回実行
<2> runtime.MemStatsで現在のメモリ情報を取得
<3> runの回数だけ関数を実行
<4> 再度runtime.MemStatsでメモリ情報を取得
<5> run回関数を実行する前のmalloc数との差分を計算
<6> 最後に１runあたりのmallocsを計算

最初のwarm up関数があることで、以下のようにtesting.AllocsPerRunのRun回数として１を指定しても、実際には２回AddNum関数が実行されていることが分かりました。

fmt.Println("Allocs:", int(testing.AllocsPerRun(1, func() {
    AddNum(1)
})))

１回だけ関数を実行したときのmalloc数を確認するために、testing.AllocsPerRunを参考に MyAllocsPerRun関数を作ってみました。また、関数の実行前後のmallocの差分をプリントするようにしてみたのが以下のコードです。

AddNum関数は同じなので省略しています。

func TestAddNum(t *testing.T) {
    fmt.Println("MyAllocs:", int(MyAllocsPerRun(1, func() {
        AddNum(1)
    })))
}

func MyAllocsPerRun(runs int, f func()) (avg float64) {
    defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))

    var memstats runtime.MemStats
    runtime.ReadMemStats(&memstats)
    mallocs := 0 - memstats.Mallocs
    before := memstats.Mallocs // 関数実行前のmallocs

    for i := 0; i < runs; i++ {
        f()
    }

    runtime.ReadMemStats(&memstats)
    mallocs += memstats.Mallocs

    fmt.Printf("mallocs: %v, memstats.Mallocs(before %d ->after %d). run: %d\n", mallocs, before, memstats.Mallocs, uint64(runs))

    return float64(mallocs / uint64(runs))
}

これを実行すると以下のようになります

[~/go/src/github.com/ludwig125/sync-pool/check_allocs2] $go test -v . -count=1
=== RUN   TestAddNum
mallocs: 4, memstats.Mallocs(before 278 ->after 282). run: 1
MyAllocs: 4
--- PASS: TestAddNum (0.00s)
PASS
ok      github.com/ludwig125/sync-pool/check_allocs2    0.002s

なんといきなり MyAllocs: 4となりました！

testing.AllocsPerRun の結果が0だったということは、 warm upの関数実行がmalloc数4にあたり、そのあとの以下の部分では新しいアロケーションは行われなかったということが考えられます。

for i := 0; i < runs; i++ {
    f()
}

実際にMyAllocsPerRunでも、最初の行でf()を実行するとMyAllocs: 0になりました。

func MyAllocsPerRun(runs int, f func()) (avg float64) {
    defer runtime.GOMAXPROCS(runtime.GOMAXPROCS(1))

    f()
    ＜略＞

mallocs: 0, memstats.Mallocs(before 279 ->after 279). run: 2
MyAllocs: 0

Allocsの確認（直接runtime.ReadMemStatsで確認）

アロケーションが0とカウントされる原因がかなり分かってきたので、

以下では直接AddNum関数本体にアロケーションの確認を入れてみました。

package main

import (
    "fmt"
    "runtime"
    "sync"
    "testing"
)

var pool = &sync.Pool{
    New: func() interface{} {
        return &[]int{}
    },
}

func AddNum(n int) []int {
    var memstats runtime.MemStats
    runtime.ReadMemStats(&memstats)
    mallocs := 0 - memstats.Mallocs
    before := memstats.Mallocs

    l := pool.Get().(*[]int)
    defer pool.Put(l)
    (*l) = (*l)[:0]

    (*l) = append((*l), n)

    runtime.ReadMemStats(&memstats)
    mallocs += memstats.Mallocs
    fmt.Printf("mallocs: %v, memstats.Mallocs(before %d ->after %d). IN FUNC\n", mallocs, before, memstats.Mallocs)

    return (*l)
}

func TestAddNum(t *testing.T) {
    AddNum(1)
    AddNum(1)
}

この実行結果は以下です。

予想通り、最初のAddNum関数実行時にはmallocs: 4なのに、２回目はmallocs: 0となりました。

[~/go/src/github.com/ludwig125/sync-pool/check_allocs3] $go test -v . -count=1
=== RUN   TestAddNum
mallocs: 4, memstats.Mallocs(before 272 ->after 276). IN FUNC
mallocs: 0, memstats.Mallocs(before 279 ->after 279). IN FUNC
--- PASS: TestAddNum (0.00s)
PASS
ok      github.com/ludwig125/sync-pool/check_allocs3    0.003s

以下のようにさらにAddNumを書き換えるとようやく分かってきます。 l := pool.Get().(*[]int) 部分のみをmallocの計測範囲としました。

ついでに、pool内のsliceの長さlenと容量capを出力するようにします。 fmt.Printf("*l: %v, len(*l): %v, cap(*l): %v\n", *l, len(*l), cap(*l))

結果が分かりやすいようにTestAddNum内でAddNum関数を実行するときに、１回目は1を２回目は2を引数にしました。

func AddNum(n int) []int {
    var memstats runtime.MemStats
    runtime.ReadMemStats(&memstats)
    mallocs := 0 - memstats.Mallocs
    before := memstats.Mallocs

    l := pool.Get().(*[]int)

    runtime.ReadMemStats(&memstats)
    mallocs += memstats.Mallocs
    fmt.Printf("mallocs: %v, memstats.Mallocs(before %d ->after %d). IN FUNC\n", mallocs, before, memstats.Mallocs)

    defer pool.Put(l)
    (*l) = (*l)[:0]

    (*l) = append((*l), n)

    fmt.Printf("*l: %v, len(*l): %v, cap(*l): %v\n", *l, len(*l), cap(*l))
    return (*l)
}

func TestAddNum(t *testing.T) {
    AddNum(1)
    AddNum(2)
}

これの実行結果は以下の通りです。

mallocs: 3, memstats.Mallocs(before 278 ->after 281). IN FUNC
*l: [1], len(*l): 1, cap(*l): 1
mallocs: 0, memstats.Mallocs(before 287 ->after 287). IN FUNC
*l: [2], len(*l): 1, cap(*l): 1

次に、今度は(*l) = append((*l), n)部分のみをmallocsの確認対象として囲んでみます。

func AddNum(n int) []int {
    l := pool.Get().(*[]int)
    defer pool.Put(l)
    (*l) = (*l)[:0]

    var memstats runtime.MemStats
    runtime.ReadMemStats(&memstats)
    mallocs := 0 - memstats.Mallocs
    before := memstats.Mallocs

    (*l) = append((*l), n)

    runtime.ReadMemStats(&memstats)
    mallocs += memstats.Mallocs
    fmt.Printf("mallocs: %v, memstats.Mallocs(before %d ->after %d). IN FUNC\n", mallocs, before, memstats.Mallocs)
    fmt.Printf("*l: %v, len(*l): %v, cap(*l): %v\n", *l, len(*l), cap(*l))
    return (*l)
}

実行結果

mallocs: 1, memstats.Mallocs(before 278 ->after 279). IN FUNC
*l: [1], len(*l): 1, cap(*l): 1
mallocs: 0, memstats.Mallocs(before 284 ->after 284). IN FUNC
*l: [2], len(*l): 1, cap(*l): 1

ここから次の結果が得られました。

AddNum １回目: l := pool.Get().(*[]int)のアロケーション数は3
AddNum １回目: (*l) = append((*l), n)のアロケーション数は1
AddNum ２回目: アロケーション数は０

関数内で、(*l) = (*l)[:0]をしたあとappendしているので、 *lの容量は１回目と同じ１のまま、中身の数字だけ1から2に変わっています。

以上のことから、最初に私が疑問に思った通り、appendをするとアロケーションがされることは確認できました。

また、testing.AllocsPerRun の結果が0になる理由も確認できました。

testing.AllocsPerRun はmallocの計測前に関数を１回実行するので、それ以降の実行時のアロケーションは0になるからです。

Allocsの確認（Benchmarkのコードを確認）

同様のことがBenchmarkにも言えそうです。

Benchmarkのアロケーションのカウントも同じように memstats.Mallocsの差分を実行回数で割るという方法は変わりません。

Benchmarkでも、以下のように最初の時点のmalloc数との差分を取ってから、

runtime.ReadMemStats(&memStats)
b.netAllocs += memStats.Mallocs - b.startAllocs

実行回数で割っています

int64(r.MemAllocs) / int64(r.N)

https://github.com/golang/go/blob/0941dbca6ae805dd7b5f7871d5811b7b7f14f77f/src/testing/benchmark.go#L389-L397

また、Benchmarkでは、最初にb.run1()と１回だけ実行してから、そのあとメインのr := b.doBench()をしているようです。 - https://github.com/golang/go/blob/0941dbca6ae805dd7b5f7871d5811b7b7f14f77f/src/testing/benchmark.go#L568-L583

さらに、このdoBench関数の先を見ていくと、Benchmarkの測定対象であるrunN関数内では、事前にGCをしていることが分かりました。事前にrun1でPoolに何か書き込まれても、GCで空になるので次の関数実行タイミングではまっさらの状態からのメモリ割り当てが置きそうです。

// Try to get a comparable environment for each run
// by clearing garbage from previous runs.
runtime.GC()  <- ガベージコレクションをするのでPoolの中身が空になる
b.raceErrors = -race.Errors()
b.N = n
b.parallelism = 1
b.ResetTimer()
b.StartTimer()
b.benchFunc(b) <- ここで関数を実行

https://github.com/golang/go/blob/0941dbca6ae805dd7b5f7871d5811b7b7f14f77f/src/testing/benchmark.go#L186

確認するために、ReplicateStrNTimesWithPool 関数内でグローバル変数cntをインクリメントして、Benchmark時に出力するようにしてみます。

またBenchmark関数内は１回だけ実行するようにfor n := 0; n < b.N; n++ {をやめます。

package main

import (
    "fmt"
    "sync"
    "testing"
)

var pool = &sync.Pool{
    New: func() interface{} {
        return &[]string{}
    },
}

func ReplicateStrNTimesWithPool(s string, n int) []string {
    cnt++
    ss := pool.Get().(*[]string)

    (*ss) = (*ss)[:0]
    defer pool.Put(ss)
    for i := 0; i < n; i++ {
        (*ss) = append((*ss), s)
    }
    return *ss
}

var Result []string

var cnt int

func BenchmarkReplicateStrNTimesWithPool(b *testing.B) {
    b.ReportAllocs()
    Result = ReplicateStrNTimesWithPool("12345", 1)
    fmt.Printf("\ncnt %d\n", cnt)
}

そして、Benchmarkを測定するときに、実行回数が確実に１回だけになるように -benchtime=1x を指定、さらに余計な並行処理をしないように -cpu 1とします。

Benchmarkのオプションについては公式ドキュメントを参考にしています。

https://pkg.go.dev/cmd/go#hdr-Testing_flags

この実行結果は以下の通りです。

[~/go/src/github.com/ludwig125/sync-pool/replicate_str_revised_run1] $go test -bench . -benchtime=1x -cpu 1

cnt 1
goos: linux
goarch: amd64
pkg: github.com/ludwig125/sync-pool/replicate_str_revised_run1
BenchmarkReplicateStrNTimesWithPool
cnt 2
       1             51800 ns/op             280 B/op          4 allocs/op
PASS
ok      github.com/ludwig125/sync-pool/replicate_str_revised_run1       0.004s

想定通り、Benchmarkの測定前に１回関数が実行されているので、cnt 1が最初にでます。

そのあとで、やはり１回だけ関数が実行されてcnt 2となり、メモリアロケーションは 4 allocs/opとなりました。この 4 allocs/opというのは、前述の「PoolからのGet: 3」+「append: 1」で確認した４という数字と一致します。

先に書いた通り、Benchmarkのアロケーション数は、「実際のアロケーション数／関数の実行回数」となるので、 benchtime=5x のように５回以上を指定すれば、4/5 は１未満になるので、結果は0 allocs/opとみなされます。

以下の通りです。

[~/go/src/github.com/ludwig125/sync-pool/replicate_str_revised_run1] $go test -bench . -benchtime=5x -cpu 1

cnt 1
goos: linux
goarch: amd64
pkg: github.com/ludwig125/sync-pool/replicate_str_revised_run1
BenchmarkReplicateStrNTimesWithPool
cnt 2
       5             10540 ns/op              56 B/op          0 allocs/op
PASS
ok      github.com/ludwig125/sync-pool/replicate_str_revised_run1       0.004s
[~/go/src/github.com/ludwig125/sync-pool/replicate_str_revised_run1] $

これで、一番最初の疑問の、ReplicateStrNTimesWithPool関数でappendをしているのに、アロケーション数が0になる原因がはっきりと分かりました。

Benchmarkでは実際にアロケーションがあっても、実行回数で割った時に１未満になる時は0と出力される、という単純なことでした。

この確認にずいぶんと時間がかかりましたが、Benchmark関数の挙動の理解ができて満足です。

ludwig125のブログ

頑張りすぎずに頑張る父

golangのappendでBenchmark時にアロケーション数が0と測定される場合について

概要