「crashdmesg」の仕組み 〜vmcoreからリングバッファ領域を取得する方法〜
前回公開した「crashdmesg」の仕組みを順を追ってご紹介します。
vmcoreを覗いてみる
kexec+kdumpを使って取得したvmcoreの解析には、gdbを拡張したcrashコマンドを利用します。
crashコマンドは、デバッグシンボル付きのカーネルを準備して、次のように実行します。
$ crash -s vmlinux.debug vmcore
ダンプの調査をする場合には、このままcrashコマンドを使って作業を進めるのですが、今回はvmcoreファイルそのものに注目してみます。
このvmcoreファイル、正体はELF形式のコアファイルです。
readelfコマンドを使うとELFフォーマットのヘッダに書かれた情報を表示できます。vmcoreをreadelfで開いてみると、次のような情報を見ることができます。
$ readelf -a vmcore
ELF Header:
Magic: 7f 45 4c 46 02 01 01 00 00 00 00 00 00 00 00 00
Class: ELF64
Data: 2's complement, little endian
Version: 1 (current)
OS/ABI: UNIX - System V
ABI Version: 0
Type: CORE (Core file)
Machine: Advanced Micro Devices X86-64
Version: 0x1
Entry point address: 0x0
Start of program headers: 64 (bytes into file)
Start of section headers: 0 (bytes into file)
Flags: 0x0
Size of this header: 64 (bytes)
Size of program headers: 56 (bytes)
Number of program headers: 5
Size of section headers: 0 (bytes)
Number of section headers: 0
Section header string table index: 0
There are no sections in this file.
There are no sections in this file.
Program Headers:
Type Offset VirtAddr PhysAddr
FileSiz MemSiz Flags Align
NOTE 0x0000000000000158 0x0000000000000000 0x0000000000000000
0x000000000000083c 0x000000000000083c 0
LOAD 0x0000000000000994 0xffffffff81000000 0x0000000001000000
0x0000000002125000 0x0000000002125000 RWE 0
LOAD 0x0000000002125994 0xffff880000000000 0x0000000000000000
0x00000000000a0000 0x00000000000a0000 RWE 0
LOAD 0x00000000021c5994 0xffff880000100000 0x0000000000100000
0x0000000018f00000 0x0000000018f00000 RWE 0
LOAD 0x000000001b0c5994 0xffff88001f000000 0x000000001f000000
0x0000000000ffd000 0x0000000000ffd000 RWE 0
There is no dynamic section in this file.
There are no relocations in this file.
There are no unwind sections in this file.
No version information found in this file.
Notes at offset 0x00000158 with length 0x0000083c:
Owner Data size Description
CORE 0x00000150 NT_PRSTATUS (prstatus structure)
CORE 0x00000150 NT_PRSTATUS (prstatus structure)
VMCOREINFO 0x0000055a Unknown note type: (0x00000000)
LOADセグメント内に、メモリ内容がダンプされています。
/proc/iomemやカーネルドキュメント(Documentation/x86/x86_64/mm.txt)と見比べてみると、カーネル本体がロードされている領域、メモリの先頭から640KBまでの領域、残りのメモリのうちセカンドカーネルが使用する領域を除いた部分に分割して格納されているようです。
ELFプログラムヘッダを解析すれば、各LOADセグメントがどの物理・仮想アドレスに対応するかと、vmcoreファイル中でのオフセット位置 がわかります。シンボル情報等から目的の値が格納されている仮想アドレスがわかれば、vmcoreから内容を取得することができそうです。
カーネルログ領域(リングバッファ)を探す
今回の目的である、カーネルのリングバッファ領域がどこにあるのか探してみましょう
リングバッファの定義や、アクセスする関数は kernel/printk.c に書かれています。
(以降のカーネルソースの引用で、行頭に書かれている行番号は、バージョン 2.6.37 時点での番号です。)
kernel/printk.c: 58 #define __LOG_BUF_LEN (1 << CONFIG_LOG_BUF_SHIFT) 146 static char __log_buf[__LOG_BUF_LEN]; 147 static char *log_buf = __log_buf; 148 static int log_buf_len = __LOG_BUF_LEN;
バッファのサイズはカーネルビルド時にCONFIG_LOG_BUF_SHIFTで指定します。
カーネル上でもlog_buf_len変数にバイト単位で格納されていて、バッファ本体はそのサイズ分の配列として__log_bufと定義されています。
バッファサイズlog_buf_lenとバッファ本体__log_buf(もしくはlog_buf)が分かればバッファ領域を取得することができそうです。
リングバッファが循環する仕組みを探る
運用中のサーバのカーネルメッセージをdmesgコマンドで表示したことがある人は、カーネルメッセージの量が多くなってくると古いログが消えていくのを見たことがあると思います。
カーネルメッセージは、リングバッファという仕組みで、一定のサイズ内で循環するように書きこむことで古いログを捨てながら保存されていきます。
この仕組を探ってみましょう。
kernel/printk.c:
109 #define LOG_BUF_MASK (log_buf_len-1)
110 #define LOG_BUF(idx) (log_buf[(idx) & LOG_BUF_MASK])
116 static unsigned log_start; /* Index into log_buf: next char to be read by syslog() */
117 static unsigned con_start; /* Index into log_buf: next char to be sent to consoles */
118 static unsigned log_end; /* Index into log_buf: most-recently-written-char + 1 */
149 static unsigned logged_chars; /* Number of chars produced since last read+clear operation */
548 static void emit_log_char(char c)
549 {
550 LOG_BUF(log_end) = c;
551 log_end++;
552 if (log_end - log_start > log_buf_len)
553 log_start = log_end - log_buf_len;
554 if (log_end - con_start > log_buf_len)
555 con_start = log_end - log_buf_len;
556 if (logged_chars < log_buf_len)
557 logged_chars++;
558 }
バッファへの書き込みを循環させるロジックのキモは、LOG_BUF(idx)というマクロです。
LOG_BUF(idx) マクロを使用してログメッセージを書きこむ際、単純に log_buf[idx] に書くのではなく、インデックスに log_buf_len - 1とのAND演算を行っています。
バッファサイズは、2のべき乗バイトに制限されているので、LOG_BUF_MASK はちょうど log_buf のインデックスの範囲(0 〜 log_buf_len-1)を選択するマスクになるため、バッファサイズを超えた部分の桁を無視することができます。
こうして、idx がバッファサイズを越えても、オーバーフローした桁を無視するので先頭に戻ってくるのです。
printk等からのバッファへの書き込みはemit_log_char()関数が使われますが、その中で特にバッファ領域のダンプに必要な情報として、log_endとlogged_charsが更新されます。
バッファに書きこむたびに、log_endは単純増加しますが、logged_charsはlog_buf_lenまで到達すると、それ以後の書き込みでは増えません。
実際に、バッファ領域をダンプするには、logged_charsの値をもとに、バッファがまだ一杯ではない状態と、バッファが一杯で循環して書き込まれている状態の2パターンを考える必要があります。
-
バッファが一杯でない場合：
バッファ領域の先頭から、logged_charsまでの範囲 -
バッファが一杯で循環書き込みしている場合：
前半(バッファ領域的には後半)部分、log_end & (log_buf_len - 1) から log_buf_len - 1 までの範囲と、
後半部分、バッファの先頭から log_end & (log_buf_len - 1) - 1までの範囲
シンボル情報を探す
log_buf、log_buf_len、logged_chars、log_endの4つの値が分かればリングバッファを正しい順序でダンプできそうなので、この4つの値が格納されている仮想アドレスを探してみましょう。
カーネルビルド時に生成されるSystem.mapからシンボル情報をさがす方法と、同様の情報をカーネル本体(vmlinux)から探す方法の2つを試してみます。
■ System.mapから探す方法
$ egrep " (log_buf|log_buf_len|logged_chars|log_end)$" /boot/System.map ffffffff82c16b60 d log_buf_len ffffffff82c16b68 d log_buf ffffffff82d2a080 d log_buf ffffffff82edb300 b log_end ffffffff82edb3e0 b logged_chars
■ vmlinuxをobjdumpする方法
$ objdump -t /boot/vmlinux |egrep " (log_buf|log_buf_len|logged_chars|log_end)$" ffffffff82c16b60 l O .data 0000000000000004 log_buf_len ffffffff82c16b68 l O .data 0000000000000008 log_buf ffffffff82edb300 l O .bss 0000000000000004 log_end ffffffff82edb3e0 l O .bss 0000000000000004 logged_chars ffffffff82d2a080 l O .data 0000000000000020 log_buf
(サイズの違うlog_bufが2個見つかっていますが、0xffffffff82d2a080にあるlog_bufはリングバッファとは無関係なネットワーク関連の構造体のようです。)
これで、各変数の格納されている仮想アドレスが判明したので、vmcore内でこの変数が格納されているLOADセグメントを探して読み出せば、リングバッファのダンプが可能になります。
VMCOREINFOからシンボル情報を取得する
リングバッファをダンプするのに必要な情報は集まりましたが、ダンプするにはSystem.mapかvmlinuxが必要です。
crashdmesgは、クラッシュカーネル上で実行することを前提に考えているので、クラッシュしたカーネルのSystem.mapやvmlinuxが読めるとは限りません。
ここで、先程、readelfで読み取ったvmcoreの情報を見直してみます。
NOTEセグメントの中に、VMCOREINFOという意味深なデータが入っています。
VMCOREINFO 0x0000055a Unknown note type: (0x00000000)
ダンプしてみると、このような内容で、CRASHTIMEを除き、"NAME=num\n"もしくは"TYPE(name)=num\n"という形式のテキストで、いくつかの情報が出力されています。
log_buf等の情報もばっちり記録されています。
VMCOREINFOの内容は、カーネルソースの各所からVMCOREINFO_SYMBOL(name)等のマクロを呼ぶことで記録しています。 ちなみに、CRASHTIMEの値だけは、panic関数から呼ばれるcrash_kexec関数の処理内で追記されるため、カーネルパニックが起こった時間の正確な記録として使えそうです。
crashdmesgでは、vmcoreのNOTEセグメントに保存されているVMCOREINFOのシンボル情報を利用することで、vmcoreファイル以外の追加情報を読み込むこと無く、リングバッファをダンプできるようになっています。
次回は、セカンドカーネル上でこのcrashdmesgを利用するためのinitramfsの作り方等をご紹介しようと思います。
