ludwig125のブログ

頑張りすぎずに頑張る父

go言語で複数のgoroutineのleakを検出する（goleak使用）

関連

ludwig125.hatenablog.com

ludwig125.hatenablog.com

概要

goleakパッケージでのgoroutine leakを検出してみました。

goroutine数の確認

runtime package - runtime - Go Packages

上のパッケージを使って、goroutineの数を調べてみます。

何もしないmain関数

printlnするだけのmainのgoroutine数を調べてみます。

https://goplay.tools/snippet/TO3jpRrT8Ju

package main

import "runtime"

func main() {
    println(runtime.NumGoroutine())
}

私の環境では、1とでました。

main関数だけなのでこれは納得です。

Test関数

次にテスト関数でgoroutine数を調べてみます

https://goplay.tools/snippet/kPaUslIP_R1

package main

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

func TestSample(t *testing.T) {
    fmt.Println("num goroutine: ", runtime.NumGoroutine())
}

=== RUN   TestSample
num goroutine:  2
--- PASS: TestSample (0.00s)
PASS

私の環境では2とでました。

ここで2となる理由については詳しく調べませんが、runtime.main()以外にも他のgoroutineが動いていることがあり、 それが検出されているそうです。

参考にさせていただ記事： jxck.hatenablog.com

github.com

goroutineを起動（leakしないけど不安なコード）

ここから本題です。

文字列に「a1」とつけて返す関数GetResourceAをgoroutineで起動して終了を待つ関数Executeを作り、 各所でgoroutine数を測ってみます。

以下のは、leakしないものの本番導入するのは不安なコードです。（説明は後述）

https://goplay.tools/snippet/cOGJG5PmCG7

package main

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

func TestSample(t *testing.T) {
    fmt.Println("begin num goroutine: ", runtime.NumGoroutine())

    got, err := Execute("100")
    t.Log(got)
    t.Log(err)

    fmt.Println("end num goroutine: ", runtime.NumGoroutine())
}

type response struct {
    id  string
    res string
    err error
}

func Execute(id string) (string, error) {
    chA := make(chan response)
    fmt.Println("begin0 num goroutine: ", runtime.NumGoroutine())

    go func(id string) {
        fmt.Println("resA num goroutine: ", runtime.NumGoroutine())
        a, err := GetResourceA(id)
        fmt.Println("resA-1 num goroutine: ", runtime.NumGoroutine())
        if err != nil {
            chA <- response{err: err}
            return
        }
        chA <- response{id: id, res: a, err: err}
    }(id)
    fmt.Println("begin1 num goroutine: ", runtime.NumGoroutine())

    var resA string
    errs := make([]error, 0, 1)
    rr := <-chA
    fmt.Println("begin3 num goroutine: ", runtime.NumGoroutine())
    if rr.err != nil {
        errs = append(errs, rr.err)
    } else {
        resA = rr.res
    }

    fmt.Println("begin6 num goroutine: ", runtime.NumGoroutine())

    if len(errs) > 0 {
        return "", fmt.Errorf("%v", errs)
    }

    fmt.Println("res:", resA)

    fmt.Println("begin7 num goroutine: ", runtime.NumGoroutine())
    return "", nil
}

func GetResourceA(id string) (string, error) {

    return id + "a1", nil
}

結果は以下のようになりました

=== RUN   TestSample
begin num goroutine:  2
begin0 num goroutine:  2
begin1 num goroutine:  3
resA num goroutine:  3
resA-1 num goroutine:  3
begin3 num goroutine:  2
begin6 num goroutine:  2
res: 100a1
begin7 num goroutine:  2
    prog.go:13: 
    prog.go:14: <nil>
end num goroutine:  2
--- PASS: TestSample (0.00s)
PASS
  • goroutineでGetResourceAを待ち合わせている間はgoroutine数が２から３になって、また２に戻っていることがわかります

つまり以下のようになります

go func(id string) {
        fmt.Println("resA num goroutine: ", runtime.NumGoroutine())   ←goroutineが新たに起動したので３
        a, err := GetResourceA(id)
        fmt.Println("resA-1 num goroutine: ", runtime.NumGoroutine())   ←ここではまだ結果が返ってきてないので３
＜略＞
}(id)

＜略＞
rr := <-chA    ←ここで結果が返ってきたのでこの下の結果は２
fmt.Println("begin3 num goroutine: ", runtime.NumGoroutine()) ← ２

複数のgoroutineを起動（leakしないけど不安なコード）

上のgoroutineを２つにしてみます。 また、contextパッケージでtimeoutもできるようにします。

  • Timeoutはtime.Millisecondなので１ミリ秒です（短い）

呼びだした二つの関数のどちらかでエラーがでたらそれを出力します。

https://goplay.tools/snippet/r65dbSgNCYj

package main

import (
    "context"
    "fmt"
    "runtime"
    "testing"
    "time"
)

func TestSample(t *testing.T) {
    fmt.Println("begin num goroutine: ", runtime.NumGoroutine())

    id := "100"
    got, err := Execute(context.Background(), time.Millisecond, id)
    t.Log(got)
    t.Log(err)

    fmt.Println("end num goroutine: ", runtime.NumGoroutine())
}

type response struct {
    id  string
    res string
    err error
}

func Execute(ctx context.Context, timeout time.Duration, id string) (string, error) {
    ctx, cancel := context.WithTimeout(ctx, timeout)
    defer cancel()

    chA := make(chan response)
    chB := make(chan response)
    fmt.Println("begin0 num goroutine: ", runtime.NumGoroutine())

    go func(id string) {
        fmt.Println("resA num goroutine: ", runtime.NumGoroutine())
        a, err := GetResourceA(ctx, id)
        fmt.Println("resA-1 num goroutine: ", runtime.NumGoroutine())
        if err != nil {
            chA <- response{err: err}
            return
        }
        chA <- response{id: id, res: a, err: err}
    }(id)
    fmt.Println("begin1 num goroutine: ", runtime.NumGoroutine())
    go func(id string) {
        fmt.Println("resB num goroutine: ", runtime.NumGoroutine())
        b, err := GetResourceB(ctx, id)
        fmt.Println("resB-1 num goroutine: ", runtime.NumGoroutine())
        if err != nil {
            chB <- response{err: err}
            return
        }
        chB <- response{id: id, res: b, err: err}
    }(id)
    fmt.Println("begin2 num goroutine: ", runtime.NumGoroutine())

    var resA, resB string
    errs := make([]error, 0, 2)
    for i := 0; i < 2; i++ {
        fmt.Println("begin2-2 num goroutine: ", runtime.NumGoroutine())
        select {
        case rr := <-chA:
            fmt.Println("begin3 num goroutine: ", runtime.NumGoroutine())
            if rr.err != nil {
                errs = append(errs, rr.err)
                continue
            }
            resA = rr.res
        case rr := <-chB:
            fmt.Println("begin4 num goroutine: ", runtime.NumGoroutine())
            if rr.err != nil {
                errs = append(errs, rr.err)
                continue
            }
            resB = rr.res
        case <-ctx.Done():
            fmt.Println("begin5 num goroutine: ", runtime.NumGoroutine())
            errs = append(errs, ctx.Err())
        }
    }
    fmt.Println("begin6 num goroutine: ", runtime.NumGoroutine())

    if len(errs) > 0 { // GetResourceAとGetResourceBのどちらかで失敗したらエラー
        return "", fmt.Errorf("%v", errs)
    }

    fmt.Println("res:", resA, resB)

    fmt.Println("begin7 num goroutine: ", runtime.NumGoroutine())
    return "", nil
}

func GetResourceA(ctx context.Context, id string) (string, error) {

    return id + "a1", nil
}

func GetResourceB(ctx context.Context, id string) (string, error) {

    return id + "b1", nil
}

=== RUN   TestSample
begin num goroutine:  2
begin0 num goroutine:  2
begin1 num goroutine:  3
begin2 num goroutine:  4
begin2-2 num goroutine:  4
resB num goroutine:  4
resB-1 num goroutine:  4
begin4 num goroutine:  3
begin2-2 num goroutine:  3
resA num goroutine:  4
resA-1 num goroutine:  3
begin3 num goroutine:  2
begin6 num goroutine:  2
res: 100a1 100b1
begin7 num goroutine:  2
    prog.go:16: 
    prog.go:17: <nil>
end num goroutine:  2
--- PASS: TestSample (0.00s)
PASS
  • 結果は上の通り、goroutineが２つ起動したタイミングでgoroutine数は４となり、各goroutineが戻ってきた（selectのcaseに入った）時点で、徐々に減らし、最後はまた２になって終わります

ここまでは何の問題もないように思えます。

複数のgoroutineを起動（明確にleakする場合）

上の関数GetResourceBの中で、10秒Sleepさせてみます。 contextのTimeout時間がtime.Millisecondなので、これだと確実にTimeoutになります。 このコードを実行すると以下のようになります。

https://goplay.tools/snippet/f_40NzONfko

func GetResourceB(ctx context.Context, id string) (string, error) {
    time.Sleep(10 * time.Second)
    return id + "b1", nil
}

=== RUN   TestSample
begin num goroutine:  2
begin0 num goroutine:  2
begin1 num goroutine:  3
begin2 num goroutine:  4
begin2-2 num goroutine:  4
resA num goroutine:  4
resA-1 num goroutine:  4
begin3 num goroutine:  3
begin2-2 num goroutine:  3
resB num goroutine:  4
begin5 num goroutine:  3
begin6 num goroutine:  3
    prog.go:15: 
    prog.go:16: [context deadline exceeded]
end num goroutine:  3
--- PASS: TestSample (0.00s)
PASS
  • GetResourceBがTimeout以内に終わらなかったので、goroutineが回収されずにgoroutineが３のまま終わっています。
  • goroutine leakしている状態です
  • もしGetResourceBがなかなか終わらず、かつメモリを多量に消費する関数であれば、`Execute``関数が呼び出されるたびにメモリが回収されずやがては全体のメモリを圧迫することになります

goroutine leakを検出する

上のgoroutine leakを検出するのに、良いパッケージとしてgo.uber.org/goleakというものがあります。 Test関数の最後にgoleak.VerifyNone(t)するだけで検出されます

pkg.go.dev

package main

import (
    "context"
    "fmt"
    "runtime"
    "testing"
    "time"

    "go.uber.org/goleak"
)

func TestSample(t *testing.T) {
    defer goleak.VerifyNone(t)
    fmt.Println("begin num goroutine: ", runtime.NumGoroutine())

    got, err := Execute(context.Background(), time.Millisecond)
    t.Log(got)
    t.Log(err)

    fmt.Println("end num goroutine: ", runtime.NumGoroutine())
}

https://goplay.tools/snippet/3AOHnWHx9Ww

=== RUN   TestSample
begin num goroutine:  2
begin0 num goroutine:  2
begin1 num goroutine:  3
begin2 num goroutine:  4
begin2-2 num goroutine:  4
resB num goroutine:  4
resA num goroutine:  3
resA-1 num goroutine:  4
begin3 num goroutine:  3
begin2-2 num goroutine:  3
begin5 num goroutine:  3
begin6 num goroutine:  3
    prog.go:18: 
    prog.go:19: [context deadline exceeded]
end num goroutine:  3
    leaks.go:78: found unexpected goroutines:
        [Goroutine 8 in state sleep, with time.Sleep on top of the stack:
        goroutine 8 [sleep]:
        time.Sleep(0x2540be400?)
            /usr/local/go-faketime/src/runtime/time.go:194 +0x111
        main.GetResourceB(...)
            /tmp/sandbox2930251588/prog.go:105
        main.Execute.func2({0x4dda2e, 0x3})
            /tmp/sandbox2930251588/prog.go:53 +0xff
        created by main.Execute
            /tmp/sandbox2930251588/prog.go:51 +0x3af
        ]
--- FAIL: TestSample (0.43s)
FAIL
  • leaks.go:78: found unexpected goroutines:とはっきり出してくれました

複数のgoroutineを起動（leakさせないように改修）

  • 上のleakの原因はcontextのTimeoutになってmain関数が終わったのに、GetResourceBが終わらない（キャンセルされない）ためでした。

  • この修正は簡単で、以下のようにTimeoutでcontextのキャンセルがあった時に、GetResourceBがそのキャンセルを受け取ればよいだけです

  • つまり以下のように修正すればよいです

https://goplay.tools/snippet/YFxohza2aFc

func GetResourceB(ctx context.Context, id string) (string, error) {
    // time.Sleep(10 * time.Second)
    select {
    case <-ctx.Done():
        fmt.Println("context Done in GetResourceB")
        return "", ctx.Err()
    case <-time.After(10 * time.Second):
        fmt.Println("sleep finished in GetResourceB")
    }
    return id + "b1", nil
}

  • 上のselect処理は10秒経過するのか、ctx.Done()を受け取るか、のどちらかが来れば終わります

  • これにより、10秒経過前にcontextがキャンセルされればctx.Done()を受信して終わります。

  • この方法は「Go言語による並行処理」にも書いてあります。

    • 私の持つ初版では「4.12 contextパッケージ」にありました。

www.oreilly.co.jp

上のコードを実行してみます。

=== RUN   TestSample
begin num goroutine:  2
begin0 num goroutine:  2
begin1 num goroutine:  3
begin2 num goroutine:  4
begin2-2 num goroutine:  4
resA num goroutine:  4
resA-1 num goroutine:  4
begin3 num goroutine:  3
begin2-2 num goroutine:  3
resB num goroutine:  4
begin5 num goroutine:  3
begin6 num goroutine:  3
    prog.go:18: 
    prog.go:19: [context deadline exceeded]
context Done in GetResourceB
resB-1 num goroutine:  3
end num goroutine:  2
--- PASS: TestSample (1.00s)
PASS

  • goroutine leakが検出されず、goroutine数は起動時と同じ２で終わっています

  • context Done in GetResourceBが出ているので、contextのキャンセルを受け取ったことがわかります

ちなみに、time.Afterを10秒ではなく、contextのTimeoutより短い10マイクロ秒にすると、GetResourceBはキャンセルされずに終わります

https://goplay.tools/snippet/7WiqTULOmTR

=== RUN   TestSample
begin num goroutine:  2
begin0 num goroutine:  2
begin1 num goroutine:  3
resA num goroutine:  3
resA-1 num goroutine:  4
resB num goroutine:  4
begin2 num goroutine:  4
begin2-2 num goroutine:  3
begin3 num goroutine:  3
begin2-2 num goroutine:  3
sleep finished in GetResourceB
resB-1 num goroutine:  3
begin4 num goroutine:  2
begin6 num goroutine:  2
res: 100a1 100b1
begin7 num goroutine:  2
    prog.go:18: 
    prog.go:19: <nil>
end num goroutine:  2
--- PASS: TestSample (1.00s)
PASS
  • 今度は、sleep finished in GetResourceBが出力されました
  • キャンセルされずに関数が正常終了した場合です

まとめ

  • go.uber.org/goleakを使うことでgoroutine leakの検出ができるようになりました
  • 今後も使ってみたいと思います