Ryzen SEGV Battle

Ryzen SEGV Battle

The result of the analysis of so called SEGV (or segfault) problem in Ryzen processor

842515eaf8fbb2dfcc75197e7797dc15?s=128

Satoru Takeuchi

October 12, 2017
Tweet

Transcript

  1. 3.

    終わりの始まり • 何度かカーネルビルドしたらgccがSEGV吐いて死亡 • 先代マシンでは起きない 3 ./include/trace/perf.h:41:9: internal compiler error:

    Segmentation fault struct hlist_head *head; \ ^ ... Please submit a full bug report, with preprocessed source if appropriate. See <file:///usr/share/doc/gcc-5/README.Bugs> for instructions.
  2. 5.

    検証環境 • ハードウェア ◦ CPU: Ryzen 1800X ◦ マザーボード: ASUS

    PRIME X370-PRO ◦ BIOS: 常に最新。設定はSVM有効化以外はデフォルト ▪ バージョン: 0504(AGESA1.0.0.4)~0805(AGESA1.0.0.6a) ◦ DIMM: Kingston KVR24N17S8/8 * 4 (8 * 4 = 32GB) ▪ QVLには載ってないがAMDからOKが出ている ▪ Memtest86パス、およびRowHammerテストを一晩生存 ◦ GPU: GeForce GTX 1060 • ソフトウェア(OSはUbunru16.04) ◦ kernel: 4.8.0-5[468]-generic, その時々の最新upstream kernel ◦ gcc: gcc (Ubuntu 5.4.0-6ubuntu1~16.04.4) 5.4.0 20160609 5
  3. 6.

    切り分け: gcc or not • 無限ビルドスクリプトを流したら10回に1回程度失敗 ◦ 失敗する箇所は毎回異なる • 少なくとも問題はgccとその依存ライブラリではありえない

    ◦ gccは入力(ソースコード)が同じなら出力も同じ ◦ シングルスレッド、非シグナルドリブン => 何らかの競合でもなさそう 6
  4. 16.

    知人からの激励 16 ど R う Y で Z す E

    か N !? ん 直 じ ん ゃ な ね い !? な 半 直 る 分 っ ん く て じ ら も ゃ い 性 ね に 能 !? こ 俺 と 何 し か た 悪 !? い
  5. 18.

    解析: linuxカーネル or not? • WSL(bash on Windows)において、同じ手順で問題発生 ◦ fork()の失敗という形で顕在化

    • NetBSDでも同じ手順でのSEGV発生事例あり • 3つのOS全てに同じ/類似のバグがある確率 <<< ハード問題の確率 18 make[3]: fork: Invalid argument make[2]: *** [arch/x86/realmode/rm/realmode.bin] Error 2 make[1]: *** [arch/x86/realmode] Error 2 make[1]: *** Waiting for unfinished jobs.... make: *** [arch/x86] Error 2 make: *** Waiting for unfinished jobs....
  6. 21.

    • SEGVと言っても原因はいろいろ • ftraceを使ってシグナルイベントをトレース 具体的にどんなSEGV? 21 TRACEDIR=/sys/kernel/debug/tracing/ echo 1 >

    ${TRACEDIR}/events/signal/signal_generate/enable echo '!stacktrace' > ${TRACEDIR}/events/signal/signal_generate/trigger echo 'stacktrace if sig == 11' > ${TRACEDIR}/events/signal/signal_generate/trigger echo 1 > ${TRACEDIR}/tracing_on echo > ${TRACEDIR}/trace
  7. 22.

    トレース結果 code=128 comm=cc1 pid=19539 grp=0 res=0 <...>-19539 [014] d... 3257.455416:

    <stack trace> => send_signal => force_sig_info => do_general_protection => general_protection 22 • General Protection Fault(GPF)で死亡 ◦ アクセス許可が無いメモリに触る ◦ ユーザプログラムから特権命令を実行 ◦ その他色々
  8. 23.

    もうちょっと深堀り • GPFの詳細をログに出すカーネルパッチを作成 23 --- a/arch/x86/kernel/traps.c +++ b/arch/x86/kernel/traps.c @@ -514,10

    +514,9 @@ do_general_protection(struct pt_regs *regs, long error_code) tsk->thread.error_code = error_code; tsk->thread.trap_nr = X86_TRAP_GP; - if (show_unhandled_signals && unhandled_signal(tsk, SIGSEGV) && - printk_ratelimit()) { - pr_info("%s[%d] general protection ip:%lx sp:%lx error:%lx", - tsk->comm, task_pid_nr(tsk), + if (show_unhandled_signals) { + pr_err("CPU%u: %s[%d] general protection ip:%lx sp:%lx error:%lx", + tsk->cpu, tsk->comm, task_pid_nr(tsk), regs->ip, regs->sp, error_code);
  9. 24.

    カスタムカーネルのログ • エラーコード0: セグメント違反ならセレクタのindexになるので、それ以外 24 traps: CPU2: cc1[15404] general protection

    ip:e4f4f4 sp:7ffe1aefc4a0 error:0 in cc1[400000+13d4000] traps: CPU15: cc1[31616] general protection ip:d0d253 sp:7fffd764db60 error:0 in cc1[400000+13d4000] traps: CPU3: cc1[14060] general protection ip:1131185 sp:7ffc6b6f71b0 error:0 in cc1[400000+13d4000] traps: CPU8: cc1[18405] general protection ip:d0d253 sp:7ffc7ac2e930 error:0 in cc1[400000+13d4000] traps: CPU0: cc1[31556] general protection ip:fc0d7c sp:7ffede8d0630 error:0 in cc1[400000+13d4000] ...
  10. 25.

    • メモリアクセスしていないのにSEGVが起きていることがある SEGVに実行していた命令 * d0d0c9: 45 01 ee add %r13d,%r14d

    * d0d253: e9 e3 fe ff ff jmpq d0d13b <_Z19cselib_process_insnP8rtx_insn@@Base+0x38b> *1131150: 41 c6 44 24 04 35 movb $0x35,0x4(%r12) *113117d: 41 83 ed 71 sub $0x71,%r13d *1131185: 66 43 f7 84 12 60 2e testw $0x204,0x1622e60(%r10,%r10,1) *1131190: 0f 84 1a 05 00 00 je 11316b0 <_cpp_lex_token@@Base+0x6a0> *11311ad: 45 8d 6c 32 8f lea -0x71(%r10,%rsi,1),%r13d * fe41ba: 76 24 jbe fe41e0 <_Z16get_nonzero_bitsPK9tree_node@@Base+0x40> * e4f4f4: 48 85 c0 test %rax,%rax * e4f4f4: 48 85 c0 test %rax,%rax * fc0d7c: 48 85 c0 test %rax,%rax ... 25
  11. 27.

    えいらくさんの解析手法 • BitVisor(ハイパーバイザの一つ)を使用 • SEGV発生時にLinux VMを停止させて、その時の状態を調査 • SEGV発生直前のbranchに関する情報をLastBranchRecordから採取 ◦ LastBranchFromIP:

    最後のbranchは、どの命令から飛んだか ◦ LastBranchToIP: 最後のbranchは、どの命令に飛んだか 27 ハードウェア BitVisor linux SEGV発生 トラップ
  12. 28.

    IPとLast Branch Recordの情報 • SEGV時rip(0x0101356e) • LastBranchFromIP(0xc67aee), LastBranchToIP(0x01013560) 28 =>

    0x101356e <_Z22private_is_attribute_pPKcmPK9tree_node+14>: jb 0x1013588 <_Z22private_is_attribute_pPKcmPK9tree_node+40> c67aee: e8 6d ba 3a 00 callq 1013560 メモリアクセス無し
  13. 29.

    スタックの確認 • SEGV時rip(0x0101356e) • LastBranchFromIP(0xc67aee), LastBranchToIP(0x01013560) • rsp(0x7ffe731e3668)の中身 29 =>

    0x101356e <_Z22private_is_attribute_pPKcmPK9tree_node+14>: jb 0x1013588 <_Z22private_is_attribute_pPKcmPK9tree_node+40> c67aee: e8 6d ba 3a 00 callq 1013560 0x7ffe731e3668: 0x0000000000c67af3 0x000000fb00000010 • 恐らく現在のスタックフレームから の戻りアドレス • LastBranchFromIPの次の命令
  14. 30.

    SEGV時の各種レジスタの確認 • LastBranchToIPからの実行の流れ 30 1013560: 48 83 ec 08 sub

    $0x8,%rsp 1013564: 8b 42 20 mov 0x20(%rdx),%eax 1013567: 48 39 f0 cmp %rsi,%rax 101356a: 75 1c jne 1013588 101356c: 48 8b 72 18 mov 0x18(%rdx),%rsi • rspは戻りアドレスを指している • 辻褄が合わない RIP LastBranchToIP 以下5命令を実行したはず
  15. 31.

    仮説 • call時にLastBranchToIPから0x40バイト低位の命令に飛んだ? ◦ 事前調査で「ripが0x40バイト手前にあれば辻褄が合いそう」という例が複数あったらしい 31 1013520: 48 8b 57

    10 mov 0x10(%rdi),%rdx 1013524: b8 01 00 00 00 mov $0x1,%eax 1013529: 48 85 d2 test %rdx,%rdx 101352c: 74 e9 je 1013517 101352e: 48 8b 4a 10 mov 0x10(%rdx),%rcx rip - 0x40 LastBranchToIP - 0x40 以下5命令を実行した?
  16. 32.

    仮説の検証: 1個目の命令 • (0x10 + rdi)とrdxが等しい => 辻褄が合う 32 1013520:

    48 8b 57 10 mov 0x10(%rdi),%rdx 1013524: b8 01 00 00 00 mov $0x1,%eax 1013529: 48 85 d2 test %rdx,%rdx 101352c: 74 e9 je 1013517 101352e: 48 8b 4a 10 mov 0x10(%rdx),%rcx (gdb) x/xg 0x10+$rdi 0x15b7afd: 0x000a656c63796320 (gdb) p/x $rdx $5 = 0xa656c63796320 この間rdi,rdxは変更なし
  17. 33.

    仮説の検証: 2-4個目の命令 • 0x101352でジャンプしていない & eaxは0x1 => 辻津が合う 33 1013520:

    48 8b 57 10 mov 0x10(%rdi),%rdx 1013524: b8 01 00 00 00 mov $0x1,%eax 1013529: 48 85 d2 test %rdx,%rdx 101352c: 74 e9 je 1013517 101352e: 48 8b 4a 10 mov 0x10(%rdx),%rcx (gdb) p/x $rax $6 = 0x1 rdx = 0xa656c63796320 != 0
  18. 34.

    仮説の検証: 5個目の(実際に動いてた?)命令 • 0x10 + rdx(= 0xa656c63796320)は現在のx86_64 CPUの仮想アドレス空間 (48bit)を超えているのでGPF発生 =>

    辻褄が合う 34 1013520: 48 8b 57 10 mov 0x10(%rdi),%rdx 1013524: b8 01 00 00 00 mov $0x1,%eax 1013529: 48 85 d2 test %rdx,%rdx 101352c: 74 e9 je 1013517 101352e: 48 8b 4a 10 mov 0x10(%rdx),%rcx
  19. 35.

    仮説の検証: BitVisorによるデータ修正&実行再開 1. 1つ目の命令((LastBranchToIP - 40) = 0x1013520)から死亡時までに変更された レジスタ(%rdx, %eax,

    各種フラグレジスタ)を復元 2. 本来あるべきripからlinux VM実行を再開 3. 継続動作に成功 => 辻褄が合う 続きはえいらくさんのブログで… 35 1013520: 48 8b 57 10 mov 0x10(%rdi),%rdx 1013524: b8 01 00 00 00 mov $0x1,%eax 1013529: 48 85 d2 test %rdx,%rdx 101352c: 74 e9 je 1013517 101352e: 48 8b 4a 10 mov 0x10(%rdx),%rcx 巻き戻し
  20. 36.

    0x40バイトずれについての考察 • これですべて説明つく? ◦ 説明つくものもあれば、まだ不明なものもある ◦ ずれてからしばらく実行継続すると、最終的に何が起きても不思議ではない ▪ 途中でcall/jmpするかも ▪

    0x40バイト完走後はどこを実行するか不明 • SEGV以外の事象は起きないの? ◦ futex()待ちでwaitすることもある ◦ VM起動中に負荷を流すとシステムが超スローダウン ◦ 現時点でSIGILLやオブジェクトファイルの破壊は未確認 • 0x40バイトはキャッシュラインのサイズ => キャッシュに何か問題が? ◦ uop cache切っても問題が出る人がいるので uop cacheだけでは説明つかなさそう 36
  21. 37.

    結局どのハードが原因? • 有志のユーザから出た対処案は、どれも一部の人にしか効果なし ◦ CPU以外のパーツ変更 ◦ メモリ周波数、枚数の変更、 ECCメモリの使用 ◦ CPU(コア、アンコア)の電圧変更、uop

    cache無効化、ハイパースレッド無効化 ◦ Kernel Address Space Location Randomization(KASLR)無効化 • 全員に共通しているハードはCPUのみ • 仮説: 様々な要素が発生確率に影響する何らかの根本原因がRyzenに存在? 37
  22. 39.

    サポート担当者を動かす方法の一例 1. 問題があることを認識してもらう => done 2. 再現させる => done 3.

    インパクトの大きさを訴える => done 4. 具体的に何が悪いのかを明らかにする => done 5. 偉い人にエスカレーション ◦ AMDに知り合いはいない 39
  23. 44.

    交換品の再現試験 • SEGVは起きなくなったが別の2つの問題が発生 ◦ 数分~数十分に一回 MCE ◦ ◦ 数十分~数時間に一回ハング •

    他の人の交換状況: 1名は問題解決。残り4,5人は引き続きSEGV発生 44 [ 627.958024] mce: [Hardware Error]: Machine check events logged [ 627.958027] [Hardware Error]: Corrected error, no action required. [ 627.958034] [Hardware Error]: CPU:13 (17:1:1) MC3_STATUS[-|CE|MiscV|-|-|-|-|SyndV|-]: 0x9820000000000150 [ 627.958037] [Hardware Error]: IPID: 0x000300b000000000, Syndrome: 0x000000002a000503 [ 627.958040] [Hardware Error]: Decode Unit Extended Error Code: 0 [ 627.958041] [Hardware Error]: Decode Unit Error: uop cache tag parity error. [ 627.958044] [Hardware Error]: cache level: RESV, tx: INSN, mem-tx: IRD
  24. 48.

    転機 • RedditにおいてEPYCでも問題が起きると噂に ◦ gccとは異なる独自再現プログラムを使用 • 再現プログラムのバグと判明 => AMDもRedditに火消しをしにきた •

    その直後、AMDがPhoronix(技術系ニュースサイト)に対してコメント ◦ 初期のRyzenにはgcc負荷によるSEGV問題が存在する(原因についてはほぼ言及無し ) ◦ EPYC、Threadripperでは起きない(Ryzen Proについては言及無し ) ◦ 問題が起きるユーザには個別対応する (事実上SEGV問題テスト済みの石への交換 ) 48