Kernel deadlock/hang/stall

[sajattack]

When performing a heavy operation (such as opening firefox to youtube.com , or opening KDE discover to start updates) the kernel will stall.
It also occurs when idling for long periods, as observed by myself and @FieryFlames. The cause is unclear.

https://gist.github.com/sajattack/3938d42dfbca80e25b7c5a7b4ef3c7a1

[sajattack]

Observed something similar now with error message "wait for video done timed out", which lends credence to the theory of it being gpu related.

[Smankusors]

I know this sounds absurd, but try spamming kernel logs

while true; do date > /dev/kmsg; sleep 0.1; done

and see if the system is more stable this way

[minlexx]

On 6.17 you'll be presented with new hang that happens reliably every time:
the one new message about gpu fault, accompaned with rcu stall and other failures growing after that like a snowball

[  178.810562] *** gpu fault: ttbr0=00000000486ca000 iova=00000000044c1280 dir=READ type=TRANSLATION source=e030001 (0,0,0,0)
[  184.040221] adreno 5000000.gpu: Failed to set performance state 320 (-110)
[  189.160207] adreno 5000000.gpu: Failed to set performance state 320 (-110)
[  192.031997] watchdog: CPU7: Watchdog detected hard LOCKUP on cpu 0
[  192.032050] Modules linked in: rfcomm cpufreq_conservative bnep algif_aead cbc des_generic libdes algif_skcipher md5 md4 algif_hash
 af_alg qcom_smgr_mag qcom_smgr_accel qcom_smgr_prox qcom_smgr_gyro kfifo_buf q6asm_dai q6routing q6afe_dai qcom_smgr q6afe_clocks sns
_smgr venus_dec venus_enc q6adm q6asm snd_q6dsp_common videobuf2_dma_contig q6afe videobuf2_memops q6core hci_uart apr btqca pdr_inter
face btrtl qrtr_smd fastrpc btintel btbcm qcom_pd_mapper qcom_pdr_msg ledtrig_pattern qcom_sns_reg venus_core bluetooth v4l2_mem2mem e
cdh_generic videobuf2_v4l2 ecc videodev videobuf2_common ath10k_snoc mc snd_soc_sdm660_int snd_soc_qcom_common ath10k_core ath mac8021
1 leds_qcom_lpg led_class_multicolor snd_soc_msm8916_analog qcom_spmi_haptics libarc4 snd_soc_msm8916_digital qcom_spmi_temp_alarm qrt
r snd_soc_core cfg80211 qcom_q6v5_mss qcom_q6v5_pas snd_compress qcom_pil_info qcom_spmi_adc5 qcom_q6v5 snd_pcm qcom_vadc_common qcom_
sysmon rfkill snd_timer qcom_rng qcom_common rng_core snd pinctrl_sdm660_lpass_lpi
[  192.032256]  pinctrl_lpass_lpi soundcore qcom_stats qmi_helpers rmtfs_mem uhid zram lz4hc_compress zsmalloc fuse nfnetlink ipv6 pan
el_novatek_nt36672a msm ubwc_config mdt_loader drm_dp_aux_bus llcc_qcom ocmem drm_gpuvm drm_exec gpu_sched drm_display_helper novatek_
nvt_ts cec qcom_smbx qcom_spmi_rradc industrialio pmi8998_fg qcom_aoss
[  192.032328] Sending NMI from CPU 7 to CPUs 0:
[  194.288156] adreno 5000000.gpu: Failed to set performance state 320 (-110)
[  199.408085] adreno 5000000.gpu: Failed to set performance state 320 (-110)
[  199.827832] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  199.827902] rcu:     0-...0: (1 GPs behind) idle=342c/1/0x4000000000000000 softirq=13716/13717 fqs=1964
[  199.832930] rcu:     (detected by 1, t=5252 jiffies, g=29905, q=1522 ncpus=8)
[  202.156182] mmc2: Timeout waiting for hardware interrupt.
[  202.156227] mmc2: sdhci: ============ SDHCI REGISTER DUMP ===========
[  202.160573] mmc2: sdhci: Sys addr:  0x00000108 | Version:  0x00006b02
[  202.166995] mmc2: sdhci: Blk size:  0x00000200 | Blk cnt:  0x00000000
[  202.173417] mmc2: sdhci: Argument:  0x02387c00 | Trn mode: 0x0000002b
[  202.179840] mmc2: sdhci: Present:   0x03f800f0 | Host ctl: 0x0000001f
[  202.186264] mmc2: sdhci: Power:     0x0000000f | Blk gap:  0x00000000
[  202.192687] mmc2: sdhci: Wake-up:   0x00000000 | Clock:    0x00000007
[  202.199111] mmc2: sdhci: Timeout:   0x0000000f | Int stat: 0x00000003
[  202.205535] mmc2: sdhci: Int enab:  0x03ff100b | Sig enab: 0x03ff100b
[  202.211960] mmc2: sdhci: ACmd stat: 0x00000000 | Slot int: 0x00000000
[  202.218382] mmc2: sdhci: Caps:      0x322dc8b2 | Caps_1:   0x0000808f
[  202.224806] mmc2: sdhci: Cmd:       0x0000193a | Max curr: 0x00000000
[  202.231229] mmc2: sdhci: Resp[0]:   0x00000900 | Resp[1]:  0x5b590000
[  202.237652] mmc2: sdhci: Resp[2]:   0xebfd7f80 | Resp[3]:  0x00000900
[  202.244077] mmc2: sdhci: Host ctl2: 0x0000000c
[  202.250495] mmc2: sdhci: ADMA Err:  0x00000000 | ADMA Ptr: 0x0000000041982230
[  202.254842] mmc2: sdhci_msm: ----------- VENDOR REGISTER DUMP -----------
[  202.262046] mmc2: sdhci_msm: DLL sts: 0x00000000 | DLL cfg:  0x6008642c | DLL cfg2: 0x0020a000
[  202.268822] mmc2: sdhci_msm: DLL cfg3: 0x00000000 | DLL usr ctl:  0x00000000 | DDR cfg: 0x80040873
[  202.277329] mmc2: sdhci_msm: Vndr func: 0x00018a9c | Vndr func2 : 0xf88218a8 Vndr func3: 0x02626040
[  202.286269] mmc2: sdhci: ============================================
[  204.524278] adreno 5000000.gpu: Failed to set performance state 320 (-110)

Just try to login into plasma-mobile session, happens in 80% cases right after entering pin code, in 100% cases after few taps in the shell across >10 reboots.

[minlexx]

Series where that new print was added: https://patchwork.freedesktop.org/series/114004/

[Smankusors]

I know this sounds absurd, but try spamming kernel logs

while true; do date > /dev/kmsg; sleep 0.1; done

and see if the system is more stable this way

btw @minlexx , does this previously reproducible on your side?

[minlexx]

This "trick" does not help at all (on 6.17)

on 6.16 I haven't even tried, I can successfully finish a race in stk:

[minlexx]

Sometimes you see this even before you start entering your pin code:

[  104.768134] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  104.768653] msm_dpu c901000.display-controller: CP | opcode error | possible opcode=0x00000004
[  104.777081] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30a status 800001C1 rb 0090/000
c ib1 0000000002494000/00d3 ib2 00000000024AD000/0000
[  105.784165] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  105.784619] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30a status 800001C1 rb 000c/000
c ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  106.792135] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  106.792574] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30a status 800001C1 rb 000c/000
c ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  106.792814] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: hangcheck recover!
[  107.816144] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  107.816611] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30a status 800001C1 rb 000c/000
c ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  108.824128] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  108.824598] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30a status 800001C1 rb 000c/000
c ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  108.824637] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: hangcheck recover!
[  108.849780] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: hangcheck recover!
[  109.856126] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  110.856121] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  110.856562] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30a status 800001C1 rb 000c/000
c ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  111.864126] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  111.864622] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: hangcheck recover!
[  111.864607] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30a status 800001C1 rb 000c/000
c ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  111.883179] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: hangcheck recover!
[  122.080164] msm_dpu c901000.display-controller: [drm:a5xx_preempt_timer [msm]] *ERROR* 5.1.2.0: preemption timed out
[  122.080571] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: hangcheck recover!
[  149.076126] [drm:adreno_idle [msm]] *ERROR* 5.1.2.0: timeout waiting to drain ringbuffer 0 rptr/wptr = 23/C
[  149.076735] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30b status 800001C1 rb 000c/000
c ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  150.076140] msm_dpu c901000.display-controller: [drm:adreno_wait_ring [msm]] *ERROR* timeout waiting for space in ringbuffer 0
[  150.076755] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: hangcheck recover!
[  150.078347] msm_dpu c901000.display-controller: [drm:a5xx_irq [msm]] *ERROR* gpu fault ring 0 fence 30c status 800001C1 rb 0035/003
5 ib1 0000000002494000/0000 ib2 00000000024AD000/0000
[  150.086977] msm_dpu c901000.display-controller: [drm:recover_worker [msm]] *ERROR* 5.1.2.0: offending task: kwin_wayland (/usr/bin/
kwin_wayland --wayland-fd 7 --socket wayland-0 --xwayland-fd 8 --xwayland-fd 9 --xwayland-display :0 --xwayland-xauthority /run/user/1
0000/xauth_cGajAd --xwayland)
[  168.012329] watchdog: CPU1: Watchdog detected hard LOCKUP on cpu 2
[  168.012404] Modules linked in: rfcomm cpufreq_conservative bnep algif_aead cbc des_generic libdes algif_skcipher md5 md4 algif_hash
 af_alg qcom_smgr_mag qcom_smgr_gyro qcom_smgr_prox qcom_smgr_accel kfifo_buf q6asm_dai q6routing qcom_smgr sns_smgr q6afe_dai q6afe_c
locks q6adm q6asm snd_q6dsp_common q6afe q6core venus_enc venus_dec videobuf2_dma_contig videobuf2_memops apr pdr_interface fastrpc qr
tr_smd hci_uart qcom_pd_mapper btqca qcom_pdr_msg qcom_sns_reg btrtl btintel ledtrig_pattern btbcm bluetooth venus_core v4l2_mem2mem e
cdh_generic videobuf2_v4l2 ecc videodev videobuf2_common ath10k_snoc snd_soc_msm8916_analog mc ath10k_core snd_soc_sdm660_int leds_qco
m_lpg snd_soc_qcom_common led_class_multicolor ath mac80211 qcom_spmi_haptics qrtr qcom_spmi_adc5 snd_soc_msm8916_digital qcom_spmi_te
mp_alarm libarc4 qcom_vadc_common qcom_rng snd_soc_core rng_core qcom_q6v5_mss qcom_q6v5_pas snd_compress cfg80211 qcom_pil_info snd_p
cm qcom_q6v5 qcom_sysmon rfkill qcom_stats snd_timer qcom_common snd pinctrl_sdm660_lpass_lpi
[  168.012670]  pinctrl_lpass_lpi soundcore qmi_helpers rmtfs_mem uhid zram lz4hc_compress zsmalloc fuse nfnetlink ipv6 panel_novatek_
nt36672a msm ubwc_config mdt_loader drm_dp_aux_bus llcc_qcom ocmem drm_gpuvm drm_exec gpu_sched drm_display_helper cec novatek_nvt_ts 
qcom_spmi_rradc qcom_smbx industrialio pmi8998_fg qcom_aoss
[  168.012769] Sending NMI from CPU 1 to CPUs 2:
[  168.069993] q6asm-dai 15700000.remoteproc:glink-edge:apr:service@7:dais: command[0x10bdb] not expecting rsp
[  171.172139] rcu: INFO: rcu_preempt detected stalls on CPUs/tasks:
[  171.172192] rcu:     2-...0: (38 ticks this GP) idle=6a1c/1/0x4000000000000000 softirq=16030/16032 fqs=954
[  171.177232] rcu:     (detected by 0, t=5253 jiffies, g=27213, q=1466 ncpus=8)
[  171.186429] rcu: rcu_preempt kthread timer wakeup didn't happen for 789 jiffies! g27213 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402
[  171.193382] rcu:     Possible timer handling issue on cpu=5 timer-softirq=2996
[  171.204743] rcu: rcu_preempt kthread starved for 790 jiffies! g27213 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=5
[  171.211523] rcu:     Unless rcu_preempt kthread gets sufficient CPU time, OOM is now expected behavior.
[  171.221936] rcu: RCU grace-period kthread stack dump:
[  171.231215] task:rcu_preempt     state:I stack:0     pid:15    tgid:15    ppid:2      task_flags:0x208040 flags:0x00000010
[  171.236178] Call trace:
[  171.247093]  __switch_to+0xec/0x168 (T)
[  171.249440]  __schedule+0x3a8/0xb98
[  171.253258]  schedule+0x3c/0x120
[  171.256731]  schedule_timeout+0x94/0x130
[  171.260204]  rcu_gp_fqs_loop+0xfc/0x4d8
[  171.264110]  rcu_gp_kthread+0x138/0x178
[  171.267669]  kthread+0x14c/0x210
[  171.271488]  ret_from_fork+0x10/0x20
[  171.274961] rcu: Stack dump where RCU GP kthread last ran:

[sajattack]

Disabling userspace dev node access to the drm cards seems to help somewhat as found by @r00t-

create /etc/udev/rules.d/99-disable-drm.rules and add:

SUBSYSTEM=="drm", RUN+="/usr/bin/rm -f %N"