Comment 3 for bug 1824827

Revision history for this message
Mauricio Faria de Oliveira (mfo) wrote :

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