Goチャンネルをwatchする
この記事はBBSakuraNetworksアドベントカレンダー2022の5日目の記事です。
昨日は「モバイル技術検定2級を受けてみました」でした。
こんにちは。BBSakura Networks株式会社のmasu-miです。
GoのデバッグではDelveを使います。
このDelveはStarlarkというPython3ライクなスクリプト言語を提供しています。
使ったことがなかったので試してみたいと思います。いわゆるやってみた記事です。
Goroutine間でのメッセージングにはチャンネルを多用します。ということでチャンネルの利用箇所でプログラムを停止させてみます。
Goチャンネルの実態
Goのチャンネルの実態は *runtime.hchanです。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
|
type hchan struct {
qcount uint // total data in the queue
dataqsiz uint // size of the circular queue
buf unsafe.Pointer // points to an array of dataqsiz elements
elemsize uint16
closed uint32
elemtype *_type // element type
sendx uint // send index
recvx uint // receive index
recvq waitq // list of recv waiters
sendq waitq // list of send waiters
// lock protects all fields in hchan, as well as several
// fields in sudogs blocked on this channel.
//
// Do not change another G's status while holding this lock
// (in particular, do not ready a G), as this can deadlock
// with stack shrinking.
lock mutex
}
|
読み書きの際にはlockフィールドが使われるはずなので、ここへの書き込みを watch すれば意図した停止が得られるはずです。
これをしたのスクリプト(command_watch_chan.star)に書き起こしました。説明はコメントとして残しています。(また手元のハイライトがStarlarkに対応していないのでPythonでやっています)
1
2
3
4
5
6
7
|
# コマンド実態: prefix: `command_`がコマンドを意味している
def command_watch_chan(args):
create_watchpoint(None, args + ".lock", 2)
# エイリアスを定義: この場合 `wch` を `watch_chan` コマンドに向けている
def main():
dlv_command("config alias watch_chan wch")
|
スクリプトに提供されている関数は公式を参考にしてください。
さっそく使ってみましょう。まず対象となるプログラムを準備します。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
|
package main
import (
"fmt"
)
func main() {
testChan()
testList()
}
func testChan() {
ch := make(chan struct{})
go func() {
for i := 0; i < 2; i++ {
_ = <-ch
fmt.Println("received")
}
}()
ch <- struct{}{}
fmt.Println("send")
ch <- struct{}{}
fmt.Println("send")
}
|
デバッガを起動してスクリプトを読み込みます。
1
2
3
|
$ dlv debug ./main.go
Type 'help' for list of commands.
(dlv) source command_watch_chan.star
|
ブレークポイントとステップ実行をいい感じに使って目的のチャンネルが見えてるところまで進めます。
1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
|
(dlv) b main.testChan
(dlv) n
(dlv) n
> main.testChan() ./main.go:42 (PC: 0x49d5b9)
37: testList()
38: }
39:
40: func testChan() {
41: ch := make(chan struct{})
=> 42: go func() {
43: for i := 0; i < 2; i++ {
44: _ = <-ch
45: fmt.Println("received")
46: }
47: }()
|
呼んでみましょう。
1
2
3
4
5
|
(dlv) wch ch
(dlv) breakpoints
....
Breakpoint 1 (enabled) at 0x49d58f for main.testChan() ./main.go:40 (1)
Watchpoint ch.lock (enabled) at 0xc00008c0b8 (0)
|
設定されていそうなので動作を確認します。frame 5でメッセージ送信を捕まえていることが確認できます。
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
|
(dlv) c
> watchpoint on [ch.lock] runtime.lock2() /home/debian/go/src/runtime/lock_futex.go:61 (hits goroutine(1):1 total:1) (PC: 0x40afc5)
Warning: debugging optimized function
56: }
57: gp.m.locks++
58:
59: // Speculative grab for lock.
60: v := atomic.Xchg(key32(&l.key), mutex_locked)
=> 61: if v == mutex_unlocked {
62: return
63: }
64:
65: // wait is either MUTEX_LOCKED or MUTEX_SLEEPING
66: // depending on whether there is a thread sleeping
(dlv) bt
0 0x000000000040afc5 in runtime.lock2
at /home/debian/go/src/runtime/lock_futex.go:61
1 0x000000000040b859 in runtime.lockWithRank
at /home/debian/go/src/runtime/lockrank_off.go:22
2 0x000000000040af4b in runtime.lock
at /home/debian/go/src/runtime/lock_futex.go:48
3 0x00000000004051bd in runtime.chansend
at /home/debian/go/src/runtime/chan.go:202
4 0x00000000004050dd in runtime.chansend1
at /home/debian/go/src/runtime/chan.go:145
5 0x000000000049ae98 in main.testChan
at ./main.go:19
6 0x000000000049add7 in main.main
at ./main.go:8
7 0x000000000043a0d8 in runtime.main
at /home/debian/go/src/runtime/proc.go:250
8 0x0000000000464c21 in runtime.goexit
at /home/debian/go/src/runtime/asm_amd64.s:1594
(dlv) frame 5
> watchpoint on [ch.lock] runtime.lock2() /home/debian/go/src/runtime/lock_futex.go:61 (hits goroutine(1):1 total:1) (PC: 0x40afc5)
Warning: debugging optimized function
Frame 5: ./main.go:19 (PC: 49ae98)
14: for i := 0; i < 2; i++ {
15: _ = <-ch
16: fmt.Println("received")
17: }
18: }()
=> 19: ch <- struct{}{}
20: fmt.Println("send")
21: ch <- struct{}{}
22: fmt.Println("send")
23: }
|
続けるとランタイムで行われているlock解放も見えてしまいます。アプリケーションのデバッグや動きを追いたい時には無視して構いません。
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
|
(dlv) c
> watchpoint on [ch.lock] runtime.lock2() /home/debian/go/src/runtime/lock_futex.go:61 (hits goroutine(6):1 total:3) (PC: 0x40afc5)
Warning: debugging optimized function
> watchpoint on [ch.lock] runtime.unlock2() /home/debian/go/src/runtime/lock_futex.go:117 (hits total:3) (PC: 0x40b1c9)
Warning: debugging optimized function
112: unlockWithRank(l)
113: }
114:
115: func unlock2(l *mutex) {
116: v := atomic.Xchg(key32(&l.key), mutex_unlocked)
=> 117: if v == mutex_unlocked {
118: throw("unlock of unlocked lock")
119: }
120: if v == mutex_sleeping {
121: futexwakeup(key32(&l.key), 1)
122: }
(dlv) bt
0 0x000000000040b1c9 in runtime.unlock2
at /home/debian/go/src/runtime/lock_futex.go:117
1 0x000000000040b8b9 in runtime.unlockWithRank
at /home/debian/go/src/runtime/lockrank_off.go:32
2 0x000000000040b179 in runtime.unlock
at /home/debian/go/src/runtime/lock_futex.go:112
3 0x00000000004062ce in runtime.chanparkcommit
at /home/debian/go/src/runtime/chan.go:673
4 0x00000000004406cb in runtime.park_m
at /home/debian/go/src/runtime/proc.go:3344
5 0x0000000000462b23 in runtime.mcall
at /home/debian/go/src/runtime/asm_amd64.s:448
|
最後に受信側でも動くことをみました。
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
|
(dlv) c
> watchpoint on [ch.lock] runtime.lock2() /home/debian/go/src/runtime/lock_futex.go:84 (hits goroutine(6):2 total:4) (PC: 0x40b11c)
Warning: debugging optimized function
79: }
80: for {
81: // Try for lock, spinning.
82: for i := 0; i < spin; i++ {
83: for l.key == mutex_unlocked {
=> 84: if atomic.Cas(key32(&l.key), mutex_unlocked, wait) {
85: return
86: }
87: }
88: procyield(active_spin_cnt)
89: }
(dlv) bt
0 0x000000000040b11c in runtime.lock2
at /home/debian/go/src/runtime/lock_futex.go:84
1 0x000000000040b859 in runtime.lockWithRank
at /home/debian/go/src/runtime/lockrank_off.go:22
2 0x000000000040af4b in runtime.lock
at /home/debian/go/src/runtime/lock_futex.go:48
3 0x0000000000405c4f in runtime.chanrecv
at /home/debian/go/src/runtime/chan.go:511
4 0x0000000000405af8 in runtime.chanrecv1
at /home/debian/go/src/runtime/chan.go:442
5 0x000000000049afc5 in main.testChan.func1
at ./main.go:15
6 0x0000000000464c21 in runtime.goexit
at /home/debian/go/src/runtime/asm_amd64.s:1594
(dlv) frame 5
> watchpoint on [ch.lock] runtime.lock2() /home/debian/go/src/runtime/lock_futex.go:84 (hits goroutine(6):2 total:4) (PC: 0x40b11c)
Warning: debugging optimized function
Frame 5: ./main.go:15 (PC: 49afc5)
10:
11: func testChan() {
12: ch := make(chan struct{})
13: go func() {
14: for i := 0; i < 2; i++ {
=> 15: _ = <-ch
16: fmt.Println("received")
17: }
18: }()
19: ch <- struct{}{}
20: fmt.Println("send")
|
というわけでStarlarkスクリプトから watch を使ってチャンネル読み書きを捕まえてみました。
Delveが提供しているAPIを眺めると Goroutineやバックトレースやスコープ内の変数も取れそうです。
ある変数を共有している全てのスタックフレームを探すこともできるかも知れません。
Starlarkはコールバックには対応していません。ブレークポイントにコールバックを登録できればランタイム内部での呼び出しを表示せず無視できるなど便利に使えるのにと少し残念に思っています。
