Go言語で記述されたプログラムでデバイスファイルを読み取ろうとすると O_NONBLOCK を指定していてもプログラムがハングする問題があることに気づきました。この記事ではなぜこのような問題が起こるのかと、その回避策について紹介します。
写真は記事の内容と関係のない、実家の猫がパソコンに興味を持っている様子です。
やりたかったこと
Go言語で記述されたプログラム実行中にカーネルのリングバッファに書き込まれた内容（通常 dmesg コマンドで表示される内容）を、プログラム終了時に確認したかったのです。
C言語のプログラムの場合は次のような記述になります。
// ヘッダファイルなどは省略 void program() { int fd = open("/dev/kmsg", O_WRONLY); if (fd < 0) { perror("open"); return; } for (int i = 0; i < 10; i++) { if (dprintf(fd, "This is test message %d\n", i) < 0) { perror("dperintf"); } } close(fd); } int main() { int fd = open("/dev/kmsg", O_RDONLY | O_NONBLOCK); if (fd < 0) { perror("open"); return -1; } lseek(fd, 0, SEEK_END); program(); const int buf_size = 256; char buf[buf_size]; int read_c = 1; while (1) { read_c = read(fd, buf, buf_size); if (read_c < 0) { if (errno == EPIPE) { continue; } if (errno == EAGAIN) { break; } perror("read"); break; } if (read_c == 0) break; char *start = memchr(buf, ';', read_c); if (start == NULL) { continue; } fwrite(start + 1, 1, read_c - (start - buf + 1), stdout); } close(fd); return 0; }
実行結果
$ sudo ./main This is test message 0 This is test message 1 This is test message 2 This is test message 3 This is test message 4 This is test message 5 This is test message 6 This is test message 7 This is test message 8 This is test message 9
カーネルのリングバッファの内容は /dev/kmsg に書き込まれます。どうやらこれはデバイスファイルになっており、ユーザ空間からでも write(2) で書き込むことができます。今回はプログラムの実行を /dev/kmsg に書き込むプログラムと仮定しています。
/dev/kmsg を開く際には O_NONBLOCK を指定しています。このオプションを指定せずにカーネルバッファを読もうとすると、次のバッファが来るまで永遠に待機してしまうので、これを避けるため、ノンブロックでファイルを開き EAGAIN 1 が来た時に正常終了することで最後まで読むように設計しました。
Go言語で O_NONBLOCK が効かない問題
Go言語で上記のC言語のコードをそのまま記述すると次のようになります。
package main import ( "fmt" "io" "os" "strings" "syscall" ) func main() { kmsg, err := os.OpenFile("/dev/kmsg", os.O_RDONLY|syscall.O_NONBLOCK, 0) if err != nil { fmt.Println("Failed to open", err) return } kmsg.Seek(0, io.SeekEnd) defer func() { defer kmsg.Close() buf := make([]byte, 1024) fmt.Println("Reading kernel messages:") for { n, err := kmsg.Read(buf) if errors.Is(err, syscall.EAGAIN) { break } if err != nil { fmt.Println("Read error:", err) return } if _, msg, ok := strings.Cut(string(buf[:n]), ";"); ok { fmt.Println(strings.TrimSpace(msg)) } } }() program() } func program() { kmsg, err := os.OpenFile("/dev/kmsg", os.O_WRONLY, 0) if err != nil { fmt.Println("Failed to open kmsg", err) return } defer kmsg.Close() for i := range 10 { fmt.Fprintf(kmsg, "This is test message %d\n", i) } }
しかし、このプログラムを実際に実行すると This is test message 9 が出力されたあとにプログラムがハングしてしまい、 O_NONBLOCK を指定していない場合と同じ状態になってしまいます。
$ sudo ./read-dmsg-go This is test message 0 This is test message 1 This is test message 2 This is test message 3 This is test message 4 This is test message 5 This is test message 6 This is test message 7 This is test message 8 This is test message 9 ^C
このとき何が起こっているのかを strace を使って確認してみました。
1. O_NONBLOCK read に渡されている
read システムコールは正しく O_NONBLOCK が指定されており、ノンブロッキングな読み取りとしてファイルが開かれていることが確認できます。
openat(AT_FDCWD, "/dev/kmsg", O_RDONLY|O_NONBLOCK|O_CLOEXEC) = 4
2. readシステムコールはEAGAINを返している
read システムコールは最後に EAGAIN を返していますが、プログラムはbreakされず実行が続いています。
read(4, 0x1efdff818a78, 1024) = -1 EAGAIN (Resource temporarily unavailable)
3. EAGAINを受け取った後、プログラムは epoll_pwait を呼んでいる
2で EAGAIN を読んだ後 epoll_pwait システムコールが呼ばれていることが確認できます。
epoll_pwait(5, [], 128, 0, NULL, 0) = 0 epoll_pwait(5, 0x7fff0ef6184c, 128, -1, NULL, 0) = -1 EINTR (Interrupted system call)
epoll_pwait は第4引数の timeout に0が指定されると即時に終了し値が返ります。一方-1が指定された場合にはブロッキングにイベントの発生を待機します。今回の場合は最後にtimeout=-1が指定された状態で epoll_pwait を呼んでいたためにプログラムがブロックされてハングしているように見えたと考えられます。
Specifying a timeout of -1 causes epoll_wait() to block indefinitely, while specifying a timeout equal to zero causes epoll_wait() to return immediately, even if no events are available.
なぜ EAGAIN は握りつぶされているのか？
2で read がEAGAINを返したとき私の想定では次の分岐でプログラムが終了するはずでした。
if errors.Is(err, syscall.EAGAIN) { break }
しかし、実際にはこの分岐には入らずプログラムは続いていました。これはなぜなのでしょうか？
Goの os.Read はOSごとに分岐して実装されており、Linuxの場合は下記のようなコードが呼び出されます。
for { n, err := ignoringEINTRIO(syscall.Read, fd.Sysfd, p) if err != nil { n = 0 if err == syscall.EAGAIN && fd.pd.pollable() { if err = fd.pd.waitRead(fd.isFile); err == nil { continue } } } err = fd.eofError(n, err) return n, err }
これを見ると明らかに syscall.EAGAIN が返され、fd.pd.pollable() == true の場合には fd.pd.waitRead が呼ばれエラーが握りつぶされていそうなことがわかります。
回避策
回避策がいくつかあります。
1つめは SetReadDeadline を利用し、タイムアウトさせることです。これによりデッドラインを超えた場合には os.ErrDeadlineExceeded を受け取ることができるようになります。
for { kmsg.SetReadDeadline(time.Now().Add(100 * time.Millisecond)) n, err := kmsg.Read(buf) if errors.Is(err, os.ErrDeadlineExceeded) { break } if err != nil { fmt.Println("Read error:", err) return } if _, msg, ok := strings.Cut(string(buf[:n]), ";"); ok { fmt.Println(strings.TrimSpace(msg)) } }
2つめは SyscallConn を用いる方法です。このインターフェイスを用いると、EAGAINが握りつぶされる分岐（waitRead）に入る前に引数fが呼ばれ、かつf内で常にtrueを返すようにしているため、その分岐に一切入らずEAGAINをそのままキャッチすることができます。
for { var n int var readErr error err := raw.Read(func(fdPtr uintptr) bool { n, readErr = syscall.Read(int(fdPtr), buf) return true }) if errors.Is(readErr, syscall.EAGAIN) { break } if err != nil { fmt.Println("Read error:", err) return } if readErr != nil { fmt.Println("Read error:", readErr) return } if _, msg, ok := strings.Cut(string(buf[:n]), ";"); ok { fmt.Printf("%s\n", strings.TrimSpace(msg)) } }
おまけ: epoll_pwaitは誰が読んでいるのか
さらにstraceの結果の続きを見ると最後に epoll_pwait が呼ばれていることがわかります。
epoll_pwait(5, [], 128, 0, NULL, 0) = 0 epoll_pwait(5, 0x7fff0ef6184c, 128, -1, NULL, 0) = -1 EINTR (Interrupted system call)
しかし、 fd.pd.waitRead が呼んでいる internal/poll_runtime_pollWait では epoll_pwait を直接呼ぶような処理はなく、代わりに gopark という関数が呼ばれスレッドがスリープされていることがわかります。
// need to recheck error states after setting gpp to pdWait // this is necessary because runtime_pollUnblock/runtime_pollSetDeadline/deadlineimpl // do the opposite: store to closing/rd/wd, publishInfo, load of rg/wg if waitio || netpollcheckerr(pd, mode) == pollNoError { gopark(netpollblockcommit, unsafe.Pointer(gpp), waitReasonIOWait, traceBlockNet, 5) }
gopark 関数は次のように説明されています。
func gopark(unlockf func(*g, unsafe.Pointer) bool, lock unsafe.Pointer, reason waitReason, traceReason traceBlockReason, traceskip int)
Puts the current goroutine into a waiting state and calls unlockf on the system stack. If unlockf returns false, the goroutine is resumed.
要約すると次のような挙動のようです。
- 現在のgoroutineをwaitingにする
- システムスタックで
unlockfを呼ぶ - もし
unlockfがfalseを返したら、goroutineが再開される
poll_runtime_pollWait では unlockf の関数として netpollblockcommit という関数を呼んでおり、その実体は下記のようなコードです。つまり単に netpollWaiters という変数をインクリメントしてるだけです。
delta = 1 if delta != 0 { netpollWaiters.Add(delta) }
では、誰が epoll_pwait を呼んでいるのでしょうか？gdbを使って確認してみましょう。gdbには catch syscall という特定のシステムコール呼び出しをキャプチャする機能があります。試してみると epoll_pwait はプログラム中で何度も呼ばれていますが、今回は最後の2回の呼び出しに着目しました。
調べてみると2回の呼び出しはどちらも runtime.schedule->runtime.findRunnable という関数から呼び出されていました。runtime.schedule のコメントを見ると下記のように記述されており、実行可能な goroutine を探して実行する関数のようです。
One round of scheduler: find a runnable goroutine and execute it.
まず1つ目のノンブロッキングな呼び出し（ timeout=0 ）についてです。
Thread 3 "read-dmsg-go" hit Catchpoint 1 (returned from syscall epoll_pwait), internal/runtime/syscall/linux.Syscall6 ()
at /go/src/internal/runtime/syscall/linux/asm_linux_amd64.s:36
36 CMPQ AX, $0xfffffffffffff001
(gdb) p/x $r10
$5 = 0x0
(gdb) bt
#0 internal/runtime/syscall/linux.Syscall6 ()
at /go/src/internal/runtime/syscall/linux/asm_linux_amd64.s:36
#1 0x00000000004087e5 in internal/runtime/syscall/linux.EpollWait (epfd=<optimized out>,
events=..., maxev=<optimized out>, waitms=<optimized out>, n=<optimized out>,
errno=<optimized out>)
at /go/src/internal/runtime/syscall/linux/syscall_linux.go:32
#2 0x00000000004438d4 in runtime.netpoll (delay=<optimized out>, ~r0=...,
~r1=<optimized out>) at /go/src/runtime/netpoll_epoll.go:119
#3 0x000000000044fd79 in runtime.findRunnable (gp=<optimized out>,
inheritTime=<optimized out>, tryWakeP=<optimized out>)
at /go/src/runtime/proc.go:3496
#4 0x0000000000451971 in runtime.schedule ()
at /go/src/runtime/proc.go:4164
...
こちらは proc.go の3496行目から呼ばれていることがわかります。
if netpollinited() && netpollAnyWaiters() && sched.lastpoll.Load() != 0 && sched.pollingNet.Swap(1) == 0 { list, delta := netpoll(0) // ここで呼び出されている sched.pollingNet.Store(0) if !list.empty() { // non-blocking gp := list.pop() injectglist(&list) netpollAdjustWaiters(delta) trace := traceAcquire() casgstatus(gp, _Gwaiting, _Grunnable) if trace.ok() { trace.GoUnpark(gp, 0) traceRelease(trace) } return gp, false, false } }
もし epoll_pwait でイベントが見つかれば分岐に入り、対象の goroutine( gp )がreturnされ関数が終了することがわかります。イベントが見つからない場合は findRunnable の続きが実行されます。
次の epoll_pwait の呼び出しを見てみましょう。
Thread 3 "read-dmsg-go" hit Catchpoint 1 (call to syscall epoll_pwait), internal/runtime/syscall/linux.Syscall6 ()
at /go/src/internal/runtime/syscall/linux/asm_linux_amd64.s:36
36 CMPQ AX, $0xfffffffffffff001
(gdb) p/x $r10
$6 = 0xffffffffffffffff
(gdb) bt
#0 internal/runtime/syscall/linux.Syscall6 ()
at /go/src/internal/runtime/syscall/linux/asm_linux_amd64.s:36
#1 0x00000000004087e5 in internal/runtime/syscall/linux.EpollWait (epfd=<optimized out>,
events=..., maxev=<optimized out>, waitms=<optimized out>, n=<optimized out>,
errno=<optimized out>)
at /go/src/internal/runtime/syscall/linux/syscall_linux.go:32
#2 0x00000000004438d4 in runtime.netpoll (delay=<optimized out>, ~r0=...,
~r1=<optimized out>) at /go/src/runtime/netpoll_epoll.go:119
#3 0x00000000004502df in runtime.findRunnable (gp=<optimized out>,
inheritTime=<optimized out>, tryWakeP=<optimized out>)
at /go/src/runtime/proc.go:3754
こちらは次のようなコードから epoll_pwait がタイムアウトを-1（ 0xffffffffffffffff ）に指定して呼び出されていることがわかります。
delay := int64(-1) ... list, delta := netpoll(delay) // block until new work is available
ここで明示的に次のイベントの到着をブロッキングに待機するため、プログラムが止まる結果になったことがわかります。 この箇所は findRunnable の関数のかなり最後に位置しています。私は findRunnable をすべて読んだわけではありませんが、本当に実行するgoroutineが全く見つからなかった場合の最終手段として epoll_pwait を使っていそうだと感じました。
-
↩EAGAIN The file descriptor fd refers to a file other than a socket and has been marked nonblocking (O_NONBLOCK), and the read would block. See open(2) for further details on the O_NONBLOCK flag.
