一个print 0 的问题定位过程
in Go with 0 comment

一个print 0 的问题定位过程

in Go with 0 comment

注:本文章仅用来记录问题分析的过程,从实际使用上来说,该例子存在data race,不应该依赖其执行结果。

该例子是在饶大的一次夜读分享中所展示的。

package main

import (
	"fmt"
	"runtime"
	"time"
)

func main() {
	runtime.GOMAXPROCS(8)
	var x int64 = 0
	for i := 0; i < 8; i++ {
		go func() { // 后续中没有特殊说明的goroutine都是该goroutine
			for {
				x++
			}
		}()
	}
	time.Sleep(time.Second)
	fmt.Println(x)
}

该例子的本意是想验证Go的异步抢占机制。

在Go1.13版本中,由于设置了runtime.GOMAXPROCS(8),随后又启动了8个死循环的Goroutine,所以main goroutine在调用time.Sleep“协作式”的让出执行权后,再无机会得到执行,会导致程序一直无法执行打印和退出。

在Go1.14版本中,由于加入了异步抢占,使得可以“暂停”死循环的Goroutine,使得main goroutine可以继续执行打印。

现象到这里都还符合预期,但是打印的值却稳定为0。

在main goroutine sleep的过程中,其他goroutine是会执行的,那为什么x的值没有变呢?

开始时,有以下几个怀疑点:

那么如何确认呢?

goroutine 中的x是一个副本,与外层的x不是同一个变量?

go build -gcflags="-m=2" ./main.go

关注如下几点:

main.func1 capturing by ref: x main.func1是main中的匿名函数,即例子中 main函数所启动的goroutine,x被捕获,且是被引用捕获的

x escapes to heap x 逃逸到了堆上

./main.go:15:5: main.func1 capturing by ref: x (addr=true assign=true width=8)

./main.go:11:6: x escapes to heap:
./main.go:11:6: moved to heap: x
./main.go:20:13: x escapes to heap

x在goroutine中是被引用捕获的而非值捕获,所以并不是发生了拷贝导致的。

goroutine 没有得到执行?

这个其实确认的方式有很多,可以使用 go trace 进行确认,下图可以看出main.func1 是在多个P中并行执行的。

image-20210502102222836

硬件层面,Cpu cache导致,x的值还没有被刷新到内存中?

这个其实细想下来原理上说不通,假如机器只有8个核心,那么8个goroutine占据了8个核心,main goroutine结束时总会在这8个核心中的一个,会公用同一个cache,也不会为0。

而且通过加大goroutine数量和加大睡眠时间,输出结果仍稳定为0。

看起来上述的怀疑点都不能说通,接下来搬出大杀器:汇编。

go build -gcflags="-m=2" ./main.go或者先编译为二进制,再反汇编都可以。

仅关注main.func1 的汇编代码

"".main.func1 STEXT nosplit size=8 args=0x8 locals=0x0 funcid=0x0
0x0000 00000 (main.go:19)     TEXT    "".main.func1(SB), NOSPLIT|ABIInternal, $0-8
0x0000 00000 (main.go:19)     FUNCDATA        $0, gclocals·2a5305abe05176240e61b8620e19a815(SB)
0x0000 00000 (main.go:19)     FUNCDATA        $1, gclocals·33cdeccccebe80329f1fdbee7f5874cb(SB)
0x0000 00000 (main.go:20)     JMP     2
0x0002 00002 (main.go:21)     JMP     4
0x0004 00004 (main.go:21)     JMP     6
0x0006 00006 (main.go:21)     JMP     2
0x0000 eb 00 eb 00 eb 00 eb fa

FUNCDATA是编译器插入的GC相关的伪指令,不会被编译到二进制中,在反汇编代码中是不存在的,先忽略。

可以看到汇编代码中仅有4条跳转(JMP)指令,而没有任何执行加法(ADD)的汇编执行

大概的执行流程如下,第一行跳转到第二行,第二行跳转到第三行,第三行又跳转到第一行,如此往复。

0x0000 00000 (main.go:20)   |---> JMP     2 ----
                            |                  |
0x0002 00002 (main.go:21)   |     JMP     4 <---
                            |             | ----
                            |                  |
0x0004 00004 (main.go:21)   |     JMP     6 <---
                            |             | ----
                            |                  |
0x0006 00006 (main.go:21)   ----  JMP     2 <---

那么可以确定了,goroutine虽然在运行,但是却没有做”正经事“加法。

编译过程中将该加法操作优化掉了,所以和前面的现象也就对得上了。

至此,该问题的根因已经查清楚了,编译器做了优化,没有实际执行++操作,所以无论main goroutine等待多久,输出仍稳定为0。

问题后续:

作者认为这是一个“错误的”优化,官方的答复如下

A program with a data race in it is not a valid Go program and it could do anything. In this case, it look like the compiler decided that it is allowed to remove the writes to x, so the program will print 0. We usually don't consider this kind of issues (of a racy program) as bugs.

该例子存在数据竞争,即多个线程同时对x进行读写操作,但是没有做任何同步保证,Go项目中对于这种data rece不做任何保证,看起来编译器决定允许删除对x的写入,因此程序将输出0,这并不被认为是一个bug。

如何进行检测rece呢?Go中提供了 data race的检测机制,说明详见 https://blog.golang.org/race-detector
使用的方式有如下几种:

$ go test -race mypkg    // test the package
$ go run -race mysrc.go  // compile and run the program
$ go build -race mycmd   // build the command
$ go install -race mypkg // install the package

经检测,该例子确实存在 data race,但是由于插入了race检测的桩代码,所以输出结果也并不为0了。

go run -race ./main.go                                                                                                                        [49df10c] 
==================
WARNING: DATA RACE
Read at 0x00c00013a058 by goroutine 9:
  main.main.func1()
      /Users/leonardwang//main.go:21 +0x38

Previous write at 0x00c00013a058 by goroutine 8:
  main.main.func1()
      /Users/leonardwang/main.go:21 +0x4e

Goroutine 9 (running) created at:
  main.main()
      /Users/leonardwang/main.go:19 +0x124

Goroutine 8 (running) created at:
  main.main()
      /Users/leonardwang/main.go:19 +0x124
==================
16328120
Found 1 data race(s)
exit status 66