[Paranoia] Parallel ripping causes extreme slowdowns

Mon Dec 16 07:36:37 UTC 2019

Hi,

This was indeed the problem. The problem was not related to the
USB<->SATA bridges, but indeed in the sr driver itself, see inline.

On 16/12/2019 07:21, Merlijn B.W. Wajer wrote:
> Hi,
> 
> Bingo, I think.
> 
> On 16/12/2019 04:54, Merlijn B.W. Wajer wrote:
>>
>> 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.
> 
> This commit introduces a sr global mutex, when removing the BKL:
> 
> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/diff/drivers/scsi/sr.c?id=2a48fc0ab24241755dc93bfd4f01d68efab47f5a
> 
> A part of this code is still in place today, in sr_block_ioctl (see
> below callstack)
> 
>> [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
> 
> I guess next steps are to see how this can be turned into a per device
> mutex.

With a simple change to drivers/scsi/sr.c and drivers/scsi/sr.h
(introducing a per-device lock to struct scsi_cd, replacing sr_mutex
with a per device lock) - the problem no longer occurs and reads from
different sr devices happily interleave:

> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 Send: scmd 0x0000000000000000
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 CDB: Volume set (in), Read cd be 00 00 00 10 1f 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 CDB: Volume set (in), Read cd be 00 00 00 10 1f 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 124 sectors total, 63504 bytes done.
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 CDB: Volume set (in), Read cd be 00 00 00 0e a5 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 124 sectors total, 63504 bytes done.
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 Send: scmd 0x0000000000000000
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 CDB: Volume set (in), Read cd be 00 00 00 10 3a 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 Send: scmd 0x0000000000000000
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 CDB: Volume set (in), Read cd be 00 00 00 0e c0 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 CDB: Volume set (in), Read cd be 00 00 00 10 3a 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 124 sectors total, 63504 bytes done.
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 Send: scmd 0x0000000000000000
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 CDB: Volume set (in), Read cd be 00 00 00 10 55 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 CDB: Volume set (in), Read cd be 00 00 00 0e c0 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 124 sectors total, 63504 bytes done.
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 Send: scmd 0x0000000000000000
> Dec 16 08:20:01 gentoo-x230 kernel: sr 7:0:0:0: [sr1] tag#0 CDB: Volume set (in), Read cd be 00 00 00 0e db 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 Done: SUCCESS Result: hostbyte=DID_OK driverbyte=DRIVER_OK
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 CDB: Volume set (in), Read cd be 00 00 00 10 55 00 00 1b f8 00 00
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 124 sectors total, 63504 bytes done.
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 Send: scmd 0x0000000000000000
> Dec 16 08:20:01 gentoo-x230 kernel: sr 6:0:0:0: [sr0] tag#0 CDB: Volume set (in), Read cd be 00 00 00 10 70 00 00 1b f8 00 00
Will see if I can turn this into a patch that can be accepted on
mainline Linux... Hope this was useful and no too spammy!

Regards,
Merlijn