20. 目前 Go 语言的 GC 还存在哪些问题?

尽管 Go 团队宣称 STW 停顿时间得以优化到 100 微秒级别,但这本质上是一种取舍。原本的 STW 某种意义上来说其实转移到了可能导致用户代码停顿的几个位置;除此之外,由于运行时调度器的实现方式,同样对 GC 存在一定程度的影响。

目前 Go 中的 GC 仍然存在以下问题:

1. Mark Assist 停顿时间过长

package main

import (
    "fmt"
    "os"
    "runtime"
    "runtime/trace"
    "time"
)

const (
    windowSize = 200000
    msgCount   = 1000000
)

var (
    best    time.Duration = time.Second
    bestAt  time.Time
    worst   time.Duration
    worstAt time.Time

    start = time.Now()
)

func main() {
    f, _ := os.Create("trace.out")
    defer f.Close()
    trace.Start(f)
    defer trace.Stop()

    for i := 0; i < 5; i++ {
        measure()
        worst = 0
        best = time.Second
        runtime.GC()
    }
}

func measure() {
    var c channel
    for i := 0; i < msgCount; i++ {
        c.sendMsg(i)
    }
    fmt.Printf("Best send delay %v at %v, worst send delay: %v at %v. Wall clock: %v \n", best, bestAt.Sub(start), worst, worstAt.Sub(start), time.Since(start))
}

type channel [windowSize][]byte

func (c *channel) sendMsg(id int) {
    start := time.Now()

    // 模拟发送
    (*c)[id%windowSize] = newMsg(id)

    end := time.Now()
    elapsed := end.Sub(start)
    if elapsed > worst {
        worst = elapsed
        worstAt = end
    }
    if elapsed < best {
        best = elapsed
        bestAt = end
    }
}

func newMsg(n int) []byte {
    m := make([]byte, 1024)
    for i := range m {
        m[i] = byte(n)
    }
    return m
}

运行此程序我们可以得到类似下面的结果:

$ go run main.go

Best send delay 330ns at 773.037956ms, worst send delay: 7.127915ms at 579.835487ms. Wall clock: 831.066632ms 
Best send delay 331ns at 873.672966ms, worst send delay: 6.731947ms at 1.023969626s. Wall clock: 1.515295559s 
Best send delay 330ns at 1.812141567s, worst send delay: 5.34028ms at 2.193858359s. Wall clock: 2.199921749s 
Best send delay 338ns at 2.722161771s, worst send delay: 7.479482ms at 2.665355216s. Wall clock: 2.920174197s 
Best send delay 337ns at 3.173649445s, worst send delay: 6.989577ms at 3.361716121s. Wall clock: 3.615079348s 

在这个结果中,第一次的最坏延迟时间高达 7.12 毫秒,发生在程序运行 578 毫秒左右。通过 go tool trace 可以发现,这个时间段中,Mark Assist 执行了 7112312ns,约为 7.127915ms;可见,此时最坏情况下,标记辅助拖慢了用户代码的执行,是造成 7 毫秒延迟的原因。

2. Sweep 停顿时间过长

同样还是刚才的例子,如果我们仔细观察 Mark Assist 后发生的 Sweep 阶段,竟然对用户代码的影响长达约 30ms,根据调用栈信息可以看到,该 Sweep 过程发生在内存分配阶段:

3. 由于 GC 算法的不正确性导致 GC 周期被迫重新执行

此问题很难复现,但是一个已知的问题,根据 Go 团队的描述,能够在 1334 次构建中发生一次 [15],我们可以计算出其触发概率约为 0.0007496251874。虽然发生概率很低,但一旦发生,GC 需要被重新执行,非常不幸。

4. 创建大量 Goroutine 后导致 GC 消耗更多的 CPU

这个问题可以通过以下程序进行验证:

func BenchmarkGCLargeGs(b *testing.B) {
    wg := sync.WaitGroup{}

    for ng := 100; ng <= 1000000; ng *= 10 {
        b.Run(fmt.Sprintf("#g-%d", ng), func(b *testing.B) {
            // 创建大量 goroutine,由于每次创建的 goroutine 会休眠
            // 从而运行时不会复用正在休眠的 goroutine,进而不断创建新的 g
            wg.Add(ng)
            for i := 0; i < ng; i++ {
                go func() {
                    time.Sleep(100 * time.Millisecond)
                    wg.Done()
                }()
            }
            wg.Wait()

            // 现运行一次 GC 来提供一致的内存环境
            runtime.GC()

            // 记录运行 b.N 次 GC 需要的时间
            b.ResetTimer()
            for i := 0; i < b.N; i++ {
                runtime.GC()
            }
        })

    }
}

其结果可以通过如下指令来获得:

$ go test -bench=BenchmarkGCLargeGs -run=^$ -count=5 -v . | tee 4.txt
$ benchstat 4.txt
name                     time/op
GCLargeGs/#g-100-12       192µs ± 5%
GCLargeGs/#g-1000-12      331µs ± 1%
GCLargeGs/#g-10000-12    1.22ms ± 1%
GCLargeGs/#g-100000-12   10.9ms ± 3%
GCLargeGs/#g-1000000-12  32.5ms ± 4%

这种情况通常发生于峰值流量后,大量 goroutine 由于任务等待被休眠,从而运行时不断创建新的 goroutine,
旧的 goroutine 由于休眠未被销毁且得不到复用,导致 GC 需要扫描的执行栈越来越多,进而完成 GC 所需的时间越来越长。
一个解决办法是使用 goroutine 池来限制创建的 goroutine 数量。

文档更新时间: 2020-12-30 22:00   作者:kuteng