Overview: Several users report that after upgrading from 6.4.12 to 6.5 the process scsi_eh_1 will constantly consume >10% CPU resources. This happens most often in VMs. Steps to Reproduce: - Create a VM (e.g. VMware Fusion) - Create an SCSI disk - Connect a virtual CD ROM (IDE) - Boot a 6.4.12 kernel - Boot a 6.5 kernel Actual Results: - no issues for the 6.4.12 kernel - scsi_eh consumes too much CPU with the 6.5 kernel Expected Results: scsi_eh should not consume significant resources. Build Date & Hardware: Linux arch 6.5.2-arch1-1 #1 SMP PREEMPT_DYNAMIC Wed, 06 Sep 2023 21:01:01 +0000 x86_64 GNU/Linux inside a VMware Fusion VM Additional Builds and Platforms: Other users were able to reproduce the error on bare metal hardware. Additional Information: More details can be found in this thread: https://bbs.archlinux.org/viewtopic.php?id=288723 The users loqs and leonshaw helped to narrow it down to this commit: https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=624885209f31eb9985bf51abe204ecbffe2fdeea good: 6.4.0-rc1-1-00007-g152e52fb6ff1 bad: 6.4.0-rc1-1-00008-g624885209f31
On 9/15/23 12:33, bugzilla-daemon@kernel.org wrote: > The users loqs and leonshaw helped to narrow it down to this commit: > > > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=624885209f31eb9985bf51abe204ecbffe2fdeea Damien, can you please take a look? Thanks, Bart.
On Fri, 2023-09-15 at 13:42 -0700, Bart Van Assche wrote: > On 9/15/23 12:33, bugzilla-daemon@kernel.org wrote: > > The users loqs and leonshaw helped to narrow it down to this > > commit: > > > > > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=624885209f31eb9985bf51abe204ecbffe2fdeea > > Damien, can you please take a look? > > Thanks, > > Bart. > I had a quick look at this and its not making sense. The only calls I see are in the scan when the devices is added and in the re-scan. It should not be consuming the scsi_eh thread unless some type of udev events keeps happening. Would be good to get some cat /proc/<PID>/stack of the scsi_eh threads if they are constantly consuming CPUY I will try reproduce and try figure out what is going on here. Thanks Laurence
Not reproducible generically for me [root@penguin8 ~]# uname -a Linux penguin8 6.5.0+ #2 SMP PREEMPT_DYNAMIC [root@penguin8 ~]# lsscsi [0:0:0:0] disk ATA Samsung SSD 850 3B6Q /dev/sdb [1:0:0:0] disk ATA Samsung SSD 850 3B6Q /dev/sda USER PID %CPU %MEM VSZ RSS TTY STAT START TIME COMMAND root 1649 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_0] root 1651 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_1] root 1653 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_2] root 1655 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_3] root 1668 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_4] root 1670 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_5] root 1672 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_6] root 1674 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_7] root 1866 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_8] root 1887 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_9] root 1649 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_0] root 1651 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_1] root 1653 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_2] root 1655 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_3] root 1668 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_4] root 1670 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_5] root 1672 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_6] root 1674 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_7] root 1866 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_8] root 1887 0.0 0.0 0 0 ? S 16:58 0:00 [scsi_eh_9] I Have no CDROm so I think its the virtual cdrom. In VMware the CDROM will continuously get probed and log errors due to no media and every time that happens it will call the cdl stuff. I will bring up a Virtual guest now, will take time as I will have to build upstream kernels.
On Fri, Sep 15, 2023 at 01:42:18PM -0700, Bart Van Assche wrote: > On 9/15/23 12:33, bugzilla-daemon@kernel.org wrote: > > The users loqs and leonshaw helped to narrow it down to this commit: > > > > > https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=624885209f31eb9985bf51abe204ecbffe2fdeea > > Damien, can you please take a look? > Hello Bart, It seems like: https://lore.kernel.org/linux-scsi/20230915022034.678121-1-dlemoal@kernel.org/ Solves the problem. From a quick look at the logs with extra log leves enabled: https://pastebin.com/f2LQ8kQD it appears that the MAINTENANCE_IN / MI_REPORT_SUPPORTED_OPERATION_CODES command with a non-zero service action issued by scsi_cdl_check() fails, and will be added to SCSI EH over and over. Kind regards, Niklas
On 9/16/23 07:01, Niklas Cassel wrote: > On Fri, Sep 15, 2023 at 01:42:18PM -0700, Bart Van Assche wrote: >> On 9/15/23 12:33, bugzilla-daemon@kernel.org wrote: >>> The users loqs and leonshaw helped to narrow it down to this commit: >>> >>> >>> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=624885209f31eb9985bf51abe204ecbffe2fdeea >> >> Damien, can you please take a look? >> > > Hello Bart, > > It seems like: > > https://lore.kernel.org/linux-scsi/20230915022034.678121-1-dlemoal@kernel.org/ > > Solves the problem. > > From a quick look at the logs with extra log leves enabled: > https://pastebin.com/f2LQ8kQD > it appears that the MAINTENANCE_IN / MI_REPORT_SUPPORTED_OPERATION_CODES > command with a non-zero service action issued by scsi_cdl_check() fails, > and will be added to SCSI EH over and over. The failure is due to the drive not liking this command. My patch avoids sending that command, thus solves the issue with drives that choke on it. However, the constant retry sound to me like a different bug... We should not retry that command at all I think. Or maybe limit it to 3 retries. > > > Kind regards, > Niklas
On 9/16/23 07:01, Niklas Cassel wrote: > On Fri, Sep 15, 2023 at 01:42:18PM -0700, Bart Van Assche wrote: >> On 9/15/23 12:33, bugzilla-daemon@kernel.org wrote: >>> The users loqs and leonshaw helped to narrow it down to this commit: >>> >>> >>> https://git.kernel.org/pub/scm/linux/kernel/git/torvalds/linux.git/commit/?id=624885209f31eb9985bf51abe204ecbffe2fdeea >> >> Damien, can you please take a look? >> > > Hello Bart, > > It seems like: > > https://lore.kernel.org/linux-scsi/20230915022034.678121-1-dlemoal@kernel.org/ > > Solves the problem. > > From a quick look at the logs with extra log leves enabled: > https://pastebin.com/f2LQ8kQD > it appears that the MAINTENANCE_IN / MI_REPORT_SUPPORTED_OPERATION_CODES > command with a non-zero service action issued by scsi_cdl_check() fails, > and will be added to SCSI EH over and over. Looks like the vmware emulated scsi cdrom (sr) does not like this command... While SPC would allow cdroms to support CDL, I do not think we will ever see that. So we could restrict CDL probe to block devices only. That still does not explain why the constant retry. The MAINTENANCE_IN / MI_REPORT_SUPPORTED_OPERATION_CODES failing is expected in most cases so it should silently move on with cdl probe returning false. My patch is still needed as some drives seem to hang on that command. > > > Kind regards, > Niklas
Noticed the same here when upgrading from 6.1.0-13-amd64 to 6.5.0-0.deb12.1-amd64 (both Debian kernels) earlier this month: ============================================================================ $ sar -f /var/log/sysstat/sa20231108 CPU %user %nice %system %iowait %steal %idle [...] 18:30:03 all 1.03 0.00 0.45 0.04 0.00 98.47 18:40:01 all 1.07 0.00 0.52 0.05 0.00 98.36 18:50:01 all 1.07 0.00 0.53 0.04 0.00 98.37 19:00:01 all 1.35 0.00 0.69 0.08 0.00 97.88 19:10:04 all 1.09 0.00 0.52 0.07 0.00 98.31 19:20:02 all 1.14 0.00 0.51 0.05 0.00 98.30 19:30:04 all 1.62 0.00 0.65 0.08 0.00 97.65 Average: all 1.06 0.00 0.50 0.06 0.00 98.38 19:32:27 LINUX RESTART (2 CPU) 19:40:03 CPU %user %nice %system %iowait %steal %idle 19:50:00 all 2.27 0.00 3.23 57.40 0.00 37.11 20:00:02 all 1.29 0.00 2.70 59.27 0.00 36.75 20:10:03 all 1.48 0.00 2.93 58.38 0.00 37.21 20:20:03 all 1.40 0.00 2.94 58.93 0.00 36.73 20:30:02 all 1.39 0.00 2.87 59.99 0.00 35.74 20:40:03 all 1.48 0.00 3.44 59.83 0.00 35.26 20:50:00 all 1.29 0.00 2.88 60.84 0.00 34.98 21:00:03 all 1.31 0.00 2.63 59.81 0.00 36.25 21:10:03 all 1.33 0.00 2.72 59.85 0.00 36.09 21:20:01 all 1.31 0.00 2.82 59.28 0.00 36.59 21:30:01 all 1.39 0.00 2.92 60.51 0.00 35.18 21:40:01 all 1.34 0.00 3.04 60.04 0.00 35.57 21:50:03 all 1.29 0.00 2.51 59.79 0.00 36.41 22:00:03 all 1.36 0.00 3.23 59.81 0.00 35.59 22:10:03 all 1.37 0.00 2.56 59.13 0.00 36.93 22:20:03 all 1.36 0.00 2.88 58.46 0.00 37.29 22:30:03 all 1.31 0.00 2.65 59.07 0.00 36.97 22:40:00 all 1.32 0.00 2.72 59.61 0.00 36.35 22:50:01 all 1.32 0.00 2.72 59.35 0.00 36.61 23:00:03 all 1.29 0.00 2.68 59.30 0.00 36.72 23:10:03 all 1.35 0.00 2.62 60.11 0.00 35.91 23:20:02 all 1.29 0.00 2.91 59.55 0.00 36.25 23:30:03 all 1.32 0.00 2.72 58.37 0.00 37.59 23:40:01 all 1.34 0.00 2.97 57.74 0.00 37.95 23:50:00 all 1.33 0.00 2.54 59.90 0.00 36.24 Average: all 1.38 0.00 2.83 59.37 0.00 36.41 $ last -n 3 reboot reboot system boot 6.5.0-0.deb12.1- Wed Nov 8 19:32 still running reboot system boot 6.1.0-13-amd64 Mon Oct 9 23:14 - 19:32 (29+21:17) reboot system boot 6.1.0-13-amd64 Mon Oct 9 22:39 - 23:14 (00:35) ============================================================================ And top only shows a single [scsi_eh_2] thread using ~50% of CPU time, sometimes there's an events thread too. PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND 336 root 20 0 0.0m 0.0m 0.0m D 50.0 0.0 53,37 [scsi_eh_2] 3794126 root 20 0 0.0m 0.0m 0.0m I 25.7 0.0 0:06.27 [kworker/0:0-events] This is a Debian/amd64 VM running on a VMware ESX host. There's a virtual CDROM drive, but nothing is attached here and I'm not using it, all: ============================================================================ $ lsblk -d --scsi NAME HCTL TYPE VENDOR MODEL REV SERIAL TRAN sda 0:0:0:0 disk VMware Virtual disk 2.0 sr0 2:0:0:0 rom NECVMWar VMware Virtual IDE CDROM Drive 1.00 10000000000000000001 ata $ dmesg -t | grep -i scsi Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) SCSI subsystem initialized VMware PVSCSI driver - version 1.0.7.0-k vmw_pvscsi: using 64bit dma vmw_pvscsi: max_id: 65 vmw_pvscsi: setting ring_pages to 32 vmw_pvscsi: enabling reqCallThreshold vmw_pvscsi: driver-based request coalescing enabled vmw_pvscsi: using MSI-X scsi host0: VMware PVSCSI storage adapter rev 2, req/cmp/msg rings: 32/32/1 pages, cmd_per_lun=254 vmw_pvscsi 0000:03:00.0: VMware PVSCSI rev 2 host #0 scsi 0:0:0:0: Direct-Access VMware Virtual disk 2.0 PQ: 0 ANSI: 6 sd 0:0:0:0: [sda] Attached SCSI disk sd 0:0:0:0: Attached scsi generic sg0 type 0 scsi host1: ata_piix scsi host2: ata_piix scsi 2:0:0:0: CD-ROM NECVMWar VMware IDE CDR10 1.00 PQ: 0 ANSI: 5 scsi 2:0:0:0: Attached scsi generic sg1 type 5 sr 2:0:0:0: [sr0] scsi3-mmc drive: 1x/1x writer dvd-ram cd/rw xa/form2 cdda tray sr 2:0:0:0: Attached scsi CD-ROM sr0 ============================================================================ Will that "scsi: Do no try to probe for CDL on old drives" patch land in mainline or is this still under discussion?
On Mon, Nov 13, 2023 at 03:30:57AM +0000, bugzilla-daemon@kernel.org wrote: > https://bugzilla.kernel.org/show_bug.cgi?id=217914 > > Christian Kujau (kernel@nerdbynature.de) changed: > > What |Removed |Added > ---------------------------------------------------------------------------- > CC| |kernel@nerdbynature.de > > --- Comment #7 from Christian Kujau (kernel@nerdbynature.de) --- > Noticed the same here when upgrading from 6.1.0-13-amd64 to > 6.5.0-0.deb12.1-amd64 (both Debian kernels) earlier this month: > > ============================================================================ > $ sar -f /var/log/sysstat/sa20231108 > CPU %user %nice %system %iowait %steal > %idle > [...] > 18:30:03 all 1.03 0.00 0.45 0.04 0.00 > 98.47 > 18:40:01 all 1.07 0.00 0.52 0.05 0.00 > 98.36 > 18:50:01 all 1.07 0.00 0.53 0.04 0.00 > 98.37 > 19:00:01 all 1.35 0.00 0.69 0.08 0.00 > 97.88 > 19:10:04 all 1.09 0.00 0.52 0.07 0.00 > 98.31 > 19:20:02 all 1.14 0.00 0.51 0.05 0.00 > 98.30 > 19:30:04 all 1.62 0.00 0.65 0.08 0.00 > 97.65 > Average: all 1.06 0.00 0.50 0.06 0.00 > 98.38 > > 19:32:27 LINUX RESTART (2 CPU) > > 19:40:03 CPU %user %nice %system %iowait %steal > %idle > 19:50:00 all 2.27 0.00 3.23 57.40 0.00 > 37.11 > 20:00:02 all 1.29 0.00 2.70 59.27 0.00 > 36.75 > 20:10:03 all 1.48 0.00 2.93 58.38 0.00 > 37.21 > 20:20:03 all 1.40 0.00 2.94 58.93 0.00 > 36.73 > 20:30:02 all 1.39 0.00 2.87 59.99 0.00 > 35.74 > 20:40:03 all 1.48 0.00 3.44 59.83 0.00 > 35.26 > 20:50:00 all 1.29 0.00 2.88 60.84 0.00 > 34.98 > 21:00:03 all 1.31 0.00 2.63 59.81 0.00 > 36.25 > 21:10:03 all 1.33 0.00 2.72 59.85 0.00 > 36.09 > 21:20:01 all 1.31 0.00 2.82 59.28 0.00 > 36.59 > 21:30:01 all 1.39 0.00 2.92 60.51 0.00 > 35.18 > 21:40:01 all 1.34 0.00 3.04 60.04 0.00 > 35.57 > 21:50:03 all 1.29 0.00 2.51 59.79 0.00 > 36.41 > 22:00:03 all 1.36 0.00 3.23 59.81 0.00 > 35.59 > 22:10:03 all 1.37 0.00 2.56 59.13 0.00 > 36.93 > 22:20:03 all 1.36 0.00 2.88 58.46 0.00 > 37.29 > 22:30:03 all 1.31 0.00 2.65 59.07 0.00 > 36.97 > 22:40:00 all 1.32 0.00 2.72 59.61 0.00 > 36.35 > 22:50:01 all 1.32 0.00 2.72 59.35 0.00 > 36.61 > 23:00:03 all 1.29 0.00 2.68 59.30 0.00 > 36.72 > 23:10:03 all 1.35 0.00 2.62 60.11 0.00 > 35.91 > 23:20:02 all 1.29 0.00 2.91 59.55 0.00 > 36.25 > 23:30:03 all 1.32 0.00 2.72 58.37 0.00 > 37.59 > 23:40:01 all 1.34 0.00 2.97 57.74 0.00 > 37.95 > 23:50:00 all 1.33 0.00 2.54 59.90 0.00 > 36.24 > Average: all 1.38 0.00 2.83 59.37 0.00 > 36.41 > > $ last -n 3 reboot > reboot system boot 6.5.0-0.deb12.1- Wed Nov 8 19:32 still running > reboot system boot 6.1.0-13-amd64 Mon Oct 9 23:14 - 19:32 (29+21:17) > reboot system boot 6.1.0-13-amd64 Mon Oct 9 22:39 - 23:14 (00:35) > ============================================================================ > > And top only shows a single [scsi_eh_2] thread using ~50% of CPU time, > sometimes there's an events thread too. > > > PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND > 336 root 20 0 0.0m 0.0m 0.0m D 50.0 0.0 53,37 > [scsi_eh_2] > 3794126 root 20 0 0.0m 0.0m 0.0m I 25.7 0.0 0:06.27 > [kworker/0:0-events] > > This is a Debian/amd64 VM running on a VMware ESX host. There's a virtual > CDROM > drive, but nothing is attached here and I'm not using it, all: > > > ============================================================================ > $ lsblk -d --scsi > NAME HCTL TYPE VENDOR MODEL REV SERIAL > TRAN > sda 0:0:0:0 disk VMware Virtual disk 2.0 > sr0 2:0:0:0 rom NECVMWar VMware Virtual IDE CDROM Drive 1.00 > 10000000000000000001 ata > > > $ dmesg -t | grep -i scsi > Block layer SCSI generic (bsg) driver version 0.4 loaded (major 247) > SCSI subsystem initialized > VMware PVSCSI driver - version 1.0.7.0-k > vmw_pvscsi: using 64bit dma > vmw_pvscsi: max_id: 65 > vmw_pvscsi: setting ring_pages to 32 > vmw_pvscsi: enabling reqCallThreshold > vmw_pvscsi: driver-based request coalescing enabled > vmw_pvscsi: using MSI-X > scsi host0: VMware PVSCSI storage adapter rev 2, req/cmp/msg rings: 32/32/1 > pages, cmd_per_lun=254 > vmw_pvscsi 0000:03:00.0: VMware PVSCSI rev 2 host #0 > scsi 0:0:0:0: Direct-Access VMware Virtual disk 2.0 PQ: 0 ANSI: 6 > sd 0:0:0:0: [sda] Attached SCSI disk > sd 0:0:0:0: Attached scsi generic sg0 type 0 > scsi host1: ata_piix > scsi host2: ata_piix > scsi 2:0:0:0: CD-ROM NECVMWar VMware IDE CDR10 1.00 PQ: 0 ANSI: 5 > scsi 2:0:0:0: Attached scsi generic sg1 type 5 > sr 2:0:0:0: [sr0] scsi3-mmc drive: 1x/1x writer dvd-ram cd/rw xa/form2 cdda > tray > sr 2:0:0:0: Attached scsi CD-ROM sr0 > ============================================================================ > > Will that "scsi: Do no try to probe for CDL on old drives" patch land in > mainline or is this still under discussion? It has been in mainline for a while: 2132df16f53b ("scsi: core: ata: Do no try to probe for CDL on old drives") $ git tag --contains 2132df16f53b v6.6 v6.6-rc4 v6.6-rc5 v6.6-rc6 v6.6-rc7 v6.6.1 v6.7-rc1 Kind regards, Niklas
Oh, great! I was only searching for the subject line, not the actual changes. So, I just have to wait for Debian (Backports) to move to v6.6 then :-) Thanks! This Bugzilla entry can be closed then, I assume.
"scsi: core: ata: Do no try to probe for CDL on old drives" -> it's also on 6.5.6.