GPD MicroPC 上で起動した MikanOS で，いくつかのコマンドが正常に実行できないバグに遭遇した。 ターミナル自体や cat，ls など，OS の機能や組み込みコマンドは正常に動いているように見える。
正常に実行できるコマンド：
- cube
- lines
- winjpn
- cat mikanos.txt
- more
- ただし，パイプ経由で more を使おうとすると上手く行かない
上手く動かないコマンド：
- blocks
- 起動した直後にブロックが全部消える。ボールは動くが，ブロックとの当たり判定は無いので，表示上だけでなく本当にブロックが消えている。
- grep
- 何も表示されないし，実行が終わらない。
- 試しに main 関数の先頭で
fprintf(stderr, "argv[%d] = %s\n", i, argv[i]);を実行してみたらargv[を表示した時点で SIGSEGV で死ぬ。
- tview
- gview
まず，アプリがどこで SIGSEGV になっているかを知りたい。 もっとも最後に SIGSEGV したアプリの情報を取ってこれるように改造する。
lsatkill というコマンドを作り，最後に SIGSEGV したアプリについて，次の情報を表示した。
- KillApp() を呼び出した interrupt.cpp 内の行
- KillApp() の原因となった割り込みで取得された割り込みフレーム
- KillApp() の原因となった割り込みで取得されたエラーコード
- KillApp() 内の適当な場所での RSP/CR2 の値
- アプリのスタックトップから 128 バイトのダンプ
例えば grep Conv memmap を実行し，argv[ とだけ表示されて終了した直後の情報は次の通り。
| 項目 | 値 |
|---|---|
| line | 94（IntHandlerPF） |
| frame.cs:frame.rip | 0023:0000000000000000 |
| frame.rflags | 00010283 |
| frame.ss:frame.rsp | 001b:ffffffffffffea98 |
| ERR | 0000000000000005 |
| RSP | 0000000000008e38 |
| CR2 | 0000000000000000 |
| RSP+0x00 | ffff800000034a1e 0000000000000000 |
| RSP+0x10 | 0000000000000000 0000000000000000 |
| RSP+0x20 | 0000000000000000 ffffffffffffeb60 |
| RSP+0x30 | ffff8000000b86a0 ffff8000000b86a0 |
| RSP+0x40 | ffff8000000b8008 ffffffffffffec40 |
| RSP+0x50 | ffff8000000b8008 ffffffffffffeb60 |
| RSP+0x60 | ffff800000032727 ffff8000000b86a0 |
| RSP+0x70 | ffff8000000b86a0 ffff8000000b8008 |
line と CR2 から，アドレス 0 に対するメモリアクセスが #PF を引き起こしたと分かる。 エラーコードの値から，存在するページに対するユーザーモード read が原因である。 frame.cs:frame.rip の値から，どうやらアドレス 0 へジャンプしようとしたことが原因だと思われる。
アドレス 0 へのジャンプが call 命令だと仮定すると，スタックトップの ffff800000034a1e が戻り先アドレスのはず。
実際，grep コマンドの内部の __sfvwrite_r 内のアドレスであった。
ffff800000034780 <__sfvwrite_r>:
<中略>
ffff80000003479e: 49 89 f5 mov r13,rsi
<中略>
ffff800000034a17: 48 89 da mov rdx,rbx
ffff800000034a1a: 41 ff 55 40 call QWORD PTR [r13+0x40]
ffff800000034a1e: 85 c0 test eax,eax
ぱっと見る限り，r13 に伝播してくる値は __sfvwrite_r の第 2 引数。
__sfvwrite_r の実装は次の通り。
int
__sfvwrite_r (struct _reent *ptr,
register FILE *fp,
register struct __suio *uio)
{
<中略>
if (fp->_flags & __SNBF)
{
/*
* Unbuffered: Split buffer in the largest multiple of BUFSIZ < INT_MAX
* as some legacy code may expect int instead of size_t.
*/
do
{
GETIOV (;);
w = fp->_write (ptr, fp->_cookie, p,
MIN (len, INT_MAX - INT_MAX % BUFSIZ));
if (w <= 0)
goto err;
p += w;
len -= w;
}
while ((uio->uio_resid -= w) != 0);
}
逆アセンブラから，FILE 構造体のオフセット 0x40 にある関数ポインタの call だと分かる。
grep の argv[ の表示の直後にエラーになっていることを考えると，fprintf(stderr, "argv[%d] = %s\n", i, argv[i]);
の中から呼ばれる __sfvwrite_r にてバグが発生していると考えられる。
__sfvwrite_r のコードを追っていると，fp の中で呼び出している関数ポインタは唯一 fp->_write だけのようだ。
grep の先頭で stderr->_write を印字してみると 0。
関数ポインタが代入されないまま _write が呼び出され，バグが発生しているのではないだろうか。
stderr の値（FILE 型へのアドレス）自体は 0 ではなく，シンボルテーブルを確認すると impure_data というオブジェクト内のアドレスとなっている。
Newlib のソースコードを読むと impure_data は stdin, stdout, stderr やその他の Newlib の動作に必要なデータを含む大きな構造体だった。
__sinit という関数が impure_data.stderr を初期化しており，それにより stderr->_write が設定される。
ということは，grep 実行に際して __sinit が呼ばれないのではないか，と推測される。
問題が起きるのは実機だが，ここからは GDB でデバッグする。__sinit が呼ばれないこと自体はおそらく QEMU でも観測できる気がするから。
grep の main と __sinit にブレークポイントを仕掛けて動作をチェックすると，…あれ？ __sinit が呼ばれている。
実機でもロジックは同じなので __sinit が呼ばれていると思われるが，ではなぜ stderr->_write が 0 のときに発生するバグが発生しているのか。
- RQ1.
fprintf(stderr, "hoge\n");を実行するだけで__sinitは呼ばれるか？ - RQ2.
fprintf(stderr, "hoge\n");を実行後にstderr->_writeはどう変化するか。
RQ1 の答え。呼ばれる。
grep の main 関数の先頭に，試しに fprintf(stderr, "hoge\n"); を加え，__sinit にブレークポイントを張って観察。
追加した fprintf 呼び出しの中で __sinit が呼ばれることを観測。
RQ2 の答え。fprintf 実行前は 0，実行後はそれっぽい値。
(gdb) p ((struct _reent*)_impure_ptr)->_stderr->_write
$2 = (int (*)(_reent *, void *, const char *, int)) 0x0
ここで fprintf が呼ばれる。fprintf から返ってきた段階で次のような値に変化した。
(gdb) p ((struct _reent*)_impure_ptr)->_stderr->_write
$3 = (int (*)(_reent *, void *, const char *, int)) 0xffff800000030080 <__swrite>
次に，GDB を使わずに調査できるよう，grep にログ出力を追加して実験。
ログ出力で stderr->_write が使われないように注意する必要がある。
そのため，sprintf + SyscallLogString でログを出すようにした。
grep の main 関数を次のように改造した。
extern "C" struct _reent* _impure_ptr;
extern "C" void main(int argc, char** argv) {
char s[128];
sprintf(s, "_stderr->_write = %p, __sdidinit = %d\n",
_impure_ptr->_stderr->_write, _impure_ptr->__sdidinit);
SyscallLogString(kWarn, s);
fprintf(stderr, "hoge\n");
sprintf(s, "_stderr->_write = %p, __sdidinit = %d\n",
_impure_ptr->_stderr->_write, _impure_ptr->__sdidinit);
SyscallLogString(kWarn, s);
QEMU での実行結果は次の通り。
stderr->_write = 0x0, __sdidinit = 0
stderr->_write = 0xffff800000030320, __sdidinit = 1
期待通り，fprintf の呼び出し前後で __sinit が呼ばれていることが分かる。
stderr->_write = 0x0, __sdidinit = 0
stderr->_write = 0x0, __sdidinit = 0
実機だと __sinit が呼ばれないように見える。
しかし，grep コマンドの機能が正常に動くようになった。
（デバッグ用に入れていた fprintf(stderr "argv[i] = %s\n", i, argv[i]); も正常に実行できているし，
memmap ファイルの grep もちゃんとされている）
fprintf(stderr, "hoge\n"); とその前後のデバッグ表示を取り除いて再度実機で実験すると，やはり argv[ で表示が終わり，コマンドが強制終了する。
fprintf(stderr, "hoge\n"); か，sprintf か，SyscallLogString のいずれかの実行が，
stderr->_write を初期化する以外の何らかの影響を及ぼしていると思われる。
試しに fprintf(stderr, "hoge\n"); だけを残した状態でも，
fprintf(stderr "argv[i] = %s\n", i, argv[i]); やその後の表示が正常に為された。
RQ3. fprintf(stderr, "hoge\n"); を残した状態で，最後に stderr->_write の値は非 0 になっているか？
RQ3 の答え。QEMU では（当然ながら）そうなっていた。実機でも QEMU と同じ出力になった。
ここまでの結果を踏まえると，次の推測ができる。
fprintf("hoge\n");の実行が，_impure_ptr->stderr->_writeや_impure_ptr->__sdidinitの値が変わる以外の変化を起こす- その変化が，
fprintf(stderr, "argv[%d] = %s\n", i, argv[i]);が成功するのに重要な影響を及ぼす
call QWORD PTR [r13+0x40] に立ち返って考えてみる。
r13 には FILE* fp の値，つまり stderr が渡されるので，そのオフセット 0x40 のメンバが何であるかを調べる。
rep の main 関数内でブレークし，_impure_ptr の中を調べる。
(gdb) p ((struct _reent*)_impure_ptr)->_stderr
$6 = (__FILE *) 0xffff8000000b86a0 <impure_data+1688>
→ _impure_ptr->_stderr は 0xffff8000000b86a0
(gdb) p &((struct _reent*)_impure_ptr)->_stderr->_write
$7 = (int (**)(_reent *, void *, const char *, int)) 0xffff8000000b86e0 <impure_data+1752>
→ &_impure_ptr->_stderr->_write は 0xffff8000000b86e0
→ FILE のオフセット 0x40 にあるのは _write ということが確定。
fprintf("hoge\n"); を 1 回実行するだけで，それによって stderr->_write がセットされるわけでもないのに，その後の動作が上手くいくのだろうか。
__swrite 関数にブレークポイントを仕掛け，QEMU で動きを追ってみると，初回の fprintf("hoge\n"); で既に __swrite が呼ばれることが判明。
Breakpoint 2, 0xffff800000030300 in __swrite ()
(gdb) bt
#0 0xffff800000030300 in __swrite ()
#1 0xffff80000003b81e in __sfvwrite_r ()
#2 0xffff800000039527 in __sprint_r ()
#3 0xffff8000000393fc in _vfprintf_r ()
#4 0xffff80000002db36 in fprintf ()
#5 0xffff800000020044 in main (argc=3, argv=0xfffffffffffff000) at grep.cpp:12
この実験に用いたバージョンでは grep.cpp:12 が main 関数の 1 行目で， fprintf("hoge\n"); がある行。
__swrite でブレークしたときに引数を調べてみると，fprintf がどのように __swrite を呼ぶかが分かる。
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xffff800000001efd "hoge\n"
2: $rcx = 5
(gdb)
Continuing.
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xffff80000000237a "argv[%d] = %s\n"
2: $rcx = 5
(gdb)
Continuing.
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xffffffffffffecb7 "0"
2: $rcx = 1
(gdb)
Continuing.
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xffff800000002381 "] = %s\n"
2: $rcx = 4
(gdb)
Continuing.
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xfffffffffffff100 "grep"
2: $rcx = 4
(gdb)
Continuing.
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xffff800000002387 "\n"
2: $rcx = 1
(gdb)
Continuing.
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xffff80000000237a "argv[%d] = %s\n"
2: $rcx = 5
fprintf から __sinit と __swirte までの呼び出し関係を再掲する。
(gdb) bt
#0 0xffff80000002d320 in __sinit ()
#1 0xffff8000000371e9 in _vfprintf_r ()
#2 0xffff80000002db36 in fprintf ()
#3 0xffff800000020044 in main (argc=3, argv=0xfffffffffffff000) at grep.cpp:12
#0 0xffff800000030300 in __swrite ()
#1 0xffff80000003b81e in __sfvwrite_r ()
#2 0xffff800000039527 in __sprint_r ()
#3 0xffff8000000393fc in _vfprintf_r ()
#4 0xffff80000002db36 in fprintf ()
__sfvwrite_r のコードを読む限り，__swrite 呼び出しの前に __sinit を実行したり，
それが既に実行されていることを確認する処理，fp->_write が非 0 でないことを確認する処理は無い。
__sprint_r にも同様にどのような処理は無い。
_vfprintf_r に CHECK_INIT (data, fp); という行がある。ここで __sinit の呼び出しが行われているはずだ。
ではなぜ，実機では 1 回目の fprintf 呼び出しの後にも _impure_ptr->_stderr->_write や _impure_ptr->__sdidinit の値が変化しなかったのか。
とりあえず，QEMU で __sinit でブレークしたときと __swriet でブレークしたときで _impure_ptr が指す先（impure_data） の値の変化を見る。
最初に示すのは __sinit で初めてブレークしたときの値
Breakpoint 1, 0xffff80000002d320 in __sinit ()
1: (char*)$rdx = 0x6473606b6b6e61ff <error: Cannot access memory at address 0x6473606b6b6e61ff>
2: $rcx = 7310575213432759040
(gdb) p *(struct _reent*)_impure_ptr
$1 = {_errno = 0, _stdin = 0xffff8000000b8540 <impure_data+1336>,
_stdout = 0xffff8000000b85f0 <impure_data+1512>, _stderr = 0xffff8000000b86a0 <impure_data+1688>,
_inc = 0, _emergency = '\000' <repeats 24 times>, _unspecified_locale_info = 0, _locale = 0x0,
__sdidinit = 0, __cleanup = 0x0, _result = 0x0, _result_k = 0, _p5s = 0x0, _freelist = 0x0,
_cvtlen = 0, _cvtbuf = 0x0, _new = {_reent = {_unused_rand = 0, _strtok_last = 0x0,
_asctime_buf = '\000' <repeats 25 times>, _localtime_buf = {__tm_sec = 0, __tm_min = 0,
__tm_hour = 0, __tm_mday = 0, __tm_mon = 0, __tm_year = 0, __tm_wday = 0, __tm_yday = 0,
__tm_isdst = 0}, _gamma_signgam = 0, _rand_next = 1, _r48 = {_seed = {13070, 43981, 4660},
_mult = {58989, 57068, 5}, _add = 11}, _mblen_state = {__count = 0, __value = {__wch = 0,
__wchb = "\000\000\000"}}, _mbtowc_state = {__count = 0, __value = {__wch = 0,
__wchb = "\000\000\000"}}, _wctomb_state = {__count = 0, __value = {__wch = 0,
__wchb = "\000\000\000"}}, _l64a_buf = "\000\000\000\000\000\000\000",
_signal_buf = '\000' <repeats 23 times>, _getdate_err = 0, _mbrlen_state = {__count = 0,
__value = {__wch = 0, __wchb = "\000\000\000"}}, _mbrtowc_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _mbsrtowcs_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _wcrtomb_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _wcsrtombs_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _h_errno = 0}, _unused = {_nextf = {
0x0 <repeats 11 times>, 0x1 "",
0xe66d1234abcd330e <error: Cannot access memory at address 0xe66d1234abcd330e>,
0xb0005deec "", 0x0 <repeats 16 times>}, _nmalloc = {0 <repeats 30 times>}}},
_atexit = 0x0, _atexit0 = {_next = 0x0, _ind = 0, _fns = {0x0 <repeats 32 times>},
_on_exit_args = {_fnargs = {0x0 <repeats 32 times>}, _dso_handle = {0x0 <repeats 32 times>},
_fntypes = 0, _is_cxa = 0}}, _sig_func = 0x0, __sglue = {_next = 0x0, _niobs = 0,
_iobs = 0x0}, __sf = {{_p = 0x0, _r = 0, _w = 0, _flags = 0, _file = 0, _bf = {_base = 0x0,
_size = 0}, _lbfsize = 0, _cookie = 0x0, _read = 0x0, _write = 0x0, _seek = 0x0,
_close = 0x0, _ub = {_base = 0x0, _size = 0}, _up = 0x0, _ur = 0, _ubuf = "\000\000",
_nbuf = "", _lb = {_base = 0x0, _size = 0}, _blksize = 0, _offset = 0, _data = 0x0,
_lock = 0, _mbstate = {__count = 0, __value = {__wch = 0, __wchb = "\000\000\000"}},
_flags2 = 0}, {_p = 0x0, _r = 0, _w = 0, _flags = 0, _file = 0, _bf = {_base = 0x0,
_size = 0}, _lbfsize = 0, _cookie = 0x0, _read = 0x0, _write = 0x0, _seek = 0x0,
_close = 0x0, _ub = {_base = 0x0, _size = 0}, _up = 0x0, _ur = 0, _ubuf = "\000\000",
_nbuf = "", _lb = {_base = 0x0, _size = 0}, _blksize = 0, _offset = 0, _data = 0x0,
_lock = 0, _mbstate = {__count = 0, __value = {__wch = 0, __wchb = "\000\000\000"}},
_flags2 = 0}, {_p = 0x0, _r = 0, _w = 0, _flags = 0, _file = 0, _bf = {_base = 0x0,
_size = 0}, _lbfsize = 0, _cookie = 0x0, _read = 0x0, _write = 0x0, _seek = 0x0,
_close = 0x0, _ub = {_base = 0x0, _size = 0}, _up = 0x0, _ur = 0, _ubuf = "\000\000",
_nbuf = "", _lb = {_base = 0x0, _size = 0}, _blksize = 0, _offset = 0, _data = 0x0,
_lock = 0, _mbstate = {__count = 0, __value = {__wch = 0, __wchb = "\000\000\000"}},
_flags2 = 0}}}
で，次が __swrite が初めて呼ばれたときの値。
Breakpoint 2, 0xffff800000030300 in __swrite ()
1: (char*)$rdx = 0xffff800000001efd "hoge\n"
2: $rcx = 5
(gdb) p *(struct _reent*)_impure_ptr
$2 = {_errno = 0, _stdin = 0xffff8000000b8540 <impure_data+1336>,
_stdout = 0xffff8000000b85f0 <impure_data+1512>, _stderr = 0xffff8000000b86a0 <impure_data+1688>,
_inc = 0, _emergency = '\000' <repeats 24 times>, _unspecified_locale_info = 0, _locale = 0x0,
__sdidinit = 1, __cleanup = 0xffff80000002d4b0 <_cleanup_r>, _result = 0x0, _result_k = 0,
_p5s = 0x0, _freelist = 0x0, _cvtlen = 0, _cvtbuf = 0x0, _new = {_reent = {_unused_rand = 0,
_strtok_last = 0x0, _asctime_buf = '\000' <repeats 25 times>, _localtime_buf = {__tm_sec = 0,
__tm_min = 0, __tm_hour = 0, __tm_mday = 0, __tm_mon = 0, __tm_year = 0, __tm_wday = 0,
__tm_yday = 0, __tm_isdst = 0}, _gamma_signgam = 0, _rand_next = 1, _r48 = {_seed = {13070,
43981, 4660}, _mult = {58989, 57068, 5}, _add = 11}, _mblen_state = {__count = 0,
__value = {__wch = 0, __wchb = "\000\000\000"}}, _mbtowc_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _wctomb_state = {__count = 0, __value = {__wch = 0,
__wchb = "\000\000\000"}}, _l64a_buf = "\000\000\000\000\000\000\000",
_signal_buf = '\000' <repeats 23 times>, _getdate_err = 0, _mbrlen_state = {__count = 0,
__value = {__wch = 0, __wchb = "\000\000\000"}}, _mbrtowc_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _mbsrtowcs_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _wcrtomb_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _wcsrtombs_state = {__count = 0, __value = {
__wch = 0, __wchb = "\000\000\000"}}, _h_errno = 0}, _unused = {_nextf = {
0x0 <repeats 11 times>, 0x1 "",
0xe66d1234abcd330e <error: Cannot access memory at address 0xe66d1234abcd330e>,
0xb0005deec "", 0x0 <repeats 16 times>}, _nmalloc = {0 <repeats 30 times>}}},
_atexit = 0x0, _atexit0 = {_next = 0x0, _ind = 0, _fns = {0x0 <repeats 32 times>},
_on_exit_args = {_fnargs = {0x0 <repeats 32 times>}, _dso_handle = {0x0 <repeats 32 times>},
_fntypes = 0, _is_cxa = 0}}, _sig_func = 0x0, __sglue = {_next = 0x0, _niobs = 3,
_iobs = 0xffff8000000b8540 <impure_data+1336>}, __sf = {{_p = 0x0, _r = 0, _w = 0, _flags = 4,
_file = 0, _bf = {_base = 0x0, _size = 0}, _lbfsize = 0,
_cookie = 0xffff8000000b8540 <impure_data+1336>, _read = 0xffff8000000302c0 <__sread>,
_write = 0xffff800000030300 <__swrite>, _seek = 0xffff800000030360 <__sseek>,
_close = 0xffff8000000303a0 <__sclose>, _ub = {_base = 0x0, _size = 0}, _up = 0x0, _ur = 0,
_ubuf = "\000\000", _nbuf = "", _lb = {_base = 0x0, _size = 0}, _blksize = 0, _offset = 0,
_data = 0x0, _lock = 0, _mbstate = {__count = 0, __value = {__wch = 0,
__wchb = "\000\000\000"}}, _flags2 = 0}, {_p = 0x0, _r = 0, _w = 0, _flags = 9,
_file = 1, _bf = {_base = 0x0, _size = 0}, _lbfsize = 0,
_cookie = 0xffff8000000b85f0 <impure_data+1512>, _read = 0xffff8000000302c0 <__sread>,
_write = 0xffff800000030300 <__swrite>, _seek = 0xffff800000030360 <__sseek>,
_close = 0xffff8000000303a0 <__sclose>, _ub = {_base = 0x0, _size = 0}, _up = 0x0, _ur = 0,
_ubuf = "\000\000", _nbuf = "", _lb = {_base = 0x0, _size = 0}, _blksize = 0, _offset = 0,
_data = 0x0, _lock = 0, _mbstate = {__count = 0, __value = {__wch = 0,
__wchb = "\000\000\000"}}, _flags2 = 0}, {_p = 0xffff8000000b8717 <impure_data+1807> "",
_r = 0, _w = 0, _flags = 8218, _file = 2, _bf = {
_base = 0xffff8000000b8717 <impure_data+1807> "", _size = 1}, _lbfsize = 0,
_cookie = 0xffff8000000b86a0 <impure_data+1688>, _read = 0xffff8000000302c0 <__sread>,
_write = 0xffff800000030300 <__swrite>, _seek = 0xffff800000030360 <__sseek>,
_close = 0xffff8000000303a0 <__sclose>, _ub = {_base = 0x0, _size = 0}, _up = 0x0, _ur = 0,
_ubuf = "\000\000", _nbuf = "", _lb = {_base = 0x0, _size = 0}, _blksize = 0, _offset = 0,
_data = 0x0, _lock = 0, _mbstate = {__count = 0, __value = {__wch = 0,
__wchb = "\000\000\000"}}, _flags2 = 0}}}
もしかするとコンパイラの最適化などにより _impure_ptr->__sdidinit の値が変化していないように見えるだけかもしれない。
メモリを直接ダンプするコードを入れて観察してみる。
void DumpMem(uint64_t addr, int n) {
char s[128];
auto p = reinterpret_cast<volatile uint64_t*>(addr);
for (int i = 0; i < n - 1; i += 2) {
sprintf(s, "%016lx: %016lx %016lx\n",
reinterpret_cast<uint64_t>(&p[i]), p[i], p[i + 1]);
SyscallLogString(kWarn, s);
}
}
この関数を使って QEMU で値の変化を観察すると，fprintf(stderr, "hoge\n") の前後で
ffff8000000b8058: 0000000000000001 ffff80000002d4b0
となった。実機ではこの 2 つの値は 0 のままだった。つまり，本当に実機では _impure_ptr->__sdidinit の値が変化していないのである。
あり得るのは次の 3 つのパターンだろう。
__sinitが実行されていない__sinitは実行されたが，なぜか_impure_ptr->__sdidinitの値が変化しなかった__sinitが実行され_impure_ptr->__sdidinitが 1 になったが，メモリダンプの時点で 0 に戻っていた
パターン 1 になる可能性は，ソースコードおよび機械語を見る限り，次のいずれか。
_impure_ptrが 0，または_impure_ptr->__sdidinitが 1
これまでの実験で _impure_ptr は 0 ではない。
例えば DumpMem(reinterpret_cast<uint64_t>(_impure_ptr), 12); のようにメモリダンプをしているが，
ちゃんと 0xffff8000000b8008 から 12 要素分の数値が表示される。
また _impure_ptr->__sdidinit も 0 である。メモリダンプの結果がそのように物語っている。
デバッグレジスタ（DR0 - DR3）を使うと，CPU が特定のメモリアドレスの実行，書き込み，読み込みなどを検知すると例外を飛ばすことができる。
これを使って _impure_ptr->__sdidinit に書き込まれる瞬間を検出し，そのときの状態を観察したい。
grep コマンドを起動sる直前に DR0 に _impure_ptr->__sdidinit のアドレス（0xffff8000000b8058）を設定し，DR7 を次の通り設定する。
- DR7.L0 = 0, DR7.G0 = 1（グローバルに検出機能を有効化する）
- DR7.R/W0 = 1（書き込みのみを検出する）
- DR7.LEN0 = 2（検出サイズ 8 バイト）
これで grep を起動してみると，初回の fprintf 実行中に #DB が発生し grep が停止した。
#DB 発生時の RIP = 0xffff80000002d717 で，これはちょうど __sinit で r12+0x59 に 1 を書き込む命令が #DB の原因であることを示す。
（データ読み書きの #DB は Trap 扱いになって，RIP は Trap の原因になった命令の次を指す状態になっているのが仕様。）
ffff80000002d5a0 <__sinit>:
<中略>
ffff80000002d70e: 41 c7 44 24 50 01 00 mov DWORD PTR [r12+0x50],0x1
ffff80000002d715: 00 00
ffff80000002d717: 48 83 c4 18 add rsp,0x18
即値 1 を書き込んでいるのは _impure_ptr->__sdidinit に 1 を代入する処理に相当するだろうと思う。
実機でも同じ改造を施したバージョンを動かす。 すると，QEMU と同じように RIP = 0xffff80000002d717 で #DB が発生した！
この DB 例外を仕掛けたまま，次のような検証プログラムを grep コマンドの先頭に付け加えた。
DumpMem(reinterpret_cast<uint64_t>(_impure_ptr) + offsetof(_reent, __sdidinit), 2);
fprintf(stderr, "hoge\n");
DumpMem(reinterpret_cast<uint64_t>(_impure_ptr) + offsetof(_reent, __sdidinit), 2);
fprintf(stderr, "hoge\n");
DumpMem(reinterpret_cast<uint64_t>(_impure_ptr) + offsetof(_reent, __sdidinit), 2);
GPD MicroPC で実験したところ，MikanOS のコンソールに次のように表示された。
ffff8000000b8058: 0000000000000000 0000000000000000
#DB CS:RIP 0023:ffff80000002d5d7, *ffff8000000b8058=1=1
ffff8000000b8058: 0000000000000000 0000000000000000
#DB CS:RIP 0023:ffff80000002d5d7, *ffff8000000b8058=1=1
ffff8000000b8058: 0000000000000001 ffff80000002d5f0
検証中，QEMU 上の #DB 例外がちょっと不可解な動作をしたので，簡単なプログラムで動作を検証する。
まず，被験体となるアプリとして，グローバル変数に値を書くだけの簡単なプログラムを用意する。
volatile unsigned long var;
extern "C" void main(int argc, char** argv) {
var = 1;
var = 2;
var = 3;
var = 4;
var = 5;
}
名前は testdr コマンド。0xffff800000002000 に配置された 64 ビット整数変数に 5 回の書き込みを行うだけ。 逆アセンブルした結果は次の通り。とても単純。
ffff800000001000 <main>:
ffff800000001000: 55 push rbp
ffff800000001001: 48 89 e5 mov rbp,rsp
ffff800000001004: 48 b8 00 20 00 00 00 movabs rax,0xffff800000002000
ffff80000000100b: 80 ff ff
ffff80000000100e: 48 c7 00 01 00 00 00 mov QWORD PTR [rax],0x1
ffff800000001015: 48 c7 00 02 00 00 00 mov QWORD PTR [rax],0x2
ffff80000000101c: 48 c7 00 03 00 00 00 mov QWORD PTR [rax],0x3
ffff800000001023: 48 c7 00 04 00 00 00 mov QWORD PTR [rax],0x4
ffff80000000102a: 48 c7 00 05 00 00 00 mov QWORD PTR [rax],0x5
ffff800000001031: 5d pop rbp
ffff800000001032: c3 ret
DB 例外の割り込みハンドラは次の通り。
__attribute__((interrupt))
void IntHandlerDB(InterruptFrame* frame) {
uint64_t dr0;
__asm__("mov %%DR0, %0" : "=r"(dr0));
uint64_t v = *reinterpret_cast<volatile uint64_t*>(dr0);
Log(kWarn, "#DB CS:RIP %04x:%016lx, *%016lx=%lu\n",
frame->cs, frame->rip, dr0, v);
}
逆アセンブル結果は次の通り。レジスタ群を保存する部分は省いてある。
0000000000133b90 <(anonymous namespace)::IntHandlerDB(InterruptFrame*)>:
133b90: 55 push rbp
133b91: 48 89 e5 mov rbp,rsp
133b94: 50 push rax
<中略（レジスタ保存）>
133c10: 0f 29 85 b0 fe ff ff movaps XMMWORD PTR [rbp-0x150],xmm0
133c17: fc cld
133c18: 41 0f 21 c0 mov r8,db0
133c1c: 4d 8b 08 mov r9,QWORD PTR [r8]
133c1f: 48 8b 4d 08 mov rcx,QWORD PTR [rbp+0x8]
133c23: 48 8b 55 10 mov rdx,QWORD PTR [rbp+0x10]
133c27: bf 04 00 00 00 mov edi,0x4
133c2c: be e4 22 10 00 mov esi,0x1022e4
133c31: 31 c0 xor eax,eax
133c33: e8 68 f6 ff ff call 1332a0 <Log(LogLevel, char const*, ...)>
133c38: 0f 28 85 b0 fe ff ff movaps xmm0,XMMWORD PTR [rbp-0x150]
<中略（レジスタ復帰）>
133cbb: 5d pop rbp
133cbc: 48 cf iretq
Debug registers の設定は次の通り。 アプリケーションの main 関数にジャンプする直前に DR0/DR7 を設定する。
__asm__("mov %0, %%DR0" : : "r"(0xffff800000002000));
__asm__("mov %0, %%DR7" : : "r"(1llu << 1 | 1llu << 16 | 2llu << 18));
// enable global, write only, 8 bytes
int ret = CallApp(argc.value, argv, 3 << 3 | 3, app_load.entry,
stack_frame_addr.value + stack_size - 8,
&task.OSStackPointer());
__asm__("mov %0, %%DR0" : : "r"(0llu));
DR7 の設定は次の通り。
- DR7.L0 = 0 & DR7.G0 = 1: グローバルに検出を有効化する
- DR7.R/W0 = 1: データ書き込みだけでブレークする
- DR7.LEN0 = 2: 8 バイト長
IntHandlerDB の中で DR0 が指すアドレスからの読み込み命令がある 0x133c1c にブレークポイントを仕掛け，様子を見る。 ブレークした時点での r8 の値，r8 が指すメモリ領域の値，1 命令進めて r9 の値を確認する。
Breakpoint 1, (anonymous namespace)::IntHandlerDB (frame=0xffff800000001015) at interrupt.cpp:107
107 uint64_t v = *reinterpret_cast<volatile uint64_t*>(dr0);
(gdb) x /5i $rip
=> 0x133c1c <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+140>: mov r9,QWORD PTR [r8]
0x133c1f <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+143>:
mov rcx,QWORD PTR [rbp+0x8]
0x133c23 <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+147>:
mov rdx,QWORD PTR [rbp+0x10]
0x133c27 <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+151>: mov edi,0x4
0x133c2c <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+156>: mov esi,0x1022e4
(gdb) p /x $r8
$1 = 0xffff800000002000
(gdb) p /x $r9
$2 = 0x15e5e90
(gdb) ni
109 frame->cs, frame->rip, dr0, v);
(gdb) p /x $r9
$3 = 0x0
(gdb) x /1gx $r8
0xffff800000002000: 0x0000000000000001
(gdb) c
Continuing.
Breakpoint 1, (anonymous namespace)::IntHandlerDB (frame=0xffff80000000101c) at interrupt.cpp:107
107 uint64_t v = *reinterpret_cast<volatile uint64_t*>(dr0);
(gdb) x /2i $rip
=> 0x133c1c <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+140>: mov r9,QWORD PTR [r8]
0x133c1f <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+143>:
mov rcx,QWORD PTR [rbp+0x8]
(gdb) p /x $r8
$4 = 0xffff800000002000
(gdb) p /x $r9
$5 = 0x15e5e90
(gdb) x /1gx $r8
0xffff800000002000: 0x0000000000000002
(gdb) ni
109 frame->cs, frame->rip, dr0, v);
(gdb) p /x $r9
$6 = 0x2
(gdb) c
Continuing.
Breakpoint 1, (anonymous namespace)::IntHandlerDB (frame=0xffff800000001023) at interrupt.cpp:107
107 uint64_t v = *reinterpret_cast<volatile uint64_t*>(dr0);
(gdb) x /2i $rip
=> 0x133c1c <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+140>: mov r9,QWORD PTR [r8]
0x133c1f <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+143>:
mov rcx,QWORD PTR [rbp+0x8]
(gdb) x /1gx $r8
0xffff800000002000: 0x0000000000000003
(gdb) ni
109 frame->cs, frame->rip, dr0, v);
(gdb) p /x $r9
$7 = 0x3
(gdb) c
Continuing.
Breakpoint 1, (anonymous namespace)::IntHandlerDB (frame=0xffff80000000102a) at interrupt.cpp:107
107 uint64_t v = *reinterpret_cast<volatile uint64_t*>(dr0);
(gdb) x /2i $rip
=> 0x133c1c <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+140>: mov r9,QWORD PTR [r8]
0x133c1f <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+143>:
mov rcx,QWORD PTR [rbp+0x8]
(gdb) x /1gx $r8
0xffff800000002000: 0x0000000000000004
(gdb) p /x $r9
$8 = 0x15e5e90
(gdb) ni
109 frame->cs, frame->rip, dr0, v);
(gdb) p /x $r9
$9 = 0x4
(gdb) c
Continuing.
Breakpoint 1, (anonymous namespace)::IntHandlerDB (frame=0xffff800000001031) at interrupt.cpp:107
107 uint64_t v = *reinterpret_cast<volatile uint64_t*>(dr0);
(gdb) x /2i $rip
=> 0x133c1c <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+140>: mov r9,QWORD PTR [r8]
0x133c1f <(anonymous namespace)::IntHandlerDB(InterruptFrame*)+143>:
mov rcx,QWORD PTR [rbp+0x8]
(gdb) x /1gx $r8
0xffff800000002000: 0x0000000000000005
(gdb) ni
109 frame->cs, frame->rip, dr0, v);
(gdb) p /x $r9
$10 = 0x5
mov r9, [r8] を実行した時点での r9 の値をまとめると次のようになる。
| 回 | r9 | 0xffff800000002000 の値 |
|---|---|---|
| 1 | 0 | 1 |
| 2 | 2 | 2 |
| 3 | 3 | 3 |
| 4 | 4 | 4 |
| 5 | 5 | 5 |
なんと，初回だけ r9 にメモリの値が正しく読めていないことが分かった。 ちなみに，Log 関数による画面表示は r9 の値がそのまま表示された（つまり 0，2，3，…）
GDB を接続せずに実験すると，testdr コマンドの 1 回目の実行では 1，2，3，…と表示され， 2 回目の実行では 0，2，3，…と表示されるという不安定な結果となった。 何度も実行してみると 0 始まりのパターンと 1 始まりのパターンがランダムに出現した。
GPD MicroPC で何十回か実行したところ，1 始まりのパターンしか観測できなかった。 QEMU + GDB の実験に比べて安定している。
どうにも埒が明かないため，DB 例外で read も検出するようにした。
まずは QEMU で試すと __sdidinit のアクセスパターンは次のようになっていた。
- メモリダンプによる read
_vfprintf_rによる read（__sinitを呼び出すべきかどうかの判定のため）__sinitによる read（__sinit冒頭で__sdidinitを調べている）- カーネル側
memcpyによる read ←これはなんだ？？ __sinitによる write（__sdidinit = 1）__swsetup_rによる read（__sinitを呼び出すべきかどうかの判定のため）- メモリダンプによる read
_vfprintf_rによる read（__sinitを呼び出すべきかどうかの判定のため）- メモリダンプによる read
4 番の read を除き納得のアクセスパターンである。では 4 番は何だろうか？
よく考えるとこれはアプリの CoW の実装に起因するものだということに思い至った。 アプリの .text, .data, .bss それぞれ，最初は read only の設定でページがマップされている。 初めての write によってページがコピーされる。
__sinit により __sdidinit に 1 を書き込もうとするときに #PF が起き，1 ページがコピーされる。
このとき，ページの内容を仮想アドレスから読み，物理アドレスに書くようにプログラムしてあるため，
read だけが #DB として検出されたのだ。
#PF は fault であり，原因となった命令が実行される前に割り込みが起こる。
対して #DB は trap であり，原因となった命令が実行された後に割り込みが起こる。
したがって，#PF が起きてページがコピーされた後に，
改めて __sinit による書き込みが #DB として検出される，という順番であることは納得できる。
一方，GPD MicroPC で試すと __sdidinit のアクセスパターンは次のようになっていた。
- メモリダンプによる read
_vfprintf_rによる read（__sinitを呼び出すべきかどうかの判定のため）__sinitによる read（__sinit冒頭で__sdidinitを調べている）- カーネル側
memcpyによる read （CoW） - カーネル側
memcpyによる read ←謎1 __sinitによる write（__sdidinit = 1）__swsetup_rによる read（__sinitを呼び出すべきかどうかの判定のため）__sinitによる read ←謎2__sinitによる write ←謎3- メモリダンプによる read
_vfprintf_rによる read（__sinitを呼び出すべきかどうかの判定のため）- メモリダンプによる read
QEMU での実行に比較して，謎 1～3 が追加された。 謎過ぎる。
…もしかしたら，ということで，CoW したときに更新したページに対して INVLPG を実行し， TLB（ページテーブルのキャッシュ）を更新してみたら，見事にバグが消えた！