[alsa-devel] Can't detect "XRUNs"
Hi,
I don't get audio drop notification "XRUNs" in /proc/kmsg.
Not sure if this is the right mailing list as maybe my question is more kernel related, but I'll try a shot here.
I'm currently making a proof of concept to see if I can run a quite CPU hungry audio application running without audio drops over time given a set of tests. In particular I want to automate playback buffer underruns detection so that I don't have to sit and listen closely when they happen.
With some very extreme tests, I can hear that there are audio drops all over the place.
I have 2 audio cards in the system, one is audio over HDMI, and the other one is an USB audio card that supports audio class definition. In both case the sound is working as I would expect. The system itself is an Intel NUC i7.
I configured the kernel with CONFIG_SND_DEBUG=y, CONFIG_SND_PCM_XRUN_DEBUG=y and CONFIG_SND_VERBOSE_PROCFS=y as well as echo 5 > /proc/asound/cardX/pcmYp/xrun_debug with X and Y the card and pcm stream of interest, and so hw:X,Y when opening the device with snd_pcm_open.
Then I watch the output of the ksyslog interface using cat /proc/kmsg
When an audio drop occurs, there is nothing about XRUNs or whatever it is called. I don't even know what kind of log message it should look like, and can't find it on google as well.
With audio over HDMI, I have some occurence of ALSA: PCM: [Q] Lost interrupts? that seems more of less related to audio drops, but not always. With the USB audio card, I have nothing.
I tried to write to the xrun_injection proc file in the stream, but nothing happens as well.
Finally I log any occurence of snd_pcm_writei returning a negative number, but that never happens as well.
Am I missing something completely?
Thanks for any information on that matter,
Raphael
On Wed, 04 Jul 2018 12:26:01 +0200, Raphaël Dingé wrote:
Hi,
I don't get audio drop notification "XRUNs" in /proc/kmsg.
Not sure if this is the right mailing list as maybe my question is more kernel related, but I'll try a shot here.
I'm currently making a proof of concept to see if I can run a quite CPU hungry audio application running without audio drops over time given a set of tests. In particular I want to automate playback buffer underruns detection so that I don't have to sit and listen closely when they happen.
With some very extreme tests, I can hear that there are audio drops all over the place.
I have 2 audio cards in the system, one is audio over HDMI, and the other one is an USB audio card that supports audio class definition. In both case the sound is working as I would expect. The system itself is an Intel NUC i7.
I configured the kernel with CONFIG_SND_DEBUG=y, CONFIG_SND_PCM_XRUN_DEBUG=y and CONFIG_SND_VERBOSE_PROCFS=y as well as echo 5 > /proc/asound/cardX/pcmYp/xrun_debug with X and Y the card and pcm stream of interest, and so hw:X,Y when opening the device with snd_pcm_open.
Then I watch the output of the ksyslog interface using cat /proc/kmsg
When an audio drop occurs, there is nothing about XRUNs or whatever it is called. I don't even know what kind of log message it should look like, and can't find it on google as well.
With audio over HDMI, I have some occurence of ALSA: PCM: [Q] Lost interrupts? that seems more of less related to audio drops, but not always. With the USB audio card, I have nothing.
I tried to write to the xrun_injection proc file in the stream, but nothing happens as well.
Finally I log any occurence of snd_pcm_writei returning a negative number, but that never happens as well.
Am I missing something completely?
The recent kernel puts the xrun debug messages in trace buffer instead of the kernel messages. Try to enable the tracing in /sys/kernel/debug/tracing/events/snd_pcm/xrun/enable, and watch the trace buffer (/sys/kernel/debug/tracing/trace).
Takashi
Hi Takashi,
Am I missing something completely?
The recent kernel puts the xrun debug messages in trace buffer instead of the kernel messages. Try to enable the tracing in /sys/kernel/debug/tracing/events/snd_pcm/xrun/enable, and watch the trace buffer (/sys/kernel/debug/tracing/trace).
Thanks for your very quick reply, I'll try this now.
Raphael
Hi Takashi,
The recent kernel puts the xrun debug messages in trace buffer instead of the kernel messages. Try to enable the tracing in /sys/kernel/debug/tracing/events/snd_pcm/xrun/enable, and watch the trace buffer (/sys/kernel/debug/tracing/trace).
Thanks for your very quick reply, I'll try this now.
I must do this wrong again.
So I kept echo 5 > /proc/asound/card2/pcm0p/xrun_debug (not sure if still relevant with ftrace)
And I mounted tracefs mount -t tracefs nodev /sys/kernel/tracing
And then I can echo 1 > /sys/kernel/tracing/events/snd_pcm/xrun/enable
I can verify that cat /sys/kernel/tracing/events/snd_pcm/xrun/enable gives 1 and all enable upper returns X
cat /sys/kernel/tracing/tracing_on is 1
But then cat /sys/kernel/tracing/trace Starts with # tracer: nop and then the header for tracing, and that doesn't change over time.
No event gets logged.
Is tracer "nop" the right one?
As for my kernel configuration I have currently, regarding what seems to be related to FTRACE :
CONFIG_NOP_TRACER=y CONFIG_HAVE_FUNCTION_TRACER=y CONFIG_HAVE_FUNCTION_GRAPH_TRACER=y CONFIG_HAVE_DYNAMIC_FTRACE=y CONFIG_HAVE_DYNAMIC_FTRACE_WITH_REGS=y CONFIG_HAVE_FTRACE_MCOUNT_RECORD=y CONFIG_HAVE_SYSCALL_TRACEPOINTS=y CONFIG_HAVE_FENTRY=y CONFIG_HAVE_C_RECORDMCOUNT=y CONFIG_TRACE_CLOCK=y CONFIG_RING_BUFFER=y CONFIG_EVENT_TRACING=y CONFIG_CONTEXT_SWITCH_TRACER=y CONFIG_TRACING=y CONFIG_GENERIC_TRACER=y CONFIG_TRACING_SUPPORT=y CONFIG_FTRACE=y # CONFIG_FUNCTION_TRACER is not set # CONFIG_PREEMPTIRQ_EVENTS is not set # CONFIG_IRQSOFF_TRACER is not set # CONFIG_SCHED_TRACER is not set # CONFIG_HWLAT_TRACER is not set # CONFIG_FTRACE_SYSCALLS is not set # CONFIG_TRACER_SNAPSHOT is not set
I guess I might need to enable one of the config like FUNCTION_TRACER?
Sorry, I just started Linux, so my knowledge of it is very low.
Thanks,
Raphael
On Wed, 04 Jul 2018 14:11:11 +0200, Raphaël Dingé wrote:
Hi Takashi,
The recent kernel puts the xrun debug messages in trace buffer instead of the kernel messages. Try to enable the tracing in /sys/kernel/debug/tracing/events/snd_pcm/xrun/enable, and watch the trace buffer (/sys/kernel/debug/tracing/trace).
Thanks for your very quick reply, I'll try this now.
I must do this wrong again.
So I kept echo 5 > /proc/asound/card2/pcm0p/xrun_debug (not sure if still relevant with ftrace)
And I mounted tracefs mount -t tracefs nodev /sys/kernel/tracing
And then I can echo 1 > /sys/kernel/tracing/events/snd_pcm/xrun/enable
I can verify that cat /sys/kernel/tracing/events/snd_pcm/xrun/enable gives 1 and all enable upper returns X
cat /sys/kernel/tracing/tracing_on is 1
But then cat /sys/kernel/tracing/trace Starts with # tracer: nop and then the header for tracing, and that doesn't change over time.
No event gets logged.
Are you testing with XRUN injection? I found that the code path doesn't trigger the event tracing. The patch below should trigger the tracing event with xrun injection as well.
Takashi
-- 8< -- From: Takashi Iwai tiwai@suse.de Subject: [PATCH] ALSA: pcm: trace XRUN event at injection, too
The PCM xrun injection triggers directly snd_pcm_stop() without the standard xrun handler, hence it's not recorded on the event buffer. Ditto for snd_pcm_stop_xrun() call and SNDRV_PCM_IOCTL_XRUN ioctl. They are inconvenient from the debugging POV.
Let's make them to trigger XRUN via the standard helper more consistently.
Signed-off-by: Takashi Iwai tiwai@suse.de --- sound/core/pcm.c | 2 +- sound/core/pcm_lib.c | 7 ++++--- sound/core/pcm_local.h | 2 ++ sound/core/pcm_native.c | 8 ++++---- 4 files changed, 11 insertions(+), 8 deletions(-)
diff --git a/sound/core/pcm.c b/sound/core/pcm.c index c352bfb973cc..6f037a4b8b52 100644 --- a/sound/core/pcm.c +++ b/sound/core/pcm.c @@ -497,7 +497,7 @@ static void snd_pcm_xrun_injection_write(struct snd_info_entry *entry, snd_pcm_stream_lock_irq(substream); runtime = substream->runtime; if (runtime && runtime->status->state == SNDRV_PCM_STATE_RUNNING) - snd_pcm_stop(substream, SNDRV_PCM_STATE_XRUN); + __snd_pcm_xrun(substream); snd_pcm_stream_unlock_irq(substream); }
diff --git a/sound/core/pcm_lib.c b/sound/core/pcm_lib.c index 44b5ae833082..c1d2e8e1fc6b 100644 --- a/sound/core/pcm_lib.c +++ b/sound/core/pcm_lib.c @@ -153,7 +153,8 @@ EXPORT_SYMBOL(snd_pcm_debug_name); dump_stack(); \ } while (0)
-static void xrun(struct snd_pcm_substream *substream) +/* call with stream lock held */ +void __snd_pcm_xrun(struct snd_pcm_substream *substream) { struct snd_pcm_runtime *runtime = substream->runtime;
@@ -201,7 +202,7 @@ int snd_pcm_update_state(struct snd_pcm_substream *substream, } } else { if (avail >= runtime->stop_threshold) { - xrun(substream); + __snd_pcm_xrun(substream); return -EPIPE; } } @@ -297,7 +298,7 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, }
if (pos == SNDRV_PCM_POS_XRUN) { - xrun(substream); + __snd_pcm_xrun(substream); return -EPIPE; } if (pos >= runtime->buffer_size) { diff --git a/sound/core/pcm_local.h b/sound/core/pcm_local.h index 7a499d02df6c..c515612969a4 100644 --- a/sound/core/pcm_local.h +++ b/sound/core/pcm_local.h @@ -65,4 +65,6 @@ static inline void snd_pcm_timer_init(struct snd_pcm_substream *substream) {} static inline void snd_pcm_timer_done(struct snd_pcm_substream *substream) {} #endif
+void __snd_pcm_xrun(struct snd_pcm_substream *substream); + #endif /* __SOUND_CORE_PCM_LOCAL_H */ diff --git a/sound/core/pcm_native.c b/sound/core/pcm_native.c index cecc79772c94..20174d0c0527 100644 --- a/sound/core/pcm_native.c +++ b/sound/core/pcm_native.c @@ -1337,13 +1337,12 @@ int snd_pcm_drain_done(struct snd_pcm_substream *substream) int snd_pcm_stop_xrun(struct snd_pcm_substream *substream) { unsigned long flags; - int ret = 0;
snd_pcm_stream_lock_irqsave(substream, flags); if (snd_pcm_running(substream)) - ret = snd_pcm_stop(substream, SNDRV_PCM_STATE_XRUN); + __snd_pcm_xrun(substream); snd_pcm_stream_unlock_irqrestore(substream, flags); - return ret; + return 0; } EXPORT_SYMBOL_GPL(snd_pcm_stop_xrun);
@@ -1591,7 +1590,8 @@ static int snd_pcm_xrun(struct snd_pcm_substream *substream) result = 0; /* already there */ break; case SNDRV_PCM_STATE_RUNNING: - result = snd_pcm_stop(substream, SNDRV_PCM_STATE_XRUN); + __snd_pcm_xrun(substream); + result = 0; break; default: result = -EBADFD;
Hi Takashi,
No event gets logged.
Are you testing with XRUN injection? I found that the code path doesn't trigger the event tracing. The patch below should trigger the tracing event with xrun injection as well.
I'm testing with a real program with an extreme test that can't be completed on time most of the times.
Maybe I should first apply your patch and trigger a synthesised xrun with xrun_injection to see if I'm not missing something else.
Thanks,
Raphael
On Wed, 04 Jul 2018 15:49:51 +0200, Raphaël Dingé wrote:
Hi Takashi,
No event gets logged.
Are you testing with XRUN injection? I found that the code path doesn't trigger the event tracing. The patch below should trigger the tracing event with xrun injection as well.
I'm testing with a real program with an extreme test that can't be completed on time most of the times.
Maybe I should first apply your patch and trigger a synthesised xrun with xrun_injection to see if I'm not missing something else.
Yes, it makes more sense.
Takashi
Maybe I should first apply your patch and trigger a synthesised xrun with xrun_injection to see if I'm not missing something else.
Yes, it makes more sense.
Just in case I tried echo 1 > /sys/kernel/debug/tracing/events/snd_pcm/enable (so for the whole snd_pcm instead of just xrun)
and I can see a lot of events hwptr/applptr in /sys/kernel/debug/tracing/trace, so I guess tracing is working.
I'm going back to the program to see if there is anything suspect.
Thanks,
Raphael
I'm going back to the program to see if there is anything suspect.
So I got back to the program and put a bit more logging. I have new results, but they are even more confusing.
Here is the part that writes to the buffer :
snd_pcm_wait(pcm, 1000 /* milliseconds */); snd_pcm_sframes_t avail = snd_pcm_avail_update(pcm); if (avail < 0) { std::cout << "snd_pcm_avail_update failed\n"; snd_pcm_recover (pcm, avail, 1); }
snd_pcm_sframes_t nb_written = snd_pcm_writei(pcm, &buffer[0], frames_per_buffer); if (nb_written < 0) { std::cout << "snd_pcm_writei failed\n"; snd_pcm_recover(pcm, nb_written, 1 /* silent */); xrun_count++; }
Not sure if this is the proper way, didn't write it myself, but looks more or less legit.
When I launch the program, nothing is output to the console.
But! If I echo 1 > xrun_injection, then I have "snd_pcm_avail_update failed" systematically.
However at the same time, no events are traces in /sys/kernel/debug/tracing/trace
Then the program itself is always dropping audio. In /proc/kmsg I see messages about lost interrupts and callback suppression.
Does it ring a bell?
I'm using kernel 4.17.2 http://kernel.org/pub/linux/kernel/v4.x/linux-4.17.2.tar.xz
With glibc 2.27 http://ftp.gnu.org/gnu/glibc/glibc-2.27.tar.bz2
With Alsa 1.1.6 http://www.mirrorservice.org/sites/ftp.alsa-project.org/pub/lib/alsa-lib-1.1...
Thanks,
Raphael
On Wed, 04 Jul 2018 17:11:17 +0200, Raphaël Dingé wrote:
I'm going back to the program to see if there is anything suspect.
So I got back to the program and put a bit more logging. I have new results, but they are even more confusing.
Here is the part that writes to the buffer :
snd_pcm_wait(pcm, 1000 /* milliseconds */); snd_pcm_sframes_t avail = snd_pcm_avail_update(pcm); if (avail < 0) { std::cout << "snd_pcm_avail_update failed\n"; snd_pcm_recover (pcm, avail, 1);}
snd_pcm_sframes_t nb_written = snd_pcm_writei(pcm, &buffer[0],frames_per_buffer); if (nb_written < 0) { std::cout << "snd_pcm_writei failed\n"; snd_pcm_recover(pcm, nb_written, 1 /* silent */); xrun_count++; }
Not sure if this is the proper way, didn't write it myself, but looks more or less legit.
When I launch the program, nothing is output to the console.
But! If I echo 1 > xrun_injection, then I have "snd_pcm_avail_update failed" systematically.
However at the same time, no events are traces in /sys/kernel/debug/tracing/trace
You applied my patch, right? Otherwise the xrun injection won't trigger the xrun tracing event by itself, just calling snd_pcm_stop().
Takashi
You applied my patch, right? Otherwise the xrun injection won't trigger the xrun tracing event by itself, just calling snd_pcm_stop().
So with your patch, echo 1 > xrun_injection will output one xrun event in /sys/kernel/debug/tracing/trace So at least this is working!
But no other events are generated.
Thanks,
Raphael
On Wed, 04 Jul 2018 17:49:34 +0200, Raphaël Dingé wrote:
You applied my patch, right? Otherwise the xrun injection won't trigger the xrun tracing event by itself, just calling snd_pcm_stop().
So with your patch, echo 1 > xrun_injection will output one xrun event in /sys/kernel/debug/tracing/trace So at least this is working!
But no other events are generated.
It means that it's no system-wide XRUN handling.
Which hardware? If it's Intel LPE HDMI thing, -EPIPE report doesn't mean always an XRUN, but may imply just an unconnected device.
Takashi
But no other events are generated.
It means that it's no system-wide XRUN handling.
Not sure what this means. Maybe something is misconfigured on my side?
Which hardware? If it's Intel LPE HDMI thing, -EPIPE report doesn't mean always an XRUN, but may imply just an unconnected device.
I've tested your patch on Audio over HDMI. Not sure if LPE thing, but I can look into the details.
However the hardware i'm interested in is an Audio USB device, this model to be more precise : https://www.minidsp.com/products/usb-audio-interface/usbstreamer
For now I can't make sure that all the audio is correct on this latter device, because I need to setup 4 I2S converters, I can only use my oscilloscope for now. That's why I'm sometimes using HDMI, to check the sound as I make changes.
Since I applied your patch, I only tried with HDMI, but I could give a shot to the Audio USB Device just to make sure. What do you think?
Thanks,
Raphael
Hi Takashi,
Which hardware? If it's Intel LPE HDMI thing, -EPIPE report doesn't mean always an XRUN, but may imply just an unconnected device.
I've tested your patch on Audio over HDMI. Not sure if LPE thing, but I can look into the details.
My kernel is configured with : # CONFIG_HDMI_LPE_AUDIO is not set
So I guess it's fine to assume it's not the LPE HDMI thing. Additionally, description in /proc/asound/card0 never mention that.
However the hardware i'm interested in is an Audio USB device, this model to be more precise : https://www.minidsp.com/products/usb-audio-interface/usbstreamer [...] Since I applied your patch, I only tried with HDMI, but I could give a shot to the Audio USB Device just to make sure. What do you think?
So I've run with the Audio USB card with your patch, and the behaviour is the same as with HDMI, meaning that echo 1 > xrun_injection outputs a xrun in /sys/kernel/tracing/trace, but apart from that, I never have an xrun.
Thanks,
Raphael
On Thu, 05 Jul 2018 11:10:28 +0200, Raphaël Dingé wrote:
Hi Takashi,
However the hardware i'm interested in is an Audio USB device, this model to be more precise : https://www.minidsp.com/products/usb-audio-interface/usbstreamer [...] Since I applied your patch, I only tried with HDMI, but I could give a shot to the Audio USB Device just to make sure. What do you think?
So I've run with the Audio USB card with your patch, and the behaviour is the same as with HDMI, meaning that echo 1 > xrun_injection outputs a xrun in /sys/kernel/tracing/trace, but apart from that, I never have an xrun.
It means that there is no XRUN error, handled neither in PCM core nor USB-audio driver.
Takashi
So I've run with the Audio USB card with your patch, and the behaviour is the same as with HDMI, meaning that echo 1 > xrun_injection outputs a xrun in /sys/kernel/tracing/trace, but apart from that, I never have an xrun.
It means that there is no XRUN error, handled neither in PCM core nor USB-audio driver.
It seems I have a total misconception of what is an XRUN then.
What I understand from your reply is that the program I launch doesn't create XRUNs anyway (but my interpretation might be mistaken).
I changed the code of my test to the following in the write loop :
snd_pcm_wait(pcm, 1000 /* milliseconds */); snd_pcm_sframes_t avail = snd_pcm_avail_update(pcm); if (avail < 0) { std::cout << "snd_pcm_avail_update failed\n"; snd_pcm_recover (pcm, avail, 1); }
snd_pcm_sframes_t nb_written = snd_pcm_writei(pcm, &buffer[0], frames_per_buffer); if (nb_written < 0) { std::cout << "snd_pcm_writei failed\n"; snd_pcm_recover(pcm, nb_written, 1 /* silent */); xrun_count++; }
usleep (100000); // 100 msec
So basically I introduced a large sleep to force an audio drop (my buffers are 3 x 64).
But this doesn't trigger an XRUN anyway.
What is unclear for me is if the code above shall trigger an XRUN or not?
Thanks,
Raphael
Hi,
Looking more in depth into the code I understood my problem was between the chair and the computer screen *sigh*.
So the code was calling snd_pcm_sw_params_set_stop_threshold which apart from stopping the stream on underruns apparently "eats" the xrun from the kernel tracing perspective.
If I comment out this portion of code, I get the EPIPE in snd_pcm_avail_update as well as the xrun events in /sys/kernel/tracing/trace.
Thanks a million again to put me on the right track. I've learnt a lot from this exchange.
Have a good day,
Raphael
On Thu, 05 Jul 2018 14:34:02 +0200, Raphaël Dingé wrote:
Hi,
Looking more in depth into the code I understood my problem was between the chair and the computer screen *sigh*.
So the code was calling snd_pcm_sw_params_set_stop_threshold which apart from stopping the stream on underruns apparently "eats" the xrun from the kernel tracing perspective.
If I comment out this portion of code, I get the EPIPE in snd_pcm_avail_update as well as the xrun events in /sys/kernel/tracing/trace.
Thanks a million again to put me on the right track. I've learnt a lot from this exchange.
Good to hear that it's no driver problem :)
thanks,
Takashi
participants (2)
-
Raphaël Dingé -
Takashi Iwai