linux-3.16で入ったdecode_stacktrace.shを試してみる - φ(・・*)ゞｳｰﾝ　カーネルとか弄ったりのメモ

先週のLWNの記事3.16 merge window, part 2を見てて、「お、これは便利じゃね？」って思ったdecode_stacktrace.shを試してみました。これはカーネルのスタックトレースにあるオブジェクトのシンボルからソースファイル名・行番号を出してくれるという優れものらしいです。

まずスタックトレースを出す必要がありますが、これはsysrqのSys Rq + Alt + lで出します。これだとアクティブなCPU全てのスタックトレースが出るので適当なcpuを選んでファイルに保存します。

[ 2680.435448] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 3.16.0-rc1-ktest #20
[ 2680.435450] Hardware name: Gigabyte Technology Co., Ltd. To be filled by O.E.M./Z77X-UP4 TH, BIOS F3 07/12/2012
[ 2680.435453] task: ffff8808563dc460 ti: ffff88085612c000 task.ti: ffff88085612c000
[ 2680.435455] RIP: 0010:[<ffffffff81353158>]  [<ffffffff81353158>] intel_idle+0xd8/0x160
[ 2680.435459] RSP: 0018:ffff88085612fe60  EFLAGS: 00000046
[ 2680.435461] RAX: 0000000000000020 RBX: 0000000000000008 RCX: 0000000000000001
[ 2680.435462] RDX: 0000000000000000 RSI: ffff88085612ffd8 RDI: 0000000000000007
[ 2680.435463] RBP: ffff88085612fe88 R08: 00000000008ec12b R09: 0000000027a96744
[ 2680.435465] R10: 0000079d4aaad6f8 R11: 0000000000000000 R12: 0000000000000020
[ 2680.435466] R13: 0000000000000003 R14: 0000000000000004 R15: 0000000000000000
[ 2680.435468] FS:  0000000000000000(0000) GS:ffff88087f3c0000(0000) knlGS:0000000000000000
[ 2680.435469] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2680.435484] CR2: 00000000091ffde0 CR3: 0000000001a11000 CR4: 00000000001407e0
[ 2680.435485] Stack:
[ 2680.435486]  00000007814247ae ffff88087f3dc400 ffffffff81aa6a00 000002701479db0f
[ 2680.435489]  0000000000000004 ffff88085612feb8 ffffffff814247ca ffffffff81af9020
[ 2680.435492]  ffff88087f3dc400 0000000000000004 ffffffff81aa6a00 ffff88085612fec8
[ 2680.435495] Call Trace:
[ 2680.435498]  [<ffffffff814247ca>] cpuidle_enter_state+0x3a/0xc0
[ 2680.435501]  [<ffffffff81424937>] cpuidle_enter+0x17/0x20
[ 2680.435504]  [<ffffffff810b562f>] cpu_startup_entry+0x2cf/0x4c0
[ 2680.435507]  [<ffffffff81045969>] start_secondary+0x1f9/0x280
[ 2680.435509] Code: 00 00 48 8d 86 38 c0 ff ff 48 89 d1 0f 01 c8 65 48 8b 04 25 88 c9 00 00 48 8b 80 38 c0 ff ff a8 08 75 08 b1 01 4c 89 e0 0f 01 c9 <65> 48 8b 04 25 88 c9 00 00 f0 80 a0 3a c0 ff ff df 0f ae f0 65

カーネルのスタックトレースは見ての通りcpuidle_enter_state+0x3a/0xc0という形式で関数名の後ろのは関数内のオフセット/関数のサイズと出てます。これは、まあ分かるって言えば分かるんだけど面倒くさいのは確かです。

そこで3.16に入ったdecode_stacktrace.shを使うとどうなるか？

使い方は簡単で、一番目の引数はvmlinuxを指定。二番目の引数はカーネルのソースがあるディレクトリ。シェルのリダイレクトでスタックトレースのファイルを入力にする。

masami@saga:~/linux-kernel/scripts (ktest)$ ./decode_stacktrace.sh ~/linux-kernel/vmlinux ~/linux-kernel/ < ~/dump.txt

実行するとこんなふうに表示されます。

[ 2680.435448] CPU: 7 PID: 0 Comm: swapper/7 Not tainted 3.16.0-rc1-ktest #20
[ 2680.435450] Hardware name: Gigabyte Technology Co., Ltd. To be filled by O.E.M./Z77X-UP4 TH, BIOS F3 07/12/2012
[ 2680.435453] task: ffff8808563dc460 ti: ffff88085612c000 task.ti: ffff88085612c000
[ 2680.435455] RIP: intel_idle (./arch/x86/include/asm/thread_info.h:168 include/linux/sched.h:2800 include/linux/sched.h:2833 ./arch/x86/include/asm/mwait.h:56 drivers/idle/intel_idle.c:526)
[ 2680.435459] RSP: 0018:ffff88085612fe60  EFLAGS: 00000046
[ 2680.435461] RAX: 0000000000000020 RBX: 0000000000000008 RCX: 0000000000000001
[ 2680.435462] RDX: 0000000000000000 RSI: ffff88085612ffd8 RDI: 0000000000000007
[ 2680.435463] RBP: ffff88085612fe88 R08: 00000000008ec12b R09: 0000000027a96744
[ 2680.435465] R10: 0000079d4aaad6f8 R11: 0000000000000000 R12: 0000000000000020
[ 2680.435466] R13: 0000000000000003 R14: 0000000000000004 R15: 0000000000000000
[ 2680.435468] FS:  0000000000000000(0000) GS:ffff88087f3c0000(0000) knlGS:0000000000000000
[ 2680.435469] CS:  0010 DS: 0000 ES: 0000 CR0: 0000000080050033
[ 2680.435484] CR2: 00000000091ffde0 CR3: 0000000001a11000 CR4: 00000000001407e0
[ 2680.435485] Stack:
[ 2680.435486]  00000007814247ae ffff88087f3dc400 ffffffff81aa6a00 000002701479db0f
[ 2680.435489]  0000000000000004 ffff88085612feb8 ffffffff814247ca ffffffff81af9020
[ 2680.435492]  ffff88087f3dc400 0000000000000004 ffffffff81aa6a00 ffff88085612fec8
[ 2680.435495] Call Trace:
[ 2680.435498] cpuidle_enter_state (drivers/cpuidle/cpuidle.c:124)
[ 2680.435501] cpuidle_enter (drivers/cpuidle/cpuidle.c:189)
[ 2680.435504] cpu_startup_entry (kernel/sched/idle.c:159 kernel/sched/idle.c:224 kernel/sched/idle.c:272)
[ 2680.435507] start_secondary (arch/x86/kernel/smpboot.c:274)
[ 2680.435509] Code: 00 00 48 8d 86 38 c0 ff ff 48 89 d1 0f 01 c8 65 48 8b 04 25 88 c9 00 00 48 8b 80 38 c0 ff ff a8 08 75 08 b1 01 4c 89 e0 0f 01 c9 <65> 48 8b 04 25 88 c9 00 00 f0 80 a0 3a c0 ff ff df 0f ae f0 65
All code
========
   0:   00 00                   add    %al,(%rax)
   2:   48 8d 86 38 c0 ff ff    lea    -0x3fc8(%rsi),%rax
   9:   48 89 d1                mov    %rdx,%rcx
   c:   0f 01 c8                monitor %rax,%rcx,%rdx
   f:   65 48 8b 04 25 88 c9    mov    %gs:0xc988,%rax
  16:   00 00
  18:   48 8b 80 38 c0 ff ff    mov    -0x3fc8(%rax),%rax
  1f:   a8 08                   test   $0x8,%al
  21:   75 08                   jne    0x2b
  23:   b1 01                   mov    $0x1,%cl
  25:   4c 89 e0                mov    %r12,%rax
  28:   0f 01 c9                mwait  %rax,%rcx
  2b:   65 48 8b 04 25 88 c9    mov    %gs:*0xc988,%rax         <-- trapping instruction
  32:   00 00
  34:   f0 80 a0 3a c0 ff ff    lock andb $0xdf,-0x3fc6(%rax)
  3b:   df
  3c:   0f ae f0                mfence
  3f:   65                      gs

Code starting with the faulting instruction
===========================================
   0:   65 48 8b 04 25 88 c9    mov    %gs:0xc988,%rax
   7:   00 00
   9:   f0 80 a0 3a c0 ff ff    lock andb $0xdf,-0x3fc6(%rax)
  10:   df
  11:   0f ae f0                mfence
  14:   65                      gs

これは便利ですな( ´∀｀)bｸﾞｯ!