Help us understand the problem. What is going on with this article?

goroutineがGCされずにリークする

More than 3 years have passed since last update.

続編 -> goroutineのgoは剛田武の剛だ。goroutineにみるジャイアニズムを検証する。

goroutineは終了しているものの、goroutineがGCされずにメモリがリークする状態が起きて困った。

  • 大量のgoroutineが同時に存在するとGCできずにリークするみたい。
  • 即座にgoroutineが終了(つまり同時に存在するgoroutineの数が多くない)する場合は、ちゃんとGCするみたい。

環境

OS: macOS 10.12.6
Go version: 1.8.3

サンプルコード

main.go
package main

import (
    "log"
    "net/http"
    _ "net/http/pprof"
    "runtime"
    "sync"
    "time"
    "runtime/debug"
)

func main() {
    test()
    runtime.GC()
    debug.FreeOSMemory()
    time.Sleep(3600 * time.Second)
}

var wghoge sync.WaitGroup

func test() {
    go func() {
        log.Println(http.ListenAndServe("localhost:6060", nil))
    }()
    log.Println("start")
    for i := 0; i < 10000; i++ {
        wghoge.Add(1)
        go routine3()
    }
    log.Println("num goroutine: ", runtime.NumGoroutine())
    wghoge.Wait()
    log.Println("done")
    log.Println("num goroutine: ", runtime.NumGoroutine())
}

func routine1() {
    wghoge.Done()
}

func routine2() {
    time.Sleep(time.Second)
    wghoge.Done()
}

func routine3() {
    _ = make([]byte, 10000)
    time.Sleep(time.Second)
    wghoge.Done()
}

func routine4() {
    hello := make([]byte, 1000)
    go subroutine4(hello)
    time.Sleep(time.Second)
    wghoge.Done()
}

func subroutine4(buf []byte) {
    buf[0] = 1
}

結果

routine1

$ go run main.go 
2017/08/23 18:08:29 start
2017/08/23 18:08:29 num goroutine:  21
2017/08/23 18:08:29 done
2017/08/23 18:08:29 num goroutine:  4

__ ___

2.3MB (これが正常)

routine2

$ go run main.go 
2017/08/23 18:09:32 start
2017/08/23 18:09:32 num goroutine:  10003
2017/08/23 18:09:33 done
2017/08/23 18:09:33 num goroutine:  3

__ _

27.6MB (25.3MBリークしてる)

routine3

$ go run main.go 
2017/08/23 18:10:32 start
2017/08/23 18:10:32 num goroutine:  10003
2017/08/23 18:10:33 done
2017/08/23 18:10:33 num goroutine:  3

__

47.8MB (45.5MBリークしてる)

routine4

$ go run main.go 
2017/08/23 18:27:53 start
2017/08/23 18:27:53 num goroutine:  10004
2017/08/23 18:27:54 done
2017/08/23 18:27:54 num goroutine:  3

__ _

29.1MB (26.8MBリークしてる)

ヒープとスタック

routine3

スタックにallocateされている
スタックにallocateされたものは、goroutineがGCされていないため余分にリークしている。(47MB)

$ go build -gcflags -m main.go 
# command-line-arguments
./main.go:56: can inline subroutine4
./main.go:46: wghoge escapes to heap
./main.go:44: routine3 make([]byte, 1000) does not escape // <-ここ
./main.go:20: func literal escapes to heap
./main.go:20: func literal escapes to heap
./main.go:23: "start" escapes to heap
./main.go:25: wghoge escapes to heap
./main.go:28: "num goroutine: " escapes to heap
./main.go:28: runtime.NumGoroutine() escapes to heap
./main.go:29: wghoge escapes to heap
./main.go:30: "done" escapes to heap
./main.go:31: "num goroutine: " escapes to heap
./main.go:31: runtime.NumGoroutine() escapes to heap
./main.go:21: http.ListenAndServe("localhost:6060", nil) escapes to heap
./main.go:23: test ... argument does not escape
./main.go:28: test ... argument does not escape
./main.go:30: test ... argument does not escape
./main.go:31: test ... argument does not escape
./main.go:21: test.func1 ... argument does not escape
./main.go:35: wghoge escapes to heap
./main.go:40: wghoge escapes to heap
./main.go:56: subroutine4 buf does not escape
./main.go:50: make([]byte, 1000) escapes to heap
./main.go:53: wghoge escapes to heap

routine4

[]byteはヒープにallocateされている。
ヒープは正しくGCされている。(29MB)

$ go build -gcflags -m main.go 
# command-line-arguments
./main.go:56: can inline subroutine4
./main.go:56: subroutine4 buf does not escape
./main.go:50: make([]byte, 1000) escapes to heap // <- ここ
./main.go:53: wghoge escapes to heap
./main.go:20: func literal escapes to heap
./main.go:20: func literal escapes to heap
./main.go:23: "start" escapes to heap
./main.go:25: wghoge escapes to heap
./main.go:28: "num goroutine: " escapes to heap
./main.go:28: runtime.NumGoroutine() escapes to heap
./main.go:29: wghoge escapes to heap
./main.go:30: "done" escapes to heap
./main.go:31: "num goroutine: " escapes to heap
./main.go:31: runtime.NumGoroutine() escapes to heap
./main.go:21: http.ListenAndServe("localhost:6060", nil) escapes to heap
./main.go:23: test ... argument does not escape
./main.go:28: test ... argument does not escape
./main.go:30: test ... argument does not escape
./main.go:31: test ... argument does not escape
./main.go:21: test.func1 ... argument does not escape
./main.go:35: wghoge escapes to heap
./main.go:40: wghoge escapes to heap
./main.go:46: wghoge escapes to heap
./main.go:44: routine3 make([]byte, 1000) does not escape

結論

困った。

多分わかった。

routine2で

main.go
func main() {
    test()
    test()
    test()
    test()
    runtime.GC()
    debug.FreeOSMemory()
    time.Sleep(3600 * time.Second)
}

とすると、

アクティビティモニタ__自分のプロセス_.png

で 29.3MBから変わらなくなった。

おそらく、goroutineはプールに溜められて再利用するような構造になっていて、同時実行数が増えるとプールのサイズが増えて戻らなくなるみたい。(要出典) プールされるのはgoroutineではなく、Heapメモリ。

routine3 でやると同様に、49.1MBで変わらなくなった。せめてスタックにあるメモリとかも解放されないみたいだ。

runtime.MemStats を見てみる。

routine3 で
http://localhost:6060/debug/pprof/heap?debug=1
にアクセスして、最後の部分を見てみる。

# runtime.MemStats
# Alloc = 5096360
# TotalAlloc = 8603416
# Sys = 54966520
# Lookups = 5
# Mallocs = 56624
# Frees = 41047
# HeapAlloc = 5096360
# HeapSys = 49807360
# HeapIdle = 44023808
# HeapInuse = 5783552
# HeapReleased = 44023808
# HeapObjects = 15577
# Stack = 524288 / 524288
# MSpan = 170392 / 327680
# MCache = 4800 / 16384
# BuckHashSys = 1443448
# GCSys = 1912832
# OtherSys = 934528
# NextGC = 9948944
# PauseNs = [130067 67694 123189 1952067 1685557 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0 0]
# NumGC = 5
# DebugGC = false

Alloc = 5096360
HeapSys = 49807360
HeapIdle = 44023808

であるから、実際に使っているのは、5MBほど。
HeapIdle がほとんどを占めている。
つまり、Heapとしてプロセスが掴んでいるがOSに解放していないためにメモリリークが起きる。

runtime: GC: heap idle is not released / decreaseによると

  • HeapIdleは、HeapReleasedを含む。
  • Goは、OSに対して使わなくなったメモリを通知するが、そのメモリを実際に解放するかはOSが決める。OSが無視することもある。
  • 実際にメモリがOSに回収されたかは、Goからは知るすべがないとのこと。

解決策

一度Heapしたものは解放されずに再利用されるみたいだ。
メモリがOSに回収されるかはOS次第であるみたい。

瞬間最大メモリ量を減らすことでメモリ量を制限できる。
あまりgoroutine関係ない。Goのメモリの扱い方の問題。

kawasin73
ソフトウェアエンジニアです。東京大学4年Go/Ruby/Swift/Python/Javascript/Java/C
https://kawasin73.hatenablog.com/
dmmcom
総合エンタテイメントサイト「DMM.com」を運営。会員数は2,900万人を突破。動画配信、FX、英会話、ゲーム、太陽光発電、3Dプリンタなど40以上のサービスを展開。沖縄での水族館事業参入、ベルギーでのサッカークラブ経営など、様々な事業を手掛ける。また2018年より若手起業家の支援を強化、「DMM VENTURES」による出資や、M&Aなどを積極的に展開している。
https://dmm-corp.com
Why not register and get more from Qiita?
  1. We will deliver articles that match you
    By following users and tags, you can catch up information on technical fields that you are interested in as a whole
  2. you can read useful information later efficiently
    By "stocking" the articles you like, you can search right away