testcase
========
original kernel :: latest cosmic version:
----------------------------------------
$ uname -rv
4.18.0-18-generic #19-Ubuntu SMP Tue Apr 2 18:13:16 UTC 2019
[ 654.491029] kprobe_test: loading out-of-tree module taints kernel.
[ 654.493322] kprobe_test: module verification failed: signature and/or
required key missing - tainting kernel
[ 654.497033] mod_init():158 :: hello
[ 654.497976] mod_init():183 :: kernel version: orig/-18/cosmic
[ 694.254271] Program running, TID = 3292
[ 694.256600] kp1_pre_handler():070 :: state 0 .... :: pid = 3292, mapping =
0xffff962333263730, comm = 'test'
[ 694.260870] kp1_pre_handler():079 :: state 0 -> 1 :: pid = 3292, mapping =
0xffff962333263730
[ 694.262710] kp2_pre_handler():119 :: state 1 .... :: pid = 3292, page
index = 1
[ 694.264264] kp3_pre_handler():144 :: state 1 .... :: pid = 3292, page
index = 1, calling writepage()
[ 694.266641] kp2_pre_handler():119 :: state 1 .... :: pid = 3292, page
index = 2
[ 694.268456] kp3_pre_handler():144 :: state 1 .... :: pid = 3292, page
index = 2, calling writepage()
[ 695.276320] Thread 0 running, TID = 3293!
[ 695.281210] kp1_pre_handler():070 :: state 1 .... :: pid = 1165, mapping =
0xffff962333263730, comm = 'kworker/u4:2'
[ 695.299026] kp1_pre_handler():101 :: state 1 -> 2 :: pid = 1165, mapping =
0xffff962333263730, comm ('kworker/u4:2') is kworker AND wbc->range_cyclic
(0x1) is true AND mapping->writeback_index (0x2) is 0x2.
[ 695.314808] kp2_pre_handler():119 :: state 2 .... :: pid = 1165, page
index = 2
[ 695.322822] kp3_pre_handler():144 :: state 2 .... :: pid = 1165, page
index = 2, calling writepage()
[ 695.330308] kp2_pre_handler():119 :: state 2 .... :: pid = 1165, page
index = 1
[ 695.334355] kp2_pre_handler():123 :: state 2 -> 3 :: pid = 1165, page
index = 1, spin 5 seconds before lock_page()...
[ 696.283747] Thread 1 running, TID = 3295!
[ 696.284623] kp1_pre_handler():070 :: state 3 .... :: pid = 3295, mapping =
0xffff962333263730, comm = 'test'
[ 696.286726] kp2_pre_handler():119 :: state 3 .... :: pid = 3295, page
index = 1
[ 696.288392] kp3_pre_handler():144 :: state 3 .... :: pid = 3295, page
index = 1, calling writepage()
[ 696.290018] kp2_pre_handler():119 :: state 3 .... :: pid = 3295, page
index = 2
[ 697.283941] Thread 2 running, TID = 3296!
[ 697.284859] kp1_pre_handler():070 :: state 3 .... :: pid = 3296, mapping =
0xffff962333263730, comm = 'test'
[ 697.287246] kp2_pre_handler():119 :: state 3 .... :: pid = 3296, page
index = 1
[ 700.302756] kp2_pre_handler():127 :: state 3 -> 4 :: pid = 1165, page
index = 1, spun 5 seconds before lock_page().
[ 715.716717] INFO: task kworker/u4:2:1165 blocked for more than 10 seconds.
[ 715.725486] Tainted: G OE 4.18.0-18-generic #19-Ubuntu
[ 715.732832] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 715.740500] kworker/u4:2 D 0 1165 2 0x80000000
[ 715.745615] Workqueue: writeback wb_workfn (flush-7:1)
[ 715.750736] Call Trace:
[ 715.753270] __schedule+0x29e/0x840
[ 715.756493] schedule+0x2c/0x80
[ 715.759369] io_schedule+0x16/0x40
[ 715.762044] __lock_page+0x101/0x150
[ 715.764729] ? page_cache_tree_insert+0xe0/0xe0
[ 715.773625] write_cache_pages+0x283/0x4e0
[ 715.782547] ? xfs_vm_readpage+0x80/0x80 [xfs]
[ 715.792525] ? xfs_vm_readpage+0x80/0x80 [xfs]
[ 715.798175] ? write_cache_pages+0x5/0x4e0
[ 715.803180] xfs_vm_writepages+0x6b/0xa0 [xfs]
[ 715.807087] do_writepages+0x41/0xd0
[ 715.810416] __writeback_single_inode+0x40/0x360
[ 715.813588] ? fprop_fraction_percpu+0x26/0x80
[ 715.816686] writeback_sb_inodes+0x211/0x520
[ 715.819584] __writeback_inodes_wb+0x67/0xb0
[ 715.822661] wb_writeback+0x25f/0x2f0
[ 715.824963] ? get_nr_dirty_inodes+0x46/0x70
[ 715.827180] wb_workfn+0x175/0x3f0
[ 715.829225] process_one_work+0x20f/0x410
[ 715.830964] worker_thread+0x34/0x400
[ 715.832646] kthread+0x120/0x140
[ 715.834551] ? pwq_unbound_release_workfn+0xd0/0xd0
[ 715.836902] ? kthread_bind+0x40/0x40
[ 715.838772] ret_from_fork+0x35/0x40
[ 715.840579] INFO: task test:3293 blocked for more than 10 seconds.
[ 715.842927] Tainted: G OE 4.18.0-18-generic #19-Ubuntu
[ 715.845279] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 715.847771] test D 0 3293 3291 0x00000000
[ 715.849826] Call Trace:
[ 715.851266] __schedule+0x29e/0x840
[ 715.853289] schedule+0x2c/0x80
[ 715.855069] wb_wait_for_completion+0x64/0x90
[ 715.857179] ? wait_woken+0x80/0x80
[ 715.858973] sync_inodes_sb+0xc7/0x290
[ 715.860754] sync_inodes_one_sb+0x15/0x20
[ 715.862383] iterate_supers+0xaa/0x100
[ 715.863938] ? default_file_splice_write+0x30/0x30
[ 715.865666] ksys_sync+0x42/0xb0
[ 715.867082] __ia32_sys_sync+0xe/0x20
[ 715.869122] do_syscall_64+0x5a/0x110
[ 715.871041] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 715.872974] RIP: 0033:0x7f571c1d5287
[ 715.874414] Code: Bad RIP value.
[ 715.875746] RSP: 002b:00007f571c0bced8 EFLAGS: 00000217 ORIG_RAX:
00000000000000a2
[ 715.877851] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f571c1d5287
[ 715.880027] RDX: 000000000000000b RSI: 000055eee9f43f48 RDI: 0000000000000000
[ 715.882158] RBP: 00007f571c0bcef0 R08: 0000000000000000 R09: 0000000000000000
[ 715.884884] R10: 0000000000000000 R11: 0000000000000217 R12: 00007f571c0bcfc0
[ 715.887568] R13: 0000000000000000 R14: 0000000000000000 R15: 00007ffc53c52020
[ 715.890129] INFO: task test:3295 blocked for more than 10 seconds.
[ 715.892430] Tainted: G OE 4.18.0-18-generic #19-Ubuntu
[ 715.894823] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 715.897474] test D 0 3295 3291 0x00000000
[ 715.899546] Call Trace:
[ 715.901264] __schedule+0x29e/0x840
[ 715.903339] ? kp2_pre_handler.cold.1+0x33/0xd7 [kprobe_test]
[ 715.905540] schedule+0x2c/0x80
[ 715.907029] io_schedule+0x16/0x40
[ 715.908846] wait_on_page_bit+0xf7/0x140
[ 715.910379] ? page_cache_tree_insert+0xe0/0xe0
[ 715.911952] write_cache_pages+0x3ec/0x4e0
[ 715.913511] ? xfs_vm_readpage+0x80/0x80 [xfs]
[ 715.915821] ? xfs_vm_readpage+0x80/0x80 [xfs]
[ 715.918031] ? write_cache_pages+0x5/0x4e0
[ 715.919799] xfs_vm_writepages+0x6b/0xa0 [xfs]
[ 715.921751] do_writepages+0x41/0xd0
[ 715.923322] ? iomap_file_buffered_write+0x6e/0xa0
[ 715.925086] ? iomap_dirty_actor+0x220/0x220
[ 715.926871] ? xfs_iunlock+0xf8/0x100 [xfs]
[ 715.928506] __filemap_fdatawrite_range+0xc5/0x100
[ 715.930294] file_write_and_wait_range+0x5a/0xb0
[ 715.932318] xfs_file_fsync+0x5f/0x230 [xfs]
[ 715.934120] vfs_fsync_range+0x48/0x80
[ 715.935814] ? __fget_light+0x54/0x60
[ 715.937488] do_fsync+0x3d/0x70
[ 715.938920] __x64_sys_fsync+0x14/0x20
[ 715.940507] do_syscall_64+0x5a/0x110
[ 715.942050] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 715.943793] RIP: 0033:0x7f571c4c0b07
[ 715.945345] Code: Bad RIP value.
[ 715.946757] RSP: 002b:00007f571b8bbec0 EFLAGS: 00000293 ORIG_RAX:
000000000000004a
[ 715.949159] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f571c4c0b07
[ 715.951646] RDX: 0000000000000000 RSI: 000055eee9f43f48 RDI: 0000000000000003
[ 715.954258] RBP: 00007f571b8bbef0 R08: 0000000000000000 R09: 0000000000000000
[ 715.956484] R10: 0000000000000000 R11: 0000000000000293 R12: 00007f571b8bbfc0
[ 715.958650] R13: 0000000000000000 R14: 0000000000000000 R15: 00007ffc53c52020
[ 715.960822] INFO: task test:3296 blocked for more than 10 seconds.
[ 715.963048] Tainted: G OE 4.18.0-18-generic #19-Ubuntu
[ 715.965231] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this
message.
[ 715.967405] test D 0 3296 3291 0x00000000
[ 715.969468] Call Trace:
[ 715.970835] __schedule+0x29e/0x840
[ 715.972453] ? __switch_to_asm+0x34/0x70
[ 715.973969] ? __switch_to_asm+0x40/0x70
[ 715.975433] schedule+0x2c/0x80
[ 715.976915] io_schedule+0x16/0x40
[ 715.978400] wait_on_page_bit+0xf7/0x140
[ 715.980281] ? page_cache_tree_insert+0xe0/0xe0
[ 715.982226] write_cache_pages+0x3ec/0x4e0
[ 715.984178] ? xfs_vm_readpage+0x80/0x80 [xfs]
[ 715.986189] ? xfs_vm_readpage+0x80/0x80 [xfs]
[ 715.987733] ? write_cache_pages+0x5/0x4e0
[ 715.989244] xfs_vm_writepages+0x6b/0xa0 [xfs]
[ 715.990798] do_writepages+0x41/0xd0
[ 715.992261] ? iomap_file_buffered_write+0x6e/0xa0
[ 715.993940] ? iomap_dirty_actor+0x220/0x220
[ 715.995557] ? xfs_iunlock+0xf8/0x100 [xfs]
[ 715.997147] __filemap_fdatawrite_range+0xc5/0x100
[ 715.998849] file_write_and_wait_range+0x5a/0xb0
[ 716.000724] xfs_file_fsync+0x5f/0x230 [xfs]
[ 716.002367] vfs_fsync_range+0x48/0x80
[ 716.004082] ? __fget_light+0x54/0x60
[ 716.005492] do_fsync+0x3d/0x70
[ 716.006851] __x64_sys_fsync+0x14/0x20
[ 716.008342] do_syscall_64+0x5a/0x110
[ 716.010189] entry_SYSCALL_64_after_hwframe+0x44/0xa9
[ 716.012084] RIP: 0033:0x7f571c4c0b07
[ 716.013603] Code: Bad RIP value.
[ 716.015091] RSP: 002b:00007f571b0baec0 EFLAGS: 00000293 ORIG_RAX:
000000000000004a
[ 716.017558] RAX: ffffffffffffffda RBX: 0000000000000003 RCX: 00007f571c4c0b07
[ 716.019800] RDX: 0000000000000000 RSI: 000055eee9f43f48 RDI: 0000000000000003
[ 716.022123] RBP: 00007f571b0baef0 R08: 0000000000000000 R09: 0000000000000000
[ 716.024160] R10: 0000000000000000 R11: 0000000000000293 R12: 00007f571b0bafc0
[ 716.026345] R13: 0000000000000000 R14: 0000000000000000 R15: 00007ffc53c52020
$ ps -eLo pid,tid,state,comm | grep D | grep -e test -e kworker
1165 1165 D kworker/u4:2+fl
3292 3293 D test
3292 3295 D test
3292 3296 D test
--
You received this bug notification because you are a member of Kernel
Packages, which is subscribed to linux in Ubuntu.
https://bugs.launchpad.net/bugs/1824827
Title:
tasks doing write()/fsync() hit deadlock in write_cache_pages()
Status in linux package in Ubuntu:
Invalid
Status in linux source package in Cosmic:
Confirmed
Status in linux source package in Disco:
Invalid
Bug description:
[Impact]
* Tasks of a multi-threaded workload doing write() and fsync()
might deadlock in write_cache_pages(), preventing progress.
* The fix addresses a corner case in write_cache_pages() on
the range_cyclic implementation which allows the deadlock.
* Patch:
- commit 64081362e8ff4587b4554087f3cfc73d3e0a4cd7
("mm/page-writeback.c: fix range_cyclic writeback vs
writepages deadlock"), present in v4.20-rc1~92^2~19.
[Test Case]
* This issue originally has been hit by the 'perforce' (p4d)
tool in a XFS filesystem, but it's difficult/rare to occur.
* We've written an userspace + kernel module (kprobes-based)
to reproduce this problem and verify the test kernel/patch.
* The kprobes are strictly tied to particular kernel versions
because of the assembly instruction offsets. We'll provide
updated versions for -updates and -proposed for verification.
* Steps
(see output examples in comments):
- Userspace part:
$ gcc -o test test.c -pthread
- Kernel part:
$ touch Makefile
$ make -C /lib/modules/$(uname -r)/build M=$(pwd) obj-m=kprobe-test.o clean
$ make -C /lib/modules/$(uname -r)/build M=$(pwd) obj-m=kprobe-test.o
modules
- Shorter hung task timeout and higher console logging level
to notice the deadlocked tasks sooner, and watch progress:
$ echo 10 | sudo tee /proc/sys/kernel/hung_task_timeout_secs
$ echo 9 | sudo tee /proc/sys/kernel/printk
- Load module / Run userspace part (logging to kernel log) in XFS:
$ sudo insmod kprobe-test.ko
$ cd /path/to/xfs-mountpoint && sudo sh -c 'stdbuf -oL /path/to/test
>/dev/kmsg'
$ sudo rmmod kprobe-test
You may need to ctrl-z with the original kernel as 'test' doesn't
finish.
- Check kernel log or watch the system console:
$ dmesg
Check threads in D state.
$ ps -eLo pid,tid,state,comm | grep D | grep -e test -e kworker
[Regression Potential]
* The patch is small but changes core writeback infrastructure,
so there's a chance this may _affect_ some or other behavior
that has not been validated with our regression testing; not
exactly _break_ it. Please note our regression testing.
* This has been verified with 'xfstests' (not only for XFS fs,
despite its original name), used by major Linux filesystems
for regression testing during development. It's been tested
on systems with 24 and 4 CPUs (to exercise differences in
scalability, parallelism, and workload) and XFS and ext4
(reporter's environment + Ubuntu's default).
No regressions were observed (the set of failed tests is
the same in each system and tests failed in the same way).
* This has also been verified with 'iozone' for write intensive
tests, to exercise the writeback mechanism and no errors were
observed.
* The reporter has been running the test kernel with the patch
for weeks and has not observed any other issues/regressions.
[Other Info]
* This is only required in Cosmic (for the Bionic HWE kernel),
and is already applied in Disco.
To manage notifications about this bug go to:
https://bugs.launchpad.net/ubuntu/+source/linux/+bug/1824827/+subscriptions
--
Mailing list: https://launchpad.net/~kernel-packages
Post to : [email protected]
Unsubscribe : https://launchpad.net/~kernel-packages
More help : https://help.launchpad.net/ListHelp
