go run -race の有無で挙動が変わる例

go

goroutineを利用したプログラムではよく -race オプションをつけてデータ競合 (race condition) がないかチェックして開発する。 しかし、今日 -race をつけると挙動が変わるという現象に遭遇したのでそれを調べたメモ。

次のようなコードで再現可能。

package main

import "log"

func main() {
    ch := make(chan int)
    go func() {
        <-ch
        log.Printf("sub")
    }()
    go func() {
        ch <- 1
    }()
    <-ch
    log.Printf("main")
}

channel に対して、main の goroutine と go で呼び出した派生の sub goroutineの2箇所から取り出そうとしている。 値を入力しているのは1回だけなので、main と sub 、値を取り出せるのはどちらか片方だけ（早いものがち）になると予想できる。

$ go run main.go 

2020/01/06 17:31:12 main

実際に実行してみると、main の方の goroutine が先に値を取り出せてプログラムは終了した。 何度か連続で実行しても毎回結果は main 。

それはそうでよいのだが、実行時に -race をつけると挙動が変わる。 subのほうが先に値を取り出せてしまったみたい。何度か連続で実行してもやはり sub が出力される。

$ go run -race main.go

2020/01/06 17:32:29 sub

... （main の goroutineで取り出せないのでここでプログラムが停止する）

開始のタイミングを変えると同じ挙動に揃った

値を入れる goroutine を先に起動するようにしたら、-race をつけてもつけなくても同じ挙動になった。 うーん、goroutine むずかしい。

package main

import "log"

func main() {
    ch := make(chan int)
    go func() {
        ch <- 1
    }()
    go func() {
        <-ch
        log.Printf("sub")
    }()
    <-ch
    log.Printf("main")
}

$ go run main.go 

2020/01/06 17:45:03 main


$ go run -race main.go

2020/01/06 17:45:10 main

そもそもとして、1つの値しか入らない channel を2箇所で読み込むなという話ではありますが、-race の有無で挙動が変わるのはちょっと怖い。

コンパイル結果をみてみる

コンパイルされた結果のアセンブリを見るとなにかわかるかもしれないと思ってちらっと見てみた。 go tool objdump コマンドにビルド済のバイナリを渡すと対応するコードの行番号まで含めて出してくれる！

$ go build -race -o race.out main.go 
$ go tool objdump race.out | grep main.go

-race なし

  main.go:8      0x109c44d       488b442438      MOVQ 0x38(SP), AX           
  main.go:8     0x109c452       48890424        MOVQ AX, 0(SP)              
  main.go:8     0x109c456       48c744240800000000  MOVQ $0x0, 0x8(SP)          
  main.go:8     0x109c45f       e8cc89f6ff      CALL runtime.chanrecv1(SB)      
  main.go:9     0x109c464       488d05b26d0300      LEAQ go.string.*+253(SB), AX        
  main.go:9     0x109c46b       48890424        MOVQ AX, 0(SP)              
  main.go:9     0x109c46f       48c744240803000000  MOVQ $0x3, 0x8(SP)          
  main.go:9     0x109c478       48c744241000000000  MOVQ $0x0, 0x10(SP)         
  main.go:9     0x109c481       0f57c0          XORPS X0, X0                
  main.go:9     0x109c484       0f11442418      MOVUPS X0, 0x18(SP)         
  main.go:9     0x109c489       e8a2fdffff      CALL log.Printf(SB)

-race あり

goroutine 内の処理が runtime.racefuncenter と runtime.racefuncexit で囲まれている。

  main.go:7      0x11043e6       e86598f8ff      CALL runtime.racefuncenter(SB)      
  main.go:8     0x11043eb       488b442438      MOVQ 0x38(SP), AX           
  main.go:8     0x11043f0       48890424        MOVQ AX, 0(SP)              
  main.go:8     0x11043f4       48c744240800000000  MOVQ $0x0, 0x8(SP)          
  main.go:8     0x11043fd       e87e79f3ff      CALL runtime.chanrecv1(SB)      
  main.go:9     0x1104402       488d0597780300      LEAQ go.string.*+288(SB), AX        
  main.go:9     0x1104409       48890424        MOVQ AX, 0(SP)              
  main.go:9     0x110440d       48c744240803000000  MOVQ $0x3, 0x8(SP)          
  main.go:9     0x1104416       48c744241000000000  MOVQ $0x0, 0x10(SP)         
  main.go:9     0x110441f       0f57c0          XORPS X0, X0                
  main.go:9     0x1104422       0f11442418      MOVUPS X0, 0x18(SP)         
  main.go:9     0x1104427       e804fdffff      CALL log.Printf(SB)         
  main.go:10        0x110442c       e85f98f8ff      CALL runtime.racefuncexit(SB)

Goの内部仕様には全然詳しくないので、これを見て「なるほど！！！」とはならなかった。 racefuncenter ~ racefuncexit の待ち合わせかなにかで順序が入れ替わってしまうのかな？と想像だけしたけど、どうなんだろう？？