scsi_eh_1 process high cpu after upgrading to 6.5.2

laktak · 2023-09-11 16:14:33

I've upgraded several VMs

- from Linux arch 6.4.12-arch1-1 #1 SMP PREEMPT_DYNAMIC Thu, 24 Aug 2023 00:38:14 +0000 x86_64 GNU/Linux
- to Linux arch 6.5.2-arch1-1 #1 SMP PREEMPT_DYNAMIC Wed, 06 Sep 2023 21:01:01 +0000 x86_64 GNU/Linux

and in all of them the scsi_eh_1 process eats 10-15% CPU.

I can't find any errors in the logs. When I go back to a snapshot with 6.4.12 the problem disappears. The FS is btrfs.

scsi_eh should be the scsi error handler so I've tried to enable logging (https://github.com/ibm-s390-linux/s390- … ging_level) but I see no output in dmesg/journalctl.

How can I find out what is causing this?

loqs · 2023-09-11 18:04:12

laktak wrote:

How can I find out what is causing this?

https://wiki.archlinux.org/title/Kernel … egressions

laktak · 2023-09-12 11:26:23

Thank you. I've compared the kernels and the problem appears after going from 6.4.12 to 6.5.

https://cdn.kernel.org/pub/linux/kernel … ngeLog-6.5 has several changes regarding SCSI so I'll try to contact the author.

loqs · 2023-09-12 14:46:53

Please consider bisecting between 6.4 and 6.5 or reverting just those commits to see if they resolve the issue before contacting upstream.

laktak · 2023-09-12 19:07:46

Yes, I'm trying but the VMs are rather small and are taking forever to build.

loqs · 2023-09-12 19:16:50

If you need some help with the bisection I can build the kernel packages for you. If you want my help I would need to know your current bisection progress `git bisect log` and preferably the kernel config you are using for instance the one from 6.5.2-arch1-1

laktak · 2023-09-12 20:24:53

So far I only managed to build and install https://aur.archlinux.org/packages/linux-git because I saw there were additional commits regarding SCSI. Unfortunately they did not fix the bug.

The new kernel also stays a long time at ":: Triggering uevents..." at boot before proceeding.

It would be great if you could help me bisect from 6.4.12 to 6.5.

kernel config: https://pastebin.com/gYLwvbeg

There are lots of commits that mention SCSI but one references scsi_eh:

commit 3d848ca1ebc8d8864f25bd461914c93eff82a2d2
Author: Niklas Cassel <niklas.cassel@wdc.com>
Date: Thu May 11 03:13:37 2023 +0200

loqs · 2023-09-12 21:36:33

https://drive.google.com/file/d/1SzRGbE … sp=sharing linux-6.5-1.1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1k-FP2A … sp=sharing linux-headers-6.5-1.1-x86_64.pkg.tar.zst
Please test that 6.5 built with Arch's 6.5 config has the issue. I am building the first bisection point assuming it did:

$ git bisect start
status: waiting for both good and bad commits
$ git bisect good v6.4
status: waiting for bad commit, 1 good commit known
$ git bisect bad v6.5
Bisecting: 7364 revisions left to test after this (roughly 13 steps)
[b775d6c5859affe00527cbe74263de05cfe6b9f9] Merge tag 'mips_6.5' of git://git.kernel.org/pub/scm/linux/kernel/git/mips/linux

Edit:
https://drive.google.com/file/d/1mzFisD … sp=sharing linux-6.4.r7309.gb775d6c5859a-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1FN7ufH … sp=sharing linux-headers-6.4.r7309.gb775d6c5859a-1-x86_64.pkg.tar.zst

Last edited by loqs (2023-09-12 21:53:39)

MoZhonghua · 2023-09-13 07:01:02

loqs wrote:

https://drive.google.com/file/d/1SzRGbE … sp=sharing linux-6.5-1.1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1k-FP2A … sp=sharing linux-headers-6.5-1.1-x86_64.pkg.tar.zst
Please test that 6.5 built with Arch's 6.5 config has the issue. I am building the first bisection point assuming it did:
$ git bisect start
status: waiting for both good and bad commits
$ git bisect good v6.4
status: waiting for bad commit, 1 good commit known
$ git bisect bad v6.5
Bisecting: 7364 revisions left to test after this (roughly 13 steps)
[b775d6c5859affe00527cbe74263de05cfe6b9f9] Merge tag 'mips_6.5' of git://git.kernel.org/pub/scm/linux/kernel/git/mips/linux
Edit:
https://drive.google.com/file/d/1mzFisD … sp=sharing linux-6.4.r7309.gb775d6c5859a-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1FN7ufH … sp=sharing linux-headers-6.4.r7309.gb775d6c5859a-1-x86_64.pkg.tar.zst

Same issue in my virtual machines. Following kernels tested:

bad: 6.5.2-arch1-1

ok: 6.1.52-1-lts
ok: 6.4.0-1.1-07309-gb775d6c5859a

laktak · 2023-09-13 08:39:41

Thanks loqs! Same here:

bad: 6.5.0-1.1

ok: 6.4.0-1.1-07309-gb775d6c5859a

seth · 2023-09-13 10:49:24

I can't find any errors in the logs

I've tried to enable logging … but I see no output in dmesg/journalctl.

"Tried" how?

scsi_logging_level -g
sudo scsi_logging_level -a 7 -s  # should spam your log mightily

Do you have an optical drive?

MoZhonghua · 2023-09-13 11:08:26

seth wrote:

Do you have an optical drive?

I have an optical drive in VMWare virtal machine, and I don't have an physical optical drive on my host machine, so this drive is set with "connected" and "connect at startup" disabled.

When I delete optical drive from my virtual machine, the problem goes away! (tested with kernel 6.5.2-arch1-1).

Some log with "sudo scsi_logging_level -a 7 -s"

https://pastebin.com/f2LQ8kQD

Last edited by MoZhonghua (2023-09-13 11:21:53)

seth · 2023-09-13 11:23:50

Do you need some logs with "sudo scsi_logging_level -a 7 -s"?

I don't expect that helping to narrow down on the cause (beyond what my gut told you )
It was more to contest the "no log output" situation.

There's a whole bunch of commits that look like sring-clean by Christoph Hellwig and then there's

commit 8270cb10c0681d52fce508f827dfa1688d3acc3a
Author: Jordy Zomer <jordyzomer@google.com>
Date:   Sat Jun 17 12:38:28 2023 +0100

    cdrom: Fix spectre-v1 gadget

Only the latter isn't in the wider context of more generic block device code changes, so I'd maybe look there first (unless it was backported to 6.4)

Edit: Just noticed there're two users!
==================================
Wait for a situation description from laktak first.

Last edited by seth (2023-09-13 11:25:19)

MoZhonghua · 2023-09-13 11:38:58

More tests:

1. with optical disk but not connected, kernel 6.5.2: many spurious error messages like this (full log: https://pastebin.com/f2LQ8kQD )

[  300.306311] sr 0:0:0:0: [sr0] tag#0 scsi host busy 1 failed 0
[  300.326421] scsi host0: Waking error handler thread
[  300.326435] scsi host0: scsi_eh_0: waking up 0/1/1

2. with optical disk and using an ISO file, kernel 6.5.2: same problem

3. with or without optical disk, kernel 6.4.0: no problem and no error messages

loqs · 2023-09-13 11:47:48

https://drive.google.com/file/d/1Zt97LF … sp=sharing linux-6.4.r4247.g3a8a670eeeaa-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1xwqcXa … sp=sharing linux-headers-6.4.r4247.g3a8a670eeeaa-1-x86_64.pkg.tar.zst

MoZhonghua · 2023-09-13 11:56:10

loqs wrote:

https://drive.google.com/file/d/1Zt97LF … sp=sharing linux-6.4.r4247.g3a8a670eeeaa-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1xwqcXa … sp=sharing linux-headers-6.4.r4247.g3a8a670eeeaa-1-x86_64.pkg.tar.zst

bad: 6.5.2-arch1-1

ok: 6.1.52-1-lts
ok: 6.4.0-1.1-07309-gb775d6c5859a
ok: 6.4.0-1.1-04247-g3a8a670eeeaa

loqs · 2023-09-13 12:35:53

6.5.3-arch1 with 8270cb10c0681d52fce508f827dfa1688d3acc3a reverted

https://drive.google.com/file/d/1TfRS7t … sp=sharing linux-6.5.3.arch1-1.1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1NbgmjJ … sp=sharing linux-headers-6.5.3.arch1-1.1-x86_64.pkg.tar.zst
Edit:
If that was not the cause

$ git bisect good
Bisecting: 3681 revisions left to test after this (roughly 12 steps)
[56cbceab928d7ac3702de172ff8dcc1da2a6aaeb] Merge tag 'usb-6.5-rc1' of git://git.kernel.org/pub/scm/linux/kernel/git/gregkh/usb

https://drive.google.com/file/d/1F20Nu2 … sp=sharing linux-6.4.r10992.g56cbceab928d-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1V_i78p … sp=sharing linux-headers-6.4.r10992.g56cbceab928d-1-x86_64.pkg.tar.zst

I made a mistake with linux-6.4.r4247.g3a8a670eeeaa-1-x86_64.pkg.tar.zst because I marked b775d6c5859affe00527cbe74263de05cfe6b9f9 as bad when you had tested it as good.
Correct git log

]$ git bisect log
git bisect start
# status: waiting for both good and bad commits
# good: [6995e2de6891c724bfeb2db33d7b87775f913ad1] Linux 6.4
git bisect good 6995e2de6891c724bfeb2db33d7b87775f913ad1
# bad: [2dde18cd1d8fac735875f2e4987f11817cc0bc2c] Linux 6.5
git bisect bad 2dde18cd1d8fac735875f2e4987f11817cc0bc2c
# good: [b775d6c5859affe00527cbe74263de05cfe6b9f9] Merge tag 'mips_6.5' of git://git.kernel.org/pub/scm/linux/kernel/git/mips/linux
git bisect good b775d6c5859affe00527cbe74263de05cfe6b9f9

Last edited by loqs (2023-09-13 13:00:42)

laktak · 2023-09-13 13:50:38

bad: 6.5.3-arch1-1.1
bad: 6.4.0-1-10992-g56cbceab928d

loqs · 2023-09-13 14:34:15

$ git bisect bad
Bisecting: 1805 revisions left to test after this (roughly 11 steps)
[b30d7a77c53ec04a6d94683d7680ec406b7f3ac8] Merge tag 'perf-tools-for-v6.5-1-2023-06-28' of git://git.kernel.org/pub/scm/linux/kernel/git/perf/perf-tools-next

https://drive.google.com/file/d/1ZMv5pU … sp=sharing linux-6.4.r9186.gb30d7a77c53e-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1LFcQSn … sp=sharing linux-headers-6.4.r9186.gb30d7a77c53e-1-x86_64.pkg.tar.zst

laktak · 2023-09-13 14:41:27

good: 6.4.0-1-09186-gb30d7a77c53e

laktak · 2023-09-13 14:46:08

seth wrote:

scsi_logging_level -g
sudo scsi_logging_level -a 7 -s  # should spam your log mightily

Not sure what I did wrong before but this produces logs. Thanks.

loqs · 2023-09-13 15:02:47

$ git bisect good
Bisecting: 895 revisions left to test after this (roughly 10 steps)
[dfab92f27c600fea3cadc6e2cb39f092024e1fef] Merge tag 'nfs-for-6.5-1' of git://git.linux-nfs.org/projects/trondmy/linux-nfs

https://drive.google.com/file/d/11gecSQ … sp=sharing linux-6.4.r10096.gdfab92f27c60-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1vtGQ4h … sp=sharing linux-headers-6.4.r10096.gdfab92f27c60-1-x86_64.pkg.tar.zst
Edit:
6.5.3-arch1 with https://lore.kernel.org/linux-ide/20230 … l.org/T/#u applied:

https://drive.google.com/file/d/1nYW-4w … sp=sharing linux-6.5.3.arch1-1.2-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1y3NU8K … sp=sharing linux-headers-6.5.3.arch1-1.2-x86_64.pkg.tar.zst

Last edited by loqs (2023-09-13 15:51:54)

laktak · 2023-09-13 19:25:03

bad: 6.5.3-arch1-1.2
bad: 6.4.0-1-10096-gdfab92f27c60

loqs · 2023-09-13 20:20:56

$ git bisect bad
Bisecting: 476 revisions left to test after this (roughly 9 steps)
[28968f384be3c064d66954aac4c534a5e76bf973] Merge tag 'pinctrl-v6.5-1' of git://git.kernel.org/pub/scm/linux/kernel/git/linusw/linux-pinctrl

https://drive.google.com/file/d/1WpabY3 … sp=sharing linux-6.4.r9619.g28968f384be3-1-x86_64.pkg.tar.zst
https://drive.google.com/file/d/1TPKs7w … sp=sharing linux-headers-6.4.r9619.g28968f384be3-1-x86_64.pkg.tar.zst

laktak · 2023-09-13 20:57:40

bad: 6.4.0-1-09619-g28968f384be3

Arch Linux

#1 2023-09-11 16:14:33

scsi_eh_1 process high cpu after upgrading to 6.5.2

#2 2023-09-11 18:04:12

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#3 2023-09-12 11:26:23

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#4 2023-09-12 14:46:53

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#5 2023-09-12 19:07:46

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#6 2023-09-12 19:16:50

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#7 2023-09-12 20:24:53

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#8 2023-09-12 21:36:33

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#9 2023-09-13 07:01:02

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#10 2023-09-13 08:39:41

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#11 2023-09-13 10:49:24

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#12 2023-09-13 11:08:26

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#13 2023-09-13 11:23:50

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#14 2023-09-13 11:38:58

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#15 2023-09-13 11:47:48

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#16 2023-09-13 11:56:10

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#17 2023-09-13 12:35:53

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#18 2023-09-13 13:50:38

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#19 2023-09-13 14:34:15

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#20 2023-09-13 14:41:27

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#21 2023-09-13 14:46:08

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#22 2023-09-13 15:02:47

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#23 2023-09-13 19:25:03

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#24 2023-09-13 20:20:56

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

#25 2023-09-13 20:57:40

Re: scsi_eh_1 process high cpu after upgrading to 6.5.2

Board footer