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

[marc-hb]

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

[marc-hb]

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).

[aiChaoSONG]

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

[plbossart]

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

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

[marc-hb]

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.

[plbossart]

@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

[marc-hb]

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

[plbossart]

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.

[ujfalusi]

It is hard to reproduce for sure, last week I took the tglh machine and I saw once a lockup:

[19659.122778] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx: 0x40010000: GLB_PM_MSG: CTX_SAVE
[19659.123126] sof-audio-pci-intel-tgl 0000:00:1f.3: ipc tx succeeded: 0x40010000: GLB_PM_MSG: CTX_SAVE
[19659.124310] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x3010303 successful
[19659.124315] sof-audio-pci-intel-tgl 0000:00:1f.3: FW Poll Status: reg[0x4]=0x303 successful
[19659.124317] sof-audio-pci-intel-tgl 0000:00:1f.3: DSP core(s) enabled? 0 : core_mask 1
[19661.564260] INFO: task journal-offline:163719 blocked for more than 122 seconds.
[19661.564277] Not tainted 5.18.0-rc2-daily-default-20220427-0-g95ec8d32e6b6 #dev
[19661.564283] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[19661.564288] task:journal-offline state:D stack:13760 pid:163719 ppid: 1 flags:0x00004000
[19661.564300] Call Trace:
[19661.564304] <TASK>
[19661.564315] __schedule+0x2b4/0x8c0
[19661.564326] ? sched_clock_cpu+0xd/0xd0
[19661.564343] schedule+0x4e/0xb0
[19661.564349] ? folio_wait_bit+0xdd/0x1d0
[19661.564356] io_schedule+0x12/0x40
[19661.564362] folio_wait_bit+0xdd/0x1d0
[19661.564372] ? filemap_invalidate_unlock_two+0x40/0x40
[19661.564386] folio_wait_writeback+0x56/0xb0
[19661.564392] __filemap_fdatawait_range+0x87/0x120
[19661.564420] file_write_and_wait_range+0xc6/0xe0
[19661.564436] ext4_sync_file+0x1a5/0x3e0
[19661.564449] do_fsync+0x38/0x70
[19661.564460] __x64_sys_fsync+0x10/0x20
[19661.564465] do_syscall_64+0x38/0x90
[19661.564474] entry_SYSCALL_64_after_hwframe+0x44/0xae
[19661.564482] RIP: 0033:0x7ff09e5491fb
[19661.564489] RSP: 002b:00007ff090a10c70 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
[19661.564497] RAX: ffffffffffffffda RBX: 0000557f19479f60 RCX: 00007ff09e5491fb
[19661.564501] RDX: 00007ff09e3989de RSI: 00007ff09e3989de RDI: 000000000000002b
[19661.564505] RBP: 00007ff09e39a1a0 R08: 0000000000000000 R09: 00007ff090a11700
[19661.564508] R10: 000000000000001e R11: 0000000000000293 R12: 0000000000000002
[19661.564512] R13: 00007ffc6eacda8f R14: 00007ffc6eacda90 R15: 00007ff090a10d80
[19661.564536] </TASK>
[19661.564580] INFO: task kworker/u32:1:63196 blocked for more than 122 seconds.
[19661.564588] Not tainted 5.18.0-rc2-daily-default-20220427-0-g95ec8d32e6b6 #dev
[19661.564593] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[19661.564598] task:kworker/u32:1 state:D stack:12824 pid:63196 ppid: 2 flags:0x00004000
[19661.564610] Workqueue: writeback wb_workfn (flush-259:0)
[19661.564622] Call Trace:
[19661.564626] <TASK>
[19661.564637] __schedule+0x2b4/0x8c0
[19661.564645] ? __blk_flush_plug+0xdf/0x120
[19661.564660] schedule+0x4e/0xb0
[19661.564667] io_schedule+0x12/0x40
[19661.564673] blk_mq_get_tag+0x11c/0x280
[19661.564681] ? sched_clock_cpu+0xd/0xd0
[19661.564688] ? complete_all+0x60/0x60
[19661.564702] __blk_mq_alloc_requests+0x188/0x2e0
[19661.564709] ? blk_attempt_plug_merge+0x76/0x90
[19661.564721] blk_mq_submit_bio+0x421/0x700
[19661.564744] submit_bio_noacct_nocheck+0x259/0x2b0
[19661.564759] ext4_io_submit+0x20/0x40
[19661.564766] ext4_bio_write_page+0x16e/0x520
[19661.564778] mpage_submit_page+0x4e/0x70
[19661.564786] mpage_process_page_bufs+0xf8/0x110
[19661.564794] mpage_prepare_extent_to_map+0x1f9/0x450
[19661.564826] ext4_writepages+0x311/0xeb0
[19661.564843] ? __lock_acquire.isra.0+0x125/0x550
[19661.564873] do_writepages+0xbf/0x180
[19661.564879] ? find_held_lock+0x32/0x90
[19661.564886] ? sched_clock_cpu+0xd/0xd0
[19661.564897] __writeback_single_inode+0x6f/0x470
[19661.564910] writeback_sb_inodes+0x214/0x4d0
[19661.564936] __writeback_inodes_wb+0x4c/0xe0
[19661.564948] wb_writeback+0x2df/0x360
[19661.564965] wb_workfn+0x304/0x500
[19661.564991] process_one_work+0x29c/0x530
[19661.565011] worker_thread+0x4d/0x3c0
[19661.565025] ? process_one_work+0x530/0x530
[19661.565031] kthread+0xf0/0x120
[19661.565038] ? kthread_complete_and_exit+0x20/0x20
[19661.565048] ret_from_fork+0x1f/0x30
[19661.565075] </TASK>
[19661.565089] 
 Showing all locks held in the system:
[19661.565100] 1 lock held by khungtaskd/96:
[19661.565104] #0: ffffffffa0965cc0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x15/0xf7
[19661.565134] 1 lock held by in:imklog/587:
[19661.565139] #0: ffffa0c5c6b882f8 (&f->f_pos_lock){....}-{3:3}, at: __fdget_pos+0x4a/0x60
[19661.565235] 3 locks held by dmesg/20209:
[19661.565244] 4 locks held by kworker/u32:1/63196:
[19661.565251] #0: ffffa0c5c1e7b948 ((wq_completion)writeback){....}-{0:0}, at: process_one_work+0x208/0x530
[19661.565272] thesofproject/sof#1: ffffa66f81db3e58 ((work_completion)(&(&wb->dwork)->work)){....}-{0:0}, at: process_one_work+0x208/0x530
[19661.565295] thesofproject/sof#2: ffffa0c5c1c410e8 (&type->s_umount_key#35){....}-{3:3}, at: trylock_super+0x16/0x50
[19661.565319] thesofproject/sof#3: ffffa0c5c1c42c80 (&sbi->s_writepages_rwsem){....}-{0:0}, at: do_writepages+0xbf/0x180
[19661.565341] 3 locks held by kworker/0:0/104849:
[19661.565350] 2 locks held by grep/179183:

Which is FS, storage related by it's look.

Today after <50 iteration the rmmod got blocked when trying to remove snd_hda_codec and not long after:

[19661.930409] INFO: task journal-offline:33295 blocked for more than 122 seconds.
[19661.930426] Not tainted 5.18.0-rc2-daily-default-20220502-0-g23306d2cb554 #dev
[19661.930431] "echo 0 > /proc/sys/kernel/hung_task_timeout_secs" disables this message.
[19661.930436] task:journal-offline state:D stack:13784 pid:33295 ppid: 1 flags:0x00004000
[19661.930448] Call Trace:
[19661.930452] <TASK>
[19661.930462] __schedule+0x2b4/0x8c0
[19661.930475] ? __blk_flush_plug+0xdf/0x120
[19661.930491] schedule+0x4e/0xb0
[19661.930497] io_schedule+0x12/0x40
[19661.930504] blk_mq_get_tag+0x11c/0x280
[19661.930511] ? sched_clock_cpu+0xd/0xd0
[19661.930519] ? complete_all+0x60/0x60
[19661.930531] __blk_mq_alloc_requests+0x188/0x2e0
[19661.930539] ? blk_attempt_plug_merge+0x76/0x90
[19661.930551] blk_mq_submit_bio+0x421/0x700
[19661.930571] submit_bio_noacct_nocheck+0x259/0x2b0
[19661.930584] ext4_io_submit+0x20/0x40
[19661.930592] ext4_bio_write_page+0x16e/0x520
[19661.930604] mpage_submit_page+0x4e/0x70
[19661.930612] mpage_process_page_bufs+0xf8/0x110
[19661.930620] mpage_prepare_extent_to_map+0x1f9/0x450
[19661.930649] ext4_writepages+0x311/0xeb0
[19661.930661] ? sched_clock_cpu+0xd/0xd0
[19661.930688] do_writepages+0xbf/0x180
[19661.930695] ? __lock_acquire.isra.0+0x125/0x550
[19661.930709] file_write_and_wait_range+0xa6/0xe0
[19661.930725] ext4_sync_file+0x1a5/0x3e0
[19661.930735] do_fsync+0x38/0x70
[19661.930746] __x64_sys_fsync+0x10/0x20
[19661.930751] do_syscall_64+0x38/0x90
[19661.930760] entry_SYSCALL_64_after_hwframe+0x44/0xae
[19661.930768] RIP: 0033:0x7fdde438e1fb
[19661.930775] RSP: 002b:00007fdde1513c70 EFLAGS: 00000293 ORIG_RAX: 000000000000004a
[19661.930783] RAX: ffffffffffffffda RBX: 0000563e34ddf9f0 RCX: 00007fdde438e1fb
[19661.930786] RDX: 00007fdde41dd9de RSI: 00007fdde41dd9de RDI: 0000000000000021
[19661.930790] RBP: 00007fdde41df1a0 R08: 0000000000000000 R09: 00007fdde1514700
[19661.930793] R10: 000000000000001e R11: 0000000000000293 R12: 0000000000000002
[19661.930797] R13: 00007ffcc47b9f6f R14: 00007ffcc47b9f70 R15: 00007fdde1513d80
[19661.930819] </TASK>
[19661.930862] 
 Showing all locks held in the system:
[19661.930868] 3 locks held by kworker/0:1/16:
[19661.930877] 1 lock held by khungtaskd/96:
[19661.930880] #0: ffffffff9f765cc0 (rcu_read_lock){....}-{1:2}, at: debug_show_all_locks+0x15/0xf7
[19661.930906] 1 lock held by journal-offline/33295:
[19661.930909] #0: ffff9e0ac19c4c80 (&sbi->s_writepages_rwsem){....}-{0:0}, at: do_writepages+0xbf/0x180
[19661.930927] 1 lock held by in:imklog/577:
[19661.930930] #0: ffff9e0aced8c2f8 (&f->f_pos_lock){....}-{3:3}, at: __fdget_pos+0x4a/0x60
[19661.930959] 1 lock held by dmesg/34165:
[19661.930963] #0: ffff9e0ad5d400e0 (&user->lock){....}-{3:3}, at: devkmsg_read+0x4b/0x230

This looks awfully similar and if I recall right I got the first lockup also not long after I first logged in to the tglh machine (sh-tglh-0a70-hda-01).
With FS error the logs are not going to be written out for sure, so chances to see this one post mortal is unlikely.

I don't know, but during boot we have this in the kernel log:

[ 0.804691] software IO TLB: mapped [mem 0x0000000057cd6000-0x000000005bcd6000] (64MB)
[ 0.804749] DMAR: DRHD: handling fault status reg 3
[ 0.804758] DMAR: [DMA Read NO_PASID] Request device [00:02.0] fault addr 0x70e68000 [fault reason 0x07] Next page table ptr is invalid
[ 0.804863] resource sanity check: requesting [mem 0xfedc0000-0xfedcdfff], which spans more than pnp 00:05 [mem 0xfedc0000-0xfedc7fff]
[ 0.804865] caller __uncore_imc_init_box+0xc5/0x100 mapping multiple BARs
[ 0.805264] clocksource: tsc: mask: 0xffffffffffffffff max_cycles: 0x2cd5a8bb032, max_idle_ns: 440795365915 ns

[ujfalusi]

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