Process stuck in md_flush_request (state: D)

Process stuck in md_flush_request (state: D)

[Les Stroud]

I have a problem with processes entering an uninterruptible sleep state in md_flush_request and never returning. I having trouble identifying the underlying issue. I’m hoping someone on here may be able to help.

The servers in question are running in aws (xen hvm) with kernel 3.8.13-118.16.2.el6uek.x86_64.  The server has two mounts.  The first is vanilla ext4.  The second is a software RAID0 array, striped with 256k chunks, buiIt with md.  It’s file system is ext4. 

The most immediately and obvious symptom of the issue are kernel errors “kernel: INFO task [some process]: blocked for more than 120 seconds.”.  Shortly there after, other processes start entering the same uninterruptible wait state (D). This almost always impacts ssh logins.

The problem does not occur when the system is under load, or was recently under load.  It happens when the system is quiet (no cpu, very little io).

I’ve been able to gather a little information from the logs and process tree (when I could get in). It seems to start with an md process (jdb2/md-127-8). Most of the time it’s queuing up kworker processes behind it.  However, I’ve seen other processes stuck as well.  When I can find a way to execute commands on the box, some of them will work, some of them will hand immediately, and others will work a few times before hanging themselves. Every time I have been able to look, I’ve found these “hung” processes sitting in one of two methods md_flush_cache and md_flush_request.  


I would appreciate any help you can provide to diagnose and resolve this issue, find an available patch, or report a bug (if necessary).



Here is a piece of one of the call traces:

	Feb  6 15:41:57 server1 kernel: INFO: task jbd2/md127-8:2511 blocked for more than 120 seconds.
	Feb  6 15:41:57 server1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	Feb  6 15:41:57 server1 kernel: jbd2/md127-8    D ffffffff815c6d00     0  2511      2 0x00000000
	Feb  6 15:41:57 server1 kernel: ffff8803f8a659c8 0000000000000046 ffff8803f8a65fd8 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f8a64010 0000000000013040 0000000000013040 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f8a65fd8 0000000000013040 ffff8803f95b8300 ffff8803f5c3e340
	Feb  6 15:41:57 server1 kernel: Call Trace:
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0ea9>] schedule+0x29/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b886>] md_flush_request+0x86/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086da0>] ? wake_up_bit+0x40/0x40
	Feb  6 15:41:57 server1 kernel: [<ffffffffa00ab6eb>] raid0_make_request+0x11b/0x200 [raid0]
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126c83d>] ? generic_make_request_checks+0x1ad/0x400
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b60c>] md_make_request+0xdc/0x240
	Feb  6 15:41:57 server1 kernel: [<ffffffff81135365>] ? mempool_alloc_slab+0x15/0x20
	Feb  6 15:41:57 server1 kernel: [<ffffffff811354d0>] ? mempool_alloc+0x60/0x170
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cb5a>] generic_make_request+0xca/0x100
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cc09>] submit_bio+0x79/0x160
	Feb  6 15:41:57 server1 kernel: [<ffffffff811ce0e5>] ? bio_alloc_bioset+0x65/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c8e50>] _submit_bh+0x130/0x200
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c8f30>] submit_bh+0x10/0x20
	Feb  6 15:41:57 server1 kernel: [<ffffffffa0167fbd>] journal_submit_commit_record+0x14d/0x1d0 [jbd2]
	Feb  6 15:41:57 server1 kernel: [<ffffffffa016e380>] ? journal_free_journal_head+0x60/0x70 [jbd2]
	Feb  6 15:41:57 server1 kernel: [<ffffffffa0168eab>] jbd2_journal_commit_transaction+0xcfb/0x1950 [jbd2]
	Feb  6 15:41:57 server1 kernel: [<ffffffffa016f213>] kjournald2+0xf3/0x3e0 [jbd2]
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086da0>] ? wake_up_bit+0x40/0x40
	Feb  6 15:41:57 server1 kernel: [<ffffffffa016f120>] ? commit_timeout+0x10/0x10 [jbd2]
	Feb  6 15:41:57 server1 kernel: [<ffffffff810864ee>] kthread+0xce/0xe0
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff815aa9c8>] ret_from_fork+0x58/0x90
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: INFO: task ora_ckpt_rdbdev:1200 blocked for more than 120 seconds.
	Feb  6 15:41:57 server1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	Feb  6 15:41:57 server1 kernel: ora_ckpt_rdbdev D ffffffff815c6d00     0  1200      1 0x00000080
	Feb  6 15:41:57 server1 kernel: ffff8803f5327898 0000000000000082 ffff8803f5327fd8 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f5326010 0000000000013040 0000000000013040 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f5327fd8 0000000000013040 ffffffff818c3420 ffff8803f7ad4140
	Feb  6 15:41:57 server1 kernel: Call Trace:
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0ea9>] schedule+0x29/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a119e>] schedule_preempt_disabled+0xe/0x10
	Feb  6 15:41:57 server1 kernel: [<ffffffff8159f767>] __mutex_lock_slowpath+0x177/0x220
	Feb  6 15:41:57 server1 kernel: [<ffffffff81138e51>] ? prep_new_page+0x111/0x180
	Feb  6 15:41:57 server1 kernel: [<ffffffff8159f5cb>] mutex_lock+0x2b/0x50
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d400e>] do_blockdev_direct_IO+0x7be/0x860
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d40fc>] __blockdev_direct_IO+0x4c/0x50
	Feb  6 15:41:57 server1 kernel: [<ffffffffa0191ab0>] ? ext4_get_block_write+0x20/0x20 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffffa01d0c78>] ext4_ind_direct_IO+0xf8/0x480 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffffa0191ab0>] ? ext4_get_block_write+0x20/0x20 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffffa019331b>] ext4_ext_direct_IO+0x16b/0x240 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffffa01934c9>] ext4_direct_IO+0xd9/0x180 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffff811349e2>] generic_file_read_iter+0x122/0x130
	Feb  6 15:41:57 server1 kernel: [<ffffffff8119615c>] do_aio_read+0xbc/0xd0
	Feb  6 15:41:57 server1 kernel: [<ffffffff81196217>] do_sync_read+0xa7/0xe0
	Feb  6 15:41:57 server1 kernel: [<ffffffff81196521>] vfs_read+0xb1/0x130
	Feb  6 15:41:57 server1 kernel: [<ffffffff81196eaa>] sys_pread64+0x9a/0xb0
	Feb  6 15:41:57 server1 kernel: [<ffffffff815aaa79>] system_call_fastpath+0x16/0x1b
	Feb  6 15:41:57 server1 kernel: INFO: task kworker/0:5:30438 blocked for more than 120 seconds.
	Feb  6 15:41:57 server1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	Feb  6 15:41:57 server1 kernel: kworker/0:5     D 0000000000000000     0 30438      2 0x00000080
	Feb  6 15:41:57 server1 kernel: ffff8803f7df5ad8 0000000000000046 ffff8803f7df5fd8 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f7df4010 0000000000013040 0000000000013040 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f7df5fd8 0000000000013040 ffff8802958be500 ffff8802acd20200
	Feb  6 15:41:57 server1 kernel: Call Trace:
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0ea9>] schedule+0x29/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b886>] md_flush_request+0x86/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086da0>] ? wake_up_bit+0x40/0x40
	Feb  6 15:41:57 server1 kernel: [<ffffffff8159eed5>] ? schedule_timeout+0x195/0x220
	Feb  6 15:41:57 server1 kernel: [<ffffffffa00ab6eb>] raid0_make_request+0x11b/0x200 [raid0]
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126c83d>] ? generic_make_request_checks+0x1ad/0x400
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b60c>] md_make_request+0xdc/0x240
	Feb  6 15:41:57 server1 kernel: [<ffffffff81135365>] ? mempool_alloc_slab+0x15/0x20
	Feb  6 15:41:57 server1 kernel: [<ffffffff811354d0>] ? mempool_alloc+0x60/0x170
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cb5a>] generic_make_request+0xca/0x100
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cc09>] submit_bio+0x79/0x160
	Feb  6 15:41:57 server1 kernel: [<ffffffff811ce0e5>] ? bio_alloc_bioset+0x65/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126fe68>] blkdev_issue_flush+0xb8/0xf0
	Feb  6 15:41:57 server1 kernel: [<ffffffffa018c807>] ext4_sync_file+0x167/0x300 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c642e>] vfs_fsync_range+0x2e/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c6491>] generic_write_sync+0x41/0x50
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1d8b>] dio_complete+0x11b/0x140
	Feb  6 15:41:57 server1 kernel: [<ffffffff8107ce0c>] ? need_to_create_worker+0x1c/0x40
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1f04>] dio_aio_complete_work+0x24/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff8107ea50>] process_one_work+0x180/0x420
	Feb  6 15:41:57 server1 kernel: [<ffffffff8108119e>] worker_thread+0x12e/0x390
	Feb  6 15:41:57 server1 kernel: [<ffffffff81081070>] ? manage_workers+0x180/0x180
	Feb  6 15:41:57 server1 kernel: [<ffffffff810864ee>] kthread+0xce/0xe0
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff815aa9c8>] ret_from_fork+0x58/0x90
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: INFO: task kworker/1:2:31430 blocked for more than 120 seconds.
	Feb  6 15:41:57 server1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	Feb  6 15:41:57 server1 kernel: kworker/1:2     D 0000000000000001     0 31430      2 0x00000080
	Feb  6 15:41:57 server1 kernel: ffff8802a7dcfb58 0000000000000046 ffff8802a7dcffd8 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8802a7dce010 0000000000013040 0000000000013040 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8802a7dcffd8 0000000000013040 ffff8803f6dca3c0 ffff8802a25bc580
	Feb  6 15:41:57 server1 kernel: Call Trace:
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0ea9>] schedule+0x29/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff8159eed5>] schedule_timeout+0x195/0x220
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126c83d>] ? generic_make_request_checks+0x1ad/0x400
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b60c>] ? md_make_request+0xdc/0x240
	Feb  6 15:41:57 server1 kernel: [<ffffffff81135365>] ? mempool_alloc_slab+0x15/0x20
	Feb  6 15:41:57 server1 kernel: [<ffffffff811354d0>] ? mempool_alloc+0x60/0x170
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0cda>] wait_for_common+0x11a/0x170
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cb5a>] ? generic_make_request+0xca/0x100
	Feb  6 15:41:57 server1 kernel: [<ffffffff8109a3d0>] ? try_to_wake_up+0x2e0/0x2e0
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0e0d>] wait_for_completion+0x1d/0x20
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126fe70>] blkdev_issue_flush+0xc0/0xf0
	Feb  6 15:41:57 server1 kernel: [<ffffffffa018c8ef>] ext4_sync_file+0x24f/0x300 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c642e>] vfs_fsync_range+0x2e/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c6491>] generic_write_sync+0x41/0x50
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1d8b>] dio_complete+0x11b/0x140
	Feb  6 15:41:57 server1 kernel: [<ffffffff8107ce0c>] ? need_to_create_worker+0x1c/0x40
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1f04>] dio_aio_complete_work+0x24/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff8107ea50>] process_one_work+0x180/0x420
	Feb  6 15:41:57 server1 kernel: [<ffffffff8108119e>] worker_thread+0x12e/0x390
	Feb  6 15:41:57 server1 kernel: [<ffffffff81081070>] ? manage_workers+0x180/0x180
	Feb  6 15:41:57 server1 kernel: [<ffffffff810864ee>] kthread+0xce/0xe0
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff815aa9c8>] ret_from_fork+0x58/0x90
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: INFO: task kworker/3:0:32582 blocked for more than 120 seconds.
	Feb  6 15:41:57 server1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	Feb  6 15:41:57 server1 kernel: kworker/3:0     D 0000000000000003     0 32582      2 0x00000080
	Feb  6 15:41:57 server1 kernel: ffff8803f6e97ad8 0000000000000046 ffff8803f6e97fd8 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f6e96010 0000000000013040 0000000000013040 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff8803f6e97fd8 0000000000013040 ffff8802b7806440 ffff8802a1f92540
	Feb  6 15:41:57 server1 kernel: Call Trace:
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0ea9>] schedule+0x29/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b886>] md_flush_request+0x86/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086da0>] ? wake_up_bit+0x40/0x40
	Feb  6 15:41:57 server1 kernel: [<ffffffffa00ab6eb>] raid0_make_request+0x11b/0x200 [raid0]
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126c83d>] ? generic_make_request_checks+0x1ad/0x400
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b60c>] md_make_request+0xdc/0x240
	Feb  6 15:41:57 server1 kernel: [<ffffffff81135365>] ? mempool_alloc_slab+0x15/0x20
	Feb  6 15:41:57 server1 kernel: [<ffffffff811354d0>] ? mempool_alloc+0x60/0x170
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cb5a>] generic_make_request+0xca/0x100
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cc09>] submit_bio+0x79/0x160
	Feb  6 15:41:57 server1 kernel: [<ffffffff811ce0e5>] ? bio_alloc_bioset+0x65/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126fe68>] blkdev_issue_flush+0xb8/0xf0
	Feb  6 15:41:57 server1 kernel: [<ffffffffa018c807>] ext4_sync_file+0x167/0x300 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c642e>] vfs_fsync_range+0x2e/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c6491>] generic_write_sync+0x41/0x50
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1d8b>] dio_complete+0x11b/0x140
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1f04>] dio_aio_complete_work+0x24/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff8107ea50>] process_one_work+0x180/0x420
	Feb  6 15:41:57 server1 kernel: [<ffffffff8108119e>] worker_thread+0x12e/0x390
	Feb  6 15:41:57 server1 kernel: [<ffffffff81081070>] ? manage_workers+0x180/0x180
	Feb  6 15:41:57 server1 kernel: [<ffffffff810864ee>] kthread+0xce/0xe0
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff815aa9c8>] ret_from_fork+0x58/0x90
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: INFO: task kworker/1:1:416 blocked for more than 120 seconds.
	Feb  6 15:41:57 server1 kernel: "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
	Feb  6 15:41:57 server1 kernel: kworker/1:1     D ffffffff815c6d00     0   416      2 0x00000080
	Feb  6 15:41:57 server1 kernel: ffff88029ff75ad8 0000000000000046 ffff88029ff75fd8 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff88029ff74010 0000000000013040 0000000000013040 0000000000013040
	Feb  6 15:41:57 server1 kernel: ffff88029ff75fd8 0000000000013040 ffff8803f95b8300 ffff8802b1d983c0
	Feb  6 15:41:57 server1 kernel: Call Trace:
	Feb  6 15:41:57 server1 kernel: [<ffffffff815a0ea9>] schedule+0x29/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b886>] md_flush_request+0x86/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086da0>] ? wake_up_bit+0x40/0x40
	Feb  6 15:41:57 server1 kernel: [<ffffffffa00ab6eb>] raid0_make_request+0x11b/0x200 [raid0]
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126c83d>] ? generic_make_request_checks+0x1ad/0x400
	Feb  6 15:41:57 server1 kernel: [<ffffffff8146b60c>] md_make_request+0xdc/0x240
	Feb  6 15:41:57 server1 kernel: [<ffffffff81135365>] ? mempool_alloc_slab+0x15/0x20
	Feb  6 15:41:57 server1 kernel: [<ffffffff811354d0>] ? mempool_alloc+0x60/0x170
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cb5a>] generic_make_request+0xca/0x100
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126cc09>] submit_bio+0x79/0x160
	Feb  6 15:41:57 server1 kernel: [<ffffffff811ce0e5>] ? bio_alloc_bioset+0x65/0x120
	Feb  6 15:41:57 server1 kernel: [<ffffffff8126fe68>] blkdev_issue_flush+0xb8/0xf0
	Feb  6 15:41:57 server1 kernel: [<ffffffffa018c807>] ext4_sync_file+0x167/0x300 [ext4]
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c642e>] vfs_fsync_range+0x2e/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff811c6491>] generic_write_sync+0x41/0x50
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1d8b>] dio_complete+0x11b/0x140
	Feb  6 15:41:57 server1 kernel: [<ffffffff811d1f04>] dio_aio_complete_work+0x24/0x30
	Feb  6 15:41:57 server1 kernel: [<ffffffff8107ea50>] process_one_work+0x180/0x420
	Feb  6 15:41:57 server1 kernel: [<ffffffff8108119e>] worker_thread+0x12e/0x390
	Feb  6 15:41:57 server1 kernel: [<ffffffff81081070>] ? manage_workers+0x180/0x180
	Feb  6 15:41:57 server1 kernel: [<ffffffff810864ee>] kthread+0xce/0xe0
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70
	Feb  6 15:41:57 server1 kernel: [<ffffffff815aa9c8>] ret_from_fork+0x58/0x90
	Feb  6 15:41:57 server1 kernel: [<ffffffff81086420>] ? kthread_freezable_should_stop+0x70/0x70



Thank you for the time,
LES

Re: Process stuck in md_flush_request (state: D)

[Shaohua Li]

On Fri, Feb 17, 2017 at 02:05:49PM -0500, Les Stroud wrote:
> 
> I have a problem with processes entering an uninterruptible sleep state in md_flush_request and never returning. I having trouble identifying the underlying issue. I’m hoping someone on here may be able to help.
> 
> The servers in question are running in aws (xen hvm) with kernel 3.8.13-118.16.2.el6uek.x86_64.  The server has two mounts.  The first is vanilla ext4.  The second is a software RAID0 array, striped with 256k chunks, buiIt with md.  It’s file system is ext4. 
> 
> The most immediately and obvious symptom of the issue are kernel errors “kernel: INFO task [some process]: blocked for more than 120 seconds.”.  Shortly there after, other processes start entering the same uninterruptible wait state (D). This almost always impacts ssh logins.
> 
> The problem does not occur when the system is under load, or was recently under load.  It happens when the system is quiet (no cpu, very little io).

This seems suggesting we have a missed blk-plug flush in light workload. Can
you check the output of /sys/block/disk-bame/inflight for both md and the
underlayer disks? This will let us know if there is IO pending.
Also it would be great if you can test a upstream kernel.

Thanks,
Shaohua

Re: Process stuck in md_flush_request (state: D)

[Les Stroud]

It’ll take a day or two for it to happen again.  When it does, I’ll pull the inflight stats.  Anything else I should grab while I’m at it?

Thanx,
LES


> On Feb 17, 2017, at 3:06 PM, Shaohua Li <shli@kernel.org> wrote:
> 
> On Fri, Feb 17, 2017 at 02:05:49PM -0500, Les Stroud wrote:
>> 
>> I have a problem with processes entering an uninterruptible sleep state in md_flush_request and never returning. I having trouble identifying the underlying issue. I’m hoping someone on here may be able to help.
>> 
>> The servers in question are running in aws (xen hvm) with kernel 3.8.13-118.16.2.el6uek.x86_64.  The server has two mounts.  The first is vanilla ext4.  The second is a software RAID0 array, striped with 256k chunks, buiIt with md.  It’s file system is ext4. 
>> 
>> The most immediately and obvious symptom of the issue are kernel errors “kernel: INFO task [some process]: blocked for more than 120 seconds.”.  Shortly there after, other processes start entering the same uninterruptible wait state (D). This almost always impacts ssh logins.
>> 
>> The problem does not occur when the system is under load, or was recently under load.  It happens when the system is quiet (no cpu, very little io).
> 
> This seems suggesting we have a missed blk-plug flush in light workload. Can
> you check the output of /sys/block/disk-bame/inflight for both md and the
> underlayer disks? This will let us know if there is IO pending.
> Also it would be great if you can test a upstream kernel.
> 
> Thanks,
> Shaohua

Re: Process stuck in md_flush_request (state: D)

[Les Stroud]

After a period of a couple of weeks with one of our test instances having this problem every other day, they were all nice enough to operate without an issue for 9 days.  It finally reoccurred last night on one of the machines.  

It exhibits the same symptoms and the call traces look as they did previously.  This particular instance is configured with a deadline scheduler.  I was able to capture the inflight you requested:

$ cat /sys/block/xvd[abcde]/inflight
       0        0
       0        0
       0        0
       0        0
       0        0

I’ve had this happen on instances with the deadline scheduler and the noop scheduler.  At this point, I have not had this happen on an instance that is noop and the raid filesystem (ext4) is mounted with nobarrier.  The instances with noop/nobarrier have not been running long enough for me to make any sort of conclusion that it works around the problem.  Frankly, I’m not sure I understand the interaction between ext4 barriers and raid0 block flushes well enough to theorize whether it should or shouldn’t make a difference.

Does any of this help with identifying the bug?  Is there anymore information I can get that would be useful?  

I have some systems that need to be moved into production in the next couple of weeks that are having this problem.  Do you have any ideas how I might be able to work around the problem?



Thanx for the time,
LES



> On Feb 17, 2017, at 3:40 PM, Les Stroud <les@lesstroud.com> wrote:
> 
> It’ll take a day or two for it to happen again.  When it does, I’ll pull the inflight stats.  Anything else I should grab while I’m at it?
> 
> Thanx,
> LES
> 
> 
>> On Feb 17, 2017, at 3:06 PM, Shaohua Li <shli@kernel.org> wrote:
>> 
>> On Fri, Feb 17, 2017 at 02:05:49PM -0500, Les Stroud wrote:
>>> 
>>> I have a problem with processes entering an uninterruptible sleep state in md_flush_request and never returning. I having trouble identifying the underlying issue. I’m hoping someone on here may be able to help.
>>> 
>>> The servers in question are running in aws (xen hvm) with kernel 3.8.13-118.16.2.el6uek.x86_64.  The server has two mounts.  The first is vanilla ext4.  The second is a software RAID0 array, striped with 256k chunks, buiIt with md.  It’s file system is ext4. 
>>> 
>>> The most immediately and obvious symptom of the issue are kernel errors “kernel: INFO task [some process]: blocked for more than 120 seconds.”.  Shortly there after, other processes start entering the same uninterruptible wait state (D). This almost always impacts ssh logins.
>>> 
>>> The problem does not occur when the system is under load, or was recently under load.  It happens when the system is quiet (no cpu, very little io).
>> 
>> This seems suggesting we have a missed blk-plug flush in light workload. Can
>> you check the output of /sys/block/disk-bame/inflight for both md and the
>> underlayer disks? This will let us know if there is IO pending.
>> Also it would be great if you can test a upstream kernel.
>> 
>> Thanks,
>> Shaohua
> 

Re: Process stuck in md_flush_request (state: D)

[Shaohua Li]

On Mon, Feb 27, 2017 at 09:49:59AM -0500, Les Stroud wrote:
> After a period of a couple of weeks with one of our test instances having this problem every other day, they were all nice enough to operate without an issue for 9 days.  It finally reoccurred last night on one of the machines.  
> 
> It exhibits the same symptoms and the call traces look as they did previously.  This particular instance is configured with a deadline scheduler.  I was able to capture the inflight you requested:
> 
> $ cat /sys/block/xvd[abcde]/inflight
>        0        0
>        0        0
>        0        0
>        0        0
>        0        0
> 
> I’ve had this happen on instances with the deadline scheduler and the noop scheduler.  At this point, I have not had this happen on an instance that is noop and the raid filesystem (ext4) is mounted with nobarrier.  The instances with noop/nobarrier have not been running long enough for me to make any sort of conclusion that it works around the problem.  Frankly, I’m not sure I understand the interaction between ext4 barriers and raid0 block flushes well enough to theorize whether it should or shouldn’t make a difference.

If nobarrier, ext4 doesn't send flush request.
 
> Does any of this help with identifying the bug?  Is there anymore information I can get that would be useful?  


Unfortunately I can't find anything fishing. Does the xcdx disk correctly
handle flush request? For example, you can do the same test with a single such
disk and check if anything wrong.

Thanks,
Shaohua

Re: Process stuck in md_flush_request (state: D)

[Les Stroud]

> On Feb 27, 2017, at 1:28 PM, Shaohua Li <shli@kernel.org> wrote:
> 
> On Mon, Feb 27, 2017 at 09:49:59AM -0500, Les Stroud wrote:
>> After a period of a couple of weeks with one of our test instances having this problem every other day, they were all nice enough to operate without an issue for 9 days.  It finally reoccurred last night on one of the machines.  
>> 
>> It exhibits the same symptoms and the call traces look as they did previously.  This particular instance is configured with a deadline scheduler.  I was able to capture the inflight you requested:
>> 
>> $ cat /sys/block/xvd[abcde]/inflight
>>        0        0
>>        0        0
>>        0        0
>>        0        0
>>        0        0
>> 
>> I’ve had this happen on instances with the deadline scheduler and the noop scheduler.  At this point, I have not had this happen on an instance that is noop and the raid filesystem (ext4) is mounted with nobarrier.  The instances with noop/nobarrier have not been running long enough for me to make any sort of conclusion that it works around the problem. Frankly, I’m not sure I understand the interaction between ext4 barriers and raid0 block flushes well enough to theorize whether it should or shouldn’t make a difference.
> 
> If nobarrier, ext4 doesn't send flush request.

So, could ext4’s flush request deadlock with an md_flush_request?  Do they share a mutex of some sort? Could one of them be failing to acquire a mutex and not handling it?

> 
>> Does any of this help with identifying the bug?  Is there anymore information I can get that would be useful?  
> 
> 
> Unfortunately I can't find anything fishing. Does the xcdx disk correctly
> handle flush request? For example, you can do the same test with a single such
> disk and check if anything wrong.

Until recently, we had a number of these systems setup without raid0.  This issue never occurred on those systems.  Unfortunately, I can’t find a way to make it happen other than stand a server up and let it run.

I suppose I could try a different filesystem and see if that makes a difference (maybe ext3, xfs, etc).


> 
> Thanks,
> Shaohua

Re: Process stuck in md_flush_request (state: D)

[Shaohua Li]

On Mon, Feb 27, 2017 at 01:48:00PM -0500, Les Stroud wrote:
> 
> 
> 
> 
> > On Feb 27, 2017, at 1:28 PM, Shaohua Li <shli@kernel.org> wrote:
> > 
> > On Mon, Feb 27, 2017 at 09:49:59AM -0500, Les Stroud wrote:
> >> After a period of a couple of weeks with one of our test instances having this problem every other day, they were all nice enough to operate without an issue for 9 days.  It finally reoccurred last night on one of the machines.  
> >> 
> >> It exhibits the same symptoms and the call traces look as they did previously.  This particular instance is configured with a deadline scheduler.  I was able to capture the inflight you requested:
> >> 
> >> $ cat /sys/block/xvd[abcde]/inflight
> >>        0        0
> >>        0        0
> >>        0        0
> >>        0        0
> >>        0        0
> >> 
> >> I’ve had this happen on instances with the deadline scheduler and the noop scheduler.  At this point, I have not had this happen on an instance that is noop and the raid filesystem (ext4) is mounted with nobarrier.  The instances with noop/nobarrier have not been running long enough for me to make any sort of conclusion that it works around the problem. Frankly, I’m not sure I understand the interaction between ext4 barriers and raid0 block flushes well enough to theorize whether it should or shouldn’t make a difference.
> > 
> > If nobarrier, ext4 doesn't send flush request.
> 
> So, could ext4’s flush request deadlock with an md_flush_request?  Do they share a mutex of some sort? Could one of them be failing to acquire a mutex and not handling it?

No, it shouldn't deadlock. I don't have other reports for such issue. Yours are the only one.
 
> > 
> >> Does any of this help with identifying the bug?  Is there anymore information I can get that would be useful?  
> > 
> > 
> > Unfortunately I can't find anything fishing. Does the xcdx disk correctly
> > handle flush request? For example, you can do the same test with a single such
> > disk and check if anything wrong.
> 
> Until recently, we had a number of these systems setup without raid0.  This issue never occurred on those systems.  Unfortunately, I can’t find a way to make it happen other than stand a server up and let it run.
> 
> I suppose I could try a different filesystem and see if that makes a difference (maybe ext3, xfs, etc).

You could format a xcdx disk and do a test against it, and check if there is
anything wrong. To be honest, I don't think it's a problme in ext4 side too,
but better try other filesystems. If the xcdx is a proprietory driver, I highly
recommend a check with a single such disk first.

Thanks,
Shaohua

Re: Process stuck in md_flush_request (state: D)

[Les Stroud]

Sent from my iPhone

> On Feb 27, 2017, at 7:44 PM, Shaohua Li <shli@kernel.org> wrote:
>
>> On Mon, Feb 27, 2017 at 01:48:00PM -0500, Les Stroud wrote:
>>
>>
>>
>>
>>> On Feb 27, 2017, at 1:28 PM, Shaohua Li <shli@kernel.org> wrote:
>>>
>>> On Mon, Feb 27, 2017 at 09:49:59AM -0500, Les Stroud wrote:
>>>> After a period of a couple of weeks with one of our test instances having this problem every other day, they were all nice enough to operate without an issue for 9 days.  It finally reoccurred last night on one of the machines.
>>>>
>>>> It exhibits the same symptoms and the call traces look as they did previously.  This particular instance is configured with a deadline scheduler.  I was able to capture the inflight you requested:
>>>>
>>>> $ cat /sys/block/xvd[abcde]/inflight
>>>>        0        0
>>>>        0        0
>>>>        0        0
>>>>        0        0
>>>>        0        0
>>>>
>>>> I’ve had this happen on instances with the deadline scheduler and the noop scheduler.  At this point, I have not had this happen on an instance that is noop and the raid filesystem (ext4) is mounted with nobarrier.  The instances with noop/nobarrier have not been running long enough for me to make any sort of conclusion that it works around the problem. Frankly, I’m not sure I understand the interaction between ext4 barriers and raid0 block flushes well enough to theorize whether it should or shouldn’t make a difference.
>>>
>>> If nobarrier, ext4 doesn't send flush request.
>>
>> So, could ext4’s flush request deadlock with an md_flush_request?  Do they share a mutex of some sort? Could one of them be failing to acquire a mutex and not handling it?
>
> No, it shouldn't deadlock. I don't have other reports for such issue. Yours are the only one.
>
>>>
>>>> Does any of this help with identifying the bug?  Is there anymore information I can get that would be useful?
>>>
>>>
>>> Unfortunately I can't find anything fishing. Does the xcdx disk correctly
>>> handle flush request? For example, you can do the same test with a single such
>>> disk and check if anything wrong.
>>
I'll test a single disk config.


>> Until recently, we had a number of these systems setup without raid0.  This issue never occurred on those systems.  Unfortunately, I can’t find a way to make it happen other than stand a server up and let it run.
>>
>> I suppose I could try a different filesystem and see if that makes a difference (maybe ext3, xfs, etc).
>
> You could format a xcdx disk and do a test against it, and check if there is
> anything wrong. To be honest, I don't think it's a problme in ext4 side too,
> but better try other filesystems. If the xcdx is a proprietory driver, I highly
> recommend a check with a single such disk first.
>

These disks are AWS EBS. So, maybe it is an issue in the xen virtual
driver? I'll see if amazon support can give me any information about
what's happening below the OS.

Is there any other output that might tell me what the process is waiting on?

Thanx,
LES


> Thanks,
> Shaohua