Linux crashコマンドの使い方

IT

このブログもそうだが、Linuxの上で動いている。


クラウド上でポチポチと設定するだけで使える時代なので、OSについて特に気にしないユーザも多いだろう。ありがたいことに安定稼働しているので、トラブルに遭遇することがほとんどない。

しかし、システムはクラッシュすることがまれにある。


クラッシュしたときに、クラッシュダンプファイルがあると、原因の特定に役立つことがある。

交通事故でたとえるならば、事故発生時の写真のようなものだ。

もちろん証拠写真だけで解決できないこともある。

途中経過までたどる場合には別途ログを調べる必要があるが、今回はcrashコマンドのみにフォーカスしてみよう。

crashコマンドとは

カーネルがクラッシュした時に、メモリの状態をファイルに書き出すことで、システムをリブートしたときにユーザがクラッシュ時の状態を把握できるようにしている。

そのファイルは、vmcoreと呼ばれcrashコマンドを使って中身を確認することができる。

ちなみに、今回使用する環境は、以下のとおりだ。よって、バージョンがことなると結果がことなる可能性がある。

# cat /etc/redhat-release 
Red Hat Enterprise Linux release 8.2 (Ootpa)
# uname -r
4.18.0-193.1.2.el8_2.x86_64

crashコマンドのインストール

では早速crashパッケージをインストールしてみよう。ついでに、カーネルのデバッグに必要なファイルもインストールしておこう。


RHEL8のkernel-debuginfoパッケージは、500MBぐらいの大きさだ。

# dnf install crash
# crash --version
crash 7.2.7-3.el8

# debuginfo-install kernel

crashコマンドが使えるか確認してみよう。

# crash

...
      KERNEL: /usr/lib/debug/lib/modules/4.18.0-193.1.2.el8_2.x86_64/vmlinux
    DUMPFILE: /proc/kcore
        CPUS: 2
        DATE: Tue May 26 18:10:03 2020
      UPTIME: 00:06:27
LOAD AVERAGE: 0.31, 0.40, 0.26
       TASKS: 486
    NODENAME: localhost.localdomain
     RELEASE: 4.18.0-193.1.2.el8_2.x86_64
     VERSION: #1 SMP Thu May 7 16:37:54 UTC 2020
     MACHINE: x86_64  (3591 Mhz)
      MEMORY: 4 GB
         PID: 2921
     COMMAND: "crash"
        TASK: ffff99825d0b2f80  [THREAD_INFO: ffff99825d0b2f80]
         CPU: 1
       STATE: TASK_RUNNING (ACTIVE)

Kdumpの設定

Kdump HelperというWebのアプリがあるので、条件を選択してポチポチと設定するだけで設定スクリプトが作成される。
そして、ファイルをダウンロードして、次のように実行するだけだ。

# chmod +x kdumpconfig.sh
# ./kdumpconfig.sh
...
-Restarting the kdump service...
kexec: unloaded kdump kernel
Stopping kdump: [OK]
Detected change(s) in the following file(s):
  
  /etc/kdump.conf
Rebuilding /boot/initramfs-4.18.0-193.1.2.el8_2.x86_64kdump.img
kexec: loaded kdump kernel
Starting kdump: [OK]

-Starting to Configure extra diagnostic options...

-Backed up /etc/sysctl.conf to /etc/sysctl.conf.kdumphelper.20-05-26-16:55:55.
kernel.sysrq=1 set in /etc/sysctl.conf
kernel.unknown_nmi_panic=1  set in /etc/sysctl.conf
kernel.softlockup_panic=1 set in /etc/sysctl.conf
vm.panic_on_oom=1 set in /etc/sysctl.conf
# reboot

クラッシュさせる

いつクラッシュするかわからないので、ここでは無理矢理クラッシュさせよう。
もちろん、本番環境ではなく、開発環境やテスト環境で実行してほしい。

すると、次のようなファイルが作成されるので再起動後に確認してほしい。

# pwd
/var/crash/127.0.0.1-2020-05-26-18:19:15
# ls -lh
total 1.2G
-rw-------. 1 root root 1.2G May 26 18:20 vmcore
-rw-r--r--. 1 root root  50K May 26 18:19 vmcore-dmesg.txt

vmcoreの読み込み

先程作成したvmcoreを解析してみよう。「crash vmlinux vmcore」を実行して、crash を起動する。

vmlinuxはカーネルの非圧縮イメージだ。kernel-debuginfoパッケージをインストールすると一緒にインストールされる。

# crash /usr/lib/debug/lib/modules/4.18.0-193.1.2.el8_2.x86_64/vmlinux vmcore
...
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 "x86_64-unknown-linux-gnu"...

WARNING: kernel relocated [22MB]: patching 94976 gdb minimal_symbol values

      KERNEL: /usr/lib/debug/lib/modules/4.18.0-193.1.2.el8_2.x86_64/vmlinux
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 2
        DATE: Tue May 26 18:19:09 2020
      UPTIME: 00:15:34
LOAD AVERAGE: 0.00, 0.08, 0.15
       TASKS: 487
    NODENAME: localhost.localdomain
     RELEASE: 4.18.0-193.1.2.el8_2.x86_64
     VERSION: #1 SMP Thu May 7 16:37:54 UTC 2020
     MACHINE: x86_64  (3591 Mhz)
      MEMORY: 4 GB
       PANIC: "sysrq: SysRq : Trigger a crash"
         PID: 2525
     COMMAND: "bash"
        TASK: ffff99825d0b4740  [THREAD_INFO: ffff99825d0b4740]
         CPU: 0
       STATE: TASK_RUNNING (SYSRQ)

crash>

helpコマンド

helpと入力すると、利用できるコマンドの一覧が表示される。そして、help + コマンドと入力すると各コマンドの使い方が表示される。

crash> help

*              extend         log            rd             task           
alias          files          mach           repeat         timer          
ascii          foreach        mod            runq           tree           
bpf            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              

crash version: 7.2.7-3.el8   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".

crash> help ps

NAME
  ps - display process status information

SYNOPSIS
  ps [-k|-u|-G|-y policy] [-s] [-p|-c|-t|-[l|m][-C cpu]|-a|-g|-r|-S|-A]
     [pid | task | command] ...

DESCRIPTION
  This command displays process status for selected, or all, processes
  in the system.  If no arguments are entered, the process data is
  is displayed for all processes.  Specific processes may be selected
  by using the following identifier formats:
...

sysコマンド

sysと入力すると、システムの情報が表示される。時間やCPUのロードアベレージ、カーネルパニックの原因などが表示される。これは、crashを起動して最初に表示される情報と同じだ。

crash> sys
      KERNEL: /usr/lib/debug/lib/modules/4.18.0-193.1.2.el8_2.x86_64/vmlinux
    DUMPFILE: vmcore  [PARTIAL DUMP]
        CPUS: 2
        DATE: Tue May 26 18:19:09 2020
      UPTIME: 00:15:34
LOAD AVERAGE: 0.00, 0.08, 0.15
       TASKS: 487
    NODENAME: localhost.localdomain
     RELEASE: 4.18.0-193.1.2.el8_2.x86_64
     VERSION: #1 SMP Thu May 7 16:37:54 UTC 2020
     MACHINE: x86_64  (3591 Mhz)
      MEMORY: 4 GB
       PANIC: "sysrq: SysRq : Trigger a crash"

Desktop Management Interface(DMI)情報を表示させることもできる。

crash> sys -i
        DMI_BIOS_VENDOR: SeaBIOS
       DMI_BIOS_VERSION: 1.13.0-2.fc32
          DMI_BIOS_DATE: 04/01/2014
         DMI_SYS_VENDOR: QEMU
       DMI_PRODUCT_NAME: Standard PC (Q35 + ICH9, 2009)
    DMI_PRODUCT_VERSION: pc-q35-4.2
...
crash> sys -i
            DMI_BIOS_VENDOR: LENOVO
           DMI_BIOS_VERSION: G4ET37WW (1.12 )
              DMI_BIOS_DATE: 05/29/2012
             DMI_SYS_VENDOR: LENOVO
           DMI_PRODUCT_NAME: 2429BQ1
        DMI_PRODUCT_VERSION: ThinkPad T530

システムコールのテーブルを表示させることもできる。

crash> sys -c
NUM  SYSTEM CALL                FILE AND LINE NUMBER
  0  __x64_sys_read             ../fs/read_write.c: 586
  1  __x64_sys_write            ../fs/read_write.c: 607
  2  __x64_sys_open             ../fs/open.c: 1082
  3  __x64_sys_close            ../fs/open.c: 1163
  4  __x64_sys_newstat          ../fs/stat.c: 333
  5  __x64_sys_newfstat         ../fs/stat.c: 371
  6  __x64_sys_newlstat         ../fs/stat.c: 344
  7  __x64_sys_poll             ../fs/select.c: 990
  8  __x64_sys_lseek            ../fs/read_write.c: 322
...

-tオプションは汚染されているか表示する。0ならば、汚染されていない。Pならば、プロプライエタリ(Proprietary)ライセンスを持つモジュールが使われている。

crash> sys -t
TAINTED_MASK: 0 

crash> sys -t
TAINTED_MASK: 1 P

crash> mod -t
NAME       TAINTS
hpvsa      P(U)
snapapi26  P(U)   < Uは、Unsigned。
...

hexコマンド

hexと入力すると、表示を16進数に変更できる。そして、evalを使うと16進数と10進数の両方が表示できる。

crash> hex
output radix: 16 (hex)
crash> eval 24
hexadecimal: 18  
    decimal: 24  
      octal: 30
     binary: 0000000000000000000000000000000000000000000000000000000000011000

btコマンド

btと入力すると、プロセスのバックトレースが表示される。全プロセスを表示させるには、foreachと組み合わせる。

-tオプションはスタックにテキストシンボルがある場合はすべて表示する。

-fオプションはフレーム内のスタックデータをすべて表示する。関数への引数を確認するときに便利だ。

crash>foreach bt -tf
PID: 0      TASK: ffffffff83812780  CPU: 0   COMMAND: "swapper/0"
              START: __schedule at ffffffff82e8f8ff
  [ffffffff83803e48] __schedule at ffffffff82e8f8ff
  [ffffffff83803e50] irqtime_account_process_tick at ffffffff826e57a9
  [ffffffff83803ea8] schedule_idle at ffffffff82e8ffee
...
PID: 1      TASK: ffff99830778df00  CPU: 1   COMMAND: "systemd"
              START: __schedule at ffffffff82e8f8ff
  [ffffb6eec0633d38] __schedule at ffffffff82e8f8ff
  [ffffb6eec0633d50] ep_item_poll at ffffffff82913550
  [ffffb6eec0633d98] schedule at ffffffff82e8fd2f
...

-lオプションはファイル名と行数を表示する。

crash> bt -l 1
PID: 1      TASK: ffff99830778df00  CPU: 1   COMMAND: "systemd"
 #0 [ffffb6eec0633d00] __schedule at ffffffff82e8f8ff
    /usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/kernel/sched/core.c: 2822
 #1 [ffffb6eec0633d98] schedule at ffffffff82e8fd2f
    /usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/./arch/x86/include/asm/current.h: 15
 #2 [ffffb6eec0633da8] schedule_hrtimeout_range_clock at ffffffff82e93e7d
    /usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/kernel/time/hrtimer.c: 1937
 #3 [ffffb6eec0633e40] ep_poll at ffffffff82915448
    /usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/fs/eventpoll.c: 1811
...

-aオプションはカレントプロセスのみ表示する。これは、ライブシステムでは利用できない。

crash> bt -a
PID: 2525   TASK: ffff99825d0b4740  CPU: 0   COMMAND: "bash"
 #0 [ffffb6eec11fbbe0] machine_kexec at ffffffff8265982e
 #1 [ffffb6eec11fbc38] __crash_kexec at ffffffff827591bd
 #2 [ffffb6eec11fbd00] crash_kexec at ffffffff8275a09d
 #3 [ffffb6eec11fbd18] oops_end at ffffffff82621edd
 #4 [ffffb6eec11fbd38] no_context at ffffffff8266872e
 #5 [ffffb6eec11fbd90] do_page_fault at ffffffff82669262
 #6 [ffffb6eec11fbdc0] async_page_fault at ffffffff8300123e
    [exception RIP: sysrq_handle_crash+18]
...
PID: 0      TASK: ffff9983077d5f00  CPU: 1   COMMAND: "swapper/1"
 #0 [fffffe0000032e50] crash_nmi_callback at ffffffff8264ce93
 #1 [fffffe0000032e58] nmi_handle at ffffffff82622893
 #2 [fffffe0000032eb0] default_do_nmi at ffffffff82622d4e
 #3 [fffffe0000032ed0] do_nmi at ffffffff82622f28
 #4 [fffffe0000032ef0] end_repeat_nmi at ffffffff830016b4
    [exception RIP: native_safe_halt+14]
    RIP: ffffffff82e947be  RSP: ffffb6eec0693ea8  RFLAGS: 00000246
    RAX: ffffffff82e94410  RBX: 0000000000000001  RCX: 7fffff267326013f
    RDX: 0000000000000001  RSI: 0000000000000001  RDI: ffff99837bb1d5c0
    RBP: 0000000000000001   R8: 0000018970364f46   R9: 0000000000000001
    R10: 00000000fa83b2da  R11: 00000000000000e4  R12: 0000000000000000
    R13: 0000000000000000  R14: 0000000000000000  R15: 0000000000000000
    ORIG_RAX: ffffffffffffffff  CS: 0010  SS: 0018
--- <NMI exception stack> ---
 #5 [ffffb6eec0693ea8] native_safe_halt at ffffffff82e947be
 #6 [ffffb6eec0693ea8] default_idle at ffffffff82e9442c
 #7 [ffffb6eec0693ed0] do_idle at ffffffff826e67d1
 #8 [ffffb6eec0693f10] cpu_startup_entry at ffffffff826e6a3f
 #9 [ffffb6eec0693f30] start_secondary at ffffffff8264ea17
#10 [ffffb6eec0693f50] secondary_startup_64 at ffffffff826000e7

disコマンド

disと入力すると、逆アセンブルをする。

crash> bt -l
...
 #7 [ffffb6eec11fbe78] __handle_sysrq.cold.9 at ffffffff82b25308
    /usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/drivers/tty/sysrq.c: 587
 #8 [ffffb6eec11fbea8] write_sysrq_trigger at ffffffff82b251cb
    /usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/drivers/tty/sysrq.c: 1114
...
crash> dis  -l write_sysrq_trigger
/usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/drivers/tty/sysrq.c: 1105
0xffffffff82b251a0 <write_sysrq_trigger>:       nopl   0x0(%rax,%rax,1) [FTRACE NOP]
/usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/drivers/tty/sysrq.c: 1106
0xffffffff82b251a5 <write_sysrq_trigger+0x5>:   push   %rbx
0xffffffff82b251a6 <write_sysrq_trigger+0x6>:   mov    %rdx,%rbx
0xffffffff82b251a9 <write_sysrq_trigger+0x9>:   test   %rdx,%rdx
0xffffffff82b251ac <write_sysrq_trigger+0xc>:   je     0xffffffff82b251cb <write_sysrq_trigger+0x2b>
/usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/drivers/tty/sysrq.c: 1109
0xffffffff82b251ae <write_sysrq_trigger+0xe>:   mov    %rsi,%rax
0xffffffff82b251b1 <write_sysrq_trigger+0x11>:  callq  0xffffffff82e82010 <__get_user_1>
0xffffffff82b251b6 <write_sysrq_trigger+0x16>:  mov    %eax,%esi
0xffffffff82b251b8 <write_sysrq_trigger+0x18>:  mov    $0xfffffffffffffff2,%rax
0xffffffff82b251bf <write_sysrq_trigger+0x1f>:  test   %esi,%esi
0xffffffff82b251c1 <write_sysrq_trigger+0x21>:  jne    0xffffffff82b251ce <write_sysrq_trigger+0x2e>
/usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/drivers/tty/sysrq.c: 1111
0xffffffff82b251c3 <write_sysrq_trigger+0x23>:  movsbl %dl,%edi
0xffffffff82b251c6 <write_sysrq_trigger+0x26>:  callq  0xffffffff82b24d40 <__handle_sysrq>
/usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/drivers/tty/sysrq.c: 1114
0xffffffff82b251cb <write_sysrq_trigger+0x2b>:  mov    %rbx,%rax
0xffffffff82b251ce <write_sysrq_trigger+0x2e>:  pop    %rbx
0xffffffff82b251cf <write_sysrq_trigger+0x2f>:  retq   
crash> dis -s write_sysrq_trigger
FILE: drivers/tty/sysrq.c
LINE: 1105

  1100  /*
  1101   * writing 'C' to /proc/sysrq-trigger is like sysrq-C
  1102   */
  1103  static ssize_t write_sysrq_trigger(struct file *file, const char __user *buf,
  1104                                     size_t count, loff_t *ppos)
* 1105  {
  1106          if (count) {
  1107                  char c;
  1108  
  1109                  if (get_user(c, buf))
  1110                          return -EFAULT;
  1111                  __handle_sysrq(c, false);
  1112          }
  1113  
  1114          return count;
  1115  }

crash> 

または、-sオプション+アドレスでソースコードの場所を特定することもできる。

crash> dis -s ffffffff82b251cb
FILE: drivers/tty/sysrq.c
LINE: 1114

  1109                  if (get_user(c, buf))
  1110                          return -EFAULT;
  1111                  __handle_sysrq(c, false);
  1112          }
  1113  
* 1114          return count;
  1115  }

よくある命令(例):

mov 0x160(%rbx),%rbx

これは、RBXレジスタで表されるアドレスからオフセット0x160バイトの位置にある内容をRBXレジスタに格納する命令だ。

setコマンド

setと入力すると、カレントコンテクストを任意のプロセスに切り替えることができる。例えば、PID1511の”rsyslogd”がオープンしているファイルは、このように表示する。

crash> set 1511
    PID: 1511
COMMAND: "rsyslogd"
   TASK: ffff99835ee617c0  [THREAD_INFO: ffff99835ee617c0]
    CPU: 1
  STATE: TASK_INTERRUPTIBLE 
crash> files
PID: 1511   TASK: ffff99835ee617c0  CPU: 1   COMMAND: "rsyslogd"
ROOT: /    CWD: /
 FD       FILE            DENTRY           INODE       TYPE PATH
  0 ffff998376bc9400 ffff99837b6b7180 ffff998347c22fe8 CHR  /dev/null
  1 ffff998376bc9b00 ffff99837b6b7180 ffff998347c22fe8 CHR  /dev/null
  2 ffff998376bc9b00 ffff99837b6b7180 ffff998347c22fe8 CHR  /dev/null
  3 ffff99835b445100 ffff99837b6b7b40 ffff998347c21b20 CHR  /dev/urandom
  4 ffff99835b4f3000 ffff99837564a840 ffff99830783a6b0 SOCK UNIX
  5 ffff99835b53bd00 ffff998375e92b40 ffff998375ea2bc0 REG  /var/log/messages
  6 ffff99835b53b500 ffff998375e92e40 ffff998375ea1680 REG  /var/log/cron
  7 ffff99835b53b900 ffff998375e926c0 ffff998375ea3000 REG  /var/log/secure
  8 ffff99835b4d9200 ffff99837564a3c0 ffff99837b6cbc30 UNKN inotify
 10 ffff99835b4d9900 ffff99837aab8540 ffff9983467b4950 REG  /run/log/journal/e6a1f2e21c8a4df5b8f758dcc5c02d26/system.journal

modコマンド

modと入力すると、現在インストールされたモジュール情報を表示する。

-sオプションをつけると、指定したモジュールをロードすることができる。

crash> mod|grep nfs
ffffffffc0953140 nfsv3 49152 (not loaded) [CONFIG_KALLSYMS]
ffffffffc0ae2000 nfs_acl 16384 (not loaded) [CONFIG_KALLSYMS]
ffffffffc0bbb280 nfs 327680 (not loaded) [CONFIG_KALLSYMS]
crash> mod -s nfsv3
MODULE NAME SIZE OBJECT FILE
ffffffffc0953140 nfsv3 49152 /usr/lib/debug/usr/lib/modules/4.18.0-193.1.2.el8_2.x86_64/kernel/fs/nfs/nfsv3.ko.debug

sourceコマンド

source + FILEと入力すると、ファイルからコマンドを読み込むことができる。例えば、/root/macros/nfs-pointersにつぎのような設定をすることができる。

crash> cat /root/macros/nfs-pointers
define superblk-to-nfs-pointers
set $sb = (struct super_block *)$arg0
set $nfs_server = (struct nfs_server *)($sb->s_fs_info)
set $nfs_client = $nfs_server->nfs_client
print $sb
print $nfs_server
print $nfs_client
end

そのファイルを読み込むことで、使い回しができるようになる。例えば、SUPERBLKのアドレスを渡すだけで、nfs_serverやnfs_clientのアドレスを取得できる。

crash> mount
     MOUNT           SUPERBLK     TYPE   DEVNAME   DIRNAME
ffff940b07776300 ffff940b07c12000 rootfs rootfs    /         
ffff940b07777680 ffff940b74d9a000 sysfs  sysfs     /sys    
...
ffff940b38726000 ffff940b5c778000 nfs    192.168.1.103:/c/backup /mnt      
crash> mod -s nfs
     MODULE       NAME                      SIZE  OBJECT FILE
ffffffffc0bbb280  nfs                     327680  /usr/lib/debug/usr/lib/modules/4.18.0-193.1.2.el8_2.x86_64/kernel/fs/nfs/nfs.ko.debug 
crash> source /root/macros/nfs-pointers
crash> superblk-to-nfs-pointers  0xffff940b5c778000
$1 = (struct super_block *) 0xffff940b5c778000
$2 = (struct nfs_server *) 0xffff940b7540d800
$3 = (struct nfs_client *) 0xffff940b3f620c00

structコマンド

structコマンドは構造体の定義や実際のアドレスから指定した構造体にマッチしたデータを表示する。

-oオプションでオフセット情報も表示できる。

crash> struct -o nfs_client
struct nfs_client {
    [0x0] refcount_t cl_count;
    [0x4] atomic_t cl_mds_count;
    [0x8] int cl_cons_state;
   [0x10] unsigned long cl_res_state;
....
crash> struct nfs_client 0xffff940b3f620c00
struct nfs_client {
  cl_count = {
    refs = {
      counter = 0x1
    }
  }, 
...
  cl_addrlen = 0x10, 
  cl_hostname = 0xffff940b1313edd0 "192.168.1.103", 
  cl_acceptor = 0x0, 
...
  cl_rpcclient = 0xffff940b39a53600, 
...
crash> struct rpc_clnt 0xffff940b39a53600 
struct rpc_clnt {
...
  cl_xprt = 0xffff940b75409000, 
  cl_procinfo = 0xffffffffc094f5c0, 
...
crash> struct rpc_xprt 0xffff940b75409000
struct rpc_xprt {
  kref = {
    refcount = {
      refs = {
        counter = 0x4
      }
    }
  }, 
  ops = 0xffffffffc085a900, 
...

crash> struct rpc_xprt 0xffff940b75409000|grep state
  state = 0x12, 
crash> eval -b 0x12
hexadecimal: 12  
    decimal: 18  
      octal: 22
     binary: 0000000000000000000000000000000000000000000000000000000000010010
   bits set: 4 1 

stateのビットを確認すると接続されているかもチェックできる。

/usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/include/linux/sunrpc/xprt.h

/*
 * Reserved bit positions in xprt->state
 */
#define XPRT_LOCKED             (0)
#define XPRT_CONNECTED          (1)
#define XPRT_CONNECTING         (2)
#define XPRT_CLOSE_WAIT         (3)
#define XPRT_BOUND              (4)
#define XPRT_BINDING            (5)
#define XPRT_CLOSING            (6)

ビット1がセットされているから、接続されていることが確認できる。

rdコマンド

rdコマンドはメモリを直接読むコマンドだ。

# cat /proc/sys/fs/mqueue/queues_max 
256

この情報をcrashのrdコマンドで読み取ってみる。

crash> sym sysctl_table_root
ffffffffaf50d4a0 (d) sysctl_table_root
crash> whatis sysctl_table_root
struct ctl_table_root sysctl_table_root;
crash> struct ctl_table_root ffffffff8390d4a0
...
            ctl_table = 0xffffffff8390d520, 

このctl_tableを使って、階層をたどってみよう。はじめに、/proc/sys/fsをチェックしてみる。その後、その下のmqueueのctl_tableアドレスをチェックする。

crash> struct ctl_table 0xffffffff8390d520 1000|grep procname|grep fs
struct: invalid kernel virtual address: fffffffffeffffff  type: "gdb_readmem_callback"
struct: invalid kernel virtual address: fffffffffeffffff  type: "gdb_readmem_callback"
  procname = 0xffffffff836e41c6 "sysfs", 
  procname = 0xffffffff836771af "ramfs", 
  procname = 0xffffffff836a2cc5 "tracefs", 
  procname = 0xffffffff836b8918 "fs", 
  procname = 0xffffffff836bfc3b "securityfs", 
struct: seek error: kernel virtual address: ffffffffffffffff  type: "gdb_readmem_callback"
struct: seek error: kernel virtual address: ffffffffffffffff  type: "gdb_readmem_callback"

crash> struct ctl_table 0xffffffff8390d520 1000|grep -s -e 'procname = 0xffffffff836b8918 \"fs\"' -A 5
struct: invalid kernel virtual address: fffffffffeffffff  type: "gdb_readmem_callback"
struct: invalid kernel virtual address: fffffffffeffffff  type: "gdb_readmem_callback"
  procname = 0xffffffff836b8918 "fs", 
  data = 0x0, 
  maxlen = 0, 
  mode = 365, 
  child = 0xffffffff83910be0, 
  proc_handler = 0x0, 

crash> struct ctl_table 0xffffffff83910be0 
struct ctl_table {
  procname = 0xffffffff836bebe0 "mqueue", 
  data = 0x0, 
  maxlen = 0, 
  mode = 365, 
  child = 0xffffffff83910c60, 
  proc_handler = 0x0, 
  poll = 0x0, 
  extra1 = 0x0, 
  extra2 = 0x0
}

0xffffffff836bebe0を使って、ctl_tableの値をチェックし、procname=”queues_max”の情報を確認できる。

crash> struct ctl_table 0xffffffff83910c60 
struct ctl_table {
  procname = 0xffffffff836beeee "queues_max", 
  data = 0xffffffff8390e724, 
  maxlen = 4, 
  mode = 420, 
  child = 0x0, 
  proc_handler = 0xffffffff82977570 <x86_64_start_kernel+88>, 
  poll = 0x0, 
  extra1 = 0x0, 
  extra2 = 0x0
}

このdataはアドレスを表示してるので、サイズをチェックして10進数の値に変換しよう。

/usr/src/debug/kernel-4.18.0-193.1.2.el8_2/linux-4.18.0-193.1.2.el8_2.x86_64/ipc/mq_sysctl.c

tatic struct ctl_table mq_sysctls[] = {
        {
                .procname       = "queues_max",
                .data           = &init_ipc_ns.mq_queues_max,
                .maxlen         = sizeof(int),

つまり、int型のサイズは、4バイト(=32ビット)だ。

crash> rd -32 0xffffffff8390e724
ffffffff8390e724:  00000100                              ....
crash> p/d 0x00000100
$1 = 256

filesコマンド

filesと入力すると、プロセスがオープンしているファイルを表示する。

crash> files
PID: 1052   TASK: ffff9983782897c0  CPU: 0   COMMAND: "sshd"
ROOT: /    CWD: /
 FD       FILE            DENTRY           INODE       TYPE PATH
  0 ffff99837a06c700 ffff99837b6b7180 ffff998347c22fe8 CHR  /dev/null
  1 ffff99837a06c000 ffff9983756ff480 ffff99837ab6d630 SOCK UNIX
  2 ffff99837a06c000 ffff9983756ff480 ffff99837ab6d630 SOCK UNIX
  3 ffff9983782a8a00 ffff998375510d80 ffff9983767e7cc0 REG  /var/lib/sss/mc/passwd
  4 ffff9983782a8b00 ffff99837570a6c0 ffff99837576eef0 SOCK UNIX
  5 ffff9983768f4500 ffff99837570a480 ffff99837576de70 SOCK TCP
...

/var/log/配下のファイルだけ表示するには、次のように実行する。

crash> foreach files -R /var/log 
PID: 853    TASK: ffff9983733d2f80  CPU: 1   COMMAND: "auditd"
ROOT: /    CWD: / 
 FD       FILE            DENTRY           INODE       TYPE PATH
  6 ffff99837a1ae000 ffff99837b113540 ffff99837b250e00 REG  /var/log/audit/audit.log
...
PID: 1511   TASK: ffff99835ee617c0  CPU: 1   COMMAND: "rsyslogd"
ROOT: /    CWD: / 
 FD       FILE            DENTRY           INODE       TYPE PATH
  5 ffff99835b53bd00 ffff998375e92b40 ffff998375ea2bc0 REG  /var/log/messages
  6 ffff99835b53b500 ffff998375e92e40 ffff998375ea1680 REG  /var/log/cron
  7 ffff99835b53b900 ffff998375e926c0 ffff998375ea3000 REG  /var/log/secure


crash> files
PID: 1511   TASK: ffff99835ee617c0  CPU: 1   COMMAND: "rsyslogd"
ROOT: /    CWD: /
 FD       FILE            DENTRY           INODE       TYPE PATH
  0 ffff998376bc9400 ffff99837b6b7180 ffff998347c22fe8 CHR  /dev/null
  1 ffff998376bc9b00 ffff99837b6b7180 ffff998347c22fe8 CHR  /dev/null
  2 ffff998376bc9b00 ffff99837b6b7180 ffff998347c22fe8 CHR  /dev/null
  3 ffff99835b445100 ffff99837b6b7b40 ffff998347c21b20 CHR  /dev/urandom
  4 ffff99835b4f3000 ffff99837564a840 ffff99830783a6b0 SOCK UNIX
  5 ffff99835b53bd00 ffff998375e92b40 ffff998375ea2bc0 REG  /var/log/messages
  6 ffff99835b53b500 ffff998375e92e40 ffff998375ea1680 REG  /var/log/cron
  7 ffff99835b53b900 ffff998375e926c0 ffff998375ea3000 REG  /var/log/secure
  8 ffff99835b4d9200 ffff99837564a3c0 ffff99837b6cbc30 UNKN inotify
 10 ffff99835b4d9900 ffff99837aab8540 ffff9983467b4950 REG  /run/log/journal/e6a1f2e21c8a4df5b8f758dcc5c02d26/system.journal

crash> jiffies
jiffies = $1 = 0x10009ae04
crash> struct inode ffff998375ea3000|grep when
  dirtied_when = 0xfffc2333, 
  dirtied_time_when = 0x0, 
crash> pd (0x10009ae04 - 0xfffc2333)/1000/60
$12 = 14

/var/log/secureは、約15分(14分47秒)前に更新があった。

kmemコマンド

kmemコマンドはカーネルのメモリに関する情報を表示する。

-sオプションでスラブキャッシュの情報を表示する。/proc/slabinfoと同じ情報だ。

crash> kmem -s
CACHE             OBJSIZE  ALLOCATED     TOTAL  SLABS  SSIZE  NAME
ffff9983409fbe00     1056        119       120      8    16k  xfs_inode(2111:systemd-tmpfiles-clean.service)
ffff9983533c9600      192        120       126      6     4k  dentry(2111:systemd-tmpfiles-clean.service)
ffff99833d262c00      576        206       224     16     8k  radix_tree_node(2087:dnf-makecache.service)
...

-iオプションでメモリの情報を表示する。

crash> kmem -i
                 PAGES        TOTAL      PERCENTAGE
    TOTAL MEM   967220       3.7 GB         ----
         FREE   166272     649.5 MB   17% of TOTAL MEM
         USED   800948       3.1 GB   82% of TOTAL MEM
       SHARED   115695     451.9 MB   11% of TOTAL MEM
      BUFFERS      530       2.1 MB    0% of TOTAL MEM
       CACHED   330964       1.3 GB   34% of TOTAL MEM
         SLAB    37855     147.9 MB    3% of TOTAL MEM

   TOTAL HUGE        0            0         ----
    HUGE FREE        0            0    0% of TOTAL HUGE

   TOTAL SWAP   524287         2 GB         ----
    SWAP USED        0            0    0% of TOTAL SWAP
    SWAP FREE   524287         2 GB  100% of TOTAL SWAP

 COMMIT LIMIT  1007897       3.8 GB         ----
    COMMITTED  1249934       4.8 GB  124% of TOTAL LIMIT

アドレスを指定することもできる。[]で囲まれているとまだ解放されていない。

// /var/log/secure の inode から
crash> struct inode ffff998375ea3000|grep mapping
  i_mapping = 0xffff998375ea3178, 
crash> struct address_space.host 0xffff998375ea3178 
  host = 0xffff998375ea3000
crash> kmem 0xffff998375ea3000
CACHE             OBJSIZE  ALLOCATED     TOTAL  SLABS  SSIZE  NAME
ffff99835ef6ea00     1056         17        45      3    16k  xfs_inode(1615:rsyslog.service)
  SLAB              MEMORY            NODE  TOTAL  ALLOCATED  FREE
  ffffe739c5d7a800  ffff998375ea0000     0     15          4    11
  FREE / [ALLOCATED]
  [ffff998375ea2ec0]

      PAGE       PHYSICAL      MAPPING       INDEX CNT FLAGS
ffffe739c5d7a8c0 175ea3000 dead000000000400        0  0 17ffffc0000000

listコマンド

listコマンドはlist_head構造体をたどって順にアドレスを表示する。

モジュールのリストを順にたどるには、次のように実行する。

crash> whatis modules
struct list_head modules;
crash> list modules
ffffffff838adc30
ffffffffc0c9e088
ffffffffc0c28108
ffffffffc0c23148
...

グローバル変数のfile_systemsのnextによって現在登録されているファイルシステムのタイプを表示するには、次のように実行する。

crash> p file_systems
file_systems = $2 = (struct file_system_type *) 0xffffffff8390d760
crash> list file_system_type.next -s file_system_type.name 0xffffffff8390d760
ffffffff8390d760
  name = 0xffffffff836e41c6 "sysfs"
ffffffff83812700
  name = 0xffffffff836b7509 "rootfs"
ffffffff8390de60
  name = 0xffffffff836771af "ramfs"
ffffffff838fa240
  name = 0xffffffff836b7bbd "bdev"
ffffffff8390d3c0
  name = 0xffffffff836a4b06 "proc"
ffffffff838b4de0
  name = 0xffffffff836afb9f "cpuset"
...
crash> file_system_type ffffffff8390d3c0
struct file_system_type {
  name = 0xffffffff836a4b06 "proc", 
  fs_flags = 8, 
  mount = 0xffffffff82942bc0, 
  kill_sb = 0xffffffff82942b80, 
  owner = 0x0, 
  next = 0xffffffff838b4de0, 
  fs_supers = {
    first = 0xffff998307c158e0
  }, 
...

netコマンド

netと入力すると、ネットワークデバイスのリストを表示する。

crash> net
   NET_DEVICE     NAME   IP ADDRESS(ES)
ffff99837bbd7000  lo     127.0.0.1
ffff998373f27000  enp1s0 192.168.122.45
ffff998355a20000  virbr0 192.168.124.1
ffff998355a9c000  virbr0-nic 

MACアドレスとIPアドレスの関連付け情報を保存したARP(Address Resolution Protocol)キャッシュを表示するには、次のように入力する。

crash> net -a
NEIGHBOUR        IP ADDRESS      HW TYPE    HW ADDRESS         DEVICE  STATE
ffff998359eca600 224.0.0.22      ETHER      01:00:5e:00:00:16  virbr0  NOARP
ffff998359f34400 224.0.0.251     ETHER      01:00:5e:00:00:fb  virbr0  NOARP
ffff99835ec6dc00 224.0.0.22      ETHER      01:00:5e:00:00:16  enp1s0  NOARP
ffff99835b69d400 224.0.0.251     ETHER      01:00:5e:00:00:fb  enp1s0  NOARP
ffff998360301e00 0.0.0.0         UNKNOWN    00 00 00 00 00 00  lo      NOARP
ffff99835ec6cc00 192.168.122.1   ETHER      52:54:00:4a:1e:7f  enp1s0  REACHABLE

psコマンド

psコマンドはプロセス情報を表示する。

割り込み不可(uninterruptible)プロセスを表示するには、タスクステートがUNを検索する。また、そのプロセスが何分ぐらいそのような状態なのかチェックするには、次のようにする。

crash> ps |grep oracle|grep UN
   8193      1   4  ffff81012263e100  UN   0.1 6544360  17704  oracle
   8223      1   7  ffff8101d1dfa100  UN   0.3 6557744  47308  oracle
crash> set 8193  
	PID: 8193  
COMMAND: "oracle"
   TASK: ffff8104109bf7a0  [THREAD_INFO: ffff8103b9780000]
	CPU: 5
  STATE: TASK_UNINTERRUPTIBLE
crash> px per_cpu__runqueues | grep "\[5\]"
  [5]: ffff810237072120
crash> px ((struct rq *) 0xffff810237072120)->timestamp_last_tick
$5 = 0x6d70f2e3d90b
crash> px ((struct task_struct *) 0xffff8104109bf7a0)->last_ran
$6 = 0x6c0bdeddcf88
crash> pd (0x6d70f2e3d90b-0x6c0bdeddcf88)/1000000000
$7 = 1533   <- ~25 min

// 追記: timestamp_last_tick は、RHEL8では定義されていないので、-mオプションを利用する。
crash> ps -m |grep UN 

-aオプションを追加するとコマンドライン引数と環境変数を表示する。

crash> ps -a rsyslogd
PID: 1511   TASK: ffff99835ee617c0  CPU: 1   COMMAND: "rsyslogd"
ARG: /usr/sbin/rsyslogd -n 
ENV: LANG=en_US.UTF-8
     PATH=/usr/local/sbin:/usr/local/bin:/usr/sbin:/usr/bin
     NOTIFY_SOCKET=/run/systemd/notify
     INVOCATION_ID=cc20aba676a343fe93d6c4094497734f
     SYSLOGD_OPTIONS=

-tオプションを追加するとプロセスの動作時間、開始時間、ユーザ空間(UTIME)、カーネル空間(STIME)での実行時間を表示する。
utimeは、USER TIMEになり、単位はミリ秒だ。つまり、50000ならば50秒だ。

crash> ps -t
PID: 0      TASK: ffffffff83812780  CPU: 0   COMMAND: "swapper/0"
    RUN TIME: 00:15:34
  START TIME: 0
       UTIME: 0
       STIME: 0

PID: 1      TASK: ffff99830778df00  CPU: 1   COMMAND: "systemd"
    RUN TIME: 00:15:34
  START TIME: 4000000
       UTIME: 249462850
       STIME: 1390583301

PID: 0      TASK: ffff9983077d5f00  CPU: 1   COMMAND: "swapper/1"
    RUN TIME: 00:15:34
  START TIME: 5000000
       UTIME: 0
       STIME: 0

-Aオプションを追加するとアクティブなプロセスだけ表示できる。

crash> ps -A
   PID    PPID  CPU       TASK        ST  %MEM     VSZ    RSS  COMM
>     0      0   1  ffff9983077d5f00  RU   0.0       0      0  [swapper/1]
>  2525   2522   0  ffff99825d0b4740  RU   0.3   38308  17104  bash

これと同じ。
crash> ps|grep '>'
>     0      0   1  ffff9983077d5f00  RU   0.0       0      0  [swapper/1]
>  2525   2522   0  ffff99825d0b4740  RU   0.3   38308  17104  bash

runqコマンド

runqと入力すると、スケジューラのランキューを表示する。

crash> runq
CPU 0 RUNQUEUE: ffff99837ba29c40
  CURRENT: PID: 2525   TASK: ffff99825d0b4740  COMMAND: "bash"
  RT PRIO_ARRAY: ffff99837ba29e80
	 [no tasks queued]
  CFS RB_ROOT: ffff99837ba29cf0
	 [120] PID: 501    TASK: ffff998372cc8000  COMMAND: "kworker/u4:4"

CPU 1 RUNQUEUE: ffff99837bb29c40
  CURRENT: PID: 0      TASK: ffff9983077d5f00  COMMAND: "swapper/1"
  RT PRIO_ARRAY: ffff99837bb29e80
	 [no tasks queued]
  CFS RB_ROOT: ffff99837bb29cf0
	 [no tasks queued]

taskコマンド

taskと入力すると、task_struct構造体を表示する。

crash> task
PID: 2525   TASK: ffff99825d0b4740  CPU: 0   COMMAND: "bash"
struct task_struct {
  thread_info = {
    flags = 2147483776, 
    status = 0
  }, 
  state = 0, 
  stack = 0xffffb6eec11f8000, 
  usage = {
    counter = 2
  }, 
  flags = 4194304, 
...

whatisコマンド

シンボルなどの構造体の定義を表示する。

crash> whatis jiffies
volatile unsigned long jiffies;
crash> whatis modules
struct list_head modules;
crash> whatis task_struct  
struct task_struct {
    struct thread_info thread_info;
    volatile long state;
    void *stack;
    atomic_t usage;
    unsigned int flags;
...

fuserコマンド

ファイルのパスやinodeを指定すると、そのファイルを使用しているタスクを表示できる。

crash> fuser /var/log/messages
 PID         TASK        COMM             USAGE
 1511  ffff99835ee617c0  "rsyslogd"       fd 
 1529  ffff99835b4fdf00  "in:imjournal"   fd 
 1530  ffff99835b50af80  "rs:main Q:Reg"  fd 

searchコマンド

メモリを検索するには、searchを利用します。

例えば、次の文字列を含むカーネルメモリを検索するには、以下のように実行します。

crash> search -k -c "can't allocate memory" "Failure to"
    ffff8800013ddec1: can't allocate memory for key lists..<3>%s %s: error con
    ffff8801258be748: Failure to install fence: %d..<3>[drm:%s] *ERROR* Failed
    ffff880125f07ec9: can't allocate memory..<3>ACPI: Invalid data..Too many d
    ffffffff813ddec1: can't allocate memory for key lists..<3>%s %s: error con

補足:Python extension

こちらのサイトのダウンロードをクリックすると、現時点ではmpykdump-3.1.0-x86_64.tar.gzがダウンロードされる。

Python/CRASH API / Wiki / Home

ファイルを展開してmpykdump64.soをcrashコマンドからロードしよう。
はじめは、オプションなしでcrashinfoと入力すると、次のような結果が表示される。

crash> extend /root/mpykdump64.so
Setting scroll off while initializing PyKdump
/root/mpykdump64.so: shared object loaded
crash> crashinfo

						 +==========================+
						 | * Crashinfo v1.3.4 * |
						 +==========================+


	  KERNEL: /usr/lib/debug/lib/modules/4.18.0-193.1.2.el8_2.x86_64/vmlinux
	DUMPFILE: vmcore  [PARTIAL DUMP]
		CPUS: 2
		DATE: Tue May 26 18:19:09 2020
	  UPTIME: 00:15:34
LOAD AVERAGE: 0.00, 0.08, 0.15
	   TASKS: 487
	NODENAME: localhost.localdomain
	 RELEASE: 4.18.0-193.1.2.el8_2.x86_64
	 VERSION: #1 SMP Thu May 7 16:37:54 UTC 2020
	 MACHINE: x86_64  (3591 Mhz)
	  MEMORY: 4 GB
	   PANIC: "sysrq: SysRq : Trigger a crash"


						 +--------------------------+
>------------------------| Per-cpu Stacks ('bt -a') |------------------------<
						 +--------------------------+

	  -- CPU#0 -- 
PID=2525  CPU=0 CMD=bash
  #0   machine_kexec+0x1be
  #1   __crash_kexec+0x6d
  #2   crash_kexec+0x3d
  #3   oops_end+0xbd
  #4   no_context+0x1be
  #5   do_page_fault+0x32
  #6   async_page_fault+0x1e
  #-1  sysrq_handle_crash+0x12, 477 bytes of data
  #7   __handle_sysrq.cold.9+0x48
  #8   write_sysrq_trigger+0x2b
  #9   proc_reg_write+0x3c
  #10  vfs_write+0xa5
  #11  ksys_write+0x4f
  #12  do_syscall_64+0x5b
  #13  entry_SYSCALL_64_after_hwframe+0x65, 477 bytes of data

	  -- CPU#1 -- 
PID=0  CPU=1 CMD=swapper/1
  #0   crash_nmi_callback+0x33
  #1   nmi_handle+0x63
  #2   default_do_nmi+0x4e
  #3   do_nmi+0x128
  #4   end_repeat_nmi+0x16
  #-1  native_safe_halt+0xe, 507 bytes of data
  #5   native_safe_halt+0xe
  #6   default_idle+0x1c
  #7   do_idle+0x1f1
  #8   cpu_startup_entry+0x6f
  #9   start_secondary+0x1a7
  #10  secondary_startup_64+0xb7


					  +--------------------------------+
>---------------------| How This Dump Has Been Created |---------------------<
					  +--------------------------------+

Dump has been initiated: with sysrq
	- programmatically (via sysrq-trigger)
	- using unknown dump method

							   +---------------+
>------------------------------| Tasks Summary |------------------------------<
							   +---------------+

Number of Threads That Ran Recently
--------------------
   last second      40
   last     5s      89
   last    60s     174

 ----- Total Numbers of Threads per State ------
  TASK_INTERRUPTIBLE                         426
  TASK_RUNNING                                 3
  TASK_UNINTERRUPTIBLE                        57

+++WARNING+++ There are 13 threads running in their own namespaces
	Use 'taskinfo --ns' to get more details

						   +-----------------------+
>--------------------------| 5 Most Recent Threads |--------------------------<
						   +-----------------------+

  PID  CMD                Age    ARGS
-----  --------------   ------  ----------------------------
 2525 bash                0 ms  -bash 
  501 kworker/u4:4        0 ms  (no user stack)
 2522 sshd                1 ms  sshd: root@pts/0                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                                 

  616 xfsaild/dm-0       27 ms  (no user stack)
 2468 python3            32 ms  python3 /usr/bin/awx-manage run_callback_receiver 


						  +------------------------+
>-------------------------| Memory Usage (kmem -i) |-------------------------<
						  +------------------------+

				 PAGES        TOTAL      PERCENTAGE
	TOTAL MEM   967220       3.7 GB         ----
		 FREE   166272     649.5 MB   17% of TOTAL MEM
		 USED   800948       3.1 GB   82% of TOTAL MEM
	   SHARED   115695     451.9 MB   11% of TOTAL MEM
	  BUFFERS      530       2.1 MB    0% of TOTAL MEM
	   CACHED   330964       1.3 GB   34% of TOTAL MEM
		 SLAB    37855     147.9 MB    3% of TOTAL MEM

   TOTAL HUGE        0            0         ----
	HUGE FREE        0            0    0% of TOTAL HUGE

   TOTAL SWAP   524287         2 GB         ----
	SWAP USED        0            0    0% of TOTAL SWAP
	SWAP FREE   524287         2 GB  100% of TOTAL SWAP

 COMMIT LIMIT  1007897       3.8 GB         ----
	COMMITTED  1249934       4.8 GB  124% of TOTAL LIMIT

Traceback (most recent call last):
  File "/root/mpykdump64.so/progs/crashinfo.py", line 1620, in <module>
  File "/root/mpykdump64.so/progs/crashinfo.py", line 1066, in print_blkreq
  File "/home/alexs/tools/pykdump/LinuxDump/Dev.py", line 905, in print_request_queues
  File "/home/alexs/tools/pykdump/LinuxDump/Dev.py", line 892, in get_blkreq_info
  File "/home/alexs/tools/pykdump/LinuxDump/Dev.py", line 686, in check_request_queue
  File "/home/alexs/tools/pykdump/pykdump/wrapcrash.py", line 565, in getattr
KeyError: '<struct request_queue> does not have a field <in_flight>'

******************************************************************************
********************** A Summary Of Problems Found ***********************
******************************************************************************
-------------------- A list of all +++WARNING+++ messages --------------------
	There are 13 threads running in their own namespaces
	Use 'taskinfo --ns' to get more details
--------------------

 ** Execution took   5.29s (real)   3.51s (CPU), Child processes:   1.54s
crash> 

–findオプションでキーワードを含むスタック情報を表示できる。

crash> crashinfo --find crash

PID=0  CPU=1 CMD=swapper/1
  #0   crash_nmi_callback+0x33
  #1   nmi_handle+0x63
  #2   default_do_nmi+0x4e
  #3   do_nmi+0x128
  #4   end_repeat_nmi+0x16
  #-1  native_safe_halt+0xe, 507 bytes of data
  #5   native_safe_halt+0xe
  #6   default_idle+0x1c
  #7   do_idle+0x1f1
  #8   cpu_startup_entry+0x6f
  #9   start_secondary+0x1a7
  #10  secondary_startup_64+0xb7

PID=2525  CPU=0 CMD=bash
  #0   machine_kexec+0x1be
  #1   __crash_kexec+0x6d
  #2   crash_kexec+0x3d
  #3   oops_end+0xbd
  #4   no_context+0x1be
  #5   do_page_fault+0x32
  #6   async_page_fault+0x1e
  #-1  sysrq_handle_crash+0x12, 477 bytes of data
  #7   __handle_sysrq.cold.9+0x48
  #8   write_sysrq_trigger+0x2b
  #9   proc_reg_write+0x3c
  #10  vfs_write+0xa5
  #11  ksys_write+0x4f
  #12  do_syscall_64+0x5b
  #13  entry_SYSCALL_64_after_hwframe+0x65, 477 bytes of data

–sysctlオプションでsysctlの設定を表示できる。

crash> crashinfo --sysctl
abi.vsyscall32       1
crypto.fips_enabled  0
debug.exception-trace 1
debug.kprobes-optimization 0
dev.cdrom.autoclose  1
dev.cdrom.autoeject  0
dev.cdrom.check_media 0
dev.cdrom.debug      0
dev.cdrom.info       
dev.cdrom.lock       1
dev.hpet.max-user-freq 64
dev.mac_hid.mouse_button2_keycode 97
dev.mac_hid.mouse_button3_keycode 100
...

–helpオプションで利用可能なオプションを表示できる。

crash> crashinfo --help        
Usage: crashinfo [options]

Options:
  -h, --help            show this help message and exit
  -v                    verbose output
  -q                    quiet mode - print warnings only
  --fast                Fast mode - do not run potentially slow tests
  --sysctl              Print sysctl info.
  --ext3                Print EXT3 info.
  --blkreq              Print Block I/O requests
  --blkdevs             Print Block Devices Info
  --filelock            Print filelock info.
  --stacksummary        Print stacks (bt) categorized summary.
  --findstacks=FINDSTACKS
                        Print stacks (bt) containing functions that match the provided pattern
  --checkstacks          Check stacks of all threads for corruption
  --decodesyscalls=DECODESYSCALLS
                        Decode Syscalls on the Stack
  --keventd_wq          Decode keventd_wq
  --kblockd_wq          Decode kblockd_workqueue
  --lws                 Print Locks Waitqueues and Semaphores
  --devmapper           Print DeviceMapper Tables
  --runq                Print Runqueus
  --semaphore=SEMA      Print 'struct semaphore' info
  --rwsemaphore=RWSEMA  Print 'struct rw_semaphore' info
  --mutex=MUTEX         Print Mutex info
  --umem                Print User-space Memory Usage
  --ls=LS               Emulate 'ls'. You can specify either dentry address or full pathname
  --workqueues          Print Workqueues - just for some kernels
  --radix_tree_element=root offset
                        Find and print a radix tree element
  --pci                 Print PCI Info
  --version             Print program version and exit

 ** Execution took   0.01s (real)   0.01s (CPU)
crash> 

また、xportshowコマンドで、ネットワーク関連情報も表示できる。

詳細は、-hで確認してみよう。

crash> xportshow -h
usage: xportshow [-h] [-a] [-v] [-r] [--program PROGRAM] [--pid [PID]] [--netfilter] [--softnet]
                 [--summary] [-s] [-i] [--interface IF1] [--decode DECODE [DECODE ...]]
                 [--port PORT] [-l] [-t] [--tcpstate TCPSTATE] [-u] [-w] [-x] [--sysctl]
                 [--devpack] [--arp] [--rtcache] [--skbuffhead SKBUFFHEAD] [--netns NETNS]
                 [--version] [--everything]

optional arguments:
  -h, --help            show this help message and exit
  -a                    print all sockets
  -v                    verbose output
  -r                    Print routing table. Adding -v prints all routing tables and policies
  --program PROGRAM     print sockets for cmdname
  --pid [PID]           print sockets for PID
  --netfilter           Print Netfilter Hooks
  --softnet             Print Softnet Queues
  --summary             Print A Summary
  -s, --statistics      Print Statistics
  -i                    Print Interface Info
  --interface IF1       Limit output to the specified interface only
  --decode DECODE [DECODE ...]
                        Decode iph/th/uh
  --port PORT           Limit output to the specified port (src or dst)
  -l, --listening       Print LISTEN sockets only
  -t                    Print TCP Info
  --tcpstate TCPSTATE   Limit display for this state only, e.g. SYN_SENT
  -u, --udp             Print UDP Info
  -w, --raw             Print RAW Info
  -x, --unix            Print UNIX Info
  --sysctl              Print sysctl info for net.
  --devpack             Print dev_pack info
  --arp                 Print ARP & Neighbouring info
  --rtcache             Print the routing cache
  --skbuffhead SKBUFFHEAD
                        Print sk_buff_head
  --netns NETNS         Set net ns address
  --version             Print program version and exit
  --everything          Run all functions available for regression testing

 ** Execution took   0.01s (real)   0.01s (CPU)
crash> 

TCPの情報を表示するには、-tオプションをつける。

crash> xportshow -t
tcp   127.0.0.1:39736            127.0.0.1:5432              TIME_WAIT
tcp   127.0.0.1:4369             127.0.0.1:55741             ESTABLISHED
tcp6  ::ffff:127.0.0.1:5672      ::ffff:127.0.0.1:42182      ESTABLISHED
tcp   127.0.0.1:5432             127.0.0.1:39254             ESTABLISHED
tcp   127.0.0.1:39744            127.0.0.1:5432              TIME_WAIT
tcp   127.0.0.1:39724            127.0.0.1:5432              TIME_WAIT
tcp   127.0.0.1:39772            127.0.0.1:5432              ESTABLISHED
tcp   127.0.0.1:39740            127.0.0.1:5432              TIME_WAIT
...

-lオプションでLISTENソケットのみを表示できる。

crash> xportshow -l         
tcp6  :::443                     :::*                        LISTEN
tcp   0.0.0.0:443                0.0.0.0:*                   LISTEN
tcp6  :::5672                    :::*                        LISTEN
tcp   0.0.0.0:25672              0.0.0.0:*                   LISTEN
tcp6  :::111                     :::*                        LISTEN
tcp   0.0.0.0:111                0.0.0.0:*                   LISTEN
tcp6  :::80                      :::*                        LISTEN
tcp   0.0.0.0:80                 0.0.0.0:*                   LISTEN
tcp6  :::4369                    :::*                        LISTEN
tcp   0.0.0.0:4369               0.0.0.0:*                   LISTEN
tcp   192.168.124.1:53           0.0.0.0:*                   LISTEN
tcp6  :::22                      :::*                        LISTEN
tcp   0.0.0.0:22                 0.0.0.0:*                   LISTEN
tcp   0.0.0.0:15672              0.0.0.0:*                   LISTEN
...

予備知識 (oops)

[  934.371472] sysrq: SysRq : Trigger a crash
[  934.371519] BUG: unable to handle kernel NULL pointer dereference at 0000000000000000
[  934.371522] PGD 0 P4D 0 
[  934.371527] Oops: 0002 [#1] SMP PTI

このようなメッセージを見たことがあるひともいるだろう。

では、Oopsの数字の意味は何か?

実はこの数字には、次のパターンしかない。

Bit01
0No page found Invalid access or Protection fault
1Read or ExecuteWrite
2Kernel modeUser mode
3No instruction fetchInstruction fetch

0002(decimal)は、0010(binary)だ。

右から左に順に確認しよう。ビット1は、ゼロ。ビット2は、1。ビット3と4は、ゼロ。

そして、ゼロスタートでカウントしている。

0002を英語で表現するとこうなる。

“we have a page not found during a write operation in Kernel mode; the fault was not an Instruction Fetch.

予備知識 (%rdi, %rsi, %rdx)

x86_64では、関数呼出し時の引数の格納先として、rdiを1番目として次の順に利用する。

  • %rdi
  • %rsi
  • %rdx
  • %rcx
  • %r8
  • %r9

Intel CPUアーキテクチャについて簡単に触れてみよう。汎用レジスタについてこちらを見てほしい。

32-bit64-bit用途
EAXRAXオペランドの演算、結果
EBXRBXDSセグメントのデータへのポインタ
ECXRCX文字列やループのカウンタ
EDXRDXI/Oポインタ
ESIRSIDSレジスタによって示されるセグメントにあるデータへのポインタ。あるいは、文字列操作のソースポインタ。
EDIRDIESレジスタによって示されるセグメントにあるデータへのポインタ。あるいは、文字列操作のデスティネーションポインタ。
ESPRSPスタックポインタ
EBPRBPスタック上のデータへのポインタ

よくあるパターン

  • カーネルパニック(NULLポインタ参照)
    • NULLポインタアクセスによってOopsする。
BUG: unable to handle kernel NULL pointer dereference at xyz...
  • カーネルパニック(リスト破壊)
    • カーネルで実装されている双方向リストlist_headなどで破壊されたリストや解放済みのリストを参照することによって発生する。
例1:
[3893008.345544] WARNING: at lib/list_debug.c:53 __list_del_entry+0x63/0xd0()
[3893008.345547] list_del corruption, ffff881fe5c31e10->next is LIST_POISON1 (dead000000100100)


例2:
[34745.679014] WARNING: CPU: 0 PID: 1113 at lib/list_debug.c:62 __list_del_entry+0x82/0xd0
[34745.679020] list_del corruption. next->prev should be fffff5bc43a025a0, but was fffff5bc6ec540a0
  • カーネルパニック(レースコンディション 競合)
    • 複数のプロセスが共有メモリにアクセスして競合するとパニックが発生する。たまにしか発生しないタイプのバグ。
    • ソースコードを確認して競合の仕組みを理解する必要がある。
  • カーネルのストール(無限ループ)
    • 応答しなくなる状態。ハングやフリーズともいう。
    • ウォッチドッグを使いカーネルクラッシュダンプを採取する。
    • vmcoreから各スレッドが何をしているか確認する。
  • カーネルのストール(スピンロックによるデッドロック)
    • スピンロックとはスレッドがロックを獲得するまでループ(スピン)して定期的んロックをチェックしながら待つこと。その結果、2つ以上のスレッドが互いの処理終了を待ち、結果としてどの処理も先に進めなくなることをデッドロックという。
    • スピンロックはビジーウェイトなので、バックトレースをチェックしよう。
NMI Watchdog detected LOCKUP on CPU 0
CPU 0 
...
RIP: 0010:[<ffffffff80064bcb>]  [<ffffffff80064bcb>] .text.lock.spinlock+0x11/0x30
RSP: 0018:ffff8111a007f670  EFLAGS: 00000086

x86_64アーキテクチャでは、EFLAGS00000086を観るとIFフラグ(割り込みフラグ)がクリアされている。つまり、割り込み禁止状態だ。もしこれが、00000286ならばIFフラグがセットされているので割り込み許可状態だとわかる。

  • カーネルのストール(セマフォ)
    • セマフォは、排他制御の仕組みで、同時に使える資源があと何個使えるかを示す数字だ。
    • psコマンドでプロセスがUN(=UNITERRUPTABLE)かどうかチェックしよう。
    • そのプロセスをbtでバックトレース情報をだして、セマフォ関連処理がないかチェックしよう。例:down_read、 up_read、 down_write、 up_write。
    • セマフォ待ちとわかったら、何のセマフォ操作をしているかチェックしよう。

絞り込み

CPUの使用率とプロセスの状態から、ざっくりと切り分けてみよう。もちろん、ケースバイケースなので、あくまで目安としてとらえてほしい。

ケースCPU使用率プロセスの状態
1高い(100%に近い)R
2いろいろR または S
3低い (0%に近い)S または D
4低い (0%に近い)S または D
50%T
状態意味
D割り込み不可能なスリープ状態 (通常 IO 中)
R実行中または実行可能状態 (実行キューにある)
S割り込み可能なスリープ状態 (イベントの完了を待っている)
Tジョブ制御シグナルまたはトレースされているために停止中の状態
Wページング状態 (2.6.xx カーネルからは無効)
X死んだ状態 (見えるべきではない)
Z終了したが、親プロセスによって回収されなかった、 消滅した (ゾンビ) プロセス
ps state(状態のコード)
ケース状態
1どこかで無限ループ
2何かエラーが発生し、リトライ中
3プロセスが何かイベント待ち(シグナル待ち、スリープ中)
4デッドロック
5SIGSTOPなどでプロセス停止

コメント

タイトルとURLをコピーしました