Bluemix IaaS ベアメタル カーネルのクラッシュの原因追跡方法

Bluemix IaaS ベアメタルサーバーのカーネルクラッシュ時の原因追跡の方法について、まとめてみました。対象のOSは CentOS6.x 64bit です。

カーネルのクラッシュダンプの設定準備状態確認

Bluemix IaaS の ベアメタルサーバーの CentOS6.x では、デフォルトで以下の設定が入っていると思います。カーネルのクラッシュ出力のために、追加の作業は不要と思います。

• kexec-tools が導入されていること
• メモリが2GB 以上インストールされていること
• grub.conf カーネルの起動パラメータに crashkernel=auto が設定されていること
• chkconfig kdump on になっていること chkconfig --list |grep kdump で確認できる
• service kdump status の実行結果が Kdump is operational であること
• kdump サービスが有効であること cat /sys/kernel/kexec_crash_loaded　が１であれば有効

クラッシュ解析ツールのインストール

以下のコマンドで、デバック情報付きのカーネル、crash コマンドをインストールします。

yum --enablerepo=base-debuginfo install kernel-debuginfo-`uname -r` crash

注意点としては、--enablerepo=base-debuginfo のキーワードです。

以上で準備完了です。

実験的にクラッシュの発生と原因追跡

プロセスが暴走してメモリを枯渇(OOM: Out Of Memory)させた場合でも、通常の設定では、プロセスが強制停止されるだけで、カーネルがクラッシュする事はありません。　ここでは、テスト的に OOMが発生した場合、カーネルがクラッシュする設定を実施して、その原因を追跡する手順をみてみます。

OOMを発生で、カーネルがクラッシュする設定

下記の設定を/etc/sysctl.conf に追加します。

vm.panic_on_oom = 1

次に以下のコマンドで反映します。

# sysctl -p

OOMを発生するプロセスを作成

以下のPerlのプログラムは、メモリを消費し続け、カーネルをクラッシュさせます。

test.pl

#!/usr/bin/perl

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

クラッシュが発生すると、以下のディレクトリに、ダンプが生成され、再起動が起きます。

[root@server1 ~]# cd /var/crash/
[root@server1 crash]# ls -al
合計 16
drwxr-xr-x.  4 root root 4096  4月 25 15:01 2017 .
drwxr-xr-x. 21 root root 4096  4月 25 03:11 2017 ..
drwxr-xr-x.  2 root root 4096  4月 25 13:39 2017 127.0.0.1-2017-04-24-23:38:45
drwxr-xr-x.  2 root root 4096  4月 25 15:02 2017 127.0.0.1-2017-04-25-01:01:56
[root@server1 crash]# ls -al 127.0.0.1-2017-04-25-01:01:56
合計 164988
drwxr-xr-x. 2 root root      4096  4月 25 15:02 2017 .
drwxr-xr-x. 4 root root      4096  4月 25 15:01 2017 ..
-rw-------. 1 root root 168831507  4月 25 15:02 2017 vmcore
-rw-r--r--. 1 root root    101337  4月 25 15:01 2017 vmcore-dmesg.txt

クラッシュダンプの解析

crash コマンドで、デバック情報を含むカーネルを指定して vmcore を読み込みます。

[root@server1 crash]# cd 127.0.0.1-2017-04-25-01\:01\:56/
[root@server1 127.0.0.1-2017-04-25-01:01:56]# crash /usr/lib/debug/lib/modules/2.6.32-696.1.1.el6.x86_64/vmlinux vmcore

vmcoreを読み込みと、以下のサマリーが表示されます。 PANICにクラッシュの原因がメッセージされています。今回の試験用のオプションによってクラッシュが発生した事が解ります。 PIDがクラッシュの原因となったプロセスID、COMMANDが、実行ファイル名です。

This GDB was configured as "x86_64-unknown-linux-gnu"...

      KERNEL: /usr/lib/debug/lib/modules/2.6.32-696.1.1.el6.x86_64/vmlinux
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 24
        DATE: Tue Apr 25 15:01:34 2017
      UPTIME: 01:20:35
LOAD AVERAGE: 1.07, 0.39, 0.18
       TASKS: 490
    NODENAME: server1.takara.jp.ibm.com
     RELEASE: 2.6.32-696.1.1.el6.x86_64
     VERSION: #1 SMP Tue Apr 11 17:13:24 UTC 2017
     MACHINE: x86_64  (2400 Mhz)
      MEMORY: 63.9 GB
       PANIC: "Kernel panic - not syncing: Out of memory: system-wide panic_on_oom is enabled"
         PID: 4166
     COMMAND: "test.pl"
        TASK: ffff8810715f9520  [THREAD_INFO: ffff881070240000]
         CPU: 0
       STATE: TASK_RUNNING (PANIC)

crash> 

psコマンドは、クラッシュ発生時のプロセスのリストを表示するもので、RU となっていますから、test.plが実行中に発生した事が解ります。

crash> ps
<中略>
>  4166   3952   0  ffff8810715f9520  RU  93.9 66137680 64979276  test.pl

このPID 4166 にコンテキストを切り替えて表示すると、test.plが実行中であった事が解ります。

crash> set 4166
    PID: 4166
COMMAND: "test.pl"
   TASK: ffff8810715f9520  [THREAD_INFO: ffff881070240000]
    CPU: 0
  STATE: TASK_RUNNING (PANIC)

カーネルのログから、プロセスがクラッシュを引き起こした時のスタックトレースを見るこができます。メモリを要求にいって、OOMが発生、カーネルパニックに至った事が、このトレースから読み取る事ができます。

crash> log
<中略>
Kernel panic - not syncing: Out of memory: system-wide panic_on_oom is enabled

Pid: 4166, comm: test.pl Not tainted 2.6.32-696.1.1.el6.x86_64 #1
Call Trace:
 [<ffffffff81549fbe>] ? panic+0xa7/0x179
 [<ffffffff81131681>] ? dump_header+0x191/0x1b0
 [<ffffffff8113171c>] ? check_panic_on_oom+0x7c/0x80
 [<ffffffff81131ddb>] ? out_of_memory+0x1bb/0x3c0
 [<ffffffff8113e81c>] ? __alloc_pages_nodemask+0x93c/0x950
 [<ffffffff81177b6a>] ? alloc_pages_vma+0x9a/0x150
 [<ffffffff81159e7d>] ? handle_pte_fault+0x73d/0xb20
 [<ffffffff81177a6a>] ? alloc_pages_current+0xaa/0x110
 [<ffffffff81056747>] ? pte_alloc_one+0x37/0x50
 [<ffffffff81194099>] ? do_huge_pmd_anonymous_page+0xb9/0x3b0
 [<ffffffff8115a632>] ? handle_mm_fault+0x3d2/0x3f0
 [<ffffffff810520f1>] ? __do_page_fault+0x141/0x500
 [<ffffffff81162766>] ? do_mremap+0x396/0x540
 [<ffffffff8100bd4e>] ? invalidate_interrupt6+0xe/0x20
 [<ffffffff81550dbe>] ? do_page_fault+0x3e/0xa0
 [<ffffffff8154e0b5>] ? page_fault+0x25/0x30
crash> 

syslog との関係

カーネルがクラッシュした場合に、/var/log/message に クラッシュの記録を書き残してくれると、ハードウェア的なリセットなのか、カーネルがクラッシュした事によるのか判別できるのですが、Linuxの場合は残らない様ですね。 OSが突然再起動した場合は、/var/crash に新たなクラッシュダンプが出来ていないか確認するのが良さそうです。

最後に

以下の設定を取り除く事を忘れると、不意打ちを食らうので、忘れない様に削除しておきましょう。
vm.panic_on_oom = 1

では、「ご安全に！」