[Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Dexuan Cui]

Hi,
Recently fstrim and mkfs always hang in Linux VM running on Hyper-V 2012 R2 or 2016.
The VM uses the latest mainline kernel (v4.10-rc3).

git-bisect shows the patch 
"block: improve handling of the magic discard payload (f9d03f96)"
causes the issue. 
If I revert the patch, the issue will go away.

When the issue happens, any new shell command causing disk I/O will hang too, and
I even can't reboot the VM due to the pending I/O.

It seems blkdev_issue_discard() never returns, meaning the SCSI Unmap command(s) 
can't finish somehow, I think.

Any idea why the patch can cause this?

Thanks!
-- Dexuan

PS, this is the calltrace:

[ 1450.976205] INFO: task fstrim:1300 blocked for more than 120 seconds.
[ 1450.976264]       Not tainted 4.9.0+ #58
[ 1450.976291] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1450.976342] fstrim          D    0  1300   1280 0x00000000
[ 1450.976382] Call Trace:
[ 1450.976412]  ? __schedule+0x232/0x700
[ 1450.976442]  ? try_to_grab_pending+0xb3/0x160
[ 1450.976476]  schedule+0x36/0x80
[ 1450.976501]  schedule_timeout+0x235/0x3f0
[ 1450.976532]  ? blk_run_queue_async+0x3c/0x40
[ 1450.976565]  io_schedule_timeout+0xa4/0x110
[ 1450.976596]  wait_for_completion_io+0xa5/0x110
[ 1450.976628]  ? wake_up_q+0x70/0x70
[ 1450.976654]  submit_bio_wait+0x59/0x70
[ 1450.976683]  blkdev_issue_discard+0x6a/0xb0
[ 1450.976783]  xfs_trim_extents+0x24c/0x410 [xfs]
[ 1450.976862]  xfs_ioc_trim+0x157/0x1c0 [xfs]
[ 1450.976938]  xfs_file_ioctl+0x8ee/0xb20 [xfs]
[ 1450.976972]  ? path_openat+0x3fb/0x13f0
[ 1450.977002]  ? page_add_file_rmap+0x58/0x140
[ 1450.977035]  ? alloc_set_pte+0x4ee/0x640
[ 1450.977065]  ? do_filp_open+0x92/0xe0
[ 1450.977093]  ? _copy_to_user+0x2e/0x40
[ 1450.977121]  ? cp_new_stat+0x141/0x160
[ 1450.977151]  do_vfs_ioctl+0x92/0x5a0
[ 1450.977178]  ? SYSC_newfstat+0x25/0x30
[ 1450.977206]  SyS_ioctl+0x79/0x90
[ 1450.977232]  entry_SYSCALL_64_fastpath+0x1e/0xad
[ 1450.977264] RIP: 0033:0x7f8cac393687
[ 1450.977290] RSP: 002b:00007ffdce06fa38 EFLAGS: 00000202 ORIG_RAX: 0000000000000010
[ 1450.977340] RAX: ffffffffffffffda RBX: 0000000000609330 RCX: 00007f8cac393687
[ 1450.977386] RDX: 00007ffdce06fa40 RSI: 00000000c0185879 RDI: 0000000000000003
[ 1450.977431] RBP: 00007ffdce06fd18 R08: 0000000000000000 R09: 0000000000000000
[ 1450.977476] R10: 000000000000053f R11: 0000000000000202 R12: 0000000000000000
[ 1450.977522] R13: 0000000000000000 R14: 0000000000000000 R15: 0000000000000000
[ 1450.977570] INFO: task ls:1304 blocked for more than 120 seconds.
[ 1450.977609]       Not tainted 4.9.0+ #58
[ 1450.977636] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[ 1450.977685] ls              D    0  1304   1219 0x00000000
[ 1450.977723] Call Trace:
[ 1450.977745]  ? __schedule+0x232/0x700
[ 1450.977774]  ? __blk_run_queue+0x33/0x40
[ 1450.977803]  ? queue_unplugged+0x2a/0xb0
[ 1450.977833]  schedule+0x36/0x80
[ 1450.977857]  schedule_timeout+0x235/0x3f0
[ 1450.977886]  ? blk_finish_plug+0x2c/0x40
[ 1450.977963]  ? _xfs_buf_ioapply+0x324/0x440 [xfs]
[ 1450.977998]  wait_for_completion+0xa5/0x110
[ 1450.978028]  ? wake_up_q+0x70/0x70
[ 1450.978107]  ? xfs_trans_read_buf_map+0xf5/0x330 [xfs]
[ 1450.979283]  ? _xfs_buf_read+0x23/0x30 [xfs]
[ 1450.980522]  xfs_buf_submit_wait+0x7f/0x210 [xfs]
[ 1450.981706]  ? xfs_trans_read_buf_map+0xf5/0x330 [xfs]
[ 1450.982863]  _xfs_buf_read+0x23/0x30 [xfs]
[ 1450.984420]  xfs_buf_read_map+0x108/0x180 [xfs]
[ 1450.985559]  xfs_trans_read_buf_map+0xf5/0x330 [xfs]
[ 1450.986672]  xfs_imap_to_bp+0x5f/0xc0 [xfs]
[ 1450.987761]  xfs_iread+0x79/0x320 [xfs]
[ 1450.988894]  xfs_iget+0x32a/0x840 [xfs]
[ 1450.990055]  xfs_lookup+0xc6/0xe0 [xfs]
[ 1450.991132]  xfs_vn_lookup+0x4f/0x90 [xfs]
[ 1450.992221]  lookup_slow+0x96/0x140
[ 1450.993254]  walk_component+0x1ca/0x2f0
[ 1450.994283]  ? path_init+0x1d9/0x330
[ 1450.995309]  ? mntput+0x24/0x40
[ 1450.996955]  path_lookupat+0x5d/0x110
[ 1450.997979]  filename_lookup+0x9e/0x150
[ 1450.999001]  ? kmem_cache_alloc+0xd7/0x1b0
[ 1451.000126]  ? getname_flags+0x56/0x1f0
[ 1451.001150]  ? getname_flags+0x72/0x1f0
[ 1451.002164]  user_path_at_empty+0x36/0x40
[ 1451.003173]  vfs_fstatat+0x53/0xa0
[ 1451.004223]  SYSC_newlstat+0x22/0x40
[ 1451.005232]  SyS_newlstat+0xe/0x10
[ 1451.006233]  entry_SYSCALL_64_fastpath+0x1e/0xad
[ 1451.007750] RIP: 0033:0x7ff2730993d5
[ 1451.008820] RSP: 002b:00007ffc7c1650c8 EFLAGS: 00000246 ORIG_RAX: 0000000000000006
[ 1451.009880] RAX: ffffffffffffffda RBX: 00007ff273366b78 RCX: 00007ff2730993d5
[ 1451.010953] RDX: 00000000019dfb20 RSI: 00000000019dfb20 RDI: 00007ffc7c1650d0
[ 1451.012078] RBP: 00007ff273366b20 R08: 0000000000000000 R09: 00000000000000c0
[ 1451.013175] R10: 00000000019e4550 R11: 0000000000000246 R12: 0000000000008041
[ 1451.014260] R13: 00007ff273366b78 R14: 000000000000270f R15: 00007ff273366b78

Re: [Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Christoph Hellwig]

Hi Dexuan,

sorry for dropping the ball on the previous private report, I hoped
I could get my hands on a Hyper-V VM and reproduce it myself, but
that has obviously not happened.

Can you send me the output of the provisioning_mode file for the
scsi disk in question to get started?

RE: [Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Dexuan Cui]

> From: Christoph Hellwig [mailto:hch@lst.de]
> Sent: Thursday, January 12, 2017 21:44
> To: Dexuan Cui <decui@microsoft.com>
> Cc: Christoph Hellwig <hch@lst.de>; linux-block@vger.kernel.org; Jens Axboe
> <axboe@fb.com>; Vitaly Kuznetsov <vkuznets@redhat.com>; linux-
> kernel@vger.kernel.org; KY Srinivasan <kys@microsoft.com>; Chris Valean
> (Cloudbase Solutions SRL) <v-chvale@microsoft.com>
> Subject: Re: [Regression] fstrim hangs on Hyper-V: caused by "block: improve
> handling of the magic discard payload"
> 
> Hi Dexuan,
> 
> sorry for dropping the ball on the previous private report, I hoped
> I could get my hands on a Hyper-V VM and reproduce it myself, but
> that has obviously not happened.
> 
> Can you send me the output of the provisioning_mode file for the
> scsi disk in question to get started?

Hi Christoph,
Thank you very much for the help! 

The file just shows "unmap":

root@decui-u1604:~# cd /sys/class/scsi_disk/2\:0\:0\:0
root@decui-u1604:/sys/class/scsi_disk/2:0:0:0# ls
allow_restart  cache_type      device  manage_start_stop           max_write_same_blocks  protection_mode  provisioning_mode  thin_provisioning
app_tag_own    deferred_probe  FUA     max_medium_access_timeouts  power                  protection_type  subsystem          uevent
root@decui-u1604:/sys/class/scsi_disk/2:0:0:0# cat provisioning_mode
unmap

I'm ready to provide any info you need. :-)

Thanks,
-- Dexuan

Re: [Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Christoph Hellwig]

Can you check if this debug printk triggers for the discard commands?

---
diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
index 888e16e..7ab7d08 100644
--- a/drivers/scsi/storvsc_drv.c
+++ b/drivers/scsi/storvsc_drv.c
@@ -1031,6 +1031,10 @@ static void storvsc_command_completion(struct storvsc_cmd_request *cmd_request,
 			data_transfer_length = 0;
 	}
 
+	if (cmd_request->payload->range.len != data_transfer_length)
+		printk_ratelimited("request len: %u, transfer len: %u\n",
+			cmd_request->payload->range.len,
+			data_transfer_length);
 	scsi_set_resid(scmnd,
 		cmd_request->payload->range.len - data_transfer_length);
 

RE: [Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Dexuan Cui]

> From: Christoph Hellwig [mailto:hch@lst.de]
> Sent: Thursday, January 12, 2017 23:53
> To: Dexuan Cui <decui@microsoft.com>
> Cc: Christoph Hellwig <hch@lst.de>; linux-block@vger.kernel.org; Jens Axboe
> <axboe@fb.com>; Vitaly Kuznetsov <vkuznets@redhat.com>; linux-
> kernel@vger.kernel.org; KY Srinivasan <kys@microsoft.com>; Chris Valean
> (Cloudbase Solutions SRL) <v-chvale@microsoft.com>
> Subject: Re: [Regression] fstrim hangs on Hyper-V: caused by "block: improve
> handling of the magic discard payload"
> 
> Can you check if this debug printk triggers for the discard commands?
> 
> ---
> diff --git a/drivers/scsi/storvsc_drv.c b/drivers/scsi/storvsc_drv.c
> index 888e16e..7ab7d08 100644
> --- a/drivers/scsi/storvsc_drv.c
> +++ b/drivers/scsi/storvsc_drv.c
> @@ -1031,6 +1031,10 @@ static void storvsc_command_completion(struct
> storvsc_cmd_request *cmd_request,
>  			data_transfer_length = 0;
>  	}
> 
> +	if (cmd_request->payload->range.len != data_transfer_length)
> +		printk_ratelimited("request len: %u, transfer len: %u\n",
> +			cmd_request->payload->range.len,
> +			data_transfer_length);
>  	scsi_set_resid(scmnd,
>  		cmd_request->payload->range.len - data_transfer_length);
> 

// I fixed the small building issue (data_transfer_length  ==>  vm_srb->data_transfer_length).

No, the printk doesn't trigger for fstrim.

It does trigger at the early boot phase, though.

# dmesg |grep len:
[    0.000000] log_buf_len: 134217728 bytes
[    7.073423] request len: 255, transfer len: 12
[    7.084937] request len: 255, transfer len: 52
[    7.121728] request len: 64, transfer len: 12
[    7.121915] request len: 64, transfer len: 12
[    7.123180] request len: 64, transfer len: 12
[    7.123367] request len: 64, transfer len: 12
[    7.127193] request len: 64, transfer len: 12
[    7.127350] request len: 64, transfer len: 12
[    7.178930] request len: 255, transfer len: 12
[    7.179045] request len: 255, transfer len: 52

-- Dexuan

Re: [Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Christoph Hellwig]

Next try:  (I've also dropped most of the Cc list)

diff --git a/drivers/scsi/scsi_lib.c b/drivers/scsi/scsi_lib.c
index c35b6de..2f358f7 100644
--- a/drivers/scsi/scsi_lib.c
+++ b/drivers/scsi/scsi_lib.c
@@ -1018,7 +1018,10 @@ static int scsi_init_sgtable(struct request *req, struct scsi_data_buffer *sdb)
 	count = blk_rq_map_sg(req->q, req, sdb->table.sgl);
 	BUG_ON(count > sdb->table.nents);
 	sdb->table.nents = count;
-	sdb->length = blk_rq_bytes(req);
+	if (req->rq_flags & RQF_SPECIAL_PAYLOAD)
+		sdb->length = req->special_vec.bv_len;
+	else
+		sdb->length = blk_rq_bytes(req);
 	return BLKPREP_OK;
 }

Re: [Regression] fstrim hangs on Hyper-V: caused by "block: improve handling of the magic discard payload"

[Christoph Hellwig]

On Fri, Jan 13, 2017 at 06:16:02AM +0000, Dexuan Cui wrote:
> IMO this means not only SCSI Unmap command is affected, but
> some other SCSI commands can be affected too? 
> And it looks the bare metal can be affected too?

This affects all drivers looking at the sdb.length field for the
total I/O length - many drivers don't need it but just the SGL, including
both that I tested d this change on - one being virtualized and one
bare metal.

It also only affects commands where the data transfer length is different
from the length of the written blocks, so only affects WRITE SAME and
UNMAP commands, used for discard or zeroing.

I'll submit a cleaned up version with a proper block layer helper today.
Thanks for reporting and debugging this issue!