[alsa-devel] Can't detect "XRUNs"

[Takashi Iwai]

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 at 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 at 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;
-- 
2.18.0