[Paranoia] Parallel ripping causes extreme slowdowns

Merlijn B.W. Wajer merlijn at archive.org
Mon Dec 16 03:54:07 UTC 2019 

Hi,

I think I've gotten a little further to understanding the problem, but
more questions pop up too...

On 15/12/2019 06:33, Merlijn B.W. Wajer wrote:

> I think something like this is happening too. The drives (at least per
> sysfs) do not seem to be on the same bus - every USB drive seems to have
> it's own 'scsi controller' and is on bus 0. (I am not at the machines
> right not, but will verify when I am at the machines on Monday)
> 
> I will try to get some more information/insight. Once I have some more,
> maybe linux-scsi is not a bad place to mail as well.
> 
>>> Do you have suggestions for tools and settings to use to investigate the
>>> possibly activity that you mention?
>>
>> The debug level you have set could be filtered to make
>> things more visible for you... there's piles of the same
>> 12 byte commands, probably boring reads.
>>
>> Search for scsi / ata command set, scsi / sg / sr manpage.
> 
> Right, I've seen tools to change scsi logging, although it seems to log
> to kernel ring buffer, but I guess that's workable.

First, I've confirmed that the usb-storage driver is being used, and not
UAS (the controllers I use are not UASP capable). [1] This code lives in
drivers/usb/storage/

It looks like each USB<->SATA bridge is connected as it's own "SCSI
host" (aka controller). They show up as "7:0:0:0" (and 8:0:0:0, etc)
in/sys/ - the first part (7) is the host number, the last two numbers
are the (bus) id and the lun, lsscsi also confirms this. [2]

Using `scsi_logging_level -s H 2 -M 2` I've been able to see how
commands are submitted and executed, and what surprises me is that it
seems like there is never an instance where commands to both the drives
(or more than two, really) are submitted at the same time. That is, it
seems like Linux always waits for one command to complete before
submitting another one, even though the device is on a different SCSI
host [3]. This makes no sense to me. Maybe SCSI logging output somehow
confuses me, but I don't think so, as what I am observing would explain
why a RESET (takes a while) in particular slows down all the drives - no
other commands are submitted during that time.

>From looking at the source in drivers/usb/storage - there is nothing
that seems to utilise some global lock (only per device or per host), so
it's unclear to me why this would be happening - but I probably don't
know enough about the kernel block/io schedulers. This [4] is a typical
kernel stack for cdparanoia, btw.

I don't have access to a device with multiple SATA ports right now (will
later, but that's a week from now at least), but I'm surprised the
scheduling works like I'm perceiving it to work...?

Regards,
Merlijn


[1] # lsusb -t
    /:  Bus 04.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 10000M
    /:  Bus 03.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/2p, 480M
        |__ Port 1: Dev 2, If 0, Class=Hub, Driver=hub/4p, 480M
            |__ Port 1: Dev 3, If 0, Class=, Driver=, 12M
            |__ Port 2: Dev 4, If 0, Class=Vendor Specific Class,
Driver=r8152, 480M
            |__ Port 3: Dev 6, If 0, Class=Mass Storage,
Driver=usb-storage, 480M
    /:  Bus 02.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/6p, 10000M
        |__ Port 2: Dev 4, If 0, Class=Hub, Driver=hub/4p, 5000M
        |__ Port 3: Dev 19, If 0, Class=Mass Storage,
Driver=usb-storage, 5000M
        |__ Port 4: Dev 20, If 0, Class=Mass Storage,
Driver=usb-storage, 5000M
    /:  Bus 01.Port 1: Dev 1, Class=root_hub, Driver=xhci_hcd/12p, 480M
        |__ Port 2: Dev 26, If 0, Class=Hub, Driver=hub/4p, 480M
            |__ Port 1: Dev 27, If 1, Class=Human Interface Device,
Driver=usbhid, 1.5M
            |__ Port 1: Dev 27, If 0, Class=Human Interface Device,
Driver=usbhid, 1.5M
            |__ Port 2: Dev 28, If 0, Class=Human Interface Device,
Driver=usbhid, 1.5M
            |__ Port 3: Dev 31, If 0, Class=Human Interface Device,
Driver=usbhid, 12M
        |__ Port 10: Dev 5, If 0, Class=Wireless, Driver=btusb, 12M
        |__ Port 10: Dev 5, If 1, Class=Wireless, Driver=btusb, 12M

[2] # lsscsi --host
    [0]    ahci
    [1]    ahci
    [2]    ahci
    [3]    vhba
    [7]    usb-storage
    [8]    usb-storage

[3]     Dec 16 11:03:58 hname kernel: [ 4885.081502] sr 3:0:0:0: [sr1]
tag#0 Send: scmd 0x000000006a441efa
    Dec 16 11:03:58 hname kernel: [ 4885.081511] sr 3:0:0:0: [sr1] tag#0
CDB: Volume set (in), Read cd be 00 00 00 03 5b 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.109322] sr 3:0:0:0: [sr1] tag#0
Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.109329] sr 3:0:0:0: [sr1] tag#0
CDB: Volume set (in), Read cd be 00 00 00 03 5b 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.109333] sr 3:0:0:0: [sr1] tag#0
124 sectors total, 63504 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.109556] sr 4:0:0:0: [sr0] tag#0
Send: scmd 0x00000000416f12b9
    Dec 16 11:03:58 hname kernel: [ 4885.109563] sr 4:0:0:0: [sr0] tag#0
CDB: Volume set (in), Read cd be 00 00 00 01 90 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.112244] sr 4:0:0:0: [sr0] tag#0
Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.112249] sr 4:0:0:0: [sr0] tag#0
CDB: Volume set (in), Read cd be 00 00 00 01 90 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.112254] sr 4:0:0:0: [sr0] tag#0
124 sectors total, 63504 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.112432] sr 3:0:0:0: [sr1] tag#0
Send: scmd 0x00000000fcda051e
    Dec 16 11:03:58 hname kernel: [ 4885.112442] sr 3:0:0:0: [sr1] tag#0
CDB: Volume set (in), Read cd be 00 00 00 03 76 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.140262] sr 3:0:0:0: [sr1] tag#0
Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.140269] sr 3:0:0:0: [sr1] tag#0
CDB: Volume set (in), Read cd be 00 00 00 03 76 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.140274] sr 3:0:0:0: [sr1] tag#0
124 sectors total, 63504 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.140463] sr 4:0:0:0: [sr0] tag#0
Send: scmd 0x000000009bc82ee4
    Dec 16 11:03:58 hname kernel: [ 4885.140470] sr 4:0:0:0: [sr0] tag#0
CDB: Volume set (in), Read cd be 00 00 00 01 ab 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.143314] sr 4:0:0:0: [sr0] tag#0
Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.143322] sr 4:0:0:0: [sr0] tag#0
CDB: Volume set (in), Read cd be 00 00 00 01 ab 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.143330] sr 4:0:0:0: [sr0] tag#0
124 sectors total, 63504 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.143524] sr 3:0:0:0: [sr1] tag#0
Send: scmd 0x000000006a441efa
    Dec 16 11:03:58 hname kernel: [ 4885.143533] sr 3:0:0:0: [sr1] tag#0
CDB: Volume set (in), Read cd be 00 00 00 03 91 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.143664] sd 1:0:0:0: [sda]
tag#20 sd_setup_read_write_cmnd: block=487983528, count=88
    Dec 16 11:03:58 hname kernel: [ 4885.143671] sd 1:0:0:0: [sda]
tag#20 Send: scmd 0x000000007a8cc96c
    Dec 16 11:03:58 hname kernel: [ 4885.143676] sd 1:0:0:0: [sda]
tag#20 CDB: Write(10) 2a 00 1d 16 09 a8 00 00 58 00
    Dec 16 11:03:58 hname kernel: [ 4885.145540] sd 1:0:0:0: [sda]
tag#20 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.145546] sd 1:0:0:0: [sda]
tag#20 CDB: Write(10) 2a 00 1d 16 09 a8 00 00 58 00
    Dec 16 11:03:58 hname kernel: [ 4885.145551] sd 1:0:0:0: [sda]
tag#20 sd_done: completed 45056 of 45056 bytes
    Dec 16 11:03:58 hname kernel: [ 4885.145555] sd 1:0:0:0: [sda]
tag#20 88 sectors total, 45056 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.145656] sd 1:0:0:0: [sda]
tag#21 Send: scmd 0x00000000c8299150
    Dec 16 11:03:58 hname kernel: [ 4885.145663] sd 1:0:0:0: [sda]
tag#21 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.146020] sd 1:0:0:0: [sda]
tag#21 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.146024] sd 1:0:0:0: [sda]
tag#21 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.146028] sd 1:0:0:0: [sda]
tag#21 sd_done: completed 0 of 0 bytes
    Dec 16 11:03:58 hname kernel: [ 4885.146031] sd 1:0:0:0: [sda]
tag#21 0 sectors total, 0 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.146050] sd 1:0:0:0: [sda]
tag#22 sd_setup_read_write_cmnd: block=487983616, count=8
    Dec 16 11:03:58 hname kernel: [ 4885.146054] sd 1:0:0:0: [sda]
tag#22 Send: scmd 0x00000000da48d0c9
    Dec 16 11:03:58 hname kernel: [ 4885.146057] sd 1:0:0:0: [sda]
tag#22 CDB: Write(10) 2a 00 1d 16 0a 00 00 00 08 00
    Dec 16 11:03:58 hname kernel: [ 4885.146315] sd 1:0:0:0: [sda]
tag#22 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.146318] sd 1:0:0:0: [sda]
tag#22 CDB: Write(10) 2a 00 1d 16 0a 00 00 00 08 00
    Dec 16 11:03:58 hname kernel: [ 4885.146322] sd 1:0:0:0: [sda]
tag#22 sd_done: completed 4096 of 4096 bytes
    Dec 16 11:03:58 hname kernel: [ 4885.146325] sd 1:0:0:0: [sda]
tag#22 8 sectors total, 4096 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.146335] sd 1:0:0:0: [sda]
tag#23 Send: scmd 0x00000000c8299150
    Dec 16 11:03:58 hname kernel: [ 4885.146338] sd 1:0:0:0: [sda]
tag#23 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.146666] sd 1:0:0:0: [sda]
tag#23 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.146669] sd 1:0:0:0: [sda]
tag#23 CDB: Synchronize Cache(10) 35 00 00 00 00 00 00 00 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.146672] sd 1:0:0:0: [sda]
tag#23 sd_done: completed 0 of 0 bytes
    Dec 16 11:03:58 hname kernel: [ 4885.146675] sd 1:0:0:0: [sda]
tag#23 0 sectors total, 0 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.170817] sr 3:0:0:0: [sr1] tag#0
Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
    Dec 16 11:03:58 hname kernel: [ 4885.170824] sr 3:0:0:0: [sr1] tag#0
CDB: Volume set (in), Read cd be 00 00 00 03 91 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.170829] sr 3:0:0:0: [sr1] tag#0
124 sectors total, 63504 bytes done.
    Dec 16 11:03:58 hname kernel: [ 4885.170997] sr 4:0:0:0: [sr0] tag#0
Send: scmd 0x00000000416f12b9
    Dec 16 11:03:58 hname kernel: [ 4885.171002] sr 4:0:0:0: [sr0] tag#0
CDB: Volume set (in), Read cd be 00 00 00 01 c6 00 00 1b f8 00 00
    Dec 16 11:03:58 hname kernel: [ 4885.173856] sr 4:0:0:0: [sr0] tag#0
Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK

[4] # cat /proc/6380/stack
    [<0>] blk_execute_rq+0x75/0xb0
    [<0>] sg_io+0x193/0x400
    [<0>] scsi_cmd_ioctl+0x260/0x440
    [<0>] scsi_cmd_blk_ioctl+0x51/0x70
    [<0>] cdrom_ioctl+0x41/0x124a
    [<0>] sr_block_ioctl+0xa5/0xd0
    [<0>] blkdev_ioctl+0x926/0xa00
    [<0>] block_ioctl+0x3d/0x50
    [<0>] do_vfs_ioctl+0xa9/0x640
    [<0>] ksys_ioctl+0x75/0x80
    [<0>] __x64_sys_ioctl+0x1a/0x20
    [<0>] do_syscall_64+0x5a/0x120
    [<0>] entry_SYSCALL_64_after_hwframe+0x44/0xa9
    [<0>] 0xffffffffffffffff

More information about the Paranoia mailing list