Re: [PATCH 0/3] OOM detection rework v4

[Tetsuo Handa <penguin-kernel@I-love.SAKURA.ne.jp>]

(Posting as a reply to this thread.)

I was trying to test side effect of "oom, oom_reaper: disable oom_reaper for
oom_kill_allocating_task" compared to "oom: clear TIF_MEMDIE after oom_reaper
managed to unmap the address space" using a reproducer shown below.

---------- Reproducer start ----------
#define _GNU_SOURCE
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <unistd.h>
#include <sys/types.h>
#include <sys/stat.h>
#include <fcntl.h>
#include <sched.h>
#include <sys/prctl.h>
#include <signal.h>

static char buffer[4096] = { };

static int file_io(void *unused)
{
	const int fd = open(buffer, O_WRONLY | O_CREAT | O_APPEND, 0600);
	sleep(2);
	while (write(fd, buffer, sizeof(buffer)) > 0);
	close(fd);
	return 0;
}

int main(int argc, char *argv[])
{
	int i;
	if (chdir("/tmp"))
		return 1;
	for (i = 0; i < 64; i++)
		if (fork() == 0) {
			static cpu_set_t set = { { 1 } };
			const int fd = open("/proc/self/oom_score_adj", O_WRONLY);
			write(fd, "1000", 4);
			close(fd);
			sched_setaffinity(0, sizeof(set), &set);
			snprintf(buffer, sizeof(buffer), "file_io.%02u", i);
			prctl(PR_SET_NAME, (unsigned long) buffer, 0, 0, 0);
			for (i = 0; i < 16; i++)
				clone(file_io, malloc(1024) + 1024, CLONE_VM, NULL);
			while (1)
				pause();
		}
	{ /* A dummy process for invoking the OOM killer. */
		char *buf = NULL;
		unsigned long i;
		unsigned long size = 0;
		prctl(PR_SET_NAME, (unsigned long) "memeater", 0, 0, 0);
		for (size = 1048576; size < 512UL * (1 << 30); size <<= 1) {
			char *cp = realloc(buf, size);
			if (!cp) {
				size >>= 1;
				break;
			}
			buf = cp;
		}
		sleep(4);
		for (i = 0; i < size; i += 4096)
			buf[i] = '\0'; /* Will cause OOM due to overcommit */
	}
	kill(-1, SIGKILL);
	return * (char *) NULL; /* Not reached. */
}
---------- Reproducer end ----------

The characteristic of this reproducer is that the OOM killer chooses the same mm
for multiple times due to clone(!CLONE_SIGHAND && CLONE_VM) and the OOM reaper
happily skips reaping that mm due to marking that mm_struct as MMF_OOM_KILLED or
marking only first victim's signal_struct as OOM_SCORE_ADJ_MIN, which means that
nobody can unlock TIF_MEMDIE when non-first victim cannot terminate.

But the problem I can hit trivially is that kswapd got stuck at unkillable lock
when all allocating tasks are waiting at congestion_wait(). This situation resembles
http://lkml.kernel.org/r/201602092349.ACG81273.OSVtMJQHLOFOFF@I-love.SAKURA.ne.jp
but not looping at too_many_isolated() in shrink_inactive_list().
I don't know what is happening.

Complete log is at http://I-love.SAKURA.ne.jp/tmp/serial-20160311.txt.xz .
---------- console log start ----------
[   81.282661] memeater invoked oom-killer: gfp_mask=0x24280ca(GFP_HIGHUSER_MOVABLE|__GFP_ZERO), order=0, oom_score_adj=0
[   81.297589] memeater cpuset=/ mems_allowed=0
[   81.303615] CPU: 2 PID: 1239 Comm: memeater Tainted: G        W       4.5.0-rc7-next-20160310 #103
(...snipped...)
[   81.456295] Out of memory: Kill process 1240 (file_io.00) score 999 or sacrifice child
[   81.459768] Killed process 1240 (file_io.00) total-vm:4308kB, anon-rss:84kB, file-rss:0kB, shmem-rss:0kB
[   81.682547] ksmtuned invoked oom-killer: gfp_mask=0x24084c0(GFP_KERNEL|__GFP_REPEAT|__GFP_ZERO), order=0, oom_score_adj=0
[   81.703992] ksmtuned cpuset=/ mems_allowed=0
[   81.709402] CPU: 1 PID: 2330 Comm: ksmtuned Tainted: G        W       4.5.0-rc7-next-20160310 #103
(...snipped...)
[   81.928733] Out of memory: Kill process 1248 (file_io.00) score 1000 or sacrifice child
[   81.932194] Killed process 1248 (file_io.00) total-vm:4308kB, anon-rss:104kB, file-rss:1044kB, shmem-rss:0kB
(...snipped...)
[  136.837273] Node 0 DMA free:3864kB min:60kB low:72kB high:84kB active_anon:9504kB inactive_anon:84kB active_file:140kB inactive_file:448kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
present:15988kB managed:15904kB mlocked:0kB dirty:448kB writeback:0kB mapped:172kB shmem:84kB slab_reclaimable:164kB slab_unreclaimable:692kB kernel_stack:448kB pagetables:156kB unstable:0kB
bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:4244 all_unreclaimable? yes
[  136.858075] lowmem_reserve[]: 0 953 953 953
[  136.860609] Node 0 DMA32 free:3648kB min:3780kB low:4752kB high:5724kB active_anon:783216kB inactive_anon:6376kB active_file:33388kB inactive_file:40292kB unevictable:0kB isolated(anon):0kB
isolated(file):128kB present:1032064kB managed:980816kB mlocked:0kB dirty:40232kB writeback:120kB mapped:34720kB shmem:6628kB slab_reclaimable:10528kB slab_unreclaimable:39068kB kernel_stack:20512kB
pagetables:8000kB unstable:0kB bounce:0kB free_pcp:1648kB local_pcp:116kB free_cma:0kB writeback_tmp:0kB pages_scanned:964952 all_unreclaimable? yes
[  136.880330] lowmem_reserve[]: 0 0 0 0
[  136.883137] Node 0 DMA: 28*4kB (UE) 15*8kB (UE) 9*16kB (UME) 1*32kB (M) 2*64kB (UE) 2*128kB (UE) 0*256kB 2*512kB (UE) 2*1024kB (UE) 0*2048kB 0*4096kB = 3864kB
[  136.890862] Node 0 DMA32: 860*4kB (UME) 16*8kB (UME) 1*16kB (M) 0*32kB 1*64kB (M) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3648kB
(...snipped...)
[  143.721805] kswapd0         D ffff880039ffb760     0    52      2 0x00000000
[  143.724711]  ffff880039ffb760 ffff88003bb5e140 ffff880039ff4000 ffff880039ffc000
[  143.727782]  ffff88003a2c3850 ffff88003a2c3868 ffff880039ffb958 0000000000000001
[  143.730815]  ffff880039ffb778 ffffffff81666600 ffff880039ff4000 ffff880039ffb7d8
[  143.733839] Call Trace:
[  143.735190]  [<ffffffff81666600>] schedule+0x30/0x80
[  143.737387]  [<ffffffff8166a066>] rwsem_down_read_failed+0xd6/0x140
[  143.739964]  [<ffffffff81323708>] call_rwsem_down_read_failed+0x18/0x30
[  143.742944]  [<ffffffff810b888b>] down_read_nested+0x3b/0x50
[  143.745315]  [<ffffffffa0242c5b>] ? xfs_ilock+0x4b/0xe0 [xfs]
[  143.747737]  [<ffffffffa0242c5b>] xfs_ilock+0x4b/0xe0 [xfs]
[  143.750071]  [<ffffffffa022d2d0>] xfs_map_blocks+0x80/0x150 [xfs]
[  143.752534]  [<ffffffffa022e27b>] xfs_do_writepage+0x15b/0x500 [xfs]
[  143.755230]  [<ffffffffa022e656>] xfs_vm_writepage+0x36/0x70 [xfs]
[  143.757959]  [<ffffffff8115356f>] pageout.isra.43+0x18f/0x240
[  143.760382]  [<ffffffff81154ed3>] shrink_page_list+0x803/0xae0
[  143.762785]  [<ffffffff8115590b>] shrink_inactive_list+0x1fb/0x460
[  143.765347]  [<ffffffff81156516>] shrink_zone_memcg+0x5b6/0x780
[  143.767801]  [<ffffffff811567b4>] shrink_zone+0xd4/0x2f0
[  143.770084]  [<ffffffff81157661>] kswapd+0x441/0x830
[  143.772193]  [<ffffffff81157220>] ? mem_cgroup_shrink_node_zone+0xb0/0xb0
[  143.774941]  [<ffffffff8109181e>] kthread+0xee/0x110
[  143.777025]  [<ffffffff8166b6f2>] ret_from_fork+0x22/0x50
[  143.779276]  [<ffffffff81091730>] ? kthread_create_on_node+0x230/0x230
(...snipped...)
[  144.479298] file_io.00      D ffff88003ac97cb8     0  1248      1 0x00100084
[  144.482410]  ffff88003ac97cb8 ffff88003b8760c0 ffff88003658c040 ffff88003ac98000
[  144.485513]  ffff88003a280ac8 0000000000000246 ffff88003658c040 00000000ffffffff
[  144.488618]  ffff88003ac97cd0 ffffffff81666600 ffff88003a280ac0 ffff88003ac97ce0
[  144.491661] Call Trace:
[  144.492921]  [<ffffffff81666600>] schedule+0x30/0x80
[  144.495066]  [<ffffffff81666909>] schedule_preempt_disabled+0x9/0x10
[  144.497582]  [<ffffffff816684bf>] mutex_lock_nested+0x14f/0x3a0
[  144.500060]  [<ffffffffa0237eef>] ? xfs_file_buffered_aio_write+0x5f/0x1f0 [xfs]
[  144.503077]  [<ffffffff810bd130>] ? __lock_acquire+0x8c0/0x1f50
[  144.505494]  [<ffffffffa0237eef>] xfs_file_buffered_aio_write+0x5f/0x1f0 [xfs]
[  144.508375]  [<ffffffff8111dfca>] ? __audit_syscall_entry+0xaa/0xf0
[  144.510996]  [<ffffffffa023810a>] xfs_file_write_iter+0x8a/0x150 [xfs]
[  144.514521]  [<ffffffff811bf327>] __vfs_write+0xc7/0x100
[  144.517230]  [<ffffffff811bfedd>] vfs_write+0x9d/0x190
[  144.519407]  [<ffffffff811df5da>] ? __fget_light+0x6a/0x90
[  144.521772]  [<ffffffff811c0713>] SyS_write+0x53/0xd0
[  144.523909]  [<ffffffff8100364d>] do_syscall_64+0x5d/0x180
[  144.526145]  [<ffffffff8166b57f>] entry_SYSCALL64_slow_path+0x25/0x25
(...snipped...)
[  145.684411] kworker/3:3     D ffff88000e987878     0  2329      2 0x00000080
[  145.684415] Workqueue: events_freezable_power_ disk_events_workfn
[  145.684416]  ffff88000e987878 ffff880037d76140 ffff88000e980100 ffff88000e988000
[  145.684417]  ffff88000e9878b0 ffff88003d6d02c0 00000000fffd9bc4 ffff88003ffdf100
[  145.684417]  ffff88000e987890 ffffffff81666600 ffff88003d6d02c0 ffff88000e987938
[  145.684418] Call Trace:
[  145.684419]  [<ffffffff81666600>] schedule+0x30/0x80
[  145.684419]  [<ffffffff8166a687>] schedule_timeout+0x117/0x1c0
[  145.684420]  [<ffffffff810bc306>] ? mark_held_locks+0x66/0x90
[  145.684421]  [<ffffffff810def90>] ? init_timer_key+0x40/0x40
[  145.684422]  [<ffffffff810e5e17>] ? ktime_get+0xa7/0x130
[  145.684423]  [<ffffffff81665b41>] io_schedule_timeout+0xa1/0x110
[  145.684424]  [<ffffffff81160ccd>] congestion_wait+0x7d/0xd0
[  145.684425]  [<ffffffff810b63a0>] ? wait_woken+0x80/0x80
[  145.684426]  [<ffffffff8114a602>] __alloc_pages_nodemask+0xb42/0xd50
[  145.684427]  [<ffffffff810bc300>] ? mark_held_locks+0x60/0x90
[  145.684428]  [<ffffffff81193a26>] alloc_pages_current+0x96/0x1b0
[  145.684430]  [<ffffffff812e1b3d>] ? bio_alloc_bioset+0x20d/0x2d0
[  145.684431]  [<ffffffff812e2e74>] bio_copy_kern+0xc4/0x180
[  145.684433]  [<ffffffff812edb20>] blk_rq_map_kern+0x70/0x130
[  145.684435]  [<ffffffff8145255d>] scsi_execute+0x12d/0x160
[  145.684436]  [<ffffffff81452684>] scsi_execute_req_flags+0x84/0xf0
[  145.684438]  [<ffffffffa01ed762>] sr_check_events+0xb2/0x2a0 [sr_mod]
[  145.684440]  [<ffffffffa01e1163>] cdrom_check_events+0x13/0x30 [cdrom]
[  145.684441]  [<ffffffffa01edba5>] sr_block_check_events+0x25/0x30 [sr_mod]
[  145.684442]  [<ffffffff812f928b>] disk_check_events+0x5b/0x150
[  145.684443]  [<ffffffff812f9397>] disk_events_workfn+0x17/0x20
[  145.684445]  [<ffffffff8108b4c5>] process_one_work+0x1a5/0x400
[  145.684446]  [<ffffffff8108b461>] ? process_one_work+0x141/0x400
[  145.684448]  [<ffffffff8108b846>] worker_thread+0x126/0x490
[  145.684449]  [<ffffffff81665ec1>] ? __schedule+0x311/0xa20
[  145.684450]  [<ffffffff8108b720>] ? process_one_work+0x400/0x400
[  145.684451]  [<ffffffff8109181e>] kthread+0xee/0x110
[  145.684452]  [<ffffffff8166b6f2>] ret_from_fork+0x22/0x50
[  145.684453]  [<ffffffff81091730>] ? kthread_create_on_node+0x230/0x230
(...snipped...)
[  208.035194] Node 0 DMA free:3864kB min:60kB low:72kB high:84kB active_anon:9504kB inactive_anon:84kB active_file:140kB inactive_file:448kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
present:15988kB managed:15904kB mlocked:0kB dirty:448kB writeback:0kB mapped:172kB shmem:84kB slab_reclaimable:164kB slab_unreclaimable:692kB kernel_stack:448kB pagetables:156kB unstable:0kB
bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:4244 all_unreclaimable? yes
[  208.051970] lowmem_reserve[]: 0 953 953 953
[  208.054174] Node 0 DMA32 free:3648kB min:3780kB low:4752kB high:5724kB active_anon:783216kB inactive_anon:6376kB active_file:33388kB inactive_file:40292kB unevictable:0kB isolated(anon):0kB
isolated(file):128kB present:1032064kB managed:980816kB mlocked:0kB dirty:40232kB writeback:120kB mapped:34724kB shmem:6628kB slab_reclaimable:10528kB slab_unreclaimable:39064kB kernel_stack:20512kB
pagetables:8000kB unstable:0kB bounce:0kB free_pcp:1644kB local_pcp:108kB free_cma:0kB writeback_tmp:0kB pages_scanned:1882904 all_unreclaimable? yes
[  208.072237] lowmem_reserve[]: 0 0 0 0
[  208.074340] Node 0 DMA: 28*4kB (UE) 15*8kB (UE) 9*16kB (UME) 1*32kB (M) 2*64kB (UE) 2*128kB (UE) 0*256kB 2*512kB (UE) 2*1024kB (UE) 0*2048kB 0*4096kB = 3864kB
[  208.080915] Node 0 DMA32: 860*4kB (UME) 16*8kB (UME) 1*16kB (M) 0*32kB 1*64kB (M) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3648kB
(...snipped...)
[  290.388544] INFO: task kswapd0:52 blocked for more than 120 seconds.
[  290.391197]       Tainted: G        W       4.5.0-rc7-next-20160310 #103
[  290.393979] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[  290.397150] kswapd0         D ffff880039ffb760     0    52      2 0x00000000
[  290.400194]  ffff880039ffb760 ffff88003bb5e140 ffff880039ff4000 ffff880039ffc000
[  290.403394]  ffff88003a2c3850 ffff88003a2c3868 ffff880039ffb958 0000000000000001
[  290.406715]  ffff880039ffb778 ffffffff81666600 ffff880039ff4000 ffff880039ffb7d8
[  290.409874] Call Trace:
[  290.411242]  [<ffffffff81666600>] schedule+0x30/0x80
[  290.413423]  [<ffffffff8166a066>] rwsem_down_read_failed+0xd6/0x140
[  290.416100]  [<ffffffff81323708>] call_rwsem_down_read_failed+0x18/0x30
[  290.418835]  [<ffffffff810b888b>] down_read_nested+0x3b/0x50
[  290.421278]  [<ffffffffa0242c5b>] ? xfs_ilock+0x4b/0xe0 [xfs]
[  290.423672]  [<ffffffffa0242c5b>] xfs_ilock+0x4b/0xe0 [xfs]
[  290.426042]  [<ffffffffa022d2d0>] xfs_map_blocks+0x80/0x150 [xfs]
[  290.428569]  [<ffffffffa022e27b>] xfs_do_writepage+0x15b/0x500 [xfs]
[  290.431173]  [<ffffffffa022e656>] xfs_vm_writepage+0x36/0x70 [xfs]
[  290.433753]  [<ffffffff8115356f>] pageout.isra.43+0x18f/0x240
[  290.436135]  [<ffffffff81154ed3>] shrink_page_list+0x803/0xae0
[  290.438583]  [<ffffffff8115590b>] shrink_inactive_list+0x1fb/0x460
[  290.441090]  [<ffffffff81156516>] shrink_zone_memcg+0x5b6/0x780
[  290.443500]  [<ffffffff811567b4>] shrink_zone+0xd4/0x2f0
[  290.445703]  [<ffffffff81157661>] kswapd+0x441/0x830
[  290.447973]  [<ffffffff81157220>] ? mem_cgroup_shrink_node_zone+0xb0/0xb0
[  290.450676]  [<ffffffff8109181e>] kthread+0xee/0x110
[  290.452780]  [<ffffffff8166b6f2>] ret_from_fork+0x22/0x50
[  290.455018]  [<ffffffff81091730>] ? kthread_create_on_node+0x230/0x230
[  290.457910] 1 lock held by kswapd0/52:
[  290.459813]  #0:  (&xfs_nondir_ilock_class){++++--}, at: [<ffffffffa0242c5b>] xfs_ilock+0x4b/0xe0 [xfs]
(...snipped...)
[  336.562747] Node 0 DMA free:3864kB min:60kB low:72kB high:84kB active_anon:9504kB inactive_anon:84kB active_file:140kB inactive_file:448kB unevictable:0kB isolated(anon):0kB isolated(file):0kB
present:15988kB managed:15904kB mlocked:0kB dirty:448kB writeback:0kB mapped:172kB shmem:84kB slab_reclaimable:164kB slab_unreclaimable:692kB kernel_stack:448kB pagetables:156kB unstable:0kB
bounce:0kB free_pcp:0kB local_pcp:0kB free_cma:0kB writeback_tmp:0kB pages_scanned:4244 all_unreclaimable? yes
[  336.589823] lowmem_reserve[]: 0 953 953 953
[  336.593296] Node 0 DMA32 free:3776kB min:3780kB low:4752kB high:5724kB active_anon:783216kB inactive_anon:6376kB active_file:33388kB inactive_file:40292kB unevictable:0kB isolated(anon):0kB
isolated(file):128kB present:1032064kB managed:980816kB mlocked:0kB dirty:40232kB writeback:120kB mapped:34724kB shmem:6628kB slab_reclaimable:10528kB slab_unreclaimable:39192kB kernel_stack:20416kB
pagetables:8000kB unstable:0kB bounce:0kB free_pcp:1520kB local_pcp:100kB free_cma:0kB writeback_tmp:0kB pages_scanned:1001584 all_unreclaimable? yes
[  336.618011] lowmem_reserve[]: 0 0 0 0
[  336.620073] Node 0 DMA: 28*4kB (UE) 15*8kB (UE) 9*16kB (UME) 1*32kB (M) 2*64kB (UE) 2*128kB (UE) 0*256kB 2*512kB (UE) 2*1024kB (UE) 0*2048kB 0*4096kB = 3864kB
[  336.626844] Node 0 DMA32: 860*4kB (UME) 18*8kB (UME) 8*16kB (UM) 0*32kB 1*64kB (M) 0*128kB 0*256kB 0*512kB 0*1024kB 0*2048kB 0*4096kB = 3776kB
(...snipped...)
[  393.774051] kswapd0         D ffff880039ffb760     0    52      2 0x00000000
[  393.777018]  ffff880039ffb760 ffff88003bb5e140 ffff880039ff4000 ffff880039ffc000
[  393.779986]  ffff88003a2c3850 ffff88003a2c3868 ffff880039ffb958 0000000000000001
[  393.783000]  ffff880039ffb778 ffffffff81666600 ffff880039ff4000 ffff880039ffb7d8
[  393.785958] Call Trace:
[  393.787191]  [<ffffffff81666600>] schedule+0x30/0x80
[  393.789198]  [<ffffffff8166a066>] rwsem_down_read_failed+0xd6/0x140
[  393.791707]  [<ffffffff81323708>] call_rwsem_down_read_failed+0x18/0x30
[  393.794364]  [<ffffffff810b888b>] down_read_nested+0x3b/0x50
[  393.796634]  [<ffffffffa0242c5b>] ? xfs_ilock+0x4b/0xe0 [xfs]
[  393.798952]  [<ffffffffa0242c5b>] xfs_ilock+0x4b/0xe0 [xfs]
[  393.801274]  [<ffffffffa022d2d0>] xfs_map_blocks+0x80/0x150 [xfs]
[  393.803709]  [<ffffffffa022e27b>] xfs_do_writepage+0x15b/0x500 [xfs]
[  393.806254]  [<ffffffffa022e656>] xfs_vm_writepage+0x36/0x70 [xfs]
[  393.808718]  [<ffffffff8115356f>] pageout.isra.43+0x18f/0x240
[  393.811002]  [<ffffffff81154ed3>] shrink_page_list+0x803/0xae0
[  393.813415]  [<ffffffff8115590b>] shrink_inactive_list+0x1fb/0x460
[  393.815834]  [<ffffffff81156516>] shrink_zone_memcg+0x5b6/0x780
[  393.818316]  [<ffffffff811567b4>] shrink_zone+0xd4/0x2f0
[  393.820472]  [<ffffffff81157661>] kswapd+0x441/0x830
[  393.822658]  [<ffffffff81157220>] ? mem_cgroup_shrink_node_zone+0xb0/0xb0
[  393.825463]  [<ffffffff8109181e>] kthread+0xee/0x110
[  393.827626]  [<ffffffff8166b6f2>] ret_from_fork+0x22/0x50
[  393.829824]  [<ffffffff81091730>] ? kthread_create_on_node+0x230/0x230
(...snipped...)
[  395.000240] file_io.00      D ffff88003ac97cb8     0  1248      1 0x00100084
[  395.003355]  ffff88003ac97cb8 ffff88003b8760c0 ffff88003658c040 ffff88003ac98000
[  395.006582]  ffff88003a280ac8 0000000000000246 ffff88003658c040 00000000ffffffff
[  395.010026]  ffff88003ac97cd0 ffffffff81666600 ffff88003a280ac0 ffff88003ac97ce0
[  395.013010] Call Trace:
[  395.014201]  [<ffffffff81666600>] schedule+0x30/0x80
[  395.016248]  [<ffffffff81666909>] schedule_preempt_disabled+0x9/0x10
[  395.018824]  [<ffffffff816684bf>] mutex_lock_nested+0x14f/0x3a0
[  395.021194]  [<ffffffffa0237eef>] ? xfs_file_buffered_aio_write+0x5f/0x1f0 [xfs]
[  395.024197]  [<ffffffff810bd130>] ? __lock_acquire+0x8c0/0x1f50
[  395.026672]  [<ffffffffa0237eef>] xfs_file_buffered_aio_write+0x5f/0x1f0 [xfs]
[  395.029525]  [<ffffffff8111dfca>] ? __audit_syscall_entry+0xaa/0xf0
[  395.032029]  [<ffffffffa023810a>] xfs_file_write_iter+0x8a/0x150 [xfs]
[  395.034589]  [<ffffffff811bf327>] __vfs_write+0xc7/0x100
[  395.036723]  [<ffffffff811bfedd>] vfs_write+0x9d/0x190
[  395.038841]  [<ffffffff811df5da>] ? __fget_light+0x6a/0x90
[  395.041069]  [<ffffffff811c0713>] SyS_write+0x53/0xd0
[  395.043258]  [<ffffffff8100364d>] do_syscall_64+0x5d/0x180
[  395.045511]  [<ffffffff8166b57f>] entry_SYSCALL64_slow_path+0x25/0x25
(...snipped...)
[  446.012823] kworker/3:3     D ffff88000e987878     0  2329      2 0x00000080
[  446.015632] Workqueue: events_freezable_power_ disk_events_workfn
[  446.018103]  ffff88000e987878 ffff88003cc0c040 ffff88000e980100 ffff88000e988000
[  446.021099]  ffff88000e9878b0 ffff88003d6d02c0 0000000100016c95 ffff88003ffdf100
[  446.024247]  ffff88000e987890 ffffffff81666600 ffff88003d6d02c0 ffff88000e987938
[  446.027332] Call Trace:
[  446.028568]  [<ffffffff81666600>] schedule+0x30/0x80
[  446.030748]  [<ffffffff8166a687>] schedule_timeout+0x117/0x1c0
[  446.033122]  [<ffffffff810bc306>] ? mark_held_locks+0x66/0x90
[  446.035466]  [<ffffffff810def90>] ? init_timer_key+0x40/0x40
[  446.037756]  [<ffffffff810e5e17>] ? ktime_get+0xa7/0x130
[  446.039960]  [<ffffffff81665b41>] io_schedule_timeout+0xa1/0x110
[  446.042385]  [<ffffffff81160ccd>] congestion_wait+0x7d/0xd0
[  446.044651]  [<ffffffff810b63a0>] ? wait_woken+0x80/0x80
[  446.046817]  [<ffffffff8114a602>] __alloc_pages_nodemask+0xb42/0xd50
[  446.049395]  [<ffffffff810bc300>] ? mark_held_locks+0x60/0x90
[  446.051700]  [<ffffffff81193a26>] alloc_pages_current+0x96/0x1b0
[  446.054089]  [<ffffffff812e1b3d>] ? bio_alloc_bioset+0x20d/0x2d0
[  446.056515]  [<ffffffff812e2e74>] bio_copy_kern+0xc4/0x180
[  446.058737]  [<ffffffff812edb20>] blk_rq_map_kern+0x70/0x130
[  446.061105]  [<ffffffff8145255d>] scsi_execute+0x12d/0x160
[  446.063334]  [<ffffffff81452684>] scsi_execute_req_flags+0x84/0xf0
[  446.065810]  [<ffffffffa01ed762>] sr_check_events+0xb2/0x2a0 [sr_mod]
[  446.068343]  [<ffffffffa01e1163>] cdrom_check_events+0x13/0x30 [cdrom]
[  446.070897]  [<ffffffffa01edba5>] sr_block_check_events+0x25/0x30 [sr_mod]
[  446.073569]  [<ffffffff812f928b>] disk_check_events+0x5b/0x150
[  446.075895]  [<ffffffff812f9397>] disk_events_workfn+0x17/0x20
[  446.078340]  [<ffffffff8108b4c5>] process_one_work+0x1a5/0x400
[  446.080696]  [<ffffffff8108b461>] ? process_one_work+0x141/0x400
[  446.083069]  [<ffffffff8108b846>] worker_thread+0x126/0x490
[  446.085395]  [<ffffffff81665ec1>] ? __schedule+0x311/0xa20
[  446.087587]  [<ffffffff8108b720>] ? process_one_work+0x400/0x400
[  446.089996]  [<ffffffff8109181e>] kthread+0xee/0x110
[  446.092242]  [<ffffffff8166b6f2>] ret_from_fork+0x22/0x50
[  446.094527]  [<ffffffff81091730>] ? kthread_create_on_node+0x230/0x230
---------- console log end ----------