"I2S SYNC error", then "rcu_sched detected stalls on CPUs/tasks" then crash

Open
#3,580 15 comments 0 reactions 0 assignees View on GitHub

Nobody has claimed this yet.

Assessment

Difficulty
4/5
Estimated time
3-5 days
Newbie friendliness
25/100
Issue type
Bug
Clarity
Needs clarification
Activity status
Stale
Tech stack
c, linux

Research direction

Start with the reported bcm2835-i2s I2S SYNC error and the aplay -L/arecord -L sequence, using the attached raspinfo output and syslog as the baseline. Done means identifying and fixing the cause of the Raspberry Pi crash, with the I2S, RCU, PulseAudio, and rtkit symptoms no longer leading to a system hang.

Written by the indexing model from the issue text.

Description

Describe the bug

This is a post-mortem - the headless pi crashed, and the below is what's in syslog after reboot. Apparently the audio / pulseaudio locked up, causing a kernel panic, I think:

Apr 27 21:22:42 raspberrypi kernel: [436512.647215] bcm2835-i2s fe203000.i2s: I2S SYNC error!
Apr 27 21:23:13 raspberrypi kernel: [436533.695109] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
Apr 27 21:23:13 raspberrypi kernel: [436533.695120] rcu: 	1-...0: (0 ticks this GP) idle=f92/1/0x40000000 softirq=2474494/2474494 fqs=720 
Apr 27 21:23:13 raspberrypi kernel: [436533.695123] rcu: 	(detected by 2, t=2102 jiffies, g=8927073, q=31)
Apr 27 21:23:13 raspberrypi kernel: [436533.695131] Sending NMI from CPU 2 to CPUs 1:
Apr 27 21:23:13 raspberrypi kernel: [436543.695841] rcu: rcu_sched kthread starved for 608 jiffies! g8927073 f0x0 RCU_GP_WAIT_FQS(5) ->state=0x402 ->cpu=2
Apr 27 21:23:13 raspberrypi kernel: [436543.695844] rcu: RCU grace-period kthread stack dump:
Apr 27 21:23:13 raspberrypi kernel: [436543.695847] rcu_sched       I    0    10      2 0x00000000
Apr 27 21:23:13 raspberrypi kernel: [436543.695869] [<c09c8f5c>] (__schedule) from [<c09c95cc>] (schedule+0x50/0xa8)
Apr 27 21:23:13 raspberrypi kernel: [436543.695877] [<c09c95cc>] (schedule) from [<c09cd584>] (schedule_timeout+0x1d0/0x428)
Apr 27 21:23:13 raspberrypi kernel: [436543.695885] [<c09cd584>] (schedule_timeout) from [<c0291318>] (rcu_gp_kthread+0x4ac/0xa30)
Apr 27 21:23:13 raspberrypi kernel: [436543.695894] [<c0291318>] (rcu_gp_kthread) from [<c02446a0>] (kthread+0x138/0x168)
Apr 27 21:23:13 raspberrypi kernel: [436543.695902] [<c02446a0>] (kthread) from [<c02010ac>] (ret_from_fork+0x14/0x28)
Apr 27 21:23:13 raspberrypi kernel: [436543.695905] Exception stack(0xef923fb0 to 0xef923ff8)
Apr 27 21:23:13 raspberrypi kernel: [436543.695910] 3fa0:                                     00000000 00000000 00000000 00000000
Apr 27 21:23:13 raspberrypi kernel: [436543.695915] 3fc0: 00000000 00000000 00000000 00000000 00000000 00000000 00000000 00000000
Apr 27 21:23:13 raspberrypi kernel: [436543.695919] 3fe0: 00000000 00000000 00000000 00000000 00000013 00000000
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: The canary thread is apparently starving. Taking action.
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: Demoting known real-time threads.
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: Successfully demoted thread 7929 of process 7929 (n/a).
Apr 27 21:23:13 raspberrypi rtkit-daemon[8436]: Demoted 1 threads.
Apr 27 21:24:16 raspberrypi kernel: [436596.745463] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
Apr 27 21:24:16 raspberrypi kernel: [436596.745474] rcu: 	1-...0: (0 ticks this GP) idle=f92/1/0x40000000 softirq=2474494/2474494 fqs=2571 
Apr 27 21:24:16 raspberrypi kernel: [436596.745477] rcu: 	(detected by 2, t=8407 jiffies, g=8927073, q=94)
Apr 27 21:24:16 raspberrypi kernel: [436596.745485] Sending NMI from CPU 2 to CPUs 1:
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: The canary thread is apparently starving. Taking action.
Apr 27 21:24:16 raspberrypi systemd[629]: pulseaudio.service: State 'stop-sigterm' timed out. Killing.
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: Demoting known real-time threads.
Apr 27 21:24:16 raspberrypi systemd[629]: pulseaudio.service: Killing process 7929 (pulseaudio) with signal SIGKILL.
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: Successfully demoted thread 7929 of process 7929 (n/a).
Apr 27 21:24:16 raspberrypi rtkit-daemon[8436]: Demoted 1 threads.
Apr 27 21:25:01 raspberrypi CRON[13171]: (root) CMD (command -v debian-sa1 > /dev/null && debian-sa1 1 1)
Apr 27 21:25:19 raspberrypi kernel: [436659.795835] rcu: INFO: rcu_sched detected stalls on CPUs/tasks:
Apr 27 21:25:19 raspberrypi kernel: [436659.795846] rcu: 	1-...0: (0 ticks this GP) idle=f92/1/0x40000000 softirq=2474494/2474494 fqs=4451 
Apr 27 21:25:19 raspberrypi kernel: [436659.795849] rcu: 	(detected by 2, t=14712 jiffies, g=8927073, q=535)
Apr 27 21:25:19 raspberrypi kernel: [436659.795857] Sending NMI from CPU 2 to CPUs 1:
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: The canary thread is apparently starving. Taking action.
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: Demoting known real-time threads.
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: Successfully demoted thread 7929 of process 7929 (n/a).
Apr 27 21:25:19 raspberrypi rtkit-daemon[8436]: Demoted 1 threads.
Apr 27 21:25:19 raspberrypi systemd[1]: systemd-logind.service: Watchdog timeout (limit 3min)!
Apr 27 21:25:19 raspberrypi systemd[1]: systemd-logind.service: Killing process 356 (systemd-logind) with signal SIGABRT.
Apr 27 21:25:20 raspberrypi systemd[1]: systemd-udevd.service: Watchdog timeout (limit 3min)!
Apr 27 21:25:20 raspberrypi systemd[1]: systemd-udevd.service: Killing process 143 (systemd-udevd) with signal SIGABRT.
Apr 27 21:17:04 raspberrypi systemd-modules-load[102]: Inserted module 'snd_soc_seeed_voicecard'
Apr 27 21:17:04 raspberrypi systemd-modules-load[102]: Inserted module 'snd_soc_ac108'
Apr 27 21:17:04 raspberrypi systemd-modules-load[102]: Inserted module 'snd_soc_wm8960'
Apr 27 21:17:04 raspberrypi fake-hwclock[99]: Mon 27 Apr 20:17:01 UTC 2020
Apr 27 21:17:04 raspberrypi systemd-fsck[124]: e2fsck 1.44.5 (15-Dec-2018)
Apr 27 21:17:04 raspberrypi systemd-fsck[124]: rootfs: clean, 272697/939744 files, 2025093/3822976 blocks

To reproduce
Just before it, I was doing aplay -L / arecord -L - the I2S error seems to be a delay action to it - it appears occasionally, but never actually caused a crash in the past.

Expected behaviour
I2S error and pulseaudio/rtkit-daemon shouldn't cause this.

Actual behaviour
pi crashed.

System

raspinfo output - after reboot:

raspinfo.txt

Additional context

This is the audio board attached:
https://github.com/respeaker/seeed-voicecard

Dominant language
C
Stars
13.2k
Forks
5.5k
Avg merge
2d 21h
Merged PRs (30d)
21

Contributor guide

No contributing guide indexed for this repository

First steps

  1. Read the whole issue, then the project's contributing guide.
  2. Comment on the issue to say you are picking it up — it saves two people doing the same work.
  3. Fork the repository and make your change on a branch.
  4. Open a pull request that references the issue number.

More from raspberrypi/linux

All issues in raspberrypi/linux

Similar issues

More C issues

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.