カーネルクラッシュの調査記録
本記事では、CentOSシステムで発生したカーネルクラッシュの調査プロセスを記録します。対象となるカーネルバージョンは3.10.0です。通常動作中にカーネルがクラッシュしましたが、幸いvmcoreファイルが生成されていました。
調査環境の準備
以下のツールとパッケージが必要です：
- crashツール
- カーネルデバッグ情報RPM（カーネルバージョンと一致させる必要あり）
- kernel-debuginfo-common-x86_64-3.10.0-327.el7.x86_64.rpm
- kernel-debuginfo-3.10.0-327.el7.x86_64.rpm
これらのパッケージは以下のURLからダウンロード可能です：https://mirrors.ocf.berkeley.edu/centos-debuginfo/7/x86_64/
調査プロセス
生成されたvmcoreファイルを使用して調査を開始します。
1. crashツールの起動
[user@localhost kernel-debug]# crash ../vmcore /usr/lib/debug/lib/modules/3.10.0-327.el7.x86_64/vmlinux2. クラッシュ原因の特定
出力結果から、空ポインタ（0000000000000008）へのアクセスが直接の原因であることがわかります：
KERNEL: /usr/lib/debug/lib/modules/3.10.0-327.el7.x86_64/vmlinux
DUMPFILE: ../vmcore [PARTIAL DUMP]
CPUS: 8
DATE: Wed Apr 29 19:40:42 2020
UPTIME: 335 days, 01:46:01
LOAD AVERAGE: 23.98, 26.19, 15.75
TASKS: 688
NODENAME: localhost.localdomain
RELEASE: 3.10.0-327.el7.x86_64
VERSION: #1 SMP Thu Nov 19 22:10:57 UTC 2015
MACHINE: x86_64 (3408 Mhz)
MEMORY: 15.6 GB
PANIC: "BUG: unable to handle kernel NULL pointer dereference at 0000000000000008"
PID: 76
COMMAND: "kswapd0"
TASK: ffff88044beba280 [THREAD_INFO: ffff88044bef0000]
CPU: 2
STATE: TASK_RUNNING (PANIC)3. スタックトレースの分析
コードレベルでの問題発生箇所を特定するため、スタックトレースを確認します：
crash> bt
PID: 76 TASK: ffff88044beba280 CPU: 2 COMMAND: "kswapd0"
#0 [ffff88044bef3610] machine_kexec at ffffffff81051beb
#1 [ffff88044bef3670] crash_kexec at ffffffff810f2542
#2 [ffff88044bef3740] oops_end at ffffffff8163e1a8
#3 [ffff88044bef3768] no_context at ffffffff8162e2b8
#4 [ffff88044bef37b8] __bad_area_nosemaphore at ffffffff8162e34e
#5 [ffff88044bef3800] bad_area_nosemaphore at ffffffff8162e4b8
#6 [ffff88044bef3810] __do_page_fault at ffffffff81640fce
#7 [ffff88044bef3868] do_page_fault at ffffffff81641113
#8 [ffff88044bef3890] page_fault at ffffffff8163d408
[exception RIP: down_read_trylock+9]
RIP: ffffffff810aa989 RSP: ffff88044bef3940 RFLAGS: 00010202
RAX: 0000000000000000 RBX: ffff8801b4f9ff80 RCX: 0000000000000000
RDX: 0000000000000000 RSI: 0000000000000001 RDI: 0000000000000008
RBP: ffff88044bef3940 R8: 0000000000000000 R9: 0000000000017bc0
R10: ffff880465fd8000 R11: 0000000000000000 R12: ffff8801b4f9ff81
R13: ffffea00047dfbc0 R14: 0000000000000008 R15: 0000000000000001
ORIG_RAX: ffffffffffffffff CS: 0010 SS: 0018
#9 [ffff88044bef3948] page_lock_anon_vma_read at ffffffff811a2e65
#10 [ffff88044bef3978] page_referenced at ffffffff811a30e7
#11 [ffff88044bef39f0] shrink_page_list at ffffffff8117d264
#12 [ffff88044bef3b28] shrink_inactive_list at ffffffff8117df3a
#13 [ffff88044bef3bf0] shrink_lruvec at ffffffff8117ea05
#14 [ffff88044bef3cf0] shrink_zone at ffffffff8117ee66
#15 [ffff88044bef3d48] balance_pgdat at ffffffff8118010c
#16 [ffff88044bef3e20] kswapd at ffffffff811803d3
#17 [ffff88044bef3ec8] kthread at ffffffff810a5aef
#18 [ffff88044bef3f50] ret_from_fork at ffffffff81645858例外は`down_read_trylock`関数内で発生し、その後`page fault`が発生しています。RIPアドレス（ffffffff810aa989）の内容を逆アセンブルしてみましょう：
crash> dis -l ffffffff810aa989
/usr/src/debug/kernel-3.10.0-327.el7/linux-3.10.0-327.el7.x86_64/arch/x86/include/asm/rwsem.h: 83
0xffffffff810aa989 : mov (%rdi),%rax このカーネルバージョンの`arch/x86/include/asm/rwsem.h`を開き、以下のコードを確認します（https://elixir.bootlin.com/linux/v3.10/source/arch/x86/include/asm/rwsem.h）：
/*
* 読み取り用trylock -- 成功時は1、競合時は0を返す
*/
static inline int __down_read_trylock(struct rw_semaphore *sem)
{
long result, tmp;
asm volatile("# beginning __down_read_trylock\n\t"
" mov %0,%1\n\t"
"1:\n\t"
" mov %1,%2\n\t"
" add %3,%2\n\t"
" jle 2f\n\t"
LOCK_PREFIX " cmpxchg %2,%0\n\t"
" jnz 1b\n\t"
"2:\n\t"
"# ending __down_read_trylock\n\t"
: "+m" (sem->count), "=&a" (result), "=&r" (tmp)
: "i" (RWSEM_ACTIVE_READ_BIAS)
: "memory", "cc");
return result >= 0 ? 1 : 0;
}ポインタ`sem`（レジスタ`RAX`の値）が`0000000000000008`となっており、アドレス解決に失敗し空ポインタにアクセスして例外を引き起こしています。スタック呼び出し状況を観察すると、すべてメモリ管理関連の操作であり、kswapd呼び出しも含まれていることから、メモリ不足が原因であると推測されます。
4. メモリ使用状況の確認
当時のメモリ使用状況を確認すると、メモリ使用率98%に達しており、スワップ領域も大量に使用されており、上記関数呼び出しの推論と一致しています：
crash> kmem -i
PAGES TOTAL PERCENTAGE
TOTAL MEM 3962164 15.1 GB ----
FREE 46698 182.4 MB 1% of TOTAL MEM
USED 3915466 14.9 GB 98% of TOTAL MEM
SHARED 224712 877.8 MB 5% of TOTAL MEM
BUFFERS 0 0 0% of TOTAL MEM
CACHED 555017 2.1 GB 14% of TOTAL MEM
SLAB 136079 531.6 MB 3% of TOTAL MEM
TOTAL HUGE 0 0 ----
HUGE FREE 0 0 0% of TOTAL HUGE
TOTAL SWAP 4194303 16 GB ----
SWAP USED 3042976 11.6 GB 72% of TOTAL SWAP
SWAP FREE 1151327 4.4 GB 27% of TOTAL SWAP
COMMIT LIMIT 6175385 23.6 GB ----
COMMITTED 9409769 35.9 GB 152% of TOTAL LIMIT5. プロセス状況の確認
当時のプロセス使用状況（抜粋）を確認すると、ほぼすべてがページスワッププロセスが実行されていることがわかります：
crash> ps
PID PPID CPU TASK ST %MEM VSZ RSS COMM
> 0 0 0 ffffffff81951440 RU 0.0 0 0 [swapper/0]
> 0 0 1 ffff88044f942e00 RU 0.0 0 0 [swapper/1]
0 0 2 ffff88044f943980 RU 0.0 0 0 [swapper/2]
> 0 0 3 ffff88044f944500 RU 0.0 0 0 [swapper/3]
> 0 0 4 ffff88044f945080 RU 0.0 0 0 [swapper/4]
0 0 5 ffff88044f945c00 RU 0.0 0 0 [swapper/5]
> 0 0 6 ffff88044f946780 RU 0.0 0 0 [swapper/6]
> 0 0 7 ffff88044f947300 RU 0.0 0 0 [swapper/7]
1 0 7 ffff88044f848000 IN 0.0 189172 3080 systemd
2 0 0 ffff88044f848b80 IN 0.0 0 0 [kthreadd]
3 2 0 ffff88044f849700 IN 0.0 0 0 [ksoftirqd/0]
5 2 0 ffff88044f84ae00 IN 0.0 0 0 [kworker/0:0H]
7 2 0 ffff88044f84c500 IN 0.0 0 0 [migration/0]
8 2 7 ffff88044f84d080 IN 0.0 0 0 [rcu_bh]これにより、問題は大量のメモリページスワップが原因であることが特定されました。しかし、具体的なコードロジックについては特定できませんでした。クラッシュが発生した時期はメモリを必要とする操作中であり、回避策としてはサービスを停止してメモリを解放し、操作完了後にサービスを再起動するしかありませんでした。