[BUG] check-kmod-load-unload.sh triggers hard kernel lockups

Describe the bug

~/sof-test/test-case/check-kmod-load-unload.sh -l 25 causes hard kernel lockups

This is a very recent regression in daily tests.

To Reproduce

TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-nocodec-ci.tplg \
 MODEL=ADLP_RVP_NOCODEC_CI \
  ~/sof-test/test-case/check-kmod-load-unload.sh -l 25

or

TPLG=/lib/firmware/intel/sof-tplg/sof-tgl-rt715-rt711-rt1308-mono.tplg \
  MODEL=TGLU_SKU0A3E_SDW \
   ~/sof-test/test-case/check-kmod-load-unload-after-playback.sh -l 5

Reproduction Rate

~~Too early to tell.~~ Seems very low.

Environment

First bad daily test: 12140

Start Time: 2022-04-27 22:29:55 UTC
End Time: 2022-04-28 02:49:19 UTC
< >>
Kernel Branch: topic/sof-dev
Kernel Commit: 95ec8d3
SOF Branch: main
SOF Commit: 94e6c99

Last good daily test: 12106

Start Time: 2022-04-26 22:29:40 UTC
End Time: 2022-04-27 05:52:13 UTC
< > >>
Kernel Branch: topic/sof-dev
Kernel Commit: 95ec8d3
SOF Branch: main
SOF Commit: 3334bed

Only these commits are different between last good and first bad daily tests:

94e6c99 eddyhsu@chromium.org // (origin/main, origin/HEAD) kpb: Clean up params on component reset
99eac8d rander.wang@intel.com // ipc4: add format conversion support of s32le to s24le
f4f9e65 chao.song@linux.intel.com // sof: replace log calls with zephyr logging api
d67e2ea eddyhsu@chromium.org // dcblock: Clean up processing function on reset.
426542d daniel.baluta@nxp.com // codec_adapter: cadence: Resolve api_id at runtime
02dd7a6 daniel.baluta@nxp.com // codec_adapter: cadence: Remove api_id parameter
05969a0 marc.herbert@intel.com // .github: IPC4: build supported TGL platforms first
dccf9c0 marc.herbert@intel.com // .github/zephyr: download docker image from ghcr.io instead of docker.io
75dea11 chunxu.li@mediatek.com // topology1: add mt8186 related pipelines and components

Last good commit 3334bed seppo.ingalsuo@linux.intel.com // Tools: Testbench: Add components to testbench load

ADLP_RVP_NOCODEC_CI sh-adlp-rvp-nocodec-02

2022-04-28 00:17:08 UTC [REMOTE_INFO] ==== firmware boot complete: 16 of 25 ====
2022-04-28 00:17:11 UTC [REMOTE_INFO] ===== Starting iteration 17 of 25 =====
2022-04-28 00:17:11 UTC [REMOTE_INFO] wait dsp power status to become suspended


Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x50010000: GLB_COMP_MSG: SET_VALUE
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x50010000: GLB_COMP_MSG: SET_VALUE
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90439]: pam_unix(sudo:session): session closed for user root
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 systemd[1281]: Reached target Sound Card.
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90443]:   ubuntu : TTY=unknown ; PWD=/home/ubuntu ; USER=root ; COMMAND=/usr/sbin/modprobe snd_usb_audio
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 systemd[1]: Condition check resulted in Manage Sound Card State (restore and store) being skipped.
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90443]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 systemd[1]: Reached target Sound Card.
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90443]: pam_unix(sudo:session): session closed for user root
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 systemd[775]: Reached target Sound Card.
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90451]:   ubuntu : TTY=unknown ; PWD=/home/ubuntu ; USER=root ; COMMAND=/usr/bin/lspci -D
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 systemd-udevd[88066]: controlC0: Process '/usr/sbin/alsactl -E HOME=/run/alsa -E XDG_RUNTIME_DIR=/run/alsa/runtime restore 0' failed with exit code 99.
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90451]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90451]: pam_unix(sudo:session): session closed for user root
Apr 28 00:16:57 sh-adlp-rvp-nocodec-02 sudo[90457]:   ubuntu : TTY=unknown ; PWD=/home/ubuntu ; USER=root ; COMMAND=/usr/bin/lspci -s 0000:00:1f.3 -kx
...
Apr 28 00:16:58 sh-adlp-rvp-nocodec-02 sudo[90523]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 28 00:16:58 sh-adlp-rvp-nocodec-02 sudo[90523]: pam_unix(sudo:session): session closed for user root
Apr 28 00:16:58 sh-adlp-rvp-nocodec-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
Apr 28 00:16:58 sh-adlp-rvp-nocodec-02 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION

   => sudden journalctl death, no clean shutdown, no logs. Reboot.

Apr 28 00:17:34 sh-adlp-rvp-nocodec-02 kernel: Linux version 5.18.0-rc2-daily-nocodec-20220427-0-g95ec8d32e6b6 (jenkins@sofbld03.ostc.intel.com) (gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, GNU >
Apr 28 00:17:34 sh-adlp-rvp-nocodec-02 kernel: Command line: BOOT_IMAGE=/boot/vmlinuz-5.18.0-rc2-daily-nocodec-20220427-0-g95ec8d32e6b6 root=UUID=9c8bfe18-8e07-4cb8-b209-e7861d1988b7 ro quiet s>
...
Apr 28 00:17:34 sh-adlp-rvp-nocodec-02 systemd-fsck[514]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.

TGLU_SKU0A3E_SDW jf-tglu-sku0a3e-sdw-01

2022-04-28 00:08:53 UTC Sub-Test: [REMOTE_INFO] ===== Testing: (Round: 1/1) (PCM: HDMI 3 [hw:0,7]) (Loop: 1/1) =====
2022-04-28 00:08:53 UTC Sub-Test: [REMOTE_COMMAND] aplay   -Dhw:0,7 -r 48000 -c 2 -f S16_LE -d 3 /dev/zero -v -q

Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 sudo[102207]: pam_unix(sudo:session): session opened for user root by (uid=0)
Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 sudo[102207]: pam_unix(sudo:session): session closed for user root
Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x90040000: GLB_TRACE_MSG: FILTER_UPDATE
Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx: 0x90020000: GLB_TRACE_MSG: DMA_POSITION
Apr 28 00:08:25 jf-tglu-sku0a3e-sdw-01 kernel: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc rx done: 0x90020000: GLB_TRACE_MSG: DMA_POSITION

 => sudden journalctl death, no clean shutdown, no logs. Reboot.

Apr 27 22:32:54 jf-tglu-sku0a3e-sdw-01 kernel: microcode: microcode updated early to revision 0x88, date = 2021-03-31
Apr 27 22:32:54 jf-tglu-sku0a3e-sdw-01 kernel: Linux version 5.18.0-rc2-daily-default-20220427-0-g95ec8d32e6b6 (jenkins@sofbld03.ostc.intel.com) (gcc (Ubuntu 9.4.0-1ubuntu1~20.04.1) 9.4.0, GNU >
...
Apr 27 22:32:55 jf-tglu-sku0a3e-sdw-01 systemd-fsck[503]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
...
Apr 27 23:41:22 jf-tglu-sku0a3e-sdw-01 sudo[1208]: pam_unix(sudo:session): session closed for user root
Apr 28 00:21:32 jf-tglu-sku0a3e-sdw-01 systemd-timesyncd[511]: Initial synchronization to time server 10.104.192.232:123 (corp.intel.com).

It doesn't make sense to me that the SOF code change causes kernel issue, and in the meanwhile, there is no error in sof logger.

This is what I get from sh-adlp-rvp-nocodec-02, not sure if it is related.

[    5.074241] i915 0000:00:02.0: [drm] DMC firmware homepage: https://git.kernel.org/pub/scm/linux/kernel/git/firmware/linux-firmware.git/tree/i915
[    5.091396] sof-audio-pci-intel-tgl 0000:00:1f.3: PCI DSP detected
[    5.091428] sof-audio-pci-intel-tgl 0000:00:1f.3: enabling device (0000 -> 0002)
[    5.091743] sof-audio-pci-intel-tgl 0000:00:1f.3: DSP detected with PCI class/subclass/prog-if 0x040100
[    5.092253] i915 0000:00:02.0: Direct firmware load for i915/adlp_guc_69.0.3.bin failed with error -2
[    5.092258] i915 0000:00:02.0: [drm] GuC firmware i915/adlp_guc_69.0.3.bin: fetch failed with error -2
[    5.092260] i915 0000:00:02.0: [drm] GuC firmware(s) can be downloaded from https://git.kernel.org/pub/scm/linux/kernel/git/firmware/linux-firmware.git/tree/i915

@aiChaoSONG

Agree with @aiChaoSONG, we should try to see if we can identify regressions due to recent upstream merges.

95ec8d3 (04/21)
8f77d72 (04/18)

A short reminder that we have been regularly having lockups in suspend/resume tests since forever; we just got used to them and many are likely NOT audio related (but we can't tell of course).

While they could be more than one day old, hard lockups in kmod tests seem very new.

@marc-hb

@marc-hb It's hard to conclude for TGLU_SKU0A3E_SDW, there's only one failed test but it comes without any dmesg info.

12177 pass
12140 fail
12106 pass
12065 pass

Yes the reproduction rate has been very low so it's very hard to draw any conclusion. Apologies for sharing this SOF git log too early.

I spent time gathering data and filing this bug because:

I don't remember us ever experiencing any hard crash on kmod testing. Suspend/resume crashes: yes, kmod: no.
We had 3 systems experiencing hard lockups in the same kmod test in the same daily run. That was too much coincidence. The 3rd system was sh-tglh-0a70-hda-01 . I did not share its logs because it experienced worse NTP issues which made the logs very hard to make sense of - but there was a hard lockup on sh-tglh-0a70-hda-01 too.

it comes without any dmesg info.

Automation going back and collecting the right journalctl entry after a crash and reboot is theoretically possible (because anything is theoretically possible) but we're very far from having that capability now. To file this bug I logged into the systems and gathered info manually which... told me very little besides the fact that the systems actually crashed. So post-crash collection of journalctl may not be worth a big development effort. Something like this would be better instead but it's unlikely to come "for free" either: https://chromium.googlesource.com/chromiumos/platform2/+/d8311fbae60eefcfa/crash-reporter/docs/collectors.md#kernel_collector

@marc-hb

I will agree with you @marc-hb that in general kmod load/unload issues are directly related to audio issues, since we don't touch the other drivers. That makes the occurrences of such bugs less likely than the generic case where all possible drivers could impact suspend-resume.

I also agree that there is no such thing as coincidence, we should absolutely keep track of this issue. I wasn't trying to close it or dismiss your opinion, I commented to acknowledge that I am aware of the issue but could not suggest any useful explanation or lead to look further into the problem.

Run about 1700 iteration of check-kmod-load-unload.sh after rebooting sh-tglh-0a70-hda-01 and not a single error.

In FW bugscrub: no sign of relation to FW, so moving to kernel.

All the symptoms points to a duplicate of #3387 and it might have been fixed by the tuning of the vm parameters?

hijack: add a quick write test to monitor storage perf. after each test

@marc-hb

@marc-hb , can we close this one? we haven't seen this issue for a long time and #3387 is closed.

@plbossart

I don't think this was a duplicate of #3387 (buggy SSDs) because sh-adlp-rvp-nocodec-02 never had any SSD issue and its drive was not replaced, correct? I think people who tried to reproduce unfortunately wasted a lot of time with unrelated SSD issues on some systems.

This being said, we can always re-open if seen again @plbossart ?

yes, we can always re-open as needed.

This happened again in daily 13859?model=ADLP_RVP_NOCODEC&testcase=check-kmod-load-unload-25

journalctl ends like this:

Jul 10 23:27:10 sh-adlp-rvp-nocodec-06 sudo[92048]: pam_unix(sudo:session): session closed for user root
Jul 10 23:27:10 sh-adlp-rvp-nocodec-06 sudo[92053]:   ubuntu : TTY=unknown ; PWD=/home/ubuntu ; USER=root ; COMMAND=/usr/bin/lspci -s 0000:00:1f.3 -kx
Jul 10 23:27:10 sh-adlp-rvp-nocodec-06 sudo[92053]: pam_unix(sudo:session): session opened for user root by (uid=0)
Jul 10 23:27:10 sh-adlp-rvp-nocodec-06 sudo[92053]: pam_unix(sudo:session): session closed for user root
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof_intel_hda_common:hda_dsp_stream_trigger: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x80]=>
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x90050000: GLB_TRACE_MSG: DMA_FREE
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof:ipc3_log_header: sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_reset_enter: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]>
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_power_down: sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=>
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof_intel_hda_common:hda_dsp_core_is_enabled: sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 0 : >
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof:snd_sof_pci_update_bits_unlocked: sof-audio-pci-intel-tgl 0000:00:1f.3: Debug PCIR: 00000010 at  00000044
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof_intel_hda_common:hda_dsp_state_log: sof-audio-pci-intel-tgl 0000:00:1f.3: Current DSP power state: D3
Jul 10 23:27:11 sh-adlp-rvp-nocodec-06 kernel: snd_sof:sof_set_fw_state: sof-audio-pci-intel-tgl 0000:00:1f.3: fw_state change: 6 -> 0

(and then nothing)

The next boot has this:

Jul 10 23:28:06 sh-adlp-rvp-nocodec-06 systemd-fsck[507]: fsck.fat 4.1 (2017-01-24)
Jul 10 23:28:06 sh-adlp-rvp-nocodec-06 systemd-fsck[507]: 0x41: Dirty bit is set. Fs was not properly unmounted and some data may be corrupt.
Jul 10 23:28:06 sh-adlp-rvp-nocodec-06 systemd-fsck[507]:  Automatically removing dirty bit.

Closing this issue, no reproductions for more that one month,

Navigation Menu

Repository navigation

[BUG] check-kmod-load-unload.sh triggers hard kernel lockups #3669

7 remaining items

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

[BUG] check-kmod-load-unload.sh triggers hard kernel lockups #3669

Description

Activity

marc-hb commented on Apr 28, 2022

aiChaoSONG commented on Apr 28, 2022

plbossart commented on Apr 28, 2022

marc-hb commented on Apr 28, 2022

plbossart commented on Apr 29, 2022

marc-hb commented on Apr 29, 2022

plbossart commented on Apr 29, 2022

ujfalusi commented on May 3, 2022

ujfalusi commented on May 3, 2022

ujfalusi commented on May 10, 2022

7 remaining items

kv2019i commented on May 24, 2022

ujfalusi commented on May 24, 2022

keqiaozhang commented on Jul 4, 2022

marc-hb commented on Jul 5, 2022

plbossart commented on Jul 5, 2022

marc-hb commented on Jul 11, 2022

keqiaozhang commented on Aug 15, 2022

Metadata

Metadata

Assignees

Labels

Type

Projects

Milestone

Relationships

Development

Issue actions