Linuxのメモリダンプ解析の話 (その1)

#背景
社内で Linux マシンのとあるドライバの挙動がおかしいということで「ライブ crash で見たいなぁ」って呟いたら、「クラッシュって何？壊すの？」という反応が出て自分としてはカルチャーショックを受けたので、メモリダンプ解析の話を書いてみようと思いました。

色々と検索してみたところ、kdumpでメモリダンプ (世の中的にはクラッシュダンプと言う方が多い？) を採取する設定・手順についてはたくさんあるんですが、実際にその解析をどうやるのかって記事はあんまりないなぁと。パッと見つかったレベルだとこんな感じ。英文記事も探せば出てくるのだろうか。

- [VA Linuxの「ダンプ解析講座」の記事](http://www.valinux.co.jp/technologylibrary/document/linuxkernel/dump0001/)は結構ちゃんと書いてる。
- O'Reillyの本 [Debug Hacks -デバッグを極めるテクニック&ツール](http://www.amazon.co.jp/Debug-Hacks-%E3%83%87%E3%83%90%E3%83%83%E3%82%B0%E3%82%92%E6%A5%B5%E3%82%81%E3%82%8B%E3%83%86%E3%82%AF%E3%83%8B%E3%83%83%E3%82%AF-%E3%83%84%E3%83%BC%E3%83%AB-%E5%90%89%E5%B2%A1/dp/4873114047) は結構ページ使って説明してる (役に立つかどうかは読み手次第)。
- [ミラクル・リナックスのLinux crash dump 読み方入門 (pdf)](https://users.miraclelinux.com/support/files/u1/OSC2008_Spring_dumpver1_1.pdf) にも一通り書いてくれてる。

「ちょっとメモリダンプ見てみたいな」と思う人がいても、本気で見る人は少ないんだなと痛感したんですが、それではあまりに勿体無い！ Linux カーネルの扉を開く第一歩がメモリダンプ解析ですよ！ (多分)

というわけで、家にある Ubuntu を入れたノートPCを使いながらメモリダンプ解析の仕方・考え方をちょろっと書いていきたいと思います。まぁ、Linux ディストリビューションならどれを使ってもさほどやることに変わりは無いでしょう。CoreOS とかになるとまた別ですが (本当は一番 CoreOS で crash したいけど)。

ただ、ここで書けるのは `crash` コマンドで何ができるかということがメインになります (できるだけ、`crash` 内のコマンドの使いどころは書いていきますが、カーネルの深淵を覗くわけではないので注意)。
理由は、メモリダンプ解析にセオリーがないからです。メモリダンプはある瞬間のメモリイメージを吸い出したスナップショットみたいなものなので、発生した現象の前後関係がわからないと障害を追いかけるときはかなり辛いんです。だから、「何かメモリダンプとれてんだけど見てくれる？」と言われると「嫌です」って言いたい (でも見なきゃならない（泣）)。つまり、どういうコンテキストでメモリダンプが取れたのか考慮しながら一つ一つ中身を見ていくしかなくて、どうすれば問題解決するかなんて書き尽くせないんですね。システム全体を把握してないと、ある１つのノードで起きた問題が解決できないっていうこともよくあります。
発生した問題のポイントがどの辺りにあるのか Linux カーネル内の情報を探り当てるために、メモリダンプ解析という手段と `crash` というツールがあるだけ、ということです。ですが、強力なツールであることは間違いありません。

前置きが長くなりましたが、以下に説明していきます。

#準備
インストールしておくものは以下の３つ
1. `dpkg`: Debian のパッケージマネージャ
2. `crash`: メモリダンプ解析用コマンド
3. デバッグシンボル付きのカーネルイメージ

`dpkg`, `crash` は `apt-get install` しましょう。たぶん、`dpkg` は Ubuntu に最初からインストールされてるのでやらなくていいかもしれませんが、`crash` は無いです。メモリダンプ解析なんて普通やりませんからね。

デバッグシンボル付きのカーネルイメージが入ったパッケージは、Ubuntuの場合以下のURIから探してダウンロードすればいいのかな？
http://ddebs.ubuntu.com/pool/main/l/linux/

自分のマシンのカーネル版数は `uname -a` コマンドで調べておいて、対応するdebパッケージ (いつの間にか拡張子が .ddeb になってることに驚きましたが) をダウンロードします。この場合は `linux-image-3.13.0-83-generic-dbgsym_3.13.0-83.127_i386.ddeb` でした。ファイルサイズは数百MBになりますのでディスク容量には少し気をつけてください。

```
$ uname -a
Linux localhost 3.13.0-83-generic #127-Ubuntu SMP Fri Mar 11 00:26:47 UTC 2016 i686 i686 i686 GNU/Linux
```

上記でダウンロードしたdebパッケージをインストールします。ファイルの展開場所は `/usr/lib/debug/boot` 配下らしいです。Debian系ディストリビューション以外なら違うのかも。ELF形式のファイルで、ちゃんと not stripped になってますね。この辺りは `gdb` のコア解析と同じ。

```
$ sudo dpkg -i linux-image-3.13.0-83-generic-dbgsym_3.13.0-83.127_i386.ddeb 
以前に未選択のパッケージ linux-image-3.13.0-83-generic-dbgsym を選択しています。
(データベースを読み込んでいます ... 現在 709471 個のファイルとディレクトリがインストールされています。)
linux-image-3.13.0-83-generic-dbgsym_3.13.0-83.127_i386.ddeb を展開する準備をしています ...
linux-image-3.13.0-83-generic-dbgsym (3.13.0-83.127) を展開しています...
linux-image-3.13.0-83-generic-dbgsym (3.13.0-83.127) を設定しています ...
$ ls -l /usr/lib/debug/boot/
合計 195264
-rw-r--r-- 1 root root 199947085  3月 11 11:05 vmlinux-3.13.0-83-generic
$ file /usr/lib/debug/boot/vmlinux-3.13.0-83-generic 
/usr/lib/debug/boot/vmlinux-3.13.0-83-generic: ELF 32-bit LSB  executable, Intel 80386, version 1 (SYSV), statically linked, BuildID[sha1]=87e79bf33837fa08f71042ba10696b58642b8ded, not stripped
```

#crashの起動
基本的にメモリダンプを採取してから解析するんですが、実は Linux を動かしている状態のマシンのメモリを見ることができます (最初に言ってたライブ crash のことですね）。PC立ち上げてほっておいてもメモリダンプなんて取れないので、ライブ crash してみましょう。

通常のメモリダンプ解析で気をつけないといけないのは、メモリダンプを採取したマシンと解析するマシン (`crash` コマンドを起動するマシン) のCPUアーキテクチャを同じにしないとダメな所。`crash` コマンドを自分でビルドする場合も注意ですね。なるべくディストリビューションが提供しているパッケージをダウンロードしたほうが面倒が少なくて良いでしょう (ライブ crash は当然そのマシンで動かすので気にしなくて良い)。

`crash` には色々とオプションがありますが、自分がよく使っているのは以下のような感じ。正確なオプションの意味を知るにはちゃんと help を見てください。

```
$ crash -e {vi|emacs} -S System.map vmlinux [dumpfile]
-e : crash上でのエディタ操作を vi 形式か emacs 形式かを選べる。このオプションをしてしなければデフォルトは vi 形式となる。
-S : カーネルが使用するシンボルテーブルが書いてある System.map を指定する (別に無くても起動はできる)。
vmlinux  : デバッグシンボル付きのカーネルイメージ。自作カーネルの場合は自分で用意する。
dumpfile : 採取したダンプファイル。これを指定しなければ現状のマシンのメモリを見るモードで起動 (ライブ crash) する。
```

ライブ crash の起動例は以下の通り。`sudo` をつけたのは `/dev/mem` にアクセスするため。なんか `/boot/System.map` の読み込みができてないなどのエラーがいくつか出てますが、放っておきましょう。`crash>` の後に続けてコマンドを打ち込んでいけば、メモリ上に乗っている各種情報を取り出せます。

```
$ sudo crash -e emacs -S /boot/System.map-3.13.0-83-generic /usr/lib/debug/boot/vmlinux-3.13.0-83-generic 
[sudo] password for user: 
crash: cannot open /boot/System.map

crash 7.0.3
Copyright (C) 2002-2013  Red Hat, Inc.
Copyright (C) 2004, 2005, 2006, 2010  IBM Corporation
Copyright (C) 1999-2006  Hewlett-Packard Co
Copyright (C) 2005, 2006, 2011, 2012  Fujitsu Limited
Copyright (C) 2006, 2007  VA Linux Systems Japan K.K.
Copyright (C) 2005, 2011  NEC Corporation
Copyright (C) 1999, 2002, 2007  Silicon Graphics, Inc.
Copyright (C) 1999, 2000, 2001, 2002  Mission Critical Linux, Inc.
This program is free software, covered by the GNU General Public License,
and you are welcome to change it and/or distribute copies of it under
certain conditions.  Enter "help copying" to see the conditions.
This program has absolutely no warranty.  Enter "help warranty" for details.
 
GNU gdb (GDB) 7.6
Copyright (C) 2013 Free Software Foundation, Inc.
License GPLv3+: GNU GPL version 3 or later <http://gnu.org/licenses/gpl.html>
This is free software: you are free to change and redistribute it.
There is NO WARRANTY, to the extent permitted by law.  Type "show copying"
and "show warranty" for details.
This GDB was configured as "i686-pc-linux-gnu"...

crash: read error: kernel virtual address: c1673080  type: "cpu_possible_mask"

crash: this kernel may be configured with CONFIG_STRICT_DEVMEM, which
       renders /dev/mem unusable as a live memory source.

crash: trying /proc/kcore as an alternative to /dev/mem

  SYSTEM MAP: /boot/System.map-3.13.0-83-generic
DEBUG KERNEL: /usr/lib/debug/boot/vmlinux-3.13.0-83-generic (3.13.0-83-generic)
    DUMPFILE: /proc/kcore
        CPUS: 4
        DATE: Sat Apr 23 13:27:44 2016
      UPTIME: 03:25:32
LOAD AVERAGE: 0.17, 0.16, 0.31
       TASKS: 459
    NODENAME: titan
     RELEASE: 3.13.0-83-generic
     VERSION: #127-Ubuntu SMP Fri Mar 11 00:26:47 UTC 2016
     MACHINE: i686  (2594 Mhz)
      MEMORY: 3.7 GB
         PID: 5851
     COMMAND: "crash"
        TASK: ed136800  [THREAD_INFO: f372c000]
         CPU: 3
       STATE: TASK_RUNNING (ACTIVE)

crash> 
```

最初に表示される情報で、パニック発生時刻 (DATE)、どのプロセスがどのCPUでパニック処理したのか (PID, COMMAND, TASK, CPU)、パニックメッセージを確認することが多いです。今回はライブ crash なのでパニックメッセージ無いですね。その他はマシン情報になってます。

#crashの操作
ちょろっと書くとか言いながらめちゃくちゃ長くなってますが、こっからが本番です (急遽、タイトルに「その1」とつけた)。間違ったこと書いてたり他にもこういう使い方あるよ、ってあれば是非教えていただきたいです。

##crash> help
とりあえず、ヘルプを見てみましょう。使えるコマンドが表示されます。

```
crash> help

*              files          mach           repeat         timer          
alias          foreach        mod            runq           tree           
ascii          fuser          mount          search         union          
bt             gdb            net            set            vm             
btop           help           p              sig            vtop           
dev            ipcs           ps             struct         waitq          
dis            irq            pte            swap           whatis         
eval           kmem           ptob           sym            wr             
exit           list           ptov           sys            q              
extend         log            rd             task           

crash version: 7.0.3    gdb version: 7.6
For help on any command above, enter "help <command>".
For help on input options, enter "help input".
For help on output options, enter "help output".

```

他にも各コマンドに対してヘルプを見るには、以下の通り。
`bt` は最もよく使うコマンドで、バックトレースを表示してくれるやつですね。後で説明します。
表示する情報が長いと `more` コマンドでパイプしてくれてるのか、良い感じで見れます。`more` が嫌だっていう人は、自分で `less` をパイプしてあげましょう。`crash` 内でも、シェル上で使えるコマンドが結構使えるので、色々試してみてください (使える使えないの分かれ道が未だにわかんないけど)。

```
crash> help bt
NAME
  bt - backtrace

SYNOPSIS
  bt [-a|-g|-r|-t|-T|-l|-e|-E|-f|-F|-o|-O] [-R ref] [-s [-x|d]] [-I ip] [-S sp]
     [pid | task]

DESCRIPTION
  Display a kernel stack backtrace.  If no arguments are given, the stack
  trace of the current context will be displayed.

       -a  displays the stack traces of the active task on each CPU.
・・・（省略）・・・
 -- MORE --  forward: <SPACE>, <ENTER> or j  backward: b or k  quit: q
```

```
crash> help bt | less
この場合は、less で見た感じでヘルプが見れる。
```


##crash> sys
`sys` は `crash` 起動時に表示した情報を出してくれます。どうやらカーネルコンフィグ設定も見れるらしいのですが、自分のPCだとなぜか見れませんでした。後でちゃんと調べないとな。

```
crash> sys
  SYSTEM MAP: /boot/System.map-3.13.0-83-generic
DEBUG KERNEL: /usr/lib/debug/boot/vmlinux-3.13.0-83-generic (3.13.0-83-generic)
    DUMPFILE: /proc/kcore
        CPUS: 4
        DATE: Sun Apr 24 00:17:36 2016
      UPTIME: 04:53:47
LOAD AVERAGE: 0.21, 0.18, 0.25
       TASKS: 491
    NODENAME: titan
     RELEASE: 3.13.0-83-generic
     VERSION: #127-Ubuntu SMP Fri Mar 11 00:26:47 UTC 2016
     MACHINE: i686  (2594 Mhz)
      MEMORY: 3.7 GB
crash> 
```

```
crash> sys config
sys: kernel_config_data does not exist in this kernel
```

`crash` 起動時に分かる情報と同じなので、これで何か新しい情報が分かるというわけではありませんが、忘れた頃にタスク数 (TASKS), CPU負荷 (LOAD AVERAGE) とか起動時間 (UPTIME) 見ながら、「やっぱりタスク数/負荷が異常じゃね？」とか「起動時間が短/長過ぎない？」とかみて問題切り分けの判断・確認で使うぐらいです。

たくさんメモリダンプが取れるうちに、「マシン起動からある一定の時間が経つとパニックしてるんだな」とか他の情報が集められるようになると、新たな観点でダンプ調査が進んだりもします。

##crash> bt
`bt` はバックトレースを見るコマンドで、当然使う場面が一番多い。バックトレースが見れると言ってもカーネル内のシーケンスだけで、ユーザスタックを表示してくれるわけではないです。プロセスID (PID) を引数に指定すると、以下のように表示してくれます。

```
crash> bt 1
PID: 1      TASK: f34d0000  CPU: 3   COMMAND: "init"
 #0 [f349fa28] __schedule at c165d593
 #1 [f349faac] schedule at c165d9de
 #2 [f349fab4] schedule_hrtimeout_range_clock at c165d0e0
 #3 [f349fb28] schedule_hrtimeout_range at c165d112
 #4 [f349fb34] poll_schedule_timeout at c118c022
 #5 [f349fb48] do_select at c118c8dd
 #6 [f349fe40] core_sys_select at c118cbd9
 #7 [f349ff78] sys_select at c118cd74
 #8 [f349ffb0] ia32_sysenter_target at c16681c6
    EAX: 0000008e  EBX: 0000001d  ECX: bf98d3b0  EDX: bf98d430 
    DS:  007b      ESI: bf98d4b0  ES:  007b      EDI: 00000000
    SS:  007b      ESP: bf98d340  EBP: b77670e8  GS:  0033
    CS:  0073      EIP: b7793428  ERR: 0000008e  EFLAGS: 00000246 
```

TASK は `struct task_struct` の先頭アドレス、CPU はそのプロセス (Linux カーネル内ではプロセスもスレッドも全部タスクとして扱うから、タスクと言う方が正しそう) が動く (予定の) CPU番号を示しています。`関数名 at` に続く16進数のアドレスは、次の関数を呼び出すアドレス、つまり、呼び出された側にとってのリターンアドレスとなります。

PID=1にはinitプロセスが割り当てられているので、そのバックトレースが出てますね。#0 が一番最後の呼び出した関数で、数字がインクリメントするほど前に呼び出した関数になってます。上記だと、システムコールのエントリーポイントである `ia32_sysenter_target` が呼び出されて select システムコール (カーネル内の関数では `sys_select`) を呼び出した延長でスリープに入った (`schedule` 関数に入ってタスクスケジュール待ち) ことがわかります。
一番下に表示されているレジスタ達は、たぶん (割り込み) スタックとして積まれた値ですかね (最近のx86のシステムコール呼び出しはソフトウェア割り込みじゃなくなってんだよなぁ、ちゃんとx86のアーキ仕様も勉強しないと(汗))。

バックトレースの関数呼び出し毎のスタック情報を見たいとか、生情報を見たいときは -f/-r オプションを使います。関数呼び出しで本当に正しい引数が入ってたのか調べたり、スタック破壊起きてないかを調べるときに使ってます。どのアドレスが引数なんだ、みたいなことはまた今度。

```
crash> bt -f 1
PID: 1      TASK: f34d0000  CPU: 2   COMMAND: "init"
 #0 [f349fa28] __schedule at c165d593
    [RA: c165d9e3  SP: f349fa28  FP: f349faac  SIZE: 136]
    f349fa28: f349faa8  00000082  c1086a5d  f7bae370  
    f349fa38: 00000000  c1a9e300  a3031702  00001676  
    f349fa48: c1a9e300  f2fa9a00  f34d0000  f7ba0300  
    f349fa58: 00000000  00000000  00000000  00001648  
    f349fa68: 0000c000  00000000  0337f980  00000000  
    f349fa78: 0337f980  00000000  f6803800  00001649  
    f349fa88: ffffffff  ffffffff  f7bae348  f7bae348  
    f349fa98: 00000000  00000000  00000000  00000000  
    f349faa8: f349fab0  c165d9e3  
 #1 [f349faac] schedule at c165d9de
    [RA: c165d0e5  SP: f349fab0  FP: f349fab4  SIZE: 8]
    f349fab0: f349fb24  c165d0e5  
 #2 [f349fab4] schedule_hrtimeout_range_clock at c165d0e0
    [RA: c165d117  SP: f349fab8  FP: f349fb28  SIZE: 116]
    f349fab8: ee0e2200  eb780d00  f349fae4  c108a898  
    f349fac8: f7bae300  00000000  00000246  ee242b78  
    f349fad8: 00000246  ee242b78  f349faf4  c1091535  
    f349fae8: f36966c0  ee242b78  00000000  f349fb0c  
    f349faf8: c118bf9c  f349fb04  c13d54b9  f349fb0c  
    f349fb08: c13d15f4  f349fb28  c13cf7d9  e54116af  
    f349fb18: f349fbd4  f34d0000  00000000  f349fb30  
    f349fb28: c165d117  
・・・（省略）・・・
```

```
crash> bt -r 1
PID: 1      TASK: f34d0000  CPU: 2   COMMAND: "init"
f349e000:  f34d0000 default_exec_domain 00000000 00000000 
f349e010:  00000002 80000000 c0000000 do_no_restart_syscall 
f349e020:  00000000 00000000 00000000 00000000 
f349e030:  00000000 00000000 00000000 b7793428 
f349e040:  00000000 00000000 57ac6e9d 4c331e87 
f349e050:  507d71f1 c4d848bb 676ea14f 31ea2466 
f349e060:  25e3b88c 34efdb94 991c81da d34e157f 
f349e070:  dba691f4 2c137e8f 7890f4f3 ddb9bea1 
・・・（省略）・・・
f349ff70:  bf98d4b0 f349ffac sys_select+137 bf98d4b0 
f349ff80:  00000000 0000001d bf98d3b0 bf98d430 
f349ff90:  __close_fd+119 f34e0040 00000010 bf98d030 
f349ffa0:  0000001d bf98d4b0 00000000 f349e000 
f349ffb0:  sysenter_after_call 0000001d bf98d3b0 bf98d430 
f349ffc0:  bf98d4b0 00000000 b77670e8 0000008e 
f349ffd0:  0000007b 0000007b 00000000 00000033 
f349ffe0:  0000008e b7793428 00000073 00000246 
f349fff0:  bf98d340 0000007b 8441e759 ad0bb5cd 
```

`bt -r` で表示した情報から面白いことがわかります。表示されたスタックの開始アドレスが 0xf349e000 で、終了が 0x349fff0 + 0x10 = 0x34a0000 となってて、ちょうど 8KiB サイズとなっていますが、これはなんでだと。
正解から言うと、[Linux2.6系のtask_structとカーネルスタックの配置がこういう作りになってるから](http://www.kerneldesign.info/wiki/index.php?current_thread_info()%2Flinux2.6)なんですが、「おぉ〜、Linux-3.13 でも2.6系の作りが残ってるんだ！ いい設計(?)なんだな。」となんとなく思うわけです。

ちなみに、後で説明するコマンド `task` を使うと、あるタスクのカーネルスタック開始位置はすぐわかります。
`task_struct` 構造体のメンバ変数 `stack` ですね。ちゃんと、0xf349e000 になってます。

```
crash> task 1 | head
PID: 1      TASK: f34d0000  CPU: 0   COMMAND: "init"
struct task_struct {
  state = 1, 
  stack = 0xf349e000, 
  usage = {
    counter = 2
  }, 
  flags = 4219136, 
  ptrace = 0, 
  wake_entry = {
crash> 
```

`stack` が `thread_info` 構造体の開始アドレスなので、`struct` コマンドで中身が見れます。当然ですが、`bt -r` で確認した生のスタック情報と一致してます。

```
crash> struct thread_info 0xf349e000 | cat
struct thread_info {
  task = 0xf34d0000, 
  exec_domain = 0xc193c980 <default_exec_domain>, 
  flags = 0, 
  status = 0, 
  cpu = 0, 
  saved_preempt_count = -2147483648, 
  addr_limit = {
    seg = 3221225472
  }, 
  restart_block = {
    fn = 0xc1067ce0 <do_no_restart_syscall>, 
    {
      futex = {
        uaddr = 0x0, 
        val = 0, 
        flags = 0, 
        bitset = 0, 
        time = 0, 
        uaddr2 = 0x0
      }, 
      nanosleep = {
        clockid = 0, 
        rmtp = 0x0, 
        expires = 0
      }, 
      poll = {
        ufds = 0x0, 
        nfds = 0, 
        has_timeout = 0, 
        tv_sec = 0, 
        tv_nsec = 0
      }
    }
  }, 
  sysenter_return = 0xb7793428, 
  previous_esp = 0, 
  supervisor_stack = 0xf349e044 "", 
  sig_on_uaccess_error = 0, 
  uaccess_err = 0
}
crash> 
```

これで、カーネルスタックが異常に伸びたら `thread_info` 構造体の情報をつぶすなとか、スタックが 4KiB じゃスタック足らない場合が多くて 8KiB でいこう、ってことになったんじゃないかという設計の変遷も思い巡らすことができるわけですね (正しい推測なのかは不明)。

`bt` コマンドはもっとたくさんオプションがあるんですが、他はそんなに使った記憶がないので関数の呼び出し関係とスタック情報さえ見れればいいのかなと思います。

こんな感じで、`crash` コマンドができることからメモリダンプ解析する時の考え方 (完全に個人的な見解ではありますが) などを書いていければなと思います。
・・・これ、いつ完結するんだろ。