crash コマンドによる vmcore 解析の入門（の入門）

はじめに

crash コマンドを使った Linux kernel の vmcore の解析方法についてまとめて見ました。
検証に使った OS は、CentOS 6 です。

crash コマンドとは

vmcore の解析に使うデバッグ用のツールです。gdb のコマンドが（そのままだいたい）使えます。
詳しくはググってください。

vmcore の取得方法

kdump がセットアップしてあれば、kernel がクラッシュしたときには自動で vmcore を保存できます。保存先は、ローカルディスクや NFS、SSH でのリモートホストなどいろいろ設定できます。

# chkconfig kdump on
# service kdump restart

vmcore 取得のためには、OS をクラッシュさせる必要があります。OS がクラッシュするトリガーは色々設定できますが、ここでは以下の状況でクラッシュさせるように設定します。

• /etc/sysctl.conf

（以下の設定を追加すると、hung_task が発生した際に、OS をクラッシュさせます。）
kernel.hung_task_panic = 1

（以下の設定を追加すると、OOM が発生した際に、OS をクラッシュさせます。）
vm.panic_on_oom = 1

（以下の設定を追加すると、softlockup が発生した際に、OS をクラッシュさせます。）
kernel.softlockup_panic = 1

以下のコマンドで設定を反映させます。

# sysctl -p

インストール

開発系のツール一式は入れておきます。

# yum groupinstall "Development Tools"

以下でテスト用にデバイスドライバなどを作成するのでそれに必要なパッケージもインストールしておきます。

# yum install yum-utils kernel-devel kernel-headers

crash コマンドをインストールします。

# yum install crash

crash コマンドでコア解析するには、kernel のデバッグパッケージも必要なのでインストールしておきます。

# debuginfo-install kernel

デバイスドライバの作成

テスト用にわざとハングするデバイスドライバを作成します。

• devone.c

/*
 * devone.c
 *
 */
#include <linux/init.h>
#include <linux/module.h>
#include <linux/types.h>
#include <linux/kernel.h>
#include <linux/fs.h>
#include <linux/cdev.h>
#include <asm/uaccess.h>

MODULE_LICENSE("Dual BSD/GPL");

static int devone_devs = 1;        /* device count */
static int devone_major = 0;       /* dynamic allocation */
static int devone_minor = 0;       
static struct cdev devone_cdev;  

ssize_t devone_read(struct file *filp, char __user *buf, size_t count, loff_t *f_pos)
{
	int i;
	unsigned char val = 0xff;
	int retval;

	msleep(180000);         /* わざと 180秒スリープする */

	for (i = 0 ; i < count ; i++) {
		if (copy_to_user(&buf[i], &val, 1)) {
			retval = -EFAULT;
			goto out;
		}
	}

	retval = count;
out:
	return (retval);
}

struct file_operations devone_fops = {
	.read = devone_read,
};

static int devone_init(void)
{
	dev_t dev = MKDEV(devone_major, 0);
	int alloc_ret = 0;
	int major;
	int cdev_err = 0;

	alloc_ret = alloc_chrdev_region(&dev, 0, devone_devs, "devone");
	if (alloc_ret)
		goto error;
	devone_major = major = MAJOR(dev);

	cdev_init(&devone_cdev, &devone_fops);
	devone_cdev.owner = THIS_MODULE;
	devone_cdev.ops = &devone_fops;
	cdev_err = cdev_add(&devone_cdev, MKDEV(devone_major, devone_minor), 1);
	if (cdev_err) 
		goto error;

	printk(KERN_ALERT "devone driver(major %d) installed.\n", major);

	return 0;

error:
	if (cdev_err == 0)
		cdev_del(&devone_cdev);

	if (alloc_ret == 0)
		unregister_chrdev_region(dev, devone_devs);

	return -1;
}

static void devone_exit(void)
{
	dev_t dev = MKDEV(devone_major, 0);

	cdev_del(&devone_cdev);
	unregister_chrdev_region(dev, devone_devs);

	printk(KERN_ALERT "devone driver removed.\n");

}

module_init(devone_init);
module_exit(devone_exit);

• Makefile

obj-m := devone.o

all:
	make -C /lib/modules/$(shell uname -r)/build M=$(PWD) modules

clean:
	make -C /lib/modules/$(shell uname -r)/build M=$(PWD) clean

コンパイルしてデバイスを作成します。

# make
（devone.ko ができあがります。）

# insmod devone.ko
（できあがった kernel モジュールをインストールします。）

# lsmod | grep devone

# grep devone /proc/devices 
（devone のメジャー番号を確認します。例 247 ）

# mknod /dev/devone c 247 0
（デバイスファイルを作成します。）

# ls -l /dev/devone

これで、/dev/devone ファイルを読み込もうとすると 180秒間ハングします。

OS をクラッシュさせる

プロセスをハングさせる

わざと、/dev/devone を読み込んで hung_task を発生させます。

# dd if=/dev/devone of=/dev/null count=1 bs=1

hung_task が発生して、OS がクラッシュして、vmcore ができあがりました。デフォルトの設定のままですので、「/var/crash」以下にできあがります。

# ls -l /var/crash/

OOM を発生させる

適当な perl スクリプトなどでメモリを徐々にかつ大量に消費させます。

• test.pl

#!/usr/bin/perl

use strict;

my $i;
while(1){
	$i .= "a"x10000000;
}

OOM が発生して、OS がクラッシュして、vmcore ができあがりました。

# ls -l /var/crash/

---

vmcore 解析

hung_task の場合

「crash バイナリ vmcore」を実行して、crash を起動する。

# cd /var/crash/127.0.0.1-2015-12-20-17:24:43/
# crash /usr/lib/debug/lib/modules/2.6.32-573.12.1.el6.x86_64/vmlinux  vmcore

sys コマンドで、システム関連の情報を表示。panic のメッセージも見れる。

crash> sys
      KERNEL: /usr/lib/debug/lib/modules/2.6.32-573.12.1.el6.x86_64/vmlinux
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 3
        DATE: Sun Dec 20 17:24:40 2015
      UPTIME: 00:03:12
LOAD AVERAGE: 0.62, 0.19, 0.06
       TASKS: 120
    NODENAME: centos6a.kinoshiy
     RELEASE: 2.6.32-573.12.1.el6.x86_64
     VERSION: #1 SMP Tue Dec 15 21:19:08 UTC 2015
     MACHINE: x86_64  (997 Mhz)
      MEMORY: 2 GB
       PANIC: "Kernel panic - not syncing: hung_task: blocked tasks"

hung_task が原因だとわかる。

log コマンドで、kernel のメッセージバッファーの内容を表示する。

crash> log
... snip ...
INFO: task dd:1521 blocked for more than 120 seconds.
      Not tainted 2.6.32-573.12.1.el6.x86_64 #1
"echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
dd            D 0000000000000002     0  1521   1449 0x00000080
 ffff880078e3fdd8 0000000000000082 0000000000000000 ffff88007e560108
 ffff880078e3fd88 ffffffff8118ecf7 000000208c45c069 ffff880037434880
 ffff880037b696c0 00000000fffd8e34 ffff880037783ad8 ffff880078e3ffd8
Call Trace:
 [<ffffffff8118ecf7>] ? __dentry_open+0x257/0x380
 [<ffffffff815397b2>] schedule_timeout+0x192/0x2e0
 [<ffffffff81089be0>] ? process_timeout+0x0/0x10
 [<ffffffff8153991e>] schedule_timeout_uninterruptible+0x1e/0x20
 [<ffffffff8108bd40>] msleep+0x20/0x30
 [<ffffffffa0312148>] devone_read+0x28/0x90 [devone]
 [<ffffffff81191abd>] ? rw_verify_area+0x5d/0xc0
 [<ffffffff81192315>] vfs_read+0xb5/0x1a0
 [<ffffffff811930c6>] ? fget_light_pos+0x16/0x50
 [<ffffffff81192661>] sys_read+0x51/0xb0
 [<ffffffff8100b0d2>] system_call_fastpath+0x16/0x1b
Kernel panic - not syncing: hung_task: blocked tasks
Pid: 58, comm: khungtaskd Not tainted 2.6.32-573.12.1.el6.x86_64 #1
Call Trace:
 [<ffffffff81538231>] ? panic+0xa7/0x16f
 [<ffffffff810ecd34>] ? watchdog+0x254/0x290
 [<ffffffff810ecae0>] ? watchdog+0x0/0x290
 [<ffffffff810a0fce>] ? kthread+0x9e/0xc0
 [<ffffffff8100c28a>] ? child_rip+0xa/0x20
 [<ffffffff810a0f30>] ? kthread+0x0/0xc0
 [<ffffffff8100c280>] ? child_rip+0x0/0x20

PID 1521 の dd コマンドがハングしていたのがわかる。
devone モジュール内でハングしているのがわかる。

ps コマンドでプロセスの状況を確認。 「UN」（uninterruptible）の状態だったとわかる。

crash> ps 1521
   PID    PPID  CPU       TASK        ST  %MEM     VSZ    RSS  COMM
   1521   1449   2  ffff880037783520  UN   0.0  105176    720  dd

set コマンドで、カレントコンテクストを任意のプロセスに切り替え、files コマンドでそのプロセスがオープンしているファイルを確認します。

crash> set 1521
    PID: 1521
COMMAND: "dd"
   TASK: ffff880037783520  [THREAD_INFO: ffff880078e3c000]
    CPU: 2
  STATE: TASK_UNINTERRUPTIBLE 
crash> files
PID: 1521   TASK: ffff880037783520  CPU: 2   COMMAND: "dd"
ROOT: /    CWD: /root/git/samples/kernel/devone-cdev_add
 FD       FILE            DENTRY           INODE       TYPE PATH
  0 ffff8800377805c0 ffff880075d1ef00 ffff880037e8c418 CHR  /dev/devone
  1 ffff8800377809c0 ffff88007eb435c0 ffff88007e560108 CHR  /dev/null
  2 ffff880037493280 ffff880075ccbd80 ffff88007eb64c98 CHR  /dev/pts/0

ハングしていたプロセスは、/dev/devone をアクセスしていたとわかる。

/dev/devone が怪しい。

OOM の場合

「crash バイナリ vmcore」を実行して、crash を起動する。

# cd /var/crash/127.0.0.1-2015-12-20-18:23:16
# crash /usr/lib/debug/lib/modules/2.6.32-573.12.1.el6.x86_64/vmlinux  vmcore

crash> sys
... snip ...
       PANIC: "Kernel panic - not syncing: Out of memory: system-wide panic_on_oom is enabled"

OOM が原因でクラッシュしたとわかる。

crash> ps
   PID    PPID  CPU       TASK        ST  %MEM     VSZ    RSS  COMM
... snip ...
   1581   1578   2  ffff880037720040  IN   0.0  108304    244  bash
>  1632   1552   2  ffff8800379baab0  RU  77.8 3715784 1631992  test.pl
   1633   1581   1  ffff88003798a040  IN   0.0   15024    328  top

test.pl が、77.8% のメモリを消費している。 test.pl が怪しい。

---

参考文献

• http://people.redhat.com/anderson/crash_whitepaper/
• Linuxデバイスドライバプログラミング http://www.amazon.co.jp/dp/4797346426