Alsaloop long-running session leads to CPU spikes and stalls

[ebrodlic]

We have a recurring issue on an embedded system where we use alsaloop to continually forward audio between:
EC25E modem -> system speaker (output)
system microphone (input) -> EC25E modem

The two alsaloop processes run constantly in the background, and are in charge of enabling the GSM call audio functionality on our devices.

What ends up happening is:

• System boots up and starts the 2 processes
• System usage is normal levels for 2-3 hours (very low CPU utilization)
• After cca 3 hours of runtime, one alsaloop process will spike a single core of the CPU up to 100% continually
• After a seemingly random amount of time of the single CPU core being fully utilized, the system may show reduced responsiveness, eventually showing recurring kernel warnings regarding CPU stalls

[Tue Aug 30 16:50:42 2022] rcu: INFO: rcu_preempt self-detected stall on CPU
[Tue Aug 30 16:50:42 2022] rcu:         3-....: (5048 ticks this GP) idle=752/1/0x4000000000000002 softirq=1819133/1819133 fqs=2493
[Tue Aug 30 16:50:42 2022]      (t=5250 jiffies g=3235733 q=26917)
[Tue Aug 30 16:50:42 2022] Task dump for CPU 3:
[Tue Aug 30 16:50:42 2022] alsaloop        R  running task        0   761      1 0x00000202
[Tue Aug 30 16:50:42 2022] Call trace:
[Tue Aug 30 16:50:42 2022]  dump_backtrace+0x0/0x140
[Tue Aug 30 16:50:42 2022]  show_stack+0x14/0x20
[Tue Aug 30 16:50:42 2022]  sched_show_task+0x110/0x138
[Tue Aug 30 16:50:42 2022]  dump_cpu_task+0x40/0x4c
[Tue Aug 30 16:50:42 2022]  rcu_dump_cpu_stacks+0x94/0xd0
[Tue Aug 30 16:50:42 2022]  rcu_sched_clock_irq+0x75c/0x9c8
[Tue Aug 30 16:50:42 2022]  update_process_times+0x2c/0x68
[Tue Aug 30 16:50:42 2022]  tick_sched_handle.isra.0+0x30/0x50
[Tue Aug 30 16:50:42 2022]  tick_sched_timer+0x48/0x98
[Tue Aug 30 16:50:42 2022]  __hrtimer_run_queues+0x110/0x1b0
[Tue Aug 30 16:50:42 2022]  hrtimer_interrupt+0xe4/0x240
[Tue Aug 30 16:50:42 2022]  arch_timer_handler_phys+0x30/0x40
[Tue Aug 30 16:50:42 2022]  handle_percpu_devid_irq+0x80/0x140
[Tue Aug 30 16:50:42 2022]  generic_handle_irq+0x24/0x38
[Tue Aug 30 16:50:42 2022]  __handle_domain_irq+0x60/0xb8
[Tue Aug 30 16:50:42 2022]  gic_handle_irq+0x5c/0x148
[Tue Aug 30 16:50:42 2022]  el1_irq+0xb8/0x180
[Tue Aug 30 16:50:42 2022]  snd_power_wait+0x0/0xe8
[Tue Aug 30 16:50:42 2022]  snd_pcm_ioctl+0x2c/0x40
[Tue Aug 30 16:50:42 2022]  do_vfs_ioctl+0x964/0xb48
[Tue Aug 30 16:50:42 2022]  ksys_ioctl+0x78/0xa8
[Tue Aug 30 16:50:42 2022]  __arm64_sys_ioctl+0x1c/0xb8
[Tue Aug 30 16:50:42 2022]  el0_svc_common.constprop.0+0x68/0x160
[Tue Aug 30 16:50:42 2022]  el0_svc_handler+0x20/0x80
[Tue Aug 30 16:50:42 2022]  el0_svc+0x8/0x208
[Tue Aug 30 16:50:42 2022] retire_capture_urb: 307 callbacks suppressed

Commands used to start the two processes:
/usr/bin/alsaloop -P ec25 -C default -t 500000 -n -r 8000 -f S16_LE -c 1
/usr/bin/alsaloop -C ec25 -P default -t 500000 -n -r 8000 -f S16_LE -c 1

Our current alsa .asoundrc conf file:

pcm.dmixer {
    type dmix
    ipc_key 1024
    ipc_key_add_uid false   # let multiple users share
    ipc_perm 0666           # IPC permissions for multi-user sharing (octal, default 0600)
    slave {
        pcm "hw:tas5722,0"
    }
    bindings {
        0 0
        1 1
    }
}

pcm.dsnooped {
    type dsnoop
    ipc_key 1027
    ipc_key_add_uid false   # let multiple users share
    ipc_perm 0666           # IPC permissions for multi-user sharing (octal, default 0600)
    slave {
        pcm "hw:ics43432,0"
        channels 1
        format S32_LE
    }
}

pcm.asymed {
    type asym
    playback.pcm "dmixer"
    capture.pcm "softvol"
}

pcm.!default {
    type plug
    slave.pcm "asymed"
}

pcm_slave.ec25 {
    pcm "hw:EC25E,0"
    format S16_LE
    channels 1
    rate 8000
}

pcm.ec25 {
    type plug
    slave ec25
}

pcm.softvol {
    type softvol
    slave.pcm dsnooped
    control {
        name "Boost Capture Volume"
        card ics43432
    }
    min_dB -3.0
    max_dB 50.0
}

This one is not very easy to debug so it would be great if I could get some pointers in are we dealing with:

• potential bugs
• alsaloop misuse in approach
• problems in existing configuration

Any info would be appreciated!

[DaveBullet1050]

I am getting a similar issue. My problem is 100% CPU after the first buffer underrun is detected.

With alsaloop v1.2.2 - you get an underrun and a core dump

With alsaloop v1.2.8 - you get an underrun, no core dump and 100% CPU

It is easy to replicate by setting latency to something too small for your system to cause underruns - such as -t 20000 (20msec).

I will try and debug with my limited skills

[Ghoost666]

Same issue here, i cant use alsaloop longterm
Any Updates here?

with low latency it goes into 100% one cpu core after a few minutes ... with around 80-100ms latency this takes around 30 minutes

but another thing i noticed... if i use either -S 2 or -S 3 it basicly goes instantly into 100% one cpu core