killed by kernel (due to slow response from ring?)

[cmonfort]

context:

• created a 30GB volume
• gpt partitioned
• single ext4 fs
• mount as /mnt/dew1
• rsync /home directory to /mnt/dew1

dmesg reports lots of blocked tasks and call trace (during ext4 formatting and rsync):

[ 8288.315584] INFO: task mkfs.ext4:21886 blocked for more than 120 seconds.
[ 8288.357969] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[ 8288.400059] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 8288.482878] mkfs.ext4 D ffff88107fc14440 0 21886 21109 0x00000000
[ 8288.482881] ffff880ff78b7b18 0000000000000002 ffff881023e5c7d0 ffff880ff78b7fd8
[ 8288.482883] 0000000000014440 0000000000014440 ffff881023e5c7d0 ffff88107fc14cd8
[ 8288.482884] ffff88107ffc0f58 0000000000000002 ffffffff811ee000 ffff880ff78b7b90
[ 8288.482886] Call Trace:
[ 8288.482892] [] ? generic_block_bmap+0x50/0x50
[ 8288.482896] [] io_schedule+0x9d/0x140
[ 8288.482898] [] sleep_on_buffer+0xe/0x20
[ 8288.482899] [] __wait_on_bit+0x62/0x90
[ 8288.482906] [] ? generic_block_bmap+0x50/0x50
[ 8288.482909] [] out_of_line_wait_on_bit+0x77/0x90
[ 8288.482912] [] ? autoremove_wake_function+0x40/0x40
[ 8288.482914] [] __block_write_begin+0x304/0x430
[ 8288.482917] [] ? __inc_zone_page_state+0x35/0x40
[ 8288.482920] [] ? I_BDEV+0x10/0x10
[ 8288.482921] [] ? I_BDEV+0x10/0x10
[ 8288.482923] [] block_write_begin+0x46/0x90
[ 8288.482926] [] blkdev_write_begin+0x23/0x30
[ 8288.482931] [] generic_file_buffered_write+0xf8/0x250
[ 8288.482933] [] __generic_file_aio_write+0x1c1/0x3d0
[ 8288.482936] [] blkdev_aio_write+0x46/0x90
[ 8288.482939] [] do_sync_write+0x5a/0x90
[ 8288.482941] [] vfs_write+0xb4/0x1f0
[ 8288.482942] [] SyS_write+0x49/0xa0
[ 8288.482945] [] tracesys+0xe1/0xe6

[ 8636.261608] EXT4-fs (dewba1): mounted filesystem with ordered data mode. Opts: (null)
[ 9129.215156] INFO: task jbd2/dewba1-8:22455 blocked for more than 120 seconds.
[ 9129.257238] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[ 9129.299062] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 9129.381405] jbd2/dewba1-8 D ffff88107fd94440 0 22455 2 0x00000000
[ 9129.381408] ffff880ff7fb1bc8 0000000000000002 ffff8810234dafe0 ffff880ff7fb1fd8
[ 9129.381410] 0000000000014440 0000000000014440 ffff8810234dafe0 ffff88107fd94cd8
[ 9129.381412] ffff88107ffbaf58 0000000000000002 ffffffff811ee000 ffff880ff7fb1c40
[ 9129.381413] Call Trace:
[ 9129.381420] [] ? generic_block_bmap+0x50/0x50
[ 9129.381427] [] io_schedule+0x9d/0x140
[ 9129.381429] [] sleep_on_buffer+0xe/0x20
[ 9129.381431] [] __wait_on_bit+0x62/0x90
[ 9129.381432] [] ? generic_block_bmap+0x50/0x50
[ 9129.381434] [] out_of_line_wait_on_bit+0x77/0x90
[ 9129.381437] [] ? autoremove_wake_function+0x40/0x40
[ 9129.381439] [] __wait_on_buffer+0x2a/0x30
[ 9129.381447] [] jbd2_journal_commit_transaction+0x181c/0x1a70
[ 9129.381450] [] ? try_to_del_timer_sync+0x4f/0x70
[ 9129.381453] [] kjournald2+0xbd/0x250
[ 9129.381457] [] ? prepare_to_wait_event+0x100/0x100
[ 9129.381459] [] ? commit_timeout+0x10/0x10
[ 9129.381463] [] kthread+0xd2/0xf0
[ 9129.381464] [] ? kthread_create_on_node+0x1d0/0x1d0
[ 9129.381468] [] ret_from_fork+0x7c/0xb0
[ 9129.381470] [] ? kthread_create_on_node+0x1d0/0x1d0
[ 9129.381473] INFO: task rsync:22502 blocked for more than 120 seconds.
[ 9129.423005] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[ 9129.464284] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 9129.545480] rsync D ffff88107fd14440 0 22502 22501 0x00000000
[ 9129.545481] ffff880ff7ef3bc8 0000000000000002 ffff8810128bc7d0 ffff880ff7ef3fd8
[ 9129.545483] 0000000000014440 0000000000014440 ffff8810128bc7d0 ffff88107fd14cd8
[ 9129.545484] ffff88107ffb7f58 ffff880ff7ef3c50 0000000000000002 ffffffff811ee000
[ 9129.545486] Call Trace:
[ 9129.545488] [] ? generic_block_bmap+0x50/0x50
[ 9129.545490] [] io_schedule+0x9d/0x140
[ 9129.545491] [] sleep_on_buffer+0xe/0x20
[ 9129.545493] [] __wait_on_bit_lock+0x48/0xb0
[ 9129.545494] [] ? generic_block_bmap+0x50/0x50
[ 9129.545496] [] out_of_line_wait_on_bit_lock+0x77/0x90
[ 9129.545498] [] ? autoremove_wake_function+0x40/0x40
[ 9129.545499] [] __lock_buffer+0x2a/0x30
[ 9129.545502] [] __ext4_get_inode_loc+0x208/0x3e0
[ 9129.545509] [] ext4_get_inode_loc+0x1d/0x20
[ 9129.545514] [] ext4_reserve_inode_write+0x26/0xa0
[ 9129.545517] [] ? ext4_ext_tree_init+0x3a/0x40
[ 9129.545519] [] ext4_mark_inode_dirty+0x44/0x1f0
[ 9129.545520] [] ext4_ext_tree_init+0x3a/0x40
[ 9129.545522] [] __ext4_new_inode+0x1368/0x1470
[ 9129.545523] [] ext4_mkdir+0x180/0x3c0
[ 9129.545526] [] ? security_inode_permission+0x1c/0x30
[ 9129.545529] [] vfs_mkdir+0xb7/0x160
[ 9129.545534] [] SyS_mkdir+0xab/0xe0
[ 9129.545536] [] tracesys+0xe1/0xe6
[ 9129.545538] INFO: task rsync:22503 blocked for more than 120 seconds.
[ 9129.586494] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[ 9129.627185] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 9129.707271] rsync D ffff88107fcd4440 0 22503 22502 0x00000000
[ 9129.707276] ffff880ff74499a8 0000000000000002 ffff8810020d17f0 ffff880ff7449fd8
[ 9129.707278] 0000000000014440 0000000000014440 ffff8810020d17f0 ffff88107fcd4cd8
[ 9129.707280] ffff88107ffb7f58 0000000000000002 ffffffff811ee000 ffff880ff7449a20
[ 9129.707282] Call Trace:
[ 9129.707288] [] ? generic_block_bmap+0x50/0x50
[ 9129.707292] [] io_schedule+0x9d/0x140
[ 9129.707294] [] sleep_on_buffer+0xe/0x20
[ 9129.707295] [] __wait_on_bit+0x62/0x90
[ 9129.707297] [] ? generic_block_bmap+0x50/0x50
[ 9129.707298] [] out_of_line_wait_on_bit+0x77/0x90
[ 9129.707301] [] ? autoremove_wake_function+0x40/0x40
[ 9129.707303] [] ? _submit_bh+0x150/0x200
[ 9129.707305] [] __wait_on_buffer+0x2a/0x30
[ 9129.707308] [] __ext4_get_inode_loc+0x1c3/0x3e0
[ 9129.707310] [] ext4_get_inode_loc+0x1d/0x20
[ 9129.707312] [] ext4_reserve_inode_write+0x26/0xa0
[ 9129.707315] [] ? ext4_ext_tree_init+0x3a/0x40
[ 9129.707316] [] ext4_mark_inode_dirty+0x44/0x1f0
[ 9129.707318] [] ext4_ext_tree_init+0x3a/0x40
[ 9129.707319] [] __ext4_new_inode+0x1368/0x1470
[ 9129.707321] [] ext4_create+0xc8/0x170
[ 9129.707324] [] vfs_create+0xcd/0x130
[ 9129.707325] [] do_last+0xffd/0x1200
[ 9129.707329] [] ? apparmor_file_alloc_security+0x5b/0x180
[ 9129.707332] [] ? security_file_alloc+0x16/0x20
[ 9129.707334] [] path_openat+0xbb/0x640
[ 9129.707335] [] ? SYSC_renameat+0xeb/0x410
[ 9129.707337] [] do_filp_open+0x3a/0x90
[ 9129.707340] [] ? __alloc_fd+0xa7/0x130
[ 9129.707342] [] do_sys_open+0x129/0x280
[ 9129.707345] [] ? syscall_trace_enter+0x145/0x250
[ 9129.707347] [] SyS_open+0x1e/0x20
[ 9129.707350] [] tracesys+0xe1/0xe6
[10450.859227] INFO: task jbd2/dewba1-8:22455 blocked for more than 120 seconds.
[10450.900130] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[10450.940932] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10451.021129] jbd2/dewba1-8 D ffff88107fc54440 0 22455 2 0x00000000
[10451.021133] ffff880ff7fb1bc8 0000000000000002 ffff8810234dafe0 ffff880ff7fb1fd8
[10451.021135] 0000000000014440 0000000000014440 ffff8810234dafe0 ffff88107fc54cd8
[10451.021136] ffff88107ffad9b0 0000000000000002 ffffffff811ee000 ffff880ff7fb1c40
[10451.021138] Call Trace:
[10451.021144] [] ? generic_block_bmap+0x50/0x50
[10451.021148] [] io_schedule+0x9d/0x140
[10451.021149] [] sleep_on_buffer+0xe/0x20
[10451.021155] [] __wait_on_bit+0x62/0x90
[10451.021158] [] ? generic_block_bmap+0x50/0x50
[10451.021160] [] out_of_line_wait_on_bit+0x77/0x90
[10451.021163] [] ? autoremove_wake_function+0x40/0x40
[10451.021165] [] __wait_on_buffer+0x2a/0x30
[10451.021169] [] jbd2_journal_commit_transaction+0xee0/0x1a70
[10451.021173] [] ? try_to_del_timer_sync+0x4f/0x70
[10451.021180] [] kjournald2+0xbd/0x250
[10451.021184] [] ? prepare_to_wait_event+0x100/0x100
[10451.021186] [] ? commit_timeout+0x10/0x10
[10451.021190] [] kthread+0xd2/0xf0
[10451.021192] [] ? kthread_create_on_node+0x1d0/0x1d0
[10451.021196] [] ret_from_fork+0x7c/0xb0
[10451.021198] [] ? kthread_create_on_node+0x1d0/0x1d0
[10451.021201] INFO: task rsync:22503 blocked for more than 120 seconds.
[10451.061773] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[10451.102184] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[10451.181670] rsync D ffff88107fc14440 0 22503 22502 0x00000000
[10451.181674] ffff880ff7449938 0000000000000002 ffff8810020d17f0 ffff880ff7449fd8
[10451.181676] 0000000000014440 0000000000014440 ffff8810020d17f0 ffff88107fc14cd8
[10451.181677] ffff88107ffb7418 0000000000000002 ffffffff81284630 ffff880ff74499b0
[10451.181678] Call Trace:
[10451.181682] [] ? start_this_handle+0x590/0x590
[10451.181684] [] io_schedule+0x9d/0x140
[10451.181685] [] sleep_on_shadow_bh+0xe/0x20
[10451.181687] [] __wait_on_bit+0x62/0x90
[10451.181688] [] ? start_this_handle+0x590/0x590
[10451.181690] [] out_of_line_wait_on_bit+0x77/0x90
[10451.181697] [] ? autoremove_wake_function+0x40/0x40
[10451.181701] [] ? wake_up_bit+0x25/0x30
[10451.181702] [] do_get_write_access+0x2ad/0x4f0
[10451.181704] [] ? __getblk+0x2d/0x2e0
[10451.181706] [] jbd2_journal_get_write_access+0x27/0x40
[10451.181709] [] __ext4_journal_get_write_access+0x3b/0x80
[10451.181713] [] ext4_reserve_inode_write+0x70/0xa0
[10451.181715] [] ? ext4_dirty_inode+0x40/0x60
[10451.181718] [] ext4_mark_inode_dirty+0x44/0x1f0
[10451.181720] [] ext4_dirty_inode+0x40/0x60
[10451.181722] [] __mark_inode_dirty+0x10a/0x2d0
[10451.181729] [] generic_write_end+0x59/0x90
[10451.181733] [] ext4_da_write_end+0x9f/0x250
[10451.181737] [] generic_file_buffered_write+0x156/0x250
[10451.181741] [] __generic_file_aio_write+0x1c1/0x3d0
[10451.181744] [] generic_file_aio_write+0x58/0xa0
[10451.181747] [] ext4_file_write+0x99/0x400
[10451.181750] [] do_sync_write+0x5a/0x90
[10451.181753] [] vfs_write+0xb4/0x1f0
[10451.181756] [] SyS_write+0x49/0xa0
[10451.181758] [] tracesys+0xe1/0xe6
[13573.911135] INFO: task kworker/u16:2:15992 blocked for more than 120 seconds.
[13573.951561] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[13573.991709] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[13574.070598] kworker/u16:2 D ffff88107fc94440 0 15992 2 0x00000000
[13574.070605] Workqueue: writeback bdi_writeback_workfn (flush-251:0)
[13574.070606] ffff8800365476f8 0000000000000002 ffff881023ca97f0 ffff880036547fd8
[13574.070608] 0000000000014440 0000000000014440 ffff881023ca97f0 ffff88107fc94cd8
[13574.070610] ffff88107ffae1d8 0000000000000002 ffffffff81284630 ffff880036547770
[13574.070611] Call Trace:
[13574.070616] [] ? start_this_handle+0x590/0x590
[13574.070620] [] io_schedule+0x9d/0x140
[13574.070625] [] sleep_on_shadow_bh+0xe/0x20
[13574.070629] [] __wait_on_bit+0x62/0x90
[13574.070630] [] ? start_this_handle+0x590/0x590
[13574.070632] [] out_of_line_wait_on_bit+0x77/0x90
[13574.070635] [] ? autoremove_wake_function+0x40/0x40
[13574.070637] [] ? wake_up_bit+0x25/0x30
[13574.070639] [] do_get_write_access+0x2ad/0x4f0
[13574.070640] [] jbd2_journal_get_write_access+0x27/0x40
[13574.070646] [] __ext4_journal_get_write_access+0x3b/0x80
[13574.070649] [] ext4_mb_mark_diskspace_used+0x6e/0x4c0
[13574.070651] [] ext4_mb_new_blocks+0x2ad/0x580
[13574.070654] [] ? ext4_ext_find_extent+0x23d/0x2d0
[13574.070655] [] ext4_ext_map_blocks+0x664/0xf40
[13574.070658] [] ? kcore_update_ram+0x130/0x1f0
[13574.070660] [] ext4_map_blocks+0x2d5/0x540
[13574.070662] [] ext4_writepages+0x5f0/0xcd0
[13574.070665] [] do_writepages+0x1e/0x40
[13574.070667] [] __writeback_single_inode+0x40/0x210
[13574.070668] [] writeback_sb_inodes+0x247/0x3e0
[13574.070669] [] __writeback_inodes_wb+0x9f/0xd0
[13574.070670] [] wb_writeback+0x243/0x2c0
[13574.070672] [] bdi_writeback_workfn+0x1b9/0x430
[13574.070675] [] process_one_work+0x182/0x450
[13574.070676] [] worker_thread+0x121/0x410
[13574.070678] [] ? rescuer_thread+0x430/0x430
[13574.070680] [] kthread+0xd2/0xf0
[13574.070681] [] ? kthread_create_on_node+0x1d0/0x1d0
[13574.070684] [] ret_from_fork+0x7c/0xb0
[13574.070686] [] ? kthread_create_on_node+0x1d0/0x1d0
[13574.070760] INFO: task ext4lazyinit:21317 blocked for more than 120 seconds.
[13574.110837] Tainted: GF O 3.13.0-32-generic #57-Ubuntu
[13574.150697] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[13574.229531] ext4lazyinit D ffff88107fc94440 0 21317 2 0x00000000
[13574.229533] ffff880ff7ec3c38 0000000000000002 ffff8810234a47d0 ffff880ff7ec3fd8
[13574.229535] 0000000000014440 0000000000014440 ffff8810234a47d0 ffff88107fc94cd8
[13574.229536] ffff88107ffc2d10 0000000000000002 ffffffff81284630 ffff880ff7ec3cb0
[13574.229538] Call Trace:
[13574.229540] [] ? start_this_handle+0x590/0x590
[13574.229542] [] io_schedule+0x9d/0x140
[13574.229543] [] sleep_on_shadow_bh+0xe/0x20
[13574.229545] [] __wait_on_bit+0x62/0x90
[13574.229548] [] ? internal_add_timer+0x17/0x40
[13574.229549] [] ? start_this_handle+0x590/0x590
[13574.229551] [] out_of_line_wait_on_bit+0x77/0x90
[13574.229553] [] ? autoremove_wake_function+0x40/0x40
[13574.229555] [] ? wake_up_bit+0x25/0x30
[13574.229556] [] do_get_write_access+0x2ad/0x4f0
[13574.229558] [] jbd2_journal_get_write_access+0x27/0x40
[13574.229560] [] __ext4_journal_get_write_access+0x3b/0x80
[13574.229561] [] ext4_init_inode_table+0x11b/0x390
[13574.229564] [] ext4_lazyinit_thread+0x275/0x2f0
[13574.229566] [] ? ext4_unregister_li_request+0x60/0x60
[13574.229567] [] kthread+0xd2/0xf0
[13574.229569] [] ? kthread_create_on_node+0x1d0/0x1d0
[13574.229570] [] ret_from_fork+0x7c/0xb0
[13574.229572] [] ? kthread_create_on_node+0x1d0/0x1d0

[mcolzi]

Tested on navaro:

Start a dd task that fulfill all the disk, the dd is blocked more than 20 seconds and then after exit with the expected error; The driver is not killed by the kernel

INFO: task dd:5250 blocked for more than 20 seconds
Tainted: GF 0 3.13.0-24-generic #46-Ubuntu
and then dd complain that the is no space left on the device and took a while to complete

[olivdelp]

ok now, see TEST_11_No_Regression.test_issue_32_killedByKernel