* blk-mq 5-8 times slower for bmap-tools @ 2018-08-17 17:31 Ricardo Ribalda Delgado 2018-08-17 17:35 ` Paolo Valente 2018-08-17 23:43 ` Ming Lei 0 siblings, 2 replies; 21+ messages in thread From: Ricardo Ribalda Delgado @ 2018-08-17 17:31 UTC (permalink / raw) To: linux-block, Ben Hutchings Hello Coming from: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=906328 bmaptools is kind of a "smart dd" tool, that lets you write images very fast and securely. Since the last Debian Kernel update it has become 5-8 times slower. After some debugging, we have figured out that the reason for that slowness is the Multi-Queue Block IO Queueing Mechanism. Debian maintainer has pointed out that in the near future the single queue will be deprecated. My question is if we can get a similar perfomance for bmaptools with blk-mq and how? Thanks! -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:31 blk-mq 5-8 times slower for bmap-tools Ricardo Ribalda Delgado @ 2018-08-17 17:35 ` Paolo Valente 2018-08-17 17:39 ` Ricardo Ribalda Delgado 2018-08-17 23:43 ` Ming Lei 1 sibling, 1 reply; 21+ messages in thread From: Paolo Valente @ 2018-08-17 17:35 UTC (permalink / raw) To: Ricardo Ribalda Delgado; +Cc: linux-block, Ben Hutchings > Il giorno 17 ago 2018, alle ore 19:31, Ricardo Ribalda Delgado = <ricardo.ribalda@gmail.com> ha scritto: >=20 > Hello >=20 > Coming from: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=3D906328 >=20 > bmaptools is kind of a "smart dd" tool, that lets you write images > very fast and securely. Since the last Debian Kernel update it has > become 5-8 times slower. >=20 > After some debugging, we have figured out that the reason for that > slowness is the Multi-Queue Block IO Queueing Mechanism. >=20 > Debian maintainer has pointed out that in the near future the single > queue will be deprecated. >=20 > My question is if we can get a similar perfomance for bmaptools with > blk-mq and how? >=20 Have you also checked what happens after switching to a different I/O scheduler for the involved drive (among none, mq-deadline, bfq and kyber)? Paolo > Thanks! >=20 > --=20 > Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:35 ` Paolo Valente @ 2018-08-17 17:39 ` Ricardo Ribalda Delgado 2018-08-17 17:41 ` Jens Axboe 2018-08-17 17:42 ` Paolo Valente 0 siblings, 2 replies; 21+ messages in thread From: Ricardo Ribalda Delgado @ 2018-08-17 17:39 UTC (permalink / raw) To: paolo.valente; +Cc: linux-block, Ben Hutchings Hello Paolo On Fri, Aug 17, 2018 at 7:35 PM Paolo Valente <paolo.valente@linaro.org> wrote: > > > > > Il giorno 17 ago 2018, alle ore 19:31, Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com> ha scritto: > > > > Hello > > > > Coming from: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=906328 > > > > bmaptools is kind of a "smart dd" tool, that lets you write images > > very fast and securely. Since the last Debian Kernel update it has > > become 5-8 times slower. > > > > After some debugging, we have figured out that the reason for that > > slowness is the Multi-Queue Block IO Queueing Mechanism. > > > > Debian maintainer has pointed out that in the near future the single > > queue will be deprecated. > > > > My question is if we can get a similar perfomance for bmaptools with > > blk-mq and how? > > > > Have you also checked what happens after switching to a different I/O > scheduler for the involved drive (among none, mq-deadline, bfq and > kyber)? I have only tried mq-deadline and none (because they are enabled by default on Debian). Both produce results in the same range: 5-8 times slower. I could easily enable kyber: cat /boot/config-4.17.0-1-amd64 | grep CONFIG_MQ_IOSCHED CONFIG_MQ_IOSCHED_DEADLINE=y CONFIG_MQ_IOSCHED_KYBER=m But I left the card reader on the office, so any test would have to wait until monday sorry :( > > Paolo > > > Thanks! > > > > -- > > Ricardo Ribalda > -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:39 ` Ricardo Ribalda Delgado @ 2018-08-17 17:41 ` Jens Axboe 2018-08-17 17:49 ` Ricardo Ribalda Delgado 2018-08-17 17:42 ` Paolo Valente 1 sibling, 1 reply; 21+ messages in thread From: Jens Axboe @ 2018-08-17 17:41 UTC (permalink / raw) To: Ricardo Ribalda Delgado, paolo.valente; +Cc: linux-block, Ben Hutchings On 8/17/18 11:39 AM, Ricardo Ribalda Delgado wrote: > Hello Paolo > On Fri, Aug 17, 2018 at 7:35 PM Paolo Valente <paolo.valente@linaro.org> wrote: >> >> >> >>> Il giorno 17 ago 2018, alle ore 19:31, Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com> ha scritto: >>> >>> Hello >>> >>> Coming from: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=906328 >>> >>> bmaptools is kind of a "smart dd" tool, that lets you write images >>> very fast and securely. Since the last Debian Kernel update it has >>> become 5-8 times slower. >>> >>> After some debugging, we have figured out that the reason for that >>> slowness is the Multi-Queue Block IO Queueing Mechanism. >>> >>> Debian maintainer has pointed out that in the near future the single >>> queue will be deprecated. >>> >>> My question is if we can get a similar perfomance for bmaptools with >>> blk-mq and how? >>> >> >> Have you also checked what happens after switching to a different I/O >> scheduler for the involved drive (among none, mq-deadline, bfq and >> kyber)? > > I have only tried mq-deadline and none (because they are enabled by > default on Debian). Both produce results in the same range: 5-8 times > slower. > > I could easily enable kyber: > cat /boot/config-4.17.0-1-amd64 | grep CONFIG_MQ_IOSCHED > CONFIG_MQ_IOSCHED_DEADLINE=y > CONFIG_MQ_IOSCHED_KYBER=m > > But I left the card reader on the office, so any test would have to > wait until monday sorry :( Can someone describe what bmaptools does? IOW, how is it different than dd? Does it use multiple threads for both reads and writes? -- Jens Axboe ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:41 ` Jens Axboe @ 2018-08-17 17:49 ` Ricardo Ribalda Delgado 2018-08-17 21:23 ` Jens Axboe 0 siblings, 1 reply; 21+ messages in thread From: Ricardo Ribalda Delgado @ 2018-08-17 17:49 UTC (permalink / raw) To: axboe; +Cc: paolo.valente, linux-block, Ben Hutchings Hi Jens On Fri, Aug 17, 2018 at 7:41 PM Jens Axboe <axboe@kernel.dk> wrote: > > On 8/17/18 11:39 AM, Ricardo Ribalda Delgado wrote: > > Hello Paolo > > On Fri, Aug 17, 2018 at 7:35 PM Paolo Valente <paolo.valente@linaro.org> wrote: > >> > >> > >> > >>> Il giorno 17 ago 2018, alle ore 19:31, Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com> ha scritto: > >>> > >>> Hello > >>> > >>> Coming from: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=906328 > >>> > >>> bmaptools is kind of a "smart dd" tool, that lets you write images > >>> very fast and securely. Since the last Debian Kernel update it has > >>> become 5-8 times slower. > >>> > >>> After some debugging, we have figured out that the reason for that > >>> slowness is the Multi-Queue Block IO Queueing Mechanism. > >>> > >>> Debian maintainer has pointed out that in the near future the single > >>> queue will be deprecated. > >>> > >>> My question is if we can get a similar perfomance for bmaptools with > >>> blk-mq and how? > >>> > >> > >> Have you also checked what happens after switching to a different I/O > >> scheduler for the involved drive (among none, mq-deadline, bfq and > >> kyber)? > > > > I have only tried mq-deadline and none (because they are enabled by > > default on Debian). Both produce results in the same range: 5-8 times > > slower. > > > > I could easily enable kyber: > > cat /boot/config-4.17.0-1-amd64 | grep CONFIG_MQ_IOSCHED > > CONFIG_MQ_IOSCHED_DEADLINE=y > > CONFIG_MQ_IOSCHED_KYBER=m > > > > But I left the card reader on the office, so any test would have to > > wait until monday sorry :( > > Can someone describe what bmaptools does? IOW, how is it different than > dd? Does it use multiple threads for both reads and writes? https://github.com/intel/bmap-tools/blob/master/bmaptools/BmapCopy.py I am not an author, just a user. But from the code it looks like 1) sets the io scheduler to noop 2) Copy the file in chuncks of block_size (4096 by default) 3) fflush 4) restore io scheduler > > -- > Jens Axboe > -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:49 ` Ricardo Ribalda Delgado @ 2018-08-17 21:23 ` Jens Axboe 0 siblings, 0 replies; 21+ messages in thread From: Jens Axboe @ 2018-08-17 21:23 UTC (permalink / raw) To: Ricardo Ribalda Delgado; +Cc: paolo.valente, linux-block, Ben Hutchings On 8/17/18 11:49 AM, Ricardo Ribalda Delgado wrote: > Hi Jens > On Fri, Aug 17, 2018 at 7:41 PM Jens Axboe <axboe@kernel.dk> wrote: >> >> On 8/17/18 11:39 AM, Ricardo Ribalda Delgado wrote: >>> Hello Paolo >>> On Fri, Aug 17, 2018 at 7:35 PM Paolo Valente <paolo.valente@linaro.org> wrote: >>>> >>>> >>>> >>>>> Il giorno 17 ago 2018, alle ore 19:31, Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com> ha scritto: >>>>> >>>>> Hello >>>>> >>>>> Coming from: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=906328 >>>>> >>>>> bmaptools is kind of a "smart dd" tool, that lets you write images >>>>> very fast and securely. Since the last Debian Kernel update it has >>>>> become 5-8 times slower. >>>>> >>>>> After some debugging, we have figured out that the reason for that >>>>> slowness is the Multi-Queue Block IO Queueing Mechanism. >>>>> >>>>> Debian maintainer has pointed out that in the near future the single >>>>> queue will be deprecated. >>>>> >>>>> My question is if we can get a similar perfomance for bmaptools with >>>>> blk-mq and how? >>>>> >>>> >>>> Have you also checked what happens after switching to a different I/O >>>> scheduler for the involved drive (among none, mq-deadline, bfq and >>>> kyber)? >>> >>> I have only tried mq-deadline and none (because they are enabled by >>> default on Debian). Both produce results in the same range: 5-8 times >>> slower. >>> >>> I could easily enable kyber: >>> cat /boot/config-4.17.0-1-amd64 | grep CONFIG_MQ_IOSCHED >>> CONFIG_MQ_IOSCHED_DEADLINE=y >>> CONFIG_MQ_IOSCHED_KYBER=m >>> >>> But I left the card reader on the office, so any test would have to >>> wait until monday sorry :( >> >> Can someone describe what bmaptools does? IOW, how is it different than >> dd? Does it use multiple threads for both reads and writes? > > https://github.com/intel/bmap-tools/blob/master/bmaptools/BmapCopy.py > > I am not an author, just a user. But from the code it looks like > > 1) sets the io scheduler to noop > 2) Copy the file in chuncks of block_size (4096 by default) > 3) fflush > 4) restore io scheduler That seems like a very odd tool... Why would you switch to noop for a file-to-dev copy?! In any case, I ran it on a USB stick here. With blk-mq: bmaptool: info: copying time: 9.5s, copying speed 27.0 MiB/sec Without blk-mq: bmaptool: info: copying time: 9.5s, copying speed 26.8 MiB/sec which seems identical to me, maybe a slight edge to blk-mq. For both cases, I used --nobmap since the tool complained: bmaptool: ERROR: bmap file not found, please, use --nobmap option to flash without bmap. I used a 256MB file full of random data. I then ran it with a 1G file, and the results were: With blk-mq: bmaptool: info: copying time: 36.8s, copying speed 27.8 MiB/sec Without blk-mq: bmaptool: info: copying time: 38.6s, copying speed 26.5 MiB/sec which also doesn't seem slower, quite the contrary. -- Jens Axboe ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:39 ` Ricardo Ribalda Delgado 2018-08-17 17:41 ` Jens Axboe @ 2018-08-17 17:42 ` Paolo Valente 2018-08-17 17:52 ` Ricardo Ribalda Delgado 1 sibling, 1 reply; 21+ messages in thread From: Paolo Valente @ 2018-08-17 17:42 UTC (permalink / raw) To: Ricardo Ribalda Delgado; +Cc: linux-block, Ben Hutchings > Il giorno 17 ago 2018, alle ore 19:39, Ricardo Ribalda Delgado = <ricardo.ribalda@gmail.com> ha scritto: >=20 > Hello Paolo > On Fri, Aug 17, 2018 at 7:35 PM Paolo Valente = <paolo.valente@linaro.org> wrote: >>=20 >>=20 >>=20 >>> Il giorno 17 ago 2018, alle ore 19:31, Ricardo Ribalda Delgado = <ricardo.ribalda@gmail.com> ha scritto: >>>=20 >>> Hello >>>=20 >>> Coming from: = https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=3D906328 >>>=20 >>> bmaptools is kind of a "smart dd" tool, that lets you write images >>> very fast and securely. Since the last Debian Kernel update it has >>> become 5-8 times slower. >>>=20 >>> After some debugging, we have figured out that the reason for that >>> slowness is the Multi-Queue Block IO Queueing Mechanism. >>>=20 >>> Debian maintainer has pointed out that in the near future the single >>> queue will be deprecated. >>>=20 >>> My question is if we can get a similar perfomance for bmaptools with >>> blk-mq and how? >>>=20 >>=20 >> Have you also checked what happens after switching to a different I/O >> scheduler for the involved drive (among none, mq-deadline, bfq and >> kyber)? >=20 > I have only tried mq-deadline and none (because they are enabled by > default on Debian). Both produce results in the same range: 5-8 times > slower. >=20 > I could easily enable kyber: > cat /boot/config-4.17.0-1-amd64 | grep CONFIG_MQ_IOSCHED > CONFIG_MQ_IOSCHED_DEADLINE=3Dy > CONFIG_MQ_IOSCHED_KYBER=3Dm >=20 > But I left the card reader on the office, so any test would have to > wait until monday sorry :( >=20 Try bfq too, as it is probably the one containing also the most old way heuristics. If bfq fails too, we will at least know that the issue is out of the schedulers. Or in every scheduler! :) Paolo >=20 >>=20 >> Paolo >>=20 >>> Thanks! >>>=20 >>> -- >>> Ricardo Ribalda >>=20 >=20 >=20 > --=20 > Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:42 ` Paolo Valente @ 2018-08-17 17:52 ` Ricardo Ribalda Delgado 0 siblings, 0 replies; 21+ messages in thread From: Ricardo Ribalda Delgado @ 2018-08-17 17:52 UTC (permalink / raw) To: paolo.valente; +Cc: linux-block, Ben Hutchings Hi Paolo On Fri, Aug 17, 2018 at 7:42 PM Paolo Valente <paolo.valente@linaro.org> wrote: > > Try bfq too, as it is probably the one containing also the most old > way heuristics. If bfq fails too, we will at least know that the issue > is out of the schedulers. Or in every scheduler! :) I believe that for this specific setup: A disk reader with a cfast via USB3, the best approach might be to have a single queue and respect the tool sequence. But definitely the io layer is out of my expertise ;) Monday morning will performe the tests. Thanks again and best regards! -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-17 17:31 blk-mq 5-8 times slower for bmap-tools Ricardo Ribalda Delgado 2018-08-17 17:35 ` Paolo Valente @ 2018-08-17 23:43 ` Ming Lei [not found] ` <CAPybu_2ke4usj9Qwr9iSKTymAk1510pzZnZAgLemRB+cK4Se1A@mail.gmail.com> 1 sibling, 1 reply; 21+ messages in thread From: Ming Lei @ 2018-08-17 23:43 UTC (permalink / raw) To: ricardo.ribalda; +Cc: linux-block, ben, Ming Lei On Sat, Aug 18, 2018 at 1:32 AM Ricardo Ribalda Delgado <ricardo.ribalda@gmail.com> wrote: > > Hello > > Coming from: https://bugs.debian.org/cgi-bin/bugreport.cgi?bug=906328 > > bmaptools is kind of a "smart dd" tool, that lets you write images > very fast and securely. Since the last Debian Kernel update it has > become 5-8 times slower. > > After some debugging, we have figured out that the reason for that > slowness is the Multi-Queue Block IO Queueing Mechanism. > > Debian maintainer has pointed out that in the near future the single > queue will be deprecated. > > My question is if we can get a similar perfomance for bmaptools with > blk-mq and how? It suppose to be not worse than non-blk-mq, and maybe there is bug somewhere. Could you use 'iostat -dx $DISK_PATH 1' to collect io stat when running bmaptools in both blk-mq and non-blk-mq? BTW, don't change the default io scheduler as none, which shouldn't work well for slow disk, such as non-SSD. Thanks, Ming Lei ^ permalink raw reply [flat|nested] 21+ messages in thread
[parent not found: <CAPybu_2ke4usj9Qwr9iSKTymAk1510pzZnZAgLemRB+cK4Se1A@mail.gmail.com>]
* Re: blk-mq 5-8 times slower for bmap-tools [not found] ` <CAPybu_2ke4usj9Qwr9iSKTymAk1510pzZnZAgLemRB+cK4Se1A@mail.gmail.com> @ 2018-08-20 8:30 ` Ming Lei 2018-08-20 9:04 ` Ricardo Ribalda Delgado 0 siblings, 1 reply; 21+ messages in thread From: Ming Lei @ 2018-08-20 8:30 UTC (permalink / raw) To: Ricardo Ribalda Delgado; +Cc: tom.leiming, linux-block, Ben Hutchings On Mon, Aug 20, 2018 at 09:39:45AM +0200, Ricardo Ribalda Delgado wrote: > Some measurements: > > Please note that even when iostat shows 0.0 the LED on the device was > blinking as if there was some activity going on. > > Thanks! > > KERNEL: > Linux neopili 4.17.0-1-amd64 #1 SMP Debian 4.17.8-1 (2018-07-20) > x86_64 GNU/Linux > > DISK: > [247530.712686] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd > [247530.738906] usb 2-2: New USB device found, idVendor=174c, > idProduct=5136, bcdDevice= 1.00 > [247530.738913] usb 2-2: New USB device strings: Mfr=2, Product=3, > SerialNumber=1 > [247530.738918] usb 2-2: Product: 91686 > [247530.738921] usb 2-2: Manufacturer: Delock > [247530.738925] usb 2-2: SerialNumber: 300000003B45 > [247530.750709] scsi host6: uas > [247530.751377] scsi 6:0:0:0: Direct-Access ASMT 2105 > 0 PQ: 0 ANSI: 6 > [247530.752174] sd 6:0:0:0: Attached scsi generic sg2 type 0 > [247530.752616] sd 6:0:0:0: [sdb] 31277232 512-byte logical blocks: > (16.0 GB/14.9 GiB) > [247530.752740] sd 6:0:0:0: [sdb] Write Protect is off > [247530.752742] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00 > [247530.752905] sd 6:0:0:0: [sdb] Write cache: enabled, read cache: > enabled, doesn't support DPO or FUA > [247530.755912] sdb: sdb1 sdb2 > [247530.756832] sd 6:0:0:0: [sdb] Attached SCSI disk > > > TL/DR: > CFQ: 21.7 > NOOP: 21.7 > DEADLINE: 21.7 > MQ-DEADLINE: 175.2 > NONE: 236.4 > KYBER: 174.9 Thanks for your test! One problem found from your iostat log is that looks there is ~30sec idle period between IO activities when blk-mq is enabled. Maybe it is related with timeout, given we had big change in v4.17 timeout code, and we also fixed one scsi_mq timeout related issue recently, and the patch[1] has been merged to v4.18 release already. [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=2d5ba0e2de24ec87636244a01d4e78d095cc1b20 So could you test v4.18 and see if there is such issue? BTW, I have run the same test on usb-storage, and can't reproduce it. However you are using UAS, and I don't have it at hand, so can't reproduce it completely. Thanks, Ming ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-20 8:30 ` Ming Lei @ 2018-08-20 9:04 ` Ricardo Ribalda Delgado 2018-08-20 9:55 ` Ming Lei 2018-08-22 19:22 ` Ben Hutchings 0 siblings, 2 replies; 21+ messages in thread From: Ricardo Ribalda Delgado @ 2018-08-20 9:04 UTC (permalink / raw) To: ming.lei; +Cc: Ming Lei, linux-block, Ben Hutchings Hello Ming On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > On Mon, Aug 20, 2018 at 09:39:45AM +0200, Ricardo Ribalda Delgado wrote: > > Some measurements: > > > > Please note that even when iostat shows 0.0 the LED on the device was > > blinking as if there was some activity going on. > > > > Thanks! > > > > KERNEL: > > Linux neopili 4.17.0-1-amd64 #1 SMP Debian 4.17.8-1 (2018-07-20) > > x86_64 GNU/Linux > > > > DISK: > > [247530.712686] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd > > [247530.738906] usb 2-2: New USB device found, idVendor=174c, > > idProduct=5136, bcdDevice= 1.00 > > [247530.738913] usb 2-2: New USB device strings: Mfr=2, Product=3, > > SerialNumber=1 > > [247530.738918] usb 2-2: Product: 91686 > > [247530.738921] usb 2-2: Manufacturer: Delock > > [247530.738925] usb 2-2: SerialNumber: 300000003B45 > > [247530.750709] scsi host6: uas > > [247530.751377] scsi 6:0:0:0: Direct-Access ASMT 2105 > > 0 PQ: 0 ANSI: 6 > > [247530.752174] sd 6:0:0:0: Attached scsi generic sg2 type 0 > > [247530.752616] sd 6:0:0:0: [sdb] 31277232 512-byte logical blocks: > > (16.0 GB/14.9 GiB) > > [247530.752740] sd 6:0:0:0: [sdb] Write Protect is off > > [247530.752742] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00 > > [247530.752905] sd 6:0:0:0: [sdb] Write cache: enabled, read cache: > > enabled, doesn't support DPO or FUA > > [247530.755912] sdb: sdb1 sdb2 > > [247530.756832] sd 6:0:0:0: [sdb] Attached SCSI disk > > > > > > TL/DR: > > CFQ: 21.7 > > NOOP: 21.7 > > DEADLINE: 21.7 > > MQ-DEADLINE: 175.2 > > NONE: 236.4 > > KYBER: 174.9 > > Thanks for your test! > > One problem found from your iostat log is that looks there is ~30sec > idle period between IO activities when blk-mq is enabled. During all the test the LED on the device was blinking. But a closer look to dmesg reveals a lot of this messages: [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 inflight: CMD [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 68 00 04 00 00 [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag 2 inflight: CMD OUT [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 68 00 04 00 00 [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag 1 inflight: CMD [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 68 00 04 00 00 [ 227.784312] scsi host6: uas_eh_device_reset_handler start [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd [ 227.944842] scsi host6: uas_eh_device_reset_handler success [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 inflight: CMD [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 e8 00 04 00 00 And they take around 30 secons (227-196) Maybe this is a hw issue? I will bring the reader home tonight and see if I can replicate the bug with my notebook > > Maybe it is related with timeout, given we had big change in v4.17 timeout code, > and we also fixed one scsi_mq timeout related issue recently, and the patch[1] has > been merged to v4.18 release already. I tried with v4.18-rc4 (latest one packaged in debian experimental) and after 3 runs, 2 were fine (27 sec), but the last one was over a minute. Thanks! > > [1] https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=2d5ba0e2de24ec87636244a01d4e78d095cc1b20 > > So could you test v4.18 and see if there is such issue? > > BTW, I have run the same test on usb-storage, and can't reproduce it. > However you are using UAS, and I don't have it at hand, so can't > reproduce it completely. > > Thanks, > Ming -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-20 9:04 ` Ricardo Ribalda Delgado @ 2018-08-20 9:55 ` Ming Lei 2018-08-20 9:56 ` Ricardo Ribalda Delgado 2018-08-22 19:22 ` Ben Hutchings 1 sibling, 1 reply; 21+ messages in thread From: Ming Lei @ 2018-08-20 9:55 UTC (permalink / raw) To: Ricardo Ribalda Delgado; +Cc: Ming Lei, linux-block, Ben Hutchings On Mon, Aug 20, 2018 at 11:04:08AM +0200, Ricardo Ribalda Delgado wrote: > Hello Ming > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > On Mon, Aug 20, 2018 at 09:39:45AM +0200, Ricardo Ribalda Delgado wrote: > > > Some measurements: > > > > > > Please note that even when iostat shows 0.0 the LED on the device was > > > blinking as if there was some activity going on. > > > > > > Thanks! > > > > > > KERNEL: > > > Linux neopili 4.17.0-1-amd64 #1 SMP Debian 4.17.8-1 (2018-07-20) > > > x86_64 GNU/Linux > > > > > > DISK: > > > [247530.712686] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd > > > [247530.738906] usb 2-2: New USB device found, idVendor=174c, > > > idProduct=5136, bcdDevice= 1.00 > > > [247530.738913] usb 2-2: New USB device strings: Mfr=2, Product=3, > > > SerialNumber=1 > > > [247530.738918] usb 2-2: Product: 91686 > > > [247530.738921] usb 2-2: Manufacturer: Delock > > > [247530.738925] usb 2-2: SerialNumber: 300000003B45 > > > [247530.750709] scsi host6: uas > > > [247530.751377] scsi 6:0:0:0: Direct-Access ASMT 2105 > > > 0 PQ: 0 ANSI: 6 > > > [247530.752174] sd 6:0:0:0: Attached scsi generic sg2 type 0 > > > [247530.752616] sd 6:0:0:0: [sdb] 31277232 512-byte logical blocks: > > > (16.0 GB/14.9 GiB) > > > [247530.752740] sd 6:0:0:0: [sdb] Write Protect is off > > > [247530.752742] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00 > > > [247530.752905] sd 6:0:0:0: [sdb] Write cache: enabled, read cache: > > > enabled, doesn't support DPO or FUA > > > [247530.755912] sdb: sdb1 sdb2 > > > [247530.756832] sd 6:0:0:0: [sdb] Attached SCSI disk > > > > > > > > > TL/DR: > > > CFQ: 21.7 > > > NOOP: 21.7 > > > DEADLINE: 21.7 > > > MQ-DEADLINE: 175.2 > > > NONE: 236.4 > > > KYBER: 174.9 > > > > Thanks for your test! > > > > One problem found from your iostat log is that looks there is ~30sec > > idle period between IO activities when blk-mq is enabled. > > During all the test the LED on the device was blinking. > > But a closer look to dmesg reveals a lot of this messages: > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > inflight: CMD -71 is -EPROTO, which is returned from xhci driver, usually it means there is error from the USB device side. > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > 68 00 04 00 00 > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > 2 inflight: CMD OUT > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > 68 00 04 00 00 > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > 1 inflight: CMD > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > 68 00 04 00 00 > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > inflight: CMD > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > e8 00 04 00 00 > > And they take around 30 secons (227-196) > > > Maybe this is a hw issue? I will bring the reader home tonight and see > if I can replicate the bug with my notebook It might be. Is there such message in case of non-blk-mq? thanks, Ming ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-20 9:55 ` Ming Lei @ 2018-08-20 9:56 ` Ricardo Ribalda Delgado 2018-08-20 10:15 ` Ming Lei 0 siblings, 1 reply; 21+ messages in thread From: Ricardo Ribalda Delgado @ 2018-08-20 9:56 UTC (permalink / raw) To: ming.lei; +Cc: Ming Lei, linux-block, Ben Hutchings Hi On Mon, Aug 20, 2018 at 11:55 AM Ming Lei <ming.lei@redhat.com> wrote: > > On Mon, Aug 20, 2018 at 11:04:08AM +0200, Ricardo Ribalda Delgado wrote: > > Hello Ming > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > > > On Mon, Aug 20, 2018 at 09:39:45AM +0200, Ricardo Ribalda Delgado wrote: > > > > Some measurements: > > > > > > > > Please note that even when iostat shows 0.0 the LED on the device was > > > > blinking as if there was some activity going on. > > > > > > > > Thanks! > > > > > > > > KERNEL: > > > > Linux neopili 4.17.0-1-amd64 #1 SMP Debian 4.17.8-1 (2018-07-20) > > > > x86_64 GNU/Linux > > > > > > > > DISK: > > > > [247530.712686] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd > > > > [247530.738906] usb 2-2: New USB device found, idVendor=174c, > > > > idProduct=5136, bcdDevice= 1.00 > > > > [247530.738913] usb 2-2: New USB device strings: Mfr=2, Product=3, > > > > SerialNumber=1 > > > > [247530.738918] usb 2-2: Product: 91686 > > > > [247530.738921] usb 2-2: Manufacturer: Delock > > > > [247530.738925] usb 2-2: SerialNumber: 300000003B45 > > > > [247530.750709] scsi host6: uas > > > > [247530.751377] scsi 6:0:0:0: Direct-Access ASMT 2105 > > > > 0 PQ: 0 ANSI: 6 > > > > [247530.752174] sd 6:0:0:0: Attached scsi generic sg2 type 0 > > > > [247530.752616] sd 6:0:0:0: [sdb] 31277232 512-byte logical blocks: > > > > (16.0 GB/14.9 GiB) > > > > [247530.752740] sd 6:0:0:0: [sdb] Write Protect is off > > > > [247530.752742] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00 > > > > [247530.752905] sd 6:0:0:0: [sdb] Write cache: enabled, read cache: > > > > enabled, doesn't support DPO or FUA > > > > [247530.755912] sdb: sdb1 sdb2 > > > > [247530.756832] sd 6:0:0:0: [sdb] Attached SCSI disk > > > > > > > > > > > > TL/DR: > > > > CFQ: 21.7 > > > > NOOP: 21.7 > > > > DEADLINE: 21.7 > > > > MQ-DEADLINE: 175.2 > > > > NONE: 236.4 > > > > KYBER: 174.9 > > > > > > Thanks for your test! > > > > > > One problem found from your iostat log is that looks there is ~30sec > > > idle period between IO activities when blk-mq is enabled. > > > > During all the test the LED on the device was blinking. > > > > But a closer look to dmesg reveals a lot of this messages: > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > inflight: CMD > > -71 is -EPROTO, which is returned from xhci driver, usually it means > there is error from the USB device side. > > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > 68 00 04 00 00 > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > 2 inflight: CMD OUT > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > 68 00 04 00 00 > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > 1 inflight: CMD > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > 68 00 04 00 00 > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > inflight: CMD > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > e8 00 04 00 00 > > > > And they take around 30 secons (227-196) > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > if I can replicate the bug with my notebook > > It might be. > > Is there such message in case of non-blk-mq? No, only with blk-mq Thanks! > > thanks, > Ming -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-20 9:56 ` Ricardo Ribalda Delgado @ 2018-08-20 10:15 ` Ming Lei 2018-08-20 11:42 ` Ming Lei 0 siblings, 1 reply; 21+ messages in thread From: Ming Lei @ 2018-08-20 10:15 UTC (permalink / raw) To: Ricardo Ribalda Delgado Cc: Ming Lei, linux-block, Ben Hutchings, Oliver Neukum, Alan Stern, Greg Kroah-Hartman, linux-usb, linux-scsi On Mon, Aug 20, 2018 at 11:56:26AM +0200, Ricardo Ribalda Delgado wrote: > Hi > On Mon, Aug 20, 2018 at 11:55 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > On Mon, Aug 20, 2018 at 11:04:08AM +0200, Ricardo Ribalda Delgado wrote: > > > Hello Ming > > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > > > > > On Mon, Aug 20, 2018 at 09:39:45AM +0200, Ricardo Ribalda Delgado wrote: > > > > > Some measurements: > > > > > > > > > > Please note that even when iostat shows 0.0 the LED on the device was > > > > > blinking as if there was some activity going on. > > > > > > > > > > Thanks! > > > > > > > > > > KERNEL: > > > > > Linux neopili 4.17.0-1-amd64 #1 SMP Debian 4.17.8-1 (2018-07-20) > > > > > x86_64 GNU/Linux > > > > > > > > > > DISK: > > > > > [247530.712686] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd > > > > > [247530.738906] usb 2-2: New USB device found, idVendor=174c, > > > > > idProduct=5136, bcdDevice= 1.00 > > > > > [247530.738913] usb 2-2: New USB device strings: Mfr=2, Product=3, > > > > > SerialNumber=1 > > > > > [247530.738918] usb 2-2: Product: 91686 > > > > > [247530.738921] usb 2-2: Manufacturer: Delock > > > > > [247530.738925] usb 2-2: SerialNumber: 300000003B45 > > > > > [247530.750709] scsi host6: uas > > > > > [247530.751377] scsi 6:0:0:0: Direct-Access ASMT 2105 > > > > > 0 PQ: 0 ANSI: 6 > > > > > [247530.752174] sd 6:0:0:0: Attached scsi generic sg2 type 0 > > > > > [247530.752616] sd 6:0:0:0: [sdb] 31277232 512-byte logical blocks: > > > > > (16.0 GB/14.9 GiB) > > > > > [247530.752740] sd 6:0:0:0: [sdb] Write Protect is off > > > > > [247530.752742] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00 > > > > > [247530.752905] sd 6:0:0:0: [sdb] Write cache: enabled, read cache: > > > > > enabled, doesn't support DPO or FUA > > > > > [247530.755912] sdb: sdb1 sdb2 > > > > > [247530.756832] sd 6:0:0:0: [sdb] Attached SCSI disk > > > > > > > > > > > > > > > TL/DR: > > > > > CFQ: 21.7 > > > > > NOOP: 21.7 > > > > > DEADLINE: 21.7 > > > > > MQ-DEADLINE: 175.2 > > > > > NONE: 236.4 > > > > > KYBER: 174.9 > > > > > > > > Thanks for your test! > > > > > > > > One problem found from your iostat log is that looks there is ~30sec > > > > idle period between IO activities when blk-mq is enabled. > > > > > > During all the test the LED on the device was blinking. > > > > > > But a closer look to dmesg reveals a lot of this messages: > > > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > > inflight: CMD > > > > -71 is -EPROTO, which is returned from xhci driver, usually it means > > there is error from the USB device side. > > > > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > 68 00 04 00 00 > > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > > 2 inflight: CMD OUT > > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > > 68 00 04 00 00 > > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > > 1 inflight: CMD > > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > 68 00 04 00 00 > > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > > inflight: CMD > > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > > e8 00 04 00 00 > > > > > > And they take around 30 secons (227-196) > > > > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > > if I can replicate the bug with my notebook > > > > It might be. > > > > Is there such message in case of non-blk-mq? > > No, only with blk-mq OK, seems something doesn't work as expected in either scsi_mq or uas driver. Thanks, Ming ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-20 10:15 ` Ming Lei @ 2018-08-20 11:42 ` Ming Lei 2018-08-20 11:45 ` Ming Lei 0 siblings, 1 reply; 21+ messages in thread From: Ming Lei @ 2018-08-20 11:42 UTC (permalink / raw) To: Ricardo Ribalda Delgado Cc: Ming Lei, linux-block, Ben Hutchings, Oliver Neukum, Alan Stern, Greg Kroah-Hartman, linux-usb, linux-scsi On Mon, Aug 20, 2018 at 06:15:10PM +0800, Ming Lei wrote: > On Mon, Aug 20, 2018 at 11:56:26AM +0200, Ricardo Ribalda Delgado wrote: > > Hi > > On Mon, Aug 20, 2018 at 11:55 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > > > On Mon, Aug 20, 2018 at 11:04:08AM +0200, Ricardo Ribalda Delgado wrote: > > > > Hello Ming > > > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > > > > > > > On Mon, Aug 20, 2018 at 09:39:45AM +0200, Ricardo Ribalda Delgado wrote: > > > > > > Some measurements: > > > > > > > > > > > > Please note that even when iostat shows 0.0 the LED on the device was > > > > > > blinking as if there was some activity going on. > > > > > > > > > > > > Thanks! > > > > > > > > > > > > KERNEL: > > > > > > Linux neopili 4.17.0-1-amd64 #1 SMP Debian 4.17.8-1 (2018-07-20) > > > > > > x86_64 GNU/Linux > > > > > > > > > > > > DISK: > > > > > > [247530.712686] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd > > > > > > [247530.738906] usb 2-2: New USB device found, idVendor=174c, > > > > > > idProduct=5136, bcdDevice= 1.00 > > > > > > [247530.738913] usb 2-2: New USB device strings: Mfr=2, Product=3, > > > > > > SerialNumber=1 > > > > > > [247530.738918] usb 2-2: Product: 91686 > > > > > > [247530.738921] usb 2-2: Manufacturer: Delock > > > > > > [247530.738925] usb 2-2: SerialNumber: 300000003B45 > > > > > > [247530.750709] scsi host6: uas > > > > > > [247530.751377] scsi 6:0:0:0: Direct-Access ASMT 2105 > > > > > > 0 PQ: 0 ANSI: 6 > > > > > > [247530.752174] sd 6:0:0:0: Attached scsi generic sg2 type 0 > > > > > > [247530.752616] sd 6:0:0:0: [sdb] 31277232 512-byte logical blocks: > > > > > > (16.0 GB/14.9 GiB) > > > > > > [247530.752740] sd 6:0:0:0: [sdb] Write Protect is off > > > > > > [247530.752742] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00 > > > > > > [247530.752905] sd 6:0:0:0: [sdb] Write cache: enabled, read cache: > > > > > > enabled, doesn't support DPO or FUA > > > > > > [247530.755912] sdb: sdb1 sdb2 > > > > > > [247530.756832] sd 6:0:0:0: [sdb] Attached SCSI disk > > > > > > > > > > > > > > > > > > TL/DR: > > > > > > CFQ: 21.7 > > > > > > NOOP: 21.7 > > > > > > DEADLINE: 21.7 > > > > > > MQ-DEADLINE: 175.2 > > > > > > NONE: 236.4 > > > > > > KYBER: 174.9 > > > > > > > > > > Thanks for your test! > > > > > > > > > > One problem found from your iostat log is that looks there is ~30sec > > > > > idle period between IO activities when blk-mq is enabled. > > > > > > > > During all the test the LED on the device was blinking. > > > > > > > > But a closer look to dmesg reveals a lot of this messages: > > > > > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > > > inflight: CMD > > > > > > -71 is -EPROTO, which is returned from xhci driver, usually it means > > > there is error from the USB device side. > > > > > > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > > 68 00 04 00 00 > > > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > > > 2 inflight: CMD OUT > > > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > > > 68 00 04 00 00 > > > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > > > 1 inflight: CMD > > > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > > 68 00 04 00 00 > > > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > > > inflight: CMD > > > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > > > e8 00 04 00 00 > > > > > > > > And they take around 30 secons (227-196) > > > > > > > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > > > if I can replicate the bug with my notebook > > > > > > It might be. > > > > > > Is there such message in case of non-blk-mq? > > > > No, only with blk-mq > > OK, seems something doesn't work as expected in either scsi_mq or uas > driver. Maybe it is just an uas issue, since I can reproduce the following issue with either scsi_mq or not on v4.18, and the uas is emulated via qemu. [ 116.988843] sd 3:0:0:0: [sde] tag#10 uas_eh_abort_handler 0 uas-tag 9 inflight: CMD OUT [ 116.988859] sd 3:0:0:0: [sde] tag#10 CDB: Write(10) 2a 00 0d d9 ec 08 00 00 08 00 [ 116.991121] sd 3:0:0:0: [sde] tag#12 uas_eh_abort_handler 0 uas-tag 1 inflight: [ 116.991129] sd 3:0:0:0: [sde] tag#12 CDB: Write(10) 2a 00 0d d9 35 b0 00 00 08 00 [ 116.991136] sd 3:0:0:0: [sde] tag#2 uas_eh_abort_handler 0 uas-tag 8 inflight: [ 116.991140] sd 3:0:0:0: [sde] tag#2 CDB: Write(10) 2a 00 0d 9c 7f b8 00 00 08 00 [ 116.991146] sd 3:0:0:0: [sde] tag#5 uas_eh_abort_handler 0 uas-tag 7 inflight: [ 116.991149] sd 3:0:0:0: [sde] tag#5 CDB: Write(10) 2a 00 0d 87 0d c8 00 00 08 00 [ 116.991155] sd 3:0:0:0: [sde] tag#9 uas_eh_abort_handler 0 uas-tag 14 inflight: [ 116.991158] sd 3:0:0:0: [sde] tag#9 CDB: Write(10) 2a 00 0d 84 fa b0 00 00 08 00 [ 116.991163] sd 3:0:0:0: [sde] tag#6 uas_eh_abort_handler 0 uas-tag 6 inflight: [ 116.991167] sd 3:0:0:0: [sde] tag#6 CDB: Write(10) 2a 00 0d 5b f2 e0 00 00 08 00 [ 116.991173] sd 3:0:0:0: [sde] tag#13 uas_eh_abort_handler 0 uas-tag 5 inflight: [ 116.991176] sd 3:0:0:0: [sde] tag#13 CDB: Write(10) 2a 00 0d 27 dd a0 00 00 08 00 [ 116.991181] sd 3:0:0:0: [sde] tag#8 uas_eh_abort_handler 0 uas-tag 13 inflight: [ 116.991185] sd 3:0:0:0: [sde] tag#8 CDB: Write(10) 2a 00 0d 14 03 08 00 00 08 00 [ 116.991190] sd 3:0:0:0: [sde] tag#11 uas_eh_abort_handler 0 uas-tag 2 inflight: [ 116.991194] sd 3:0:0:0: [sde] tag#11 CDB: Write(10) 2a 00 0c f8 10 d0 00 00 08 00 [ 116.991199] sd 3:0:0:0: [sde] tag#0 uas_eh_abort_handler 0 uas-tag 12 inflight: [ 116.991203] sd 3:0:0:0: [sde] tag#0 CDB: Write(10) 2a 00 0c f7 5f 00 00 00 08 00 [ 116.991208] sd 3:0:0:0: [sde] tag#7 uas_eh_abort_handler 0 uas-tag 4 inflight: [ 116.991211] sd 3:0:0:0: [sde] tag#7 CDB: Write(10) 2a 00 0c c1 7d 98 00 00 08 00 [ 116.996641] scsi host3: uas_eh_device_reset_handler start [ 117.112534] usb 3-1: reset SuperSpeed Gen 1 USB device number 2 using xhci_hcd [ 117.128255] scsi host3: uas_eh_device_reset_handler success [ming@VM]$ [ming@VM]$ [ming@VM]$cat /proc/cmdline ftrace_dump_on_oops root=UUID=a2850628-61dd-42ee-8081-5f482a65314a ro console=tty1 console=ttyS0,115200n8 earlyprintk rootfstype=ext4 rw loglevel=9 virtio_blk.queue_depth=128 scsi_mod.use_blk_mq=0 no_console_suspend dm_mod.use_blk_mq=1 ip=dhcp iommu=force intel_iommu=on hugepages=0 debug kmemleak=off scsi_transport_iscsi.debug_session=1 scsi_transport_iscsi.debug_conn=1 thanks, Ming ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-20 11:42 ` Ming Lei @ 2018-08-20 11:45 ` Ming Lei 0 siblings, 0 replies; 21+ messages in thread From: Ming Lei @ 2018-08-20 11:45 UTC (permalink / raw) To: Ricardo Ribalda Delgado Cc: Ming Lei, linux-block, Ben Hutchings, Oliver Neukum, Alan Stern, Greg Kroah-Hartman, linux-usb, linux-scsi On Mon, Aug 20, 2018 at 07:42:09PM +0800, Ming Lei wrote: > On Mon, Aug 20, 2018 at 06:15:10PM +0800, Ming Lei wrote: > > On Mon, Aug 20, 2018 at 11:56:26AM +0200, Ricardo Ribalda Delgado wrote: > > > Hi > > > On Mon, Aug 20, 2018 at 11:55 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > > > > > On Mon, Aug 20, 2018 at 11:04:08AM +0200, Ricardo Ribalda Delgado wrote: > > > > > Hello Ming > > > > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > > > > > > > > > On Mon, Aug 20, 2018 at 09:39:45AM +0200, Ricardo Ribalda Delgado wrote: > > > > > > > Some measurements: > > > > > > > > > > > > > > Please note that even when iostat shows 0.0 the LED on the device was > > > > > > > blinking as if there was some activity going on. > > > > > > > > > > > > > > Thanks! > > > > > > > > > > > > > > KERNEL: > > > > > > > Linux neopili 4.17.0-1-amd64 #1 SMP Debian 4.17.8-1 (2018-07-20) > > > > > > > x86_64 GNU/Linux > > > > > > > > > > > > > > DISK: > > > > > > > [247530.712686] usb 2-2: new SuperSpeed USB device number 3 using xhci_hcd > > > > > > > [247530.738906] usb 2-2: New USB device found, idVendor=174c, > > > > > > > idProduct=5136, bcdDevice= 1.00 > > > > > > > [247530.738913] usb 2-2: New USB device strings: Mfr=2, Product=3, > > > > > > > SerialNumber=1 > > > > > > > [247530.738918] usb 2-2: Product: 91686 > > > > > > > [247530.738921] usb 2-2: Manufacturer: Delock > > > > > > > [247530.738925] usb 2-2: SerialNumber: 300000003B45 > > > > > > > [247530.750709] scsi host6: uas > > > > > > > [247530.751377] scsi 6:0:0:0: Direct-Access ASMT 2105 > > > > > > > 0 PQ: 0 ANSI: 6 > > > > > > > [247530.752174] sd 6:0:0:0: Attached scsi generic sg2 type 0 > > > > > > > [247530.752616] sd 6:0:0:0: [sdb] 31277232 512-byte logical blocks: > > > > > > > (16.0 GB/14.9 GiB) > > > > > > > [247530.752740] sd 6:0:0:0: [sdb] Write Protect is off > > > > > > > [247530.752742] sd 6:0:0:0: [sdb] Mode Sense: 43 00 00 00 > > > > > > > [247530.752905] sd 6:0:0:0: [sdb] Write cache: enabled, read cache: > > > > > > > enabled, doesn't support DPO or FUA > > > > > > > [247530.755912] sdb: sdb1 sdb2 > > > > > > > [247530.756832] sd 6:0:0:0: [sdb] Attached SCSI disk > > > > > > > > > > > > > > > > > > > > > TL/DR: > > > > > > > CFQ: 21.7 > > > > > > > NOOP: 21.7 > > > > > > > DEADLINE: 21.7 > > > > > > > MQ-DEADLINE: 175.2 > > > > > > > NONE: 236.4 > > > > > > > KYBER: 174.9 > > > > > > > > > > > > Thanks for your test! > > > > > > > > > > > > One problem found from your iostat log is that looks there is ~30sec > > > > > > idle period between IO activities when blk-mq is enabled. > > > > > > > > > > During all the test the LED on the device was blinking. > > > > > > > > > > But a closer look to dmesg reveals a lot of this messages: > > > > > > > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > > > > inflight: CMD > > > > > > > > -71 is -EPROTO, which is returned from xhci driver, usually it means > > > > there is error from the USB device side. > > > > > > > > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > > > 68 00 04 00 00 > > > > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > > > > 2 inflight: CMD OUT > > > > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > > > > 68 00 04 00 00 > > > > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > > > > 1 inflight: CMD > > > > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > > > 68 00 04 00 00 > > > > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > > > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > > > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > > > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > > > > inflight: CMD > > > > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > > > > e8 00 04 00 00 > > > > > > > > > > And they take around 30 secons (227-196) > > > > > > > > > > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > > > > if I can replicate the bug with my notebook > > > > > > > > It might be. > > > > > > > > Is there such message in case of non-blk-mq? > > > > > > No, only with blk-mq > > > > OK, seems something doesn't work as expected in either scsi_mq or uas > > driver. > > Maybe it is just an uas issue, since I can reproduce the following issue > with either scsi_mq or not on v4.18, and the uas is emulated via qemu. Forget to mention, no need to run bmap-tool, just by the following fio command: fio --direct=1 -size=128G --bsrange=4k-4k --runtime=20 --numjobs=32 --ioengine=libaio --iodepth=64 --group_reporting=1 --filename=/dev/sde --name=/dev/sde-test-randwrite --rw=randwrite Thanks, Ming ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-20 9:04 ` Ricardo Ribalda Delgado 2018-08-20 9:55 ` Ming Lei @ 2018-08-22 19:22 ` Ben Hutchings 2018-08-22 22:02 ` Ming Lei 2018-08-23 6:29 ` Ricardo Ribalda Delgado 1 sibling, 2 replies; 21+ messages in thread From: Ben Hutchings @ 2018-08-22 19:22 UTC (permalink / raw) To: Ricardo Ribalda Delgado, ming.lei; +Cc: Ming Lei, linux-block [-- Attachment #1: Type: text/plain, Size: 2193 bytes --] On Mon, 2018-08-20 at 11:04 +0200, Ricardo Ribalda Delgado wrote: > Hello Ming > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: [...] > > One problem found from your iostat log is that looks there is ~30sec > > idle period between IO activities when blk-mq is enabled. > > During all the test the LED on the device was blinking. > > But a closer look to dmesg reveals a lot of this messages: > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > inflight: CMD > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > 68 00 04 00 00 > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > 2 inflight: CMD OUT > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > 68 00 04 00 00 > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > 1 inflight: CMD > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > 68 00 04 00 00 > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > inflight: CMD > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > e8 00 04 00 00 > > And they take around 30 secons (227-196) > > > Maybe this is a hw issue? I will bring the reader home tonight and see > if I can replicate the bug with my notebook > > > > > Maybe it is related with timeout, given we had big change in v4.17 timeout code, > > and we also fixed one scsi_mq timeout related issue recently, and the patch[1] has > > been merged to v4.18 release already. > > I tried with v4.18-rc4 (latest one packaged in debian experimental) > and after 3 runs, 2 were fine (27 sec), but the last one was over a > minute. Is it possible that this is fixed by "block: really disable runtime-pm for blk-mq"? That fix went into Debian's version 4.17.14-1, but is not yet in any 4.18-based package. Ben. -- Ben Hutchings You can't have everything. Where would you put it? [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 833 bytes --] ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-22 19:22 ` Ben Hutchings @ 2018-08-22 22:02 ` Ming Lei 2018-08-23 0:51 ` Ben Hutchings 2018-08-23 6:29 ` Ricardo Ribalda Delgado 1 sibling, 1 reply; 21+ messages in thread From: Ming Lei @ 2018-08-22 22:02 UTC (permalink / raw) To: Ben Hutchings; +Cc: Ricardo Ribalda Delgado, Ming Lei, linux-block On Wed, Aug 22, 2018 at 08:22:00PM +0100, Ben Hutchings wrote: > On Mon, 2018-08-20 at 11:04 +0200, Ricardo Ribalda Delgado wrote: > > Hello Ming > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > [...] > > > One problem found from your iostat log is that looks there is ~30sec > > > idle period between IO activities when blk-mq is enabled. > > > > During all the test the LED on the device was blinking. > > > > But a closer look to dmesg reveals a lot of this messages: > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > inflight: CMD > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > 68 00 04 00 00 > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > 2 inflight: CMD OUT > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > 68 00 04 00 00 > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > 1 inflight: CMD > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > 68 00 04 00 00 > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > inflight: CMD > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > e8 00 04 00 00 > > > > And they take around 30 secons (227-196) > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > if I can replicate the bug with my notebook > > > > > > > > Maybe it is related with timeout, given we had big change in v4.17 timeout code, > > > and we also fixed one scsi_mq timeout related issue recently, and the patch[1] has > > > been merged to v4.18 release already. > > > > I tried with v4.18-rc4 (latest one packaged in debian experimental) > > and after 3 runs, 2 were fine (27 sec), but the last one was over a > > minute. > > Is it possible that this is fixed by "block: really disable runtime-pm > for blk-mq"? > As I mentioned, the similar issue can be triggered in both blk-mq and non-blk-mq, so it shouldn't be related with runtime PM. We need our UAS guys to take a look at this issue. Thanks, Ming ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-22 22:02 ` Ming Lei @ 2018-08-23 0:51 ` Ben Hutchings 2018-08-23 2:17 ` Ming Lei 0 siblings, 1 reply; 21+ messages in thread From: Ben Hutchings @ 2018-08-23 0:51 UTC (permalink / raw) To: Ming Lei; +Cc: Ricardo Ribalda Delgado, Ming Lei, linux-block [-- Attachment #1: Type: text/plain, Size: 2752 bytes --] On Thu, 2018-08-23 at 06:02 +0800, Ming Lei wrote: > On Wed, Aug 22, 2018 at 08:22:00PM +0100, Ben Hutchings wrote: > > On Mon, 2018-08-20 at 11:04 +0200, Ricardo Ribalda Delgado wrote: > > > Hello Ming > > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > [...] > > > > One problem found from your iostat log is that looks there is ~30sec > > > > idle period between IO activities when blk-mq is enabled. > > > > > > During all the test the LED on the device was blinking. > > > > > > But a closer look to dmesg reveals a lot of this messages: > > > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > > inflight: CMD > > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > 68 00 04 00 00 > > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > > 2 inflight: CMD OUT > > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > > 68 00 04 00 00 > > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > > 1 inflight: CMD > > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > 68 00 04 00 00 > > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > > inflight: CMD > > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > > e8 00 04 00 00 > > > > > > And they take around 30 secons (227-196) > > > > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > > if I can replicate the bug with my notebook > > > > > > > > > > > Maybe it is related with timeout, given we had big change in v4.17 timeout code, > > > > and we also fixed one scsi_mq timeout related issue recently, and the patch[1] has > > > > been merged to v4.18 release already. > > > > > > I tried with v4.18-rc4 (latest one packaged in debian experimental) > > > and after 3 runs, 2 were fine (27 sec), but the last one was over a > > > minute. > > > > Is it possible that this is fixed by "block: really disable runtime-pm > > for blk-mq"? > > > > As I mentioned, the similar issue can be triggered in both blk-mq and > non-blk-mq, so it shouldn't be related with runtime PM. > > We need our UAS guys to take a look at this issue. I saw that you found a problem with UAS in both modes, but Ricardo's problem seemed to be specific to blk-mq. Ben. -- Ben Hutchings Quantity is no substitute for quality, but it's the only one we've got. [-- Attachment #2: This is a digitally signed message part --] [-- Type: application/pgp-signature, Size: 833 bytes --] ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-23 0:51 ` Ben Hutchings @ 2018-08-23 2:17 ` Ming Lei 0 siblings, 0 replies; 21+ messages in thread From: Ming Lei @ 2018-08-23 2:17 UTC (permalink / raw) To: Ben Hutchings; +Cc: Ricardo Ribalda Delgado, Ming Lei, linux-block On Thu, Aug 23, 2018 at 01:51:05AM +0100, Ben Hutchings wrote: > On Thu, 2018-08-23 at 06:02 +0800, Ming Lei wrote: > > On Wed, Aug 22, 2018 at 08:22:00PM +0100, Ben Hutchings wrote: > > > On Mon, 2018-08-20 at 11:04 +0200, Ricardo Ribalda Delgado wrote: > > > > Hello Ming > > > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > > > > > > [...] > > > > > One problem found from your iostat log is that looks there is ~30sec > > > > > idle period between IO activities when blk-mq is enabled. > > > > > > > > During all the test the LED on the device was blinking. > > > > > > > > But a closer look to dmesg reveals a lot of this messages: > > > > > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > > > inflight: CMD > > > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > > 68 00 04 00 00 > > > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > > > 2 inflight: CMD OUT > > > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > > > 68 00 04 00 00 > > > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > > > 1 inflight: CMD > > > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > > > 68 00 04 00 00 > > > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > > > inflight: CMD > > > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > > > e8 00 04 00 00 > > > > > > > > And they take around 30 secons (227-196) > > > > > > > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > > > if I can replicate the bug with my notebook > > > > > > > > > > > > > > Maybe it is related with timeout, given we had big change in v4.17 timeout code, > > > > > and we also fixed one scsi_mq timeout related issue recently, and the patch[1] has > > > > > been merged to v4.18 release already. > > > > > > > > I tried with v4.18-rc4 (latest one packaged in debian experimental) > > > > and after 3 runs, 2 were fine (27 sec), but the last one was over a > > > > minute. > > > > > > Is it possible that this is fixed by "block: really disable runtime-pm > > > for blk-mq"? > > > > > > > As I mentioned, the similar issue can be triggered in both blk-mq and > > non-blk-mq, so it shouldn't be related with runtime PM. > > > > We need our UAS guys to take a look at this issue. > > I saw that you found a problem with UAS in both modes, but Ricardo's > problem seemed to be specific to blk-mq. > Actually both are triggered when doing WRITE to UAS, and the error message is same too. So I think two problems may be same. Thanks, Ming ^ permalink raw reply [flat|nested] 21+ messages in thread
* Re: blk-mq 5-8 times slower for bmap-tools 2018-08-22 19:22 ` Ben Hutchings 2018-08-22 22:02 ` Ming Lei @ 2018-08-23 6:29 ` Ricardo Ribalda Delgado 1 sibling, 0 replies; 21+ messages in thread From: Ricardo Ribalda Delgado @ 2018-08-23 6:29 UTC (permalink / raw) To: Ben Hutchings; +Cc: ming.lei, Ming Lei, linux-block Hi Ben On Wed, Aug 22, 2018 at 9:22 PM Ben Hutchings <ben@decadent.org.uk> wrote: > > On Mon, 2018-08-20 at 11:04 +0200, Ricardo Ribalda Delgado wrote: > > Hello Ming > > On Mon, Aug 20, 2018 at 10:30 AM Ming Lei <ming.lei@redhat.com> wrote: > [...] > > > One problem found from your iostat log is that looks there is ~30sec > > > idle period between IO activities when blk-mq is enabled. > > > > During all the test the LED on the device was blinking. > > > > But a closer look to dmesg reveals a lot of this messages: > > > > [ 196.929811] sd 6:0:0:0: [sdb] tag#3 data cmplt err -71 uas-tag 1 > > inflight: CMD > > [ 196.929822] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > 68 00 04 00 00 > > [ 227.764379] sd 6:0:0:0: [sdb] tag#4 uas_eh_abort_handler 0 uas-tag > > 2 inflight: CMD OUT > > [ 227.764389] sd 6:0:0:0: [sdb] tag#4 CDB: Write(10) 2a 00 00 04 04 > > 68 00 04 00 00 > > [ 227.766555] sd 6:0:0:0: [sdb] tag#3 uas_eh_abort_handler 0 uas-tag > > 1 inflight: CMD > > [ 227.766562] sd 6:0:0:0: [sdb] tag#3 CDB: Write(10) 2a 00 00 04 00 > > 68 00 04 00 00 > > [ 227.784312] scsi host6: uas_eh_device_reset_handler start > > [ 227.913672] usb 2-2: reset SuperSpeed USB device number 3 using xhci_hcd > > [ 227.944842] scsi host6: uas_eh_device_reset_handler success > > [ 231.416133] sd 6:0:0:0: [sdb] tag#1 data cmplt err -71 uas-tag 10 > > inflight: CMD > > [ 231.416147] sd 6:0:0:0: [sdb] tag#1 CDB: Write(10) 2a 00 00 06 d5 > > e8 00 04 00 00 > > > > And they take around 30 secons (227-196) > > > > > > Maybe this is a hw issue? I will bring the reader home tonight and see > > if I can replicate the bug with my notebook > > > > > > > > Maybe it is related with timeout, given we had big change in v4.17 timeout code, > > > and we also fixed one scsi_mq timeout related issue recently, and the patch[1] has > > > been merged to v4.18 release already. > > > > I tried with v4.18-rc4 (latest one packaged in debian experimental) > > and after 3 runs, 2 were fine (27 sec), but the last one was over a > > minute. > > Is it possible that this is fixed by "block: really disable runtime-pm > for blk-mq"? > > That fix went into Debian's version 4.17.14-1, but is not yet in any > 4.18-based package. Just tried out ricardo@neopili:~$ uname -a Linux neopili 4.17.0-3-amd64 #1 SMP Debian 4.17.17-1 (2018-08-18) x86_64 GNU/Linux and after around 10 executions all the runtimes are similar to the ones with non-blk-mq and I havent seen the "uas error" on dmesg Thanks for your help. I will keep an eye on the issue in case it triggers again > > Ben. > > -- > Ben Hutchings > You can't have everything. Where would you put it? > -- Ricardo Ribalda ^ permalink raw reply [flat|nested] 21+ messages in thread
end of thread, other threads:[~2018-08-23 9:58 UTC | newest]
Thread overview: 21+ messages (download: mbox.gz / follow: Atom feed)
-- links below jump to the message on this page --
2018-08-17 17:31 blk-mq 5-8 times slower for bmap-tools Ricardo Ribalda Delgado
2018-08-17 17:35 ` Paolo Valente
2018-08-17 17:39 ` Ricardo Ribalda Delgado
2018-08-17 17:41 ` Jens Axboe
2018-08-17 17:49 ` Ricardo Ribalda Delgado
2018-08-17 21:23 ` Jens Axboe
2018-08-17 17:42 ` Paolo Valente
2018-08-17 17:52 ` Ricardo Ribalda Delgado
2018-08-17 23:43 ` Ming Lei
[not found] ` <CAPybu_2ke4usj9Qwr9iSKTymAk1510pzZnZAgLemRB+cK4Se1A@mail.gmail.com>
2018-08-20 8:30 ` Ming Lei
2018-08-20 9:04 ` Ricardo Ribalda Delgado
2018-08-20 9:55 ` Ming Lei
2018-08-20 9:56 ` Ricardo Ribalda Delgado
2018-08-20 10:15 ` Ming Lei
2018-08-20 11:42 ` Ming Lei
2018-08-20 11:45 ` Ming Lei
2018-08-22 19:22 ` Ben Hutchings
2018-08-22 22:02 ` Ming Lei
2018-08-23 0:51 ` Ben Hutchings
2018-08-23 2:17 ` Ming Lei
2018-08-23 6:29 ` Ricardo Ribalda Delgado
This is an external index of several public inboxes, see mirroring instructions on how to clone and mirror all data and code used by this external index.