読者です 読者をやめる 読者になる 読者になる

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)

このうち、上の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からやっていきます。

f:id:masami256:20151206202621p:plain

最初に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ツールです。

f:id:masami256:20151213145224p:plain

実行のログですが、たとえば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 ―パフォーマンス改善、開発効率向上、省電力化のためのテクニック

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