scsi_eh_* process using idle CPU after upgrade to kernel 6.5

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, <email address hidden> 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, <email address hidden> 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, <email address hidden> 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://<email address hidden>/

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, <email address hidden> 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://<email address hidden>/
>
> 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, <email address hidden> 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://<email address hidden>/
>
> 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 syste...

On Mon, Nov 13, 2023 at 03:30:57AM +0000, <email address hidden> wrote:
> https://bugzilla.kernel.org/show_bug.cgi?id=217914
>
> Christian Kujau (<email address hidden>) changed:
>
> What |Removed |Added
> ----------------------------------------------------------------------------
> CC| |<email address hidden>
>
> --- Comment #7 from Christian Kujau (<email address hidden>) ---
> 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...

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.