Trying to debug alsa xruns

[Michael Lange]

Hi,

I have been experiencing audio xruns when playing back audio or video
files for a while now and thought I might try to get some debugging
information to find out what's wrong (hardware fault? driver bug?
something else?).
According to https://www.alsa-project.org/wiki/XRUN_Debug this requires a
kernel with debug symbols enabled, so I installed the
linux-image-4.19.0-16-amd64-dbg package. However this just installs what
looks like a complete kernel into /usr/lib/debug . I was not able to find
any useful information about what to do with this, currently it seems to
only use up disk space.
Maybe someone can help me out here?

Regards

Michael

.-.. .. ...- . .-.. --- -. --. .- -. -.. .--. .-. --- ... .--. . .-.

We fight only when there is no other choice. We prefer the ways of
peaceful contact.
-- Kirk, "Spectre of the Gun", stardate 4385.3

[Michael Lange]

On Sun, 2 May 2021 17:09:25 +0200
Michael Lange <klap...@freenet.de> wrote:

> Hi,
>
> I have been experiencing audio xruns when playing back audio or video
> files for a while now and thought I might try to get some debugging
> information to find out what's wrong (hardware fault? driver bug?
> something else?).

(...)

Ok, I now compiled a vanilla kernel with the suggested debug flags
enabled. As suggested I tried

# echo 29 > /proc/asound/card0/pcm0p/xrun_debug

This gives me a lot of messages like this:

[ 1794.582338] ALSA: PCM: [P] hw_ptr skipping: (pos=13200, delta=2908, period=1024, jdelta=5/15/0, hw_ptr=403508/403508)
[ 1794.582364] ALSA: PCM: [P] hw_ptr skipping: (pos=13200, delta=2908, period=1024, jdelta=0/15/0, hw_ptr=403508/403508)
[ 1794.584655] ALSA: PCM: [Q] hw_ptr skipping: (pos=13312, delta=3020, period=1024, jdelta=1/15/0, hw_ptr=403508/403508)
[ 1794.602498] ALSA: PCM: [P] hw_ptr skipping: (pos=14168, delta=3876, period=1024, jdelta=4/20/0, hw_ptr=403508/403508)
[ 1807.107315] snd_pcm_update_hw_ptr0: 39 callbacks suppressed
[ 1807.107326] ALSA: PCM: [P] hw_ptr skipping: (pos=7168, delta=15364, period=1024, jdelta=0/80/0, hw_ptr=991228/991228)
[ 1812.952627] ALSA: PCM: [P] hw_ptr skipping: (pos=11260, delta=1088, period=1024, jdelta=1/5/0, hw_ptr=1271740/1271740)

After

# echo 3 > /proc/asound/card0/pcm0p/xrun_debug

the messages become a little more verbose:

[ 323.778213] ALSA: PCM: [Q] Lost interrupts?: (stream=0, delta=15364, new_hw_ptr=487424, old_hw_ptr=472060)
[ 323.778232] CPU: 1 PID: 1926 Comm: mpv Tainted: G E 5.12.1-debugalsa #1
[ 323.778243] Hardware name: Gigabyte Technology Co., Ltd. GA-MA78LMT-S2/GA-MA78LMT-S2, BIOS F14 08/16/2011
[ 323.778248] Call Trace:
[ 323.778255] <IRQ>
[ 323.778261] dump_stack+0x76/0x94
[ 323.778283] snd_pcm_update_hw_ptr0.cold.34+0x42/0xf8 [snd_pcm]
[ 323.778328] ? check_preempt_curr+0x3f/0x70
[ 323.778342] snd_pcm_period_elapsed+0x75/0xb0 [snd_pcm]
[ 323.778379] snd_fm801_interrupt+0xac/0x16a [snd_fm801]
[ 323.778393] __handle_irq_event_percpu+0x42/0x160
[ 323.778405] handle_irq_event_percpu+0x30/0x80
[ 323.778414] handle_irq_event+0x3c/0x60
[ 323.778423] handle_fasteoi_irq+0xa3/0x160
[ 323.778431] __common_interrupt+0x41/0xa0
[ 323.778442] common_interrupt+0x7a/0xa0
[ 323.778451] </IRQ>
[ 323.778455] asm_common_interrupt+0x1e/0x40
[ 323.778463] RIP: 0010:snd_pcm_stream_unlock_irq+0x32/0x40 [snd_pcm]
[ 323.778498] Code: 80 b8 71 07 00 00 00 74 0c 48 81 c7 f8 00 00 00 e9 83 b3 21 cd 48 81 c7 f0 00 00 00 c6 07 00 0f 1f 40 00 fb 66 0f 1f 44 00 00 <c3> 66 66 2e 0f 1f 84 00 00 00 00 00 66 90 0f 1f 44 00 00 55 89 f5
[ 323.778505] RSP: 0018:ffffb08801dffe20 EFLAGS: 00000286
[ 323.778514] RAX: ffff9fe687db6800 RBX: ffff9fe6816b0c00 RCX: 0000000000000000
[ 323.778520] RDX: 0000000000000001 RSI: 0000000000000046 RDI: ffff9fe6816b0cf0
[ 323.778525] RBP: 0000000000000000 R08: 0000000000000000 R09: ffff9fe58fbb9908
[ 323.778530] R10: 0000000000000000 R11: 000000010000171c R12: 0000000000000000
[ 323.778534] R13: ffff9fe6816b0c00 R14: ffff9fe58fa63f00 R15: 0000000000000000
[ 323.778545] snd_pcm_hwsync+0x21/0x30 [snd_pcm]
[ 323.778578] snd_pcm_common_ioctl+0x76b/0xe40 [snd_pcm]
[ 323.778615] snd_pcm_ioctl+0x23/0x30 [snd_pcm]
[ 323.778646] __x64_sys_ioctl+0x84/0xc0
[ 323.778656] do_syscall_64+0x33/0x80
[ 323.778665] entry_SYSCALL_64_after_hwframe+0x44/0xae
[ 323.778675] RIP: 0033:0x7f8d5c1f7427
[ 323.778683] Code: 00 00 90 48 8b 05 69 aa 0c 00 64 c7 00 26 00 00 00 48 c7 c0 ff ff ff ff c3 66 2e 0f 1f 84 00 00 00 00 00 b8 10 00 00 00 0f 05 <48> 3d 01 f0 ff ff 73 01 c3 48 8b 0d 39 aa 0c 00 f7 d8 64 89 01 48
[ 323.778690] RSP: 002b:00007ffe614bda78 EFLAGS: 00000246 ORIG_RAX: 0000000000000010
[ 323.778698] RAX: ffffffffffffffda RBX: 0000000000000000 RCX: 00007f8d5c1f7427
[ 323.778702] RDX: 0000000000000000 RSI: 0000000000004122 RDI: 0000000000000012
[ 323.778707] RBP: 000055e1659a44b0 R08: 000055e1659a4480 R09: 0000000000013812
[ 323.778711] R10: 0000000000013812 R11: 0000000000000246 R12: 000055e165966ec0
[ 323.778716] R13: 000055e1659a42b0 R14: 0000000000000001 R15: 000055e16596a060


Does anyone have a clue what can possibly cause this?

Regards

Michael

.-.. .. ...- . .-.. --- -. --. .- -. -.. .--. .-. --- ... .--. . .-.

Conquest is easy. Control is not.
-- Kirk, "Mirror, Mirror", stardate unknown