背景
社内で Linux マシンのとあるドライバの挙動がおかしいということで「ライブ crash で見たいなぁ」って呟いたら、「クラッシュって何？壊すの？」という反応が出て自分としてはカルチャーショックを受けたので、メモリダンプ解析の話を書いてみようと思いました。
色々と検索してみたところ、kdumpでメモリダンプ (世の中的にはクラッシュダンプと言う方が多い？) を採取する設定・手順についてはたくさんあるんですが、実際にその解析をどうやるのかって記事はあんまりないなぁと。パッと見つかったレベルだとこんな感じ。英文記事も探せば出てくるのだろうか。
- VA Linuxの「ダンプ解析講座」の記事は結構ちゃんと書いてる。
- O'Reillyの本 Debug Hacks -デバッグを極めるテクニック&ツール は結構ページ使って説明してる (役に立つかどうかは読み手次第)。
- ミラクル・リナックスのLinux crash dump 読み方入門 (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とカーネルスタックの配置がこういう作りになってるからなんですが、「おぉ〜、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 コマンドができることからメモリダンプ解析する時の考え方 (完全に個人的な見解ではありますが) などを書いていければなと思います。
・・・これ、いつ完結するんだろ。