golang race detector - 隙あらば寝る

race detector?

golang には race detector というデータ操作の競合を検出してくれる機能がある。

https://golang.org/doc/articles/race_detector.html

マルチスレッドなプログラムを書いたことがある人は経験があると思うが、2つ以上のスレッドが同じデータを操作する事によって壊れたりするアレ。

go では goroutine を気軽に作成するので、データ競合はよく起きる。

この機能を使うには go run -race XXX.go のように race オプションを付けるだけで、競合が見つかると報告してくれる。

問題

このプログラムは ./race.go(自分自身) を読み込んで /dev/null に書き込む。

読み込み -> channel -> 書き込みという流れ。

そして、このプログラムには data race があった。

package main

import (
    "os"
    "sync"
)

func read(f *os.File, c chan []byte) {
    readbuf := make([]byte, 128)
    for {
        n, err := f.Read(readbuf)
        if err != nil {
            close(c)
            return
        }
        c <- readbuf[:n]
    }
}

func write(c chan []byte, f *os.File) {
    for data := range c {
        f.Write(data)
    }
    f.Close()
}

func main() {
    c := make(chan []byte)
    var wg sync.WaitGroup
    wg.Add(2)
    go func() {
        f, _ := os.Open("./race.go")
        read(f, c)
        wg.Done()
    }()
    go func() {
        f, _ := os.Create("/dev/null")
        write(c, f)
        wg.Done()
    }()
    wg.Wait()
}

race detector を使ってみる

おわかり頂けただろうか...

早速 race detector で確認してみる。

初めて見る人は読み方がわからないと思うので日本語で補足を入れている。

$ go run -race race.go
==================
WARNING: DATA RACE
Write by goroutine 6: # 6 は goroutine の番号、6番目の goroutine が書き込みをした事がわかる
  internal/race.WriteRange()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/internal/race/race.go:49 +0x38
  syscall.Read()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/syscall/syscall_unix.go:164 +0x9d
  os.(*File).read()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/os/file_unix.go:228 +0xb6
  os.(*File).Read()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/os/file.go:95 +0xbc
  main.read()
      /Users/yoru9zine/tmp/go-race-bytes/race.go:11 +0x93
  main.main.func1()
      /Users/yoru9zine/tmp/go-race-bytes/race.go:33 +0x51

Previous read by goroutine 7: # 7番目の goroutine が直前に読み込みを行っていたらしい
  internal/race.ReadRange()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/internal/race/race.go:45 +0x38
  syscall.Write()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/syscall/syscall_unix.go:182 +0xad
  os.(*File).write()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/os/file_unix.go:249 +0x119
  os.(*File).Write()
      /Users/yoru9zine/.anyenv/envs/goenv/versions/1.6/src/os/file.go:136 +0xbc
  main.write()
      /Users/yoru9zine/tmp/go-race-bytes/race.go:22 +0xad
  main.main.func2()
      /Users/yoru9zine/tmp/go-race-bytes/race.go:38 +0x51

Goroutine 6 (running) created at: # 6番目の goroutine 生成箇所
  main.main()
      /Users/yoru9zine/tmp/go-race-bytes/race.go:35 +0xb6

Goroutine 7 (running) created at: # 7番目の goroutine 生成箇所
  main.main()
      /Users/yoru9zine/tmp/go-race-bytes/race.go:40 +0xe2
==================
Found 1 data race(s)
exit status 66

スタックはユーザコードの行を見ると良い。今回は race.go に問題があるはず。整理すると以下の情報が得られる。

goroutine6 は read の goroutine(生成行からわかる)
goroutine7 は write の goroutine(同上)
競合箇所(スタック最深部のユーザコード)
- f.Read(readbuf) (11行目)
- f.Write(data) (22行目)

race detector の仕事は競合の事実を教える所までなので、なぜ競合しているのかは当然ながら自分で考える必要がある。。。

しばらく悩み込んでしまった。

答え

readbuf == data

readbuf は read 内で確保して Read に渡る
chan byte に slice して渡す
chan byte から取り出して Write に渡る

[]byte はアドレス渡しなので実体は同じ。つまり channel 経由で同じ領域を共有していた。

[:n] で一部の取り出しをしているが、これは新規割当ではないのでやはり同じ領域を見たまま。

これにより、取り出した人が中身を書き込む間に次の Read 内で内容が変更されていたという話。

修正

channel に渡す前にメモリコピーして渡すようにした。

copy が同じ中身で新規に領域を割り当ててくれる。

--- race.go
+++ race_fixed.go
@@ -6,6 +6,7 @@
 )

 func read(f *os.File, c chan []byte) {
+   var sendbuf []byte
    readbuf := make([]byte, 128)
    for {
        n, err := f.Read(readbuf)
@@ -13,7 +14,8 @@
            close(c)
            return
        }
-      c <- readbuf[:n]
+       copy(sendbuf, readbuf[:n])
+       c <- sendbuf
    }
 }

雑感

はやりマルチスレッドは難しい。この手のバグを完全に発生させずにコードを書くようになれるものなのだろうか。

おそらくそれは無理(精度は高められても 100% は無理でしょう)なので、race detector があるのだと思う。

積極的な -race の利用、特に test では付けていくようにしたい。