Kernel crash dump session write-up - April 2017 meetup
This is a write-up of the kernel crash dump session contributed by Nitin Bansal. The original email is here.
I attended the Pune Kernel Meetup on 8th April and presented a session on Kernel crash dump (vmcore) analysis. In this write-up I have tried to explain a few things about the vmcore analysis, hope it helps.
Before starting with the vmcore analysis, we need following three things:
- crash utility [1]
- vmlinux
- vmcore
vmlinux can be obtained from kernel-debuginfo (for Red Hat Enterprise Linux (RHEL) at least). One can either install kernel-debuginfo or simply extract vmlinux file using rpm2cpio:
# yum install kernel-debuginfo-2.6.32-642.13.1.el6.x86_64
Or
# rpm2cpio kernel-debuginfo-2.6.32-642.13.1.el6.x86_64.rpm | cpio -idv ./usr/lib/debug/lib/modules/2.6.32-642.13.1.el6.x86_64/vmlinux
vmcore was collected from kernel-2.6.32-642.13.1.el6 so vmlinux from debuginfo package of same version is required.
Now let's use "crash" utility to open this vmcore, which after printing a few details i.e. copyright information, GDB version information etc drops us to "crash>" prompt:
# crash /usr/lib/debug/lib/modules/2.6.32-642.13.1.el6.x86_64/vmlinux vmcore
crash 7.1.0-6.el6 .. 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"... KERNEL: /usr/lib/debug/lib/modules/2.6.32-642.13.1.el6.x86_64/vmlinux DUMPFILE: vmcore [PARTIAL DUMP] CPUS: 2 DATE: Fri Mar 31 11:15:47 2017 UPTIME: 00:06:01 LOAD AVERAGE: 0.40, 0.30, 0.13 TASKS: 232 NODENAME: rhel6 RELEASE: 2.6.32-642.13.1.el6.x86_64 VERSION: #1 SMP Wed Nov 23 16:03:01 EST 2016 MACHINE: x86_64 (2808 Mhz) MEMORY: 2 GB PANIC: "Kernel panic - not syncing: hung_task: blocked tasks" PID: 46 COMMAND: "khungtaskd" TASK: ffff880078d16ab0 [THREAD_INFO: ffff880078d20000] CPU: 1 STATE: TASK_RUNNING (PANIC)
crash>
"sys" command can be used to print most of the information that crash prints
when invoked e.g.:
crash> sys
KERNEL: /usr/lib/debug/lib/modules/2.6.32-642.13.1.el6.x86_64/vmlinux
DUMPFILE: vmcore [PARTIAL DUMP]
CPUS: 2
DATE: Fri Mar 31 11:15:47 2017
UPTIME: 00:06:01
LOAD AVERAGE: 0.40, 0.30, 0.13
TASKS: 232
NODENAME: rhel6
RELEASE: 2.6.32-642.13.1.el6.x86_64
VERSION: #1 SMP Wed Nov 23 16:03:01 EST 2016
MACHINE: x86_64 (2808 Mhz)
MEMORY: 2 GB
PANIC: "Kernel panic - not syncing: hung_task: blocked tasks"
To list all the available crash commands, type "?" and hit enter:
crash> ?
* files mach repeat timer alias foreach mod runq tree ascii 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 extend log rd task
Use "help" to get details about a command and parameters it accepts e.g.:
crash> help sys
Now, let's examine kernel ring buffer (that's where we find panic message) with the help of "log" command.
And following is the panic message, which tells us that khungtaskd crashed the system:
Call Trace: <#DB[1]> <<EOE>> Pid: 46, comm: khungtaskd Not tainted 2.6.32-642.13.1.el6.x86_64 #1 Call Trace: <NMI> [<ffffffff81009c47>] ? show_regs+0x27/0x30 [<ffffffff8154d909>] ? arch_trigger_all_cpu_backtrace_handler+0x99/0xc0 [<ffffffff8154f1a5>] ? notifier_call_chain+0x55/0x80 [<ffffffff8154f20a>] ? atomic_notifier_call_chain+0x1a/0x20 [<ffffffff810acc8e>] ? notify_die+0x2e/0x30 [<ffffffff8154ce23>] ? do_nmi+0x1c3/0x350 [<ffffffff8154c6e3>] ? nmi+0x83/0x90 [<ffffffff8104615a>] ? native_write_msr_safe+0xa/0x10 <<EOE>> [<ffffffff8103e92c>] ? x2apic_send_IPI_mask+0x6c/0xb0 [<ffffffff81039b9a>] ? arch_trigger_all_cpu_backtrace+0x27a/0x2c0 [<ffffffff810f2740>] ? watchdog+0x250/0x2a0 [<ffffffff810f24f0>] ? watchdog+0x0/0x2a0 [<ffffffff810a640e>] ? kthread+0x9e/0xc0 [<ffffffff8100c28a>] ? child_rip+0xa/0x20 [<ffffffff810a6370>] ? kthread+0x0/0xc0 [<ffffffff8100c280>] ? child_rip+0x0/0x20 Kernel panic - not syncing: hung_task: blocked tasks Pid: 46, comm: khungtaskd Not tainted 2.6.32-642.13.1.el6.x86_64 #1 Call Trace: [<ffffffff81548301>] ? panic+0xa7/0x179 [<ffffffff81039aa5>] ? arch_trigger_all_cpu_backtrace+0x185/0x2c0 [<ffffffff810f274e>] ? watchdog+0x25e/0x2a0 [<ffffffff810f24f0>] ? watchdog+0x0/0x2a0 [<ffffffff810a640e>] ? kthread+0x9e/0xc0 [<ffffffff8100c28a>] ? child_rip+0xa/0x20 [<ffffffff810a6370>] ? kthread+0x0/0xc0 [<ffffffff8100c280>] ? child_rip+0x0/0x20
khungtaskd is a kernel thread which checks for uninterruptible tasks, few relevant snips from kernel/hung_task.c:
static int __init hung_task_init(void)
{
atomic_notifier_chain_register(&panic_notifier_list, &panic_block);
watchdog_task = kthread_run(watchdog, NULL, "khungtaskd");
return 0;
}
..
static int watchdog(void *dummy)
{
set_user_nice(current, 0);
for ( ; ; ) {
unsigned long timeout = sysctl_hung_task_timeout_secs;
while (schedule_timeout_interruptible(timeout_jiffies(timeout)))
timeout = sysctl_hung_task_timeout_secs;
check_hung_uninterruptible_tasks(timeout);
}
return 0;
}
By scrolling back a bit in ring buffer a hung_task_timeout_secs warning can be seen along with the following backtrace:
1 > INFO: task dd:7224 blocked for more than 10 seconds. 2 > Not tainted 2.6.32-642.13.1.el6.x86_64 #1 3 > "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message. 4> dd D 0000000000000001 0 7224 6702 0x00000080 ffff88007c473ce8 0000000000000082 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 0000000000000000 ffff880037b71068 ffff88007c473fd8 5> Call Trace: [<ffffffff810a6bce>] ? prepare_to_wait+0x4e/0x80 [<ffffffff8119bdfc>] __sb_start_write+0xdc/0x120 [<ffffffff810a68a0>] ? autoremove_wake_function+0x0/0x40 [<ffffffff811bcc14>] mnt_want_write+0x24/0x50 [<ffffffff8119b348>] ? get_empty_filp+0xe8/0x190 [<ffffffff811aca99>] do_filp_open+0x2b9/0xd20 [<ffffffff812a885a>] ? strncpy_from_user+0x4a/0x90 [<ffffffff811ba072>] ? alloc_fd+0x92/0x160 [<ffffffff811969f7>] do_sys_open+0x67/0x130 [<ffffffff81196b00>] sys_open+0x20/0x30 [<ffffffff8100b0d2>] system_call_fastpath+0x16/0x1b
Let's look at it line by line:
- Line 1 shows that dd PID 7224 was blocked for more than 10 seconds.
- Line 2 tells us the kernel version and that it is not tainted (i.e. no third
party modules are loaded etc.).
- Line 3 is just telling us how to disable this message, not a great idea IMO.
- Line 4 contains command name, state, PID etc.
- Line 5 shows the associated call trace which suggests that dd became
uninterruptible while trying to write to a filesystem.
Process details can be checked using "ps":
crash> ps -m | grep UN
[0 00:00:14.117] [UN] PID: 7224 TASK: ffff880037b70ab0 CPU: 1 COMMAND: "dd"
^^^^^^^^^^^^^^^^
|_____This is the duration of dd in uninterruptible state (14.117 seconds)
-m switch displays timestamp in days, hours, minutes, seconds and milliseconds.
Next step is to examine dd process, in order to do that, we first need to change the process context (currently it is set to khungtaskd and needs to be switched to dd), which can be done using "set":
crash> set 7224
PID: 7224
COMMAND: "dd"
TASK: ffff880037b70ab0 [THREAD_INFO: ffff88007c470000]
CPU: 1
STATE: TASK_UNINTERRUPTIBLE
Let's print backtrace along with kernel source line numbers (source line numbers probably wouldn't be displayed if kernel-debuginfo is not installed):
crash> bt -l
PID: 7224 TASK: ffff880037b70ab0 CPU: 1 COMMAND: "dd"
#0 [ffff88007c473c18] schedule at ffffffff815489d0
/usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/kernel/sched.c: 3119
#1 [ffff88007c473cf0] __sb_start_write at ffffffff8119bdfc
/usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/super.c: 677
#2 [ffff88007c473d80] mnt_want_write at ffffffff811bcc14
/usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/namespace.c: 300
#3 [ffff88007c473db0] do_filp_open at ffffffff811aca99
/usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/namei.c: 2267
#4 [ffff88007c473f20] do_sys_open at ffffffff811969f7
/usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/open.c: 908
#5 [ffff88007c473f70] sys_open at ffffffff81196b00
/usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/open.c: 932
#6 [ffff88007c473f80] system_call_fastpath at ffffffff8100b0d2
/usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/arch/x86/kernel/entry_64.S: 492
RIP: 000000358a8db480 RSP: 00007ffcd7d37ca8 RFLAGS: 00010246
RAX: 0000000000000002 RBX: ffffffff8100b0d2 RCX: 0000000000000000
RDX: 00000000000001b6 RSI: 0000000000000241 RDI: 00007ffcd7d3870b
RBP: 0000000000000240 R8: 000000358ab8ee40 R9: 00007ffaa33c368c
R10: 1999999999999999 R11: 0000000000000246 R12: ffffffff81196b00
R13: ffff88007c473f78 R14: ffffffffffffffff R15: 0000000000000064
ORIG_RAX: 0000000000000002 CS: 0033 SS: 002b
This backtrace needs to be read from bottom to top, following chain shows how these functions were called:
921 SYSCALL_DEFINE3(open, const char __user *, filename, int, flags, int, mode)
922 {
923 long ret;
924
925 if (force_o_largefile())
926 flags |= O_LARGEFILE;
927
928 ret = do_sys_open(AT_FDCWD, filename, flags, mode);--------------------
|
----------------------------------------------------------------
|
899 long do_sys_open(int dfd, const char __user *filename, int flags, int mode)
900 {
901 struct filename *tmp = getname(filename);
902 int fd = PTR_ERR(tmp);
903
904 if (!IS_ERR(tmp)) {
905 fd = get_unused_fd_flags(flags);
906 if (fd >= 0) {
907 struct file *f = do_filp_open(dfd, tmp, flags, mode, 0); ------
|
---------------------------------------------------------
|
2166 struct file *do_filp_open(int dfd, struct filename *filename,
2167 int open_flag, int mode, int acc_mode)
2168 {
2169 struct file *filp;
..
..
2256 /*
2257 * This write is needed to ensure that a
2258 * ro->rw transition does not occur between
2259 * the time when the file is created and when
2260 * a permanent write count is taken through
2261 * the 'struct file' in nameidata_to_filp().
2262 */
2263 error = mnt_want_write(nd.path.mnt); ----------------------------------
|
-----------------------------------------------------------------
|
295 int mnt_want_write(struct vfsmount *m)
296 {
297 int ret;
298
299 sb_start_write(m->mnt_sb); -------------------------------------------
|
-------------------------------------------------
|
1569 static inline void sb_start_write(struct super_block *sb)
1570 {
1571 __sb_start_write(sb, SB_FREEZE_WRITE, true); --------------------------
|
----------------------------------------------------------------
|
668 int __sb_start_write(struct super_block *sb, int level, bool wait)
669 {
670 /* Out of tree modules don't use this mechanism */
671 if (unlikely(!sb_has_new_freeze(sb)))
672 return 1;
673 retry:
674 if (unlikely(sb->s_writers.frozen >= level)) {
675 if (!wait)
676 return 0;
677 wait_event(sb->s_writers.wait_unfrozen, <<<<<<<<<<<<<<< dd was here
678 sb->s_writers.frozen < level);
679 }
In short, mnt_want_write() called sb_start_write() which then called
__sb_start_write(), and dd was waiting at line 677 in __sb_start_write() when
this vmcore was collected.
From this code it is clear that dd was trying to write to a filesystem but somehow it couldn't and became uninterruptible, now we need to find out which filesystem it was and why dd couldn't write to it. Can we do it? Yes, absolutely, if we can determine the first argument i.e. super_block that is passed to __sb_start_write(), it will tell us about the filesystem/mount-point.
If we go back to backtrace, we can see that mnt_want_write() called __sb_start_write() and passed it three parameters, struct super_block (sb), level (SB_FREEZE_WRITE) and a Boolean called wait (true):
#1 [ffff88007c473cf0] __sb_start_write at ffffffff8119bdfc #2 [ffff88007c473d80] mnt_want_write at ffffffff811bcc14
Note: "whatis command can be used to check the function prototype (simply entering the function name or px also does the job):
crash> whatis __sb_start_write int __sb_start_write(struct super_block *, int, bool);
Before we go any further, it is important to know how arguments are passed to the called function. First argument goes to %rdi, second to %rsi, third to %rdx, fourth to %rcx and fifth and sixth to %r8 and %r9 respectively. Armed with this knowledge now we can turn our attention to disassembly. Let's disassemble mnt_start_write to find out arguments passed to __sb_start_write:
crash> dis -lr ffffffff811bcc14 /usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/namespace.c: 296 0xffffffff811bcbf0 <mnt_want_write>: push %rbp 0xffffffff811bcbf1 <mnt_want_write+1>: mov %rsp,%rbp 0xffffffff811bcbf4 <mnt_want_write+4>: push %rbx 0xffffffff811bcbf5 <mnt_want_write+5>: sub $0x18,%rsp 0xffffffff811bcbf9 <mnt_want_write+9>: nopl 0x0(%rax,%rax,1) /usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/include/linux/fs.h: 1571 0xffffffff811bcbfe <mnt_want_write+14>: mov $0x1,%edx <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< 3rd argument i.e. wait 0xffffffff811bcc03 <mnt_want_write+19>: mov $0x1,%esi <<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<<< 2nd argument i.e. SB_FREEZE_WRITE /usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/namespace.c: 296 0xffffffff811bcc08 <mnt_want_write+24>: mov %rdi,%rbx /usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/include/linux/fs.h: 1571 0xffffffff811bcc0b <mnt_want_write+27>: mov 0x28(%rdi),%rdi <<<<<<<<<<<<<<<<<<<<<<<<<<<<< first argument i.e. super_block (sb) 0xffffffff811bcc0f <mnt_want_write+31>: callq 0xffffffff8119bd20 <__sb_start_write> /usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/namespace.c: 300 0xffffffff811bcc14 <mnt_want_write+36>: mov %rbx,%rdi
The values of second and third arguments i.e. SB_FREEZE_WRITE and wait are pretty straightforward, both are set to 1.
But to determine super_block which is %rdi we have to back-peddle a little bit, 28th offset of %rdi was copied to %rdi:
mov 0x28(%rdi),%rdi
we need to determine what's inside %rdi and one line above that tells us that %rdi was copied to %rbx.
mov %rdi,%rbx
If we can determine value inside %rbx, it will give us %rdi and then 28th offset of %rdi can be calculated.
To obtain %rdi let's disassemble __sb_start_write and see if %rbx is saved somewhere:
crash> dis -lr ffffffff8119bdfc | head /usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/fs/super.c: 669 0xffffffff8119bd20 <__sb_start_write>: push %rbp 0xffffffff8119bd21 <__sb_start_write+1>: mov %rsp,%rbp 0xffffffff8119bd24 <__sb_start_write+4>: add $0xffffffffffffff80,%rsp 0xffffffff8119bd28 <__sb_start_write+8>: mov %rbx,-0x28(%rbp) <<<<<<< rbx 0xffffffff8119bd2c <__sb_start_write+12>: mov %r12,-0x20(%rbp) 0xffffffff8119bd30 <__sb_start_write+16>: mov %r13,-0x18(%rbp) 0xffffffff8119bd34 <__sb_start_write+20>: mov %r14,-0x10(%rbp) 0xffffffff8119bd38 <__sb_start_write+24>: mov %r15,-0x8(%rbp) 0xffffffff8119bd3c <__sb_start_write+28>: nopl 0x0(%rax,%rax,1)
%rbx is copied to -28th offset of %rbp, and %rbp can be found either in the stack data of __sb_start_write or schedule, I am going to use stack data of schedule for now to make it simpler. Disassembly of schedule (next function after __sb_start_write) suggests that %rbp is pushed to the stack:
crash> dis -lr ffffffff815489d0 | head /usr/src/debug/kernel-2.6.32-642.13.1.el6/linux-2.6.32-642.13.1.el6.x86_64/kernel/sched.c: 6133 0xffffffff81548630 <schedule>: push %rbp <<<<<<<<<<<<<<<<<<< 1st push 0xffffffff81548631 <schedule+1>: mov %rsp,%rbp 0xffffffff81548634 <schedule+4>: push %r15 0xffffffff81548636 <schedule+6>: push %r14 0xffffffff81548638 <schedule+8>: push %r13 0xffffffff8154863a <schedule+10>: push %r12 0xffffffff8154863c <schedule+12>: push %rbx 0xffffffff8154863d <schedule+13>: sub $0x98,%rsp 0xffffffff81548644 <schedule+20>: nopl 0x0(%rax,%rax,1)
first push at stack will give us %rbp, and bt -f can be used to print stack:
crash> bt -f | grep -A15 schedule
#0 [ffff88007c473c18] schedule at ffffffff815489d0
ffff88007c473c20: 0000000000000082 0000000000000000
ffff88007c473c30: 0000000000000000 0000000000000000
ffff88007c473c40: 0000000000000000 0000000000000000
ffff88007c473c50: 0000000000000000 0000000000000000
ffff88007c473c60: 0000000000000000 ffff880037b71068
ffff88007c473c70: ffff88007c473fd8 0000000000010068
ffff88007c473c80: ffff880037b71068 ffff88007e527520
ffff88007c473c90: ffff880037b70ab0 0000000000000002
ffff88007c473ca0: 0000000000000246 ffff88007c473ce8
ffff88007c473cb0: ffffffff810a6bce ffff880037b70ab0
ffff88007c473cc0: ffff8800379e7400 0000000000000001
ffff88007c473cd0: ffff88007c473d18 ffff8800379e76d8
ffff88007c473ce0: ffff8800379e7770 ffff88007c473d78 <<<< ffff88007c473d78 is first push == %rbp
ffff88007c473cf0: ffffffff8119bdfc
Now that we have %rbp, %rbx can be calculated i.e. -0x28th offset of %rbp:
crash> eval (0xffff88007c473d78 - 0x28)
hexadecimal: ffff88007c473d50
decimal: 18446612134399262032 (-131939310289584)
octal: 1777774200017421636520
binary: 1111111111111111100010000000000001111100010001110011110101010000
crash> rd ffff88007c473d50
ffff88007c473d50: ffff88007ef64380 .C.~....
%rbx == ffff88007ef64380
Since %rdi was copied to %rbx, %rdi also is ffff88007ef64380, now if we calculate 28th offset to %rdi we will get super_block:
crash> eval (0xffff88007ef64380 + 0x28)
hexadecimal: ffff88007ef643a8
decimal: 18446612134444286888 (-131939265264728)
octal: 1777774200017675441650
binary: 1111111111111111100010000000000001111110111101100100001110101000
crash> rd ffff88007ef643a8
ffff88007ef643a8: ffff8800379e7400 .t.7....
super_block == ffff8800379e7400.
super_block can be passed to the "mount" command to get the mount point:
crash> mount ffff8800379e7400
VFSMOUNT SUPERBLK TYPE DEVNAME DIRNAME
ffff88007ef64380 ffff8800379e7400 ext4 /dev/vda1 /boot
This tells us that that dd was trying to write to /boot. Next part of our job is to find out why couldn't it write to /boot. In order to answer that, let's take a step back and revisit the kernel code at line 677 (where dd was):
677 wait_event(sb->s_writers.wait_unfrozen, 678 sb->s_writers.frozen < level);
Following wait_event() definition tells us that dd was put to sleep (uninterruptible) and will be woken up when "sb->s_writers.frozen < level" condition becomes true:
/**
* wait_event - sleep until a condition gets true
* @wq: the waitqueue to wait on
* @condition: a C expression for the event to wait for
*
* The process is put to sleep (TASK_UNINTERRUPTIBLE) until the
* @condition evaluates to true. The @condition is checked each time
* the waitqueue @wq is woken up.
*
* wake_up() has to be called after changing any variable that could
* change the result of the wait condition.
*/
#define wait_event(wq, condition) \
do { \
if (condition) \
break; \
__wait_event(wq, condition); \
} while (0)
We know that "level" is 1 (second argument SB_FREEZE_WRITE), and sb->s_writers.frozen needs to be less than 1 for this condition to become true. Let's see what exactly is the current value of sb->s_writers.frozen, since we already have sb, it is pretty straightforward to obtain this value:
crash> pd ((struct super_block *)0xffff8800379e7400)->s_writers.frozen $5 = 4
Or do this (I prefer the 1st one):
crash> super_block.s_writers ffff8800379e7400 | grep frozen
frozen = 4,
sb->s_writers.frozen is 4 which obviously is lower than 1 and this is why dd is uninterruptible, but what does this value 4 mean? This is defined in include/linux/fs.h ("cscope" can be used to examine kernel source):
/* Possible states of 'frozen' field */
enum {
SB_UNFROZEN = 0, /* FS is unfrozen */
SB_FREEZE_WRITE = 1, /* Writes, dir ops, ioctls frozen */
SB_FREEZE_TRANS = 2,
SB_FREEZE_PAGEFAULT = 2, /* Page faults stopped as well */
SB_FREEZE_FS = 3, /* For internal FS use (e.g. to stop
* internal threads if needed) */
SB_FREEZE_COMPLETE = 4, /* ->freeze_fs finished successfully */ <<<<<<<
};
4 is SB_FREEZE_COMPLETE, which means that filesystem i.e. /boot is frozen. So, now we can say that dd became uninterruptible because /boot filesystem was frozen, this triggered hung_task_timeout_secs which was caught by hung_task_panic and this caused the crash.
Next step should be to check what exactly froze the filesystem, in this particular case I did it using fsfreeze to collect this vmcore so I can demonstrate a few things about vmcore analysis.
In order to collect this demo vmcore I used a sysctl parameter named hung_task_panic. This parameter when enabled will trigger a crash if a process becomes uninterruptible for more than 120 seconds. hung_task_timeout_secs sysctl parameter controls this duration and is set to 120 seconds by default in RHEL 6/7. After enabling hung_task_panic and reducing hung_task_timeout_secs to 10 seconds:
# echo 1 > /proc/sys/kernel/hung_task_panic # echo 10 > /proc/sys/kernel/hung_task_timeout_secs
I simply executed following dd command on /boot:
# dd if=/dev/zero of=/boot/test
And in the second terminal this:
# fsfreeze -f /boot
This made dd uninterruptible, hung_task_panic kicked in and kdump did its job by saving a vmcore under /var/crash.
We can print these values from vmcore:
crash> p sysctl_hung_task_timeout_secs sysctl_hung_task_timeout_secs = $1 = 10
crash> p sysctl_hung_task_panic sysctl_hung_task_panic = $2 = 1
Please send an email to the kernel meetup list for any queries and if this write-up needs any corrections.
