记录自己demo测试runtime.SetFinalizer的运行未如期的排查过程
问题缘由
看go-cache源码时候发现其使用了runtime.SetFinalizer这个函数绑定关闭周期性清除过期key的goroutine 到cache本身的生命周期，也就是说cache被垃圾回收的时候会停止此goroutine。
所以我也就想自己写个demo试试是不是真正的有效，设计的demo是假设有一个school，school有一个看门狗（watch_dog），假设在school开着的时候狗每一秒叫（bark）一句【此操作单独在一个goroutine通过ticker实现】，当school关闭（垃圾回收）时候自然期望能够停止前面狗叫的goroutine。demo代码如下：
1 | package main |
问题
上面的demo代码输出如下（可见狗一直在叫、即使是在学校置空后6分钟也没有停止，故也就是并没有触发dog_stop函数）：
1 | 021/07/05 09:11:13 bark |
排查过程
是因为没有GC吗？
既然是在school回收的时候触发、那是不是此期间就没有回收、没有触发GC呢？这时候先使用了通过设置GODEBUG=gctrace=1来看输出：
1 | 2021/07/05 09:27:55 bark |
从上面的输出我们可以看出来、每两分钟，是执行了GC的！
那么问题是什么呢？
经过在知识星球上、欧长坤大佬的回复得知：这里的输出只是标记阶段、并不是清除阶段。而SetFinalizer的触发是要在实际清除阶段才会触发的
结合这篇文章我知道了，其实可以说的GC和sweep完全是两个阶段，笼统的在这里可以认为GC阶段纯粹是标记阶段【所以上面的gctrace=1参数的输出信息全部是标记阶段、是看不到sweep相关信息的】，而sweep阶段是要在标记为不用的块需要再次被用到的时候才会发生的阶段！
验证回答之手动触发sweep
可以通过分配大内存（从而要用那部分标记为已不用的堆内存）或 runtime.GC()手动触发
1 | package main |
输出：
1 | 2021/07/05 13:37:52 bark |
可见在手动触发后、是有效触发了通过runtime.SetFinalizer绑定的dog_stop方法的！
怎么才能看到是真的触发了sweep呢？
虽然大佬说了，但是不看到真的是因为没有触发sweep以及runtime.GC()是真的触发了sweep还是不甘心，那么怎么能够看到是不是真的触发了sweep呢？
错解：通过gcpacertrace参数
胡乱看的时候、有看到可以设置gcpacertrace参数，其中看到了很具有迷惑性的sweep相关信息（以下是设置了GODEBUG=gctrace=1,gcpacertrace=1的输出）：
1 | 2021/07/05 10:09:47 bark |
虽然pacer的输出有sweep done at…, 但是其并不是真正说的sweep。因为pacer本身就不是处理sweep的，而是处理调整下次gc频率等作用的算法…
正解：go tool trace
go tool trace 可以看到所有的程序运行细节
这里先看下调用了runtime.GC()的情况
在代码中加入trace相关代码
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54type dog struct {
stop chan bool
}
func (d *dog) dog_run() {
ticker := time.NewTicker(1 * time.Second)
for {
select {
case <-ticker.C:
// log.Println("bark")
case <-d.stop:
ticker.Stop()
return
}
}
}
type School struct {
Students []string
dog *dog
}
func (s *School) doNothing() {
}
func dog_stop(s *School) {
// log.Println("dog_stop get called")
s.dog.stop <- true
}
func (s *School) new() {
watch_dog := dog{make(chan bool)}
s.dog = &watch_dog
go watch_dog.dog_run()
}
func NewSchool(names ...string) *School {
school := School{Students: names}
school.new()
runtime.SetFinalizer(&school, dog_stop)
return &school
}
func main() {
trace.Start(os.Stderr)
defer trace.Stop()
school := NewSchool([]string{"xx小学"}...)
school.doNothing()
time.Sleep(time.Second * 4)
school = nil
time.Sleep(4 * time.Second)
runtime.GC()
time.Sleep(4 * time.Second)
}将trace输出放到文件
1
go run main.go 2> trace_with_handly_gc.out
运行go tool trace运行可在浏览器中查看情况
1
2
3
4$ go tool trace trace_with_handly_gc.out
2021/07/05 13:52:41 Parsing trace...
2021/07/05 13:52:41 Splitting trace...
2021/07/05 13:52:41 Opening browser. Trace viewer is listening on http://127.0.0.1:64658去到浏览器后显示：
1
2
3
4
5
6
7
8
9View trace
Goroutine analysis
Network blocking profile (⬇)
Synchronization blocking profile (⬇)
Syscall blocking profile (⬇)
Scheduler latency profile (⬇)
User-defined tasks
User-defined regions
Minimum mutator utilization点击其中的“Goroutine analysis”可看到程序中每个goroutine的信息：
1
2
3
4
5
6
7
8
9Goroutines:
runtime.main N=1
runtime.gcBgMarkWorker N=4
main.(*dog).dog_run N=1
runtime/trace.Start.func1 N=1
runtime.runfinq N=1
runtime.bgsweep N=1
runtime.bgscavenge N=1
N=1其中的runtime.bgsweep goroutine就表明触发了sweep！
再次原程序并且走上面的流程、到最后一步“Goroutine analysis”可见输出如下：
1
2
3
4
5Goroutines:
main.(*dog).dog_run N=1
runtime.main N=1
runtime/trace.Start.func1 N=1
N=4可见、上面没有runtime.bgsweep goroutine、没有触发sweep
总结
- runtime.SetFinalizer的绑定触发是在sweep时候才会触发
- gctrace=1参数看到的只是gc的信息，是没有sweep相关信息的
- go tool trace非常强大、可基本看到全部信息