Linuxカーネルのデバッグでprintk(9)デバッグを卒業したいっ！

この記事はLinux Advent Calendar 2015の25日目の記事です。 Linuxカーネルのデバッグである意味一番手軽なのがprintk(9)によるデバッグだと思うんですが（ユーザランドのプログラムで言うところのprintf(3)デバッグ）、この場合h速いCPUを積んだマシンならビルドはすぐに終わるけど、カーネルを変えている以上は再起動はしないといけないし、ちょっと手間ですよね。ということで、printk(9)によるデバッグはそろそろ卒業しようというのがテーマです。 ちなみに、printk(KERN_INFO"foobar\n")よりもpr_info("foobar\n")のほうがお手軽です。pr_で始まるマクロがinclude/linux/printk.hに定義されています。

Linuxのデバッグをするための方法としても下記のようなものがあります（kmemleakとかlockdep等は省略m( )m）

• gdb
• kgdb
• crash
• ftrace (便利ツールとしてtrace-cmd)
• kprobe (便利ツールとしてsystemtap)
• perf

このうち、上の3個はいわゆるデバッガです。今回はftraceとkprobeというか、trace-cmdとsystemtap、それとperfを使いたいと思います。 今回はprintk(9)を卒業したいというのがテーマなので、printk(9)で変数を表示したり、WARN_ON()でスタックトレースを取ったりというのをtrace-cmdとsystemtapで行いたいと思います。

まず、前提条件としてカーネルのデバッグをするのでデバッグ情報が必要です。例えばFedora系のディストリビューションならkernel-debuginfoパッケージが必要になります。

masami@saga:~$ rpm -qa | grep debuginfo
kernel-debuginfo-common-x86_64-4.2.7-300.fc23.x86_64
kernel-debuginfo-4.2.7-300.fc23.x86_64

自分でカーネルをビルドしている場合はCONFIG_DEBUG_KERNELがyになってるのは最低限で、あとCONFIG_DEBUG_INFOをyにするとデバッグ情報付きでビルドになります（gcc -g）。他にはftrace、kprobe関連の設定も入れましょう。 ftrace、kprobeとかの設定はディストリビューションのconfigを元にすれば大抵は問題ないと思います。

では、まずはsystemtapからやっていきます。

最初にsystemtap関連ツールのインストールですが、デバッグ対象のカーネルがディストリビューションのカーネルならディストリビューションに含まれているsystemtapパッケージとデバッグ用のパッケージ（をインストールすれば問題無いと思います。 うちはディストリビューションはfedoraでカーネルは自前でビルドという環境でやろうとしたら、systemtapのスクリプトのコンパイルで失敗したのでsystemtapのgitリポジトリからcodeをcloneして自前でビルドしました。

そして、実際のスクリプト。例えば、trace_testというプログラムがkmallocを呼んだ時にallocateするサイズ（kmallocのsize引数）を表示してからスタックトレースを1回だけ取るのはこんな感じ。

#!/usr/bin/env stap

probe begin {
        printf("Waiting for test program runs...\n")
}

probe kernel.function("__kmalloc") {
        if (execname() == "trace_test") {
                printf("comm %s: allocate size %d\n", execname(), $size)
                print_backtrace()
                exit()
        }
}

probe end {
        printf("Done\n")
}

実行結果はこうなります。「Waiting for test program runs...」が出たら別の端末なりからtrace_testコマンドを実行するとif文の条件に合致してallocateするサイズとスタックトレースを表示して終了してます。exit()を入れなければctrl-cで止めるまでスタックトーレスを取ります。

root@saga:/home/masami# stap -v ./stacktrace.stp
Pass 1: parsed user script and 111 library script(s) using 170232virt/36436res/4940shr/31960data kb, in 90usr/10sys/95real ms.
Pass 2: analyzed script: 3 probe(s), 4 function(s), 3 embed(s), 0 global(s) using 214232virt/82260res/6416shr/75952data kb, in 510usr/210sys/717real ms.
Pass 3: translated to C into "/tmp/stap4YpMXX/stap_d551a4e9d354d09c1ba479f400118f6b_3634_src.c" using 214232virt/82556res/6608shr/75952data kb, in 220usr/0sys/225real ms.
Pass 4: compiled C into "stap_d551a4e9d354d09c1ba479f400118f6b_3634.ko" in 11590usr/1580sys/12270real ms.
Pass 5: starting run.
Waiting for test program runs...
comm trace_test: allocate size 504
 0xffffffff812054a0 : __kmalloc+0x0/0x240 [kernel]
 0xffffffff812785f4 : load_elf_phdrs+0x64/0x90 [kernel]
 0xffffffff812788f0 : load_elf_binary+0x120/0x1710 [kernel]
 0xffffffff8122950e : search_binary_handler+0x9e/0x1d0 [kernel]
 0xffffffff8122ab2e : do_execveat_common.isra.33+0x51e/0x6e0 [kernel]
 0xffffffff8122af8a : sys_execve+0x3a/0x50 [kernel]
 0xffffffff817827d5 : return_from_execve+0x0/0x23 [kernel]
 0xffffffff8178252e : entry_SYSCALL_64_fastpath+0x12/0x71 [kernel] (inexact)
Done
Pass 5: run completed in 10usr/80sys/11941real ms.

(´-`).oO(単純なprintkデバッグだったらsystemtapを使うほうが断然お手軽ですね〜

それでは次にtrace-cmdを使う場合を。

こちらも同じくkmallocを対象としてます。trace_testというコマンド実行中のkmalloc呼び出しをトレースします。trace-cmdはftraceを使いやすくするためのものなので、できることはftrace＋αという感じです。

root@saga:/home/masami# trace-cmd record -p function_graph -e 'kmem:kmalloc' -F ./trace_test

trace_testはこんなプログラムです。

#include <stdio.h>
#include <unistd.h>
#include <stdlib.h>
#include <sys/types.h>
#include <sys/wait.h>

int main(int argc, char **argv)
{
        pid_t pid;

        pid = fork();

        if (pid > 0) {
                waitpid(pid, NULL, 0);
                printf("parent done\n");
        } else if (!pid) {
                execl("/bin/ls", "-la", NULL);
                _exit(0);
        } else {
                printf("error\n");
        }
        return 0;

}

実行が終わるとカレントディレクトリにtrace.datというファイルができてますので、下記のコマンドを実行すると結果が一気に表示されます。なのでpipeでlessとかのページャに渡したほうが良いです。

trace-cmd report

結果を見るためのツールとしてkernelsharkというものもあります。こちらはGUIのツールです。

実行のログですが、たとえばexecveシステムコールが2箇所あります。2個めのほうはforkしてからのexecのところですね。

      trace_test-10075 [006]  5276.631917: funcgraph_entry:                   |  SyS_execve() {
      trace_test-10075 [006]  5276.631917: funcgraph_entry:                   |    getname() {
      trace_test-10075 [006]  5276.631918: funcgraph_entry:                   |      getname_flags() {
      trace_test-10075 [006]  5276.631918: funcgraph_entry:                   |        kmem_cache_alloc() {
      trace_test-10075 [006]  5276.631918: funcgraph_entry:        0.065 us   |          _cond_resched();
      trace_test-10075 [006]  5276.631919: funcgraph_exit:         0.661 us   |        }
      trace_test-10075 [006]  5276.631919: funcgraph_exit:         1.262 us   |      }
      trace_test-10075 [006]  5276.631919: funcgraph_exit:         1.812 us   |    }
      trace_test-10075 [006]  5276.631920: funcgraph_entry:                   |    do_execveat_common.isra.33() {
      trace_test-10075 [006]  5276.631920: funcgraph_entry:                   |      unshare_files() {
      trace_test-10075 [006]  5276.631920: funcgraph_entry:        0.135 us   |        unshare_fd();
      trace_test-10075 [006]  5276.631921: funcgraph_exit:         0.803 us   |      }
      trace_test-10075 [006]  5276.631921: funcgraph_entry:                   |      kmem_cache_alloc_trace() {
      trace_test-10075 [006]  5276.631922: funcgraph_entry:        0.058 us   |        _cond_resched();
      trace_test-10075 [006]  5276.631922: funcgraph_entry:                   |        __slab_alloc() {
      trace_test-10075 [006]  5276.631922: funcgraph_entry:        0.243 us   |          ___slab_alloc();
      trace_test-10075 [006]  5276.631923: funcgraph_exit:         0.778 us   |        }
      trace_test-10075 [006]  5276.631923: kmalloc:              (return_to_handler+0x0) [FAILED TO PARSE] call_site=0xffffffff81784ef8 ptr=0xffff881024c4f000 bytes_req=240 bytes_alloc=256 gfp_flags=37781696
      trace_test-10075 [006]  5276.631925: funcgraph_exit:         3.016 us   |      }

~~~
              ls-10076 [003]  5276.649259: funcgraph_entry:                   |  SyS_execve() {
              ls-10076 [003]  5276.649260: funcgraph_entry:                   |    getname() {
              ls-10076 [003]  5276.649260: funcgraph_entry:                   |      getname_flags() {
              ls-10076 [003]  5276.649261: funcgraph_entry:                   |        kmem_cache_alloc() {
              ls-10076 [003]  5276.649261: funcgraph_entry:        0.044 us   |          _cond_resched();
              ls-10076 [003]  5276.649262: funcgraph_exit:         0.566 us   |        }
              ls-10076 [003]  5276.649262: funcgraph_exit:         1.342 us   |      }
              ls-10076 [003]  5276.649262: funcgraph_exit:         1.773 us   |    }
              ls-10076 [003]  5276.649262: funcgraph_entry:                   |    do_execveat_common.isra.33() {
              ls-10076 [003]  5276.649263: funcgraph_entry:                   |      unshare_files() {
              ls-10076 [003]  5276.649263: funcgraph_entry:        0.185 us   |        unshare_fd();
              ls-10076 [003]  5276.649264: funcgraph_exit:         0.651 us   |      }
              ls-10076 [003]  5276.649264: funcgraph_entry:                   |      kmem_cache_alloc_trace() {
              ls-10076 [003]  5276.649264: funcgraph_entry:        0.044 us   |        _cond_resched();
              ls-10076 [003]  5276.649265: funcgraph_entry:                   |        __slab_alloc() {
              ls-10076 [003]  5276.649265: funcgraph_entry:        0.276 us   |          ___slab_alloc();
              ls-10076 [003]  5276.649265: funcgraph_exit:         0.723 us   |        }
              ls-10076 [003]  5276.649267: funcgraph_exit:         3.135 us   |      }
 

do_execveat_common()の場合はdo_execveat_common()が呼ばれて、次にunshare_files() -> unshare_fd()と来て、元のdo_execveat_common()に戻ってからkmalloc()が呼ばれています。 これをソースで確認するとこのようになっています。

1481 /*
1482  * sys_execve() executes a new program.
1483  */
1484 static int do_execveat_common(int fd, struct filename *filename,
1485                               struct user_arg_ptr argv,
1486                               struct user_arg_ptr envp,
1487                               int flags)
1488 {
〜〜〜〜
1509 
1510         /* We're below the limit (still or again), so we don't want to make
1511          * further execve() calls fail. */
1512         current->flags &= ~PF_NPROC_EXCEEDED;
1513 
1514         retval = unshare_files(&displaced);
1515         if (retval)
1516                 goto out_ret;
1517 
1518         retval = -ENOMEM;
1519         bprm = kzalloc(sizeof(*bprm), GFP_KERNEL);
1520         if (!bprm)
1521                 goto out_files;
1522 
1523 

do_execveat_common()はsys_execve()の流れで呼ばれるので、 ログのインデント的にもSyS_execve() {の中にあります。

最後にperfを。これもkmallocを対象にして、size引数を見てみたいと思います。

__kmalloc()の5行目のところにイベントを追加します。まずはソースの確認。

root@saga:/home/masami# perf probe --line '__kmalloc'
<__kmalloc@/home/masami/linux-kernel/mm/slub.c:0>
      0  void *__kmalloc(size_t size, gfp_t flags)
      1  {
                struct kmem_cache *s;
                void *ret;

      5         if (unlikely(size > KMALLOC_MAX_CACHE_SIZE))
      6                 return kmalloc_large(size, flags);

      8         s = kmalloc_slab(size, flags);

     10         if (unlikely(ZERO_OR_NULL_PTR(s)))
     11                 return s;

     13         ret = slab_alloc(s, flags, _RET_IP_);

     15         trace_kmalloc(_RET_IP_, ret, size, s->size, flags);

                kasan_kmalloc(s, ret, size);

                return ret;
     20  }
         EXPORT_SYMBOL(__kmalloc);

         #ifdef CONFIG_NUMA

イベントの追加。実行すると最後にこんなふうにperf recordを実行してねと出てくるので、そんな感じで実行します。

root@saga:/home/masami# perf probe --add '__kmalloc:5 size:u64'
Added new event:
  probe:__kmalloc      (on __kmalloc:5 with size:u64)

You can now use it in all perf tools, such as:

        perf record -e probe:__kmalloc -aR sleep 1

実行するのはいつも通りにtrace_test。

root@saga:/home/masami# perf record -e probe:__kmalloc -aR ./trace_test
~~~
[ perf record: Woken up 1 times to write data ]
[ perf record: Captured and wrote 1.411 MB perf.data (75 samples) ]

perf reportでログを確認するとこのように見ることができます。

__probe_ip=18446744071580964028 common_callchain=[] common_comm=perf common_cpu=8 common_ns=876723001 common_pid=1424 common_s=8445 size_u64=504                                                                    
__probe_ip=18446744071580964028 common_callchain=[] common_comm=perf common_cpu=8 common_ns=876727478 common_pid=1424 common_s=8445 size_u64=28                                                                     
__probe_ip=18446744071580964028 common_callchain=[] common_comm=perf common_cpu=8 common_ns=876742561 common_pid=1424 common_s=8445 size_u64=392
__probe_ip=18446744071580964028 common_callchain=[] common_comm=trace_test common_cpu=10 common_ns=877638834 common_pid=1425 common_s=8445 size_u64=504
__probe_ip=18446744071580964028 common_callchain=[] common_comm=trace_test common_cpu=10 common_ns=877642797 common_pid=1425 common_s=8445 size_u64=28 
__probe_ip=18446744071580964028 common_callchain=[] common_comm=trace_test common_cpu=10 common_ns=877655800 common_pid=1425 common_s=8445 size_u64=392
__probe_ip=18446744071580964028 common_callchain=[] common_comm=ls common_cpu=10 common_ns=878675718 common_pid=1425 common_s=8445 size_u64=30
__probe_ip=18446744071580964028 common_callchain=[] common_comm=ls common_cpu=10 common_ns=878716854 common_pid=1425 common_s=8445 size_u64=30
__probe_ip=18446744071580964028 common_callchain=[] common_comm=ls common_cpu=10 common_ns=878906619 common_pid=1425 common_s=8445 size_u64=50
__probe_ip=18446744071580964028 common_callchain=[] common_comm=ls common_cpu=10 common_ns=878909163 common_pid=1425 common_s=8445 size_u64=51 

printk(9)デバッグではなくsystemtap、trace-cmd、perfを使ったデバッグ方法を見てきました。

Linuxカーネル Hacks ―パフォーマンス改善、開発効率向上、省電力化のためのテクニック