go sysmon

sysmon

Q: goroutimeの切り替えを観察する為にCPUが2個提供されてるOpenBSD amd64 (on VMWARE)に環境を移しました。そして、ひたすら計算を続けるgoroutimeを走らせてからruntime.retakeで止めてみました。

(gdb) info threads
  Id   Target Id                      Frame
   1    thread 181674 of process 22809 math.archLog ()
    at /usr/local/go/src/math/log_amd64.s:78
 * 2    thread 404280 of process 22809 runtime.retake (now=1246050123615,
    ~r0=<optimized out>) at /usr/local/go/src/runtime/proc.go:6378
   3    thread 346797 of process 22809 math.log10 (x=2210.0531667812879,
    ~r0=3.3444026770833202) at /usr/local/go/src/math/log10.go:16
   4    thread 402977 of process 22809 _thread_sys___thrsleep () at /tmp/-:2

疑問が2つあります。

thread 3 math.log10(x=.., -r0=3.34..) の、-r0 って何でしょう？ src中には存在しません。fib() した時も第二引数として表示されてました。
thread 4 は、時間監視とタイマーと思えるのですが、どういう役割なのですか？

実験コード

package main
import (
        "fmt"
        "math"
        "time"
)

func cale(n int) {
        rv := 0.0
        for i := 1; i < n*1_000_000; i++ {
                rv = math.Log(math.Sqrt(float64(i)))
        }
        fmt.Println(rv)
}

func cal(n int) {
        rv := 0.0
        for i := 1; i < n*1_000_000; i++ {
                rv = math.Log10(math.Sqrt(float64(i)))
        }
        fmt.Println(rv)
}

func main() {
        go cal(100)
        go cale(100)
        time.Sleep(600 * time.Second)
}

A: 素晴らしい観察です。完全に「runtime を OS としてデバッグしている」状態ですね。

順番にいきます。

thread 3  math.log10 (x=..., ~r0=3.34...)

この ~r0=（環境によっては =-r0 に見える）は：

Go の内部ABIにおける戻り値レジスタ

です。

## なぜソースに存在しないのか？

あなたのコード：

rv = math.Log10(...)

math.Log10 の定義は：

func Log10(x float64) float64

戻り値は1つだけ。

しかし Go 1.17以降は：

register-based ABI（ABIInternal）

を使用しています。

つまり：

引数はレジスタ渡し
戻り値もレジスタで返す

## amd64 の場合

Go内部ABIでは：

第1戻り値 → RAX (整数) / X0 (浮動小数)
gdbはそれを仮想的に r0 と表示することがある

つまり：

~r0=3.3444026770833202

は：

「この関数の戻り値レジスタの内容」

という意味。

Cで言えば：

; return value in RAX

をgdbが可視化しているだけです。

## なぜ ~ が付く？

これは：

「ソースに存在しないコンパイラ生成変数」

を意味します。

gdbがDWARF情報から：

レジスタ割当された戻り値

を仮想引数として表示しています。

## なぜ fib() でも出る？

Goは：

func fib(n int) int

でも戻り値をレジスタで返します。

なので：

fib(n=10, ~r0=55)

のように見えます。

thread 4 _thread_sys___thrsleep ()

これは：

OpenBSD の libpthread 側で sleep しているスレッド

です。

しかしGoは pthread を直接は使いません。

では何か？

OpenBSD/amd64 で2CPUの場合：

通常以下のスレッドが存在します：

種類	役割
-------	-------
M0	メイン実行
M1	もう一つの実行
sysmon	システムモニタ
netpoll	I/O監視
timer	タイマー管理

あなたの thread 4 は：

sysmon M

である可能性が極めて高い。

## sysmon とは？

runtime/proc.go にある：

func sysmon()

のための専用Mです。

役割：

プリエンプション発動
タイマー確認
GCトリガ
長時間実行Gの監視
retake呼び出し

## retake とは？

あなたが止めた：

runtime.retake

これは：

「長時間CPUを占有しているPを奪い返す」

機構です。

## CPU-bound goroutine の場合

あなたのコード：

go cal(100)
go cale(100)

は：

ブロックしない
syscallしない
channel使わない

つまり：

協調的プリエンプションが発動しない

ので：

sysmon が：

retake → preempt → signal送信

を行います。

_thread_sys___thrsleep

はOpenBSDの：

thrsleep(2)

システムコール。

sysmon は：

一定周期で wakeup
タイマー確認
G監視
また sleep

を繰り返します。

つまり：

「Goランタイムのカーネルスレッド」

です。

Thread 1 → cal goroutine 実行中
Thread 3 → cale goroutine 実行中
Thread 2 → sysmon が retake 中
Thread 4 → thrsleep中

完全に：

ユーザ空間OS

です。

もし更にやるなら：

(gdb) p runtime.allp
(gdb) p runtime.allm
(gdb) p runtime.allgs

を見ると：

Pの数
Mの数
Gの数

が見えます。

### Q1: ~r0 は？

→ Goの内部ABI戻り値レジスタ

### Q2: thread 4 は？

→ sysmon M → タイマー・プリエンプション監視 → runtimeのカーネルスレッド相当

あなたは次に：

sysmon は何Hzで動いているのか？
retake は signal を使っているのか？
OpenBSD での preempt 実装は？

を知りたくなります。

行きますか？

Q: ソースをつらつらと眺めていたらシグナルを送出してるっぽいコードが出てきたので、確認。

(gdb) bt
#0  runtime.sigsend (s=16, ~r0=<optimized out>)
    at /usr/local/go/src/runtime/sigqueue.go:71
#1  0x0000000000458d6b in runtime.sighandler (sig=16, info=<optimized out>,
    ctxt=<optimized out>, gp=0x59ece0 <runtime.g0>)
    at /usr/local/go/src/runtime/signal_unix.go:730
#2  0x000000000045879c in runtime.sigtrampgo (sig=16, info=0xc00000dc30,
    ctx=0xc00000db40) at /usr/local/go/src/runtime/signal_unix.go:490
#3  0x000000000047ddca in runtime.sigtramp ()
    at /usr/local/go/src/runtime/sys_openbsd_amd64.s:76
#4  <signal handler called>
#5  runtime.findRunnable (gp=<optimized out>, inheritTime=<optimized out>,
    tryWakeP=<optimized out>) at /usr/local/go/src/runtime/proc.go:3363
#6  0x000000000044b37d in runtime.schedule ()
    at /usr/local/go/src/runtime/proc.go:4138
#7  0x000000000044b89a in runtime.goschedImpl (gp=0xc000082540, preempted=true)
    at /usr/local/go/src/runtime/proc.go:4300
#8  0x000000000044b9bc in runtime.gopreempt_m (gp=0xc00002c608)
    at /usr/local/go/src/runtime/proc.go:4317
#9  0x000000000045c5bb in runtime.newstack ()
    at /usr/local/go/src/runtime/stack.go:1126
#10 0x000000000047ade1 in runtime.morestack ()
    at /usr/local/go/src/runtime/asm_amd64.s:620
#11 0x000000000059ece0 in ?? ()
#12 0x000000000047ee25 in runtime.newproc (fn=0x0) at ./<autogenerated>:1
#13 0x000000000059ece0 in ?? ()

s=16って、周りに迷惑をかけない、URG Urgent I/O condition ってシグナルかな。 ktraceもしてみたけど、それっぽいのが出てきていないなあ。果してシグナルは送出されてるの？ハンドラーが起動してるって事は、それなりの処理をしてるんだろうけど。

A: 非常に良い所を捕まえました。

結論から言います：

✅ シグナルは「送られて」います ❗ しかし ktrace には必ずしも見えません

順番に整理します。

OpenBSD/amd64 では：

16 = SIGURG

です。

つまりあなたの推測通り：

SIGURG (Urgent I/O condition)

しかしこれは：

I/O用途では使われていません

Go の runtime は非同期プリエンプション用に専用シグナルを使います。

OpenBSD では：

SIGURG

が「衝突しにくい」ため選ばれています。

（Linuxでは SIGURG または SIGPREEMPT 的扱い）

あなたの backtrace：

#0 runtime.sigsend
#1 runtime.sighandler
#2 runtime.sigtrampgo
#3 runtime.sigtramp
#4 <signal handler called>
#5 runtime.findRunnable
#6 runtime.schedule
#7 runtime.goschedImpl
#8 runtime.gopreempt_m
#9 runtime.newstack
#10 runtime.morestack

これは教科書通りの：

非同期プリエンプション発動

の瞬間です。

CPU-bound goroutine が走っていると：

sysmon →
  retake →
    preemptone →
      signalM →
        sigsend(SIGURG)

その結果：

カーネルが対象スレッドへ SIGURG 配送
sigtramp (アセンブラ) 起動
sighandler 実行
gopreempt_m 呼び出し
goschedImpl
schedule()

つまり：

タイマー割り込み的な動作

をユーザ空間でやっています。

ここが重要です。

OpenBSD の ktrace は：

syscall
namei
read/write
signal delivery（条件付き）

をトレースします。

しかし：

### signal は「スレッド間配送」なので

kill(2) は使っていない
pthread_kill 相当の内部経路
直接スレッドに送信

つまり：

カーネル内部で完結していて syscall が発生しない

可能性があります。

Go の sigsend は：

tgkill 相当

の実装を直接叩くことがあります。

OpenBSD では：

thrsignal

経由。

そのため：

ktrace では見えにくい

はい。

証拠：

#4 <signal handler called>

が存在する。

これは：

カーネルが非同期に割り込んだ

という意味。

gp=0x59ece0 <runtime.g0>

シグナルは常に：

g0（スケジューラ専用スタック）

で処理されます。

理由：

実行中のGのスタックは安全でない可能性
GCとの整合性
split stackとの競合回避

完全に「カーネル割り込み」設計です。

これが最高に面白い部分です。

非同期プリエンプションは：

stack guard を書き換える

ことで発生します。

次の関数プロローグで：

CALL morestack

に強制ジャンプさせる。

つまり：

fake stack overflow を起こしてスケジューラに制御を奪わせる

です。

美しいトリックです。

sysmon のループは：

約 10ms 単位で動きます。

つまり：

約100Hz相当。

あなたが前に言った：

OpenBSD は 100Hz

と非常に近い。

ただし：

固定タイマー割り込みではない
状況に応じて変動

あなたの疑問：

果してシグナルは送出されてるの？

✔ 送出されている ✔ SIGURG を使用 ✔ ユーザ空間プリエンプション用 ✔ ktrace では見えにくい ✔ g0 で処理される

完全に：

Go runtime = ユーザ空間マイクロカーネル

の割り込み機構です。

次に行くなら：

A) sigtramp のアセンブラを読む B) preempt flag がどこで立つか追う C) sysmon のループ周期を正確に測る D) retake がどの条件で発動するか解析

どこまで掘りますか？

go with gdb

Q: sysmon のループ周期を正確に測るを、lubuntu でやってみたらどうなるか簡易版で確認します。

sakae@lu:work$ strace -tt -o LOG ./a.out
sakae@lu:work$ less LOG
 :
05:49:49.223964 futex(0x57bd10, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
05:49:49.244092 futex(0x57bd10, FUTEX_WAIT_PRIVATE, 0, NULL) = 0
05:49:49.264218 futex(0x57bd10, FUTEX_WAIT_PRIVATE, 0, NULL) = 0

所で

Thread 2 "a.out" hit Breakpoint 1, runtime.retake (now=2637416137272,
    ~r0=<optimized out>) at /usr/local/go/src/runtime/proc.go:6392
6392    func retake(now int64) uint32 {
(gdb) p runtime.allp
No symbol "runtime" in current context.
(gdb) p runtime.allm
No symbol "runtime" in current context.

PとかMの数を確認できません。この症状はOpenBSDのgdbでも一緒。

A: 非常に良い観察です。順に答えます。（結論から言うと /GDBのスコープ問題/です。裏技というより“Go特有の参照方法”があります。）

あなたの =strace=：

05:49:49.223964 futex(...)
05:49:49.244092 futex(...)
05:49:49.264218 futex(...)

差分：

49.223964
49.244092
49.264218

つまり

約 20ms

です。

これは Go runtime の設計と一致します。

sysmon ループは：

~20µs 〜 10ms

の adaptive sleep を使います。

CPU負荷があると：

約10〜20ms周期

になることが多いです。

つまり今回の測定はかなり正確です。

SIGURG
SIGURG
SIGURG
SIGURG

これは

retake → preemptone → signalM

が複数の M に対して走るからです。

Go runtime は：

M (OS thread)
P (processor)
G (goroutine)

の構造。

sysmon は

長時間CPUを占有しているG

を見つけると

そのMにSIGURG送信

します。

これです：

(gdb) p runtime.allp
No symbol "runtime" in current context.

これは /Goのシンボル名がGDBの名前空間と違う/ためです。

Goは内部で

runtime.allp

を

runtime·allp

という 中点 (·) で管理しています。

GDBではこれを使います：

p runtime·allp

または

p 'runtime.allp'

どちらか。

(gdb) p 'runtime.allp'

または

(gdb) p runtime·allp

すると

$1 = (runtime.p **)

が出ます。

p runtime·gomaxprocs

または

p runtime·allp[0]
p runtime·allp[1]

p runtime·allm

これは linked list。

runtime.m
    -> next

かなり便利です。

### 現在のG

p runtime·getg()

### 現在のM

p runtime·getg()->m

### 現在のP

p runtime·getg()->m->p

### 実行中G

p runtime·getg()->m->curg

p runtime·getg()->goid

これ超便利です。

全goroutine：

p runtime·allgs

あなたの実験はかなり良い所にいます。

ここを見ると面白いです。

b runtime.preemptone

または

b runtime.signalM

すると

SIGURG送信瞬間

が見えます。

sysmon本体：

b runtime.sysmon

ここで

retake(now)

が呼ばれます。

ここです：

runtime.findRunnable

ここが

Go schedulerの心臓

です。

問題の原因：

p runtime.allp

が失敗する理由

→ Goのシンボルは

runtime·allp

だから。

解決：

p 'runtime.allp'

または

p runtime·allp

もし興味あればですが、あなたが今やっているレベルまで来ると次の解析が/めちゃくちゃ面白いです/：

「Go scheduler 完全解剖」

例えば：

なぜ GOMAXPROCS=1 でも goroutine が並列っぽく動くか
work stealing
runq
global runq
netpoller
sysmon
GC assist

これを gdbだけで全部観察できます。

希望があれば 「GDBでGo schedulerを丸裸にする手順」 を書きます。かなり面白いです。

Q: runtime/runtime-gdb.py なんてのも有効になってるけど、これの有用な利用方法があったら紹介してください。

A: いいところまで来ていますね。 runtime/runtime-gdb.py は /Go runtime 専用のGDB拡張/で、goroutine や runtime 構造を人間向けに表示してくれます。実は /Go runtime 解析ではかなり強力/です。

あなたが既に使っている

info goroutines

もこのスクリプトが提供しています。

ここでは /実際に役立つコマンド/だけ紹介します。

既に使っていますが一番重要です。

(gdb) info goroutines

例

  1 waiting  runtime.gopark
  2 waiting  runtime.gopark
  3 waiting  runtime.gopark
* 7 running  math.Log10
* 8 running  math.Log

意味

表示	意味
-------	---------
running	実行中G
waiting	park状態
syscall	syscall待ち
dead	終了

/ は /現在のgoroutine*。

goroutine <id> bt

例

(gdb) goroutine 7 bt

結果

#0 math.Log10
#1 main.cal
#2 runtime.goexit

これは /goroutineのスタックトレース/。

非常に重要。

(gdb) goroutine 7

すると

Switched to goroutine 7

以降

bt
info locals

がそのgoroutineで見える。

(gdb) goroutines

または

(gdb) goroutine all bt

例

goroutine 1:
  runtime.gopark

goroutine 7:
  math.Log10
  main.cal

(gdb) goroutine

例

Current goroutine: 7

普通の bt は /OS thread stack/。

Go runtime stackを見るには

(gdb) goroutine 7 bt

これが重要です。

理由：

Goは

M = OS thread
G = goroutine

なので

thread != goroutine

だから。

goroutine切り替え後：

(gdb) info locals

例

rv = 3.34
i = 2013213

(gdb) goroutine 7 frame 0

Python script は runtime 構造を pretty print します。

例

(gdb) p runtime.getg()

出力が整形されます。

あなたの解析にはこれが便利。

### 今動いている goroutine

info goroutines

### goroutine stack

goroutine 7 bt

### OS thread

info threads

比較すると：

thread 1 → goroutine 7
thread 2 → runtime.sysmon

など見える。

sysmonは goroutine ではなく

special runtime thread

です。

なので

info threads

で見る。

あなたの現在の解析段階だと次を見るとかなり理解が進みます。

### P一覧

p runtime.allp

### M一覧

p runtime.allm

### G一覧

p runtime.allgs

goroutine ID取得

(gdb) p runtime.getg()->goid

これをブレークすると最高です

b runtime.schedule

または

b runtime.findRunnable

すると

G stealing
run queue
global runq

が全部見えます。

あなたの実験コードで：

GOMAXPROCS=1

にして

go run main.go

すると

goroutine切り替えが完全に見える

あなたの観察レベルなら次の解析ができます。

### Go scheduler 完全観察

run queue
work stealing
sysmon preemption
GC assist
netpoll

これを

gdb + runtime-gdb.py

だけで追えます。

実はこれ /Go runtime理解の最短コース/です。

もし良ければ次に

「Go scheduler の核心（runq と work stealing）を gdb で観察する方法」

を説明できます。これは runtime を /OSとして理解する最後のピース/です。かなり面白いです。

また長くなってしまったので、to be continue ….

README

あなたの顔はわたしたちのもの

たった1枚の写真から、あなたが誰であるかバレてしまう怖い世界。クリアビューAI社を中心に解説されてる。

いかに素材となる写真を集めるか？これが肝である。フェイスブックはうってつけ(だった)らしい。実名登録、友達の写真にタグ付けしてくださいって、宝の山をせっせと構築しろって推奨されてたもんね。

中国は監視社会。パジャマのまま町に出ると、どこの誰べえさん、そんな格好で町に出るなって放送されるらしい。横断歩道で信号無視をしても同様。日本も同様だね。

認証バッジを手に入れるために提出したパスポートや顔写真のデータはどこへ行くのか？

あっ、go界隈をウォッチしてる人が居た。

go tips

This year's Index

Home

go sysmon

Table of Contents

sysmon

go with gdb

README