diff --git a/Documentation/sound/alsa/Procfile.txt b/Documentation/sound/alsa/Procfile.txt index 7fcd1ad96fccba5e714612d1662398c07bf3bc81..7f8a0d32590577327848332b922241572ee2ed96 100644 --- a/Documentation/sound/alsa/Procfile.txt +++ b/Documentation/sound/alsa/Procfile.txt @@ -101,10 +101,6 @@ card*/pcm*/xrun_debug bit 0 = Enable XRUN/jiffies debug messages bit 1 = Show stack trace at XRUN / jiffies check bit 2 = Enable additional jiffies check - bit 3 = Log hwptr update at each period interrupt - bit 4 = Log hwptr update at each snd_pcm_update_hw_ptr() - bit 5 = Show last 10 positions on error - bit 6 = Do above only once When the bit 0 is set, the driver will show the messages to kernel log when an xrun is detected. The debug message is @@ -121,15 +117,6 @@ card*/pcm*/xrun_debug buggy) hardware that doesn't give smooth pointer updates. This feature is enabled via the bit 2. - Bits 3 and 4 are for logging the hwptr records. Note that - these will give flood of kernel messages. - - When bit 5 is set, the driver logs the last 10 xrun errors and - the proc file shows each jiffies, position, period_size, - buffer_size, old_hw_ptr, and hw_ptr_base values. - - When bit 6 is set, the full xrun log is shown only once. - card*/pcm*/sub*/info The general information of this PCM sub-stream. @@ -146,6 +133,10 @@ card*/pcm*/sub*/sw_params card*/pcm*/sub*/prealloc The buffer pre-allocation information. +card*/pcm*/sub*/xrun_injection + Triggers an XRUN to the running stream when any value is + written to this proc file. Used for fault injection. + This entry is write-only. AC97 Codec Information ---------------------- diff --git a/include/sound/pcm.h b/include/sound/pcm.h index 29eb09ef29699fd742d868459af4cb6ad2cfbe13..0b8daeed0a33ca932b0c228b58b34884dd4914ca 100644 --- a/include/sound/pcm.h +++ b/include/sound/pcm.h @@ -416,7 +416,10 @@ struct snd_pcm_substream { struct snd_info_entry *proc_status_entry; struct snd_info_entry *proc_prealloc_entry; struct snd_info_entry *proc_prealloc_max_entry; +#ifdef CONFIG_SND_PCM_XRUN_DEBUG + struct snd_info_entry *proc_xrun_injection_entry; #endif +#endif /* CONFIG_SND_VERBOSE_PROCFS */ /* misc flags */ unsigned int hw_opened: 1; }; diff --git a/sound/core/Makefile b/sound/core/Makefile index 394a38909f6b04ef26a5a9f6682f76c294b04c33..4daf2f58261ced168d2bd616bea7eeb1732e33e8 100644 --- a/sound/core/Makefile +++ b/sound/core/Makefile @@ -14,6 +14,9 @@ snd-pcm-y := pcm.o pcm_native.o pcm_lib.o pcm_timer.o pcm_misc.o \ pcm_memory.o memalloc.o snd-pcm-$(CONFIG_SND_DMA_SGBUF) += sgbuf.o +# for trace-points +CFLAGS_pcm_lib.o := -I$(src) + snd-pcm-dmaengine-objs := pcm_dmaengine.o snd-rawmidi-objs := rawmidi.o diff --git a/sound/core/pcm.c b/sound/core/pcm.c index 31acc3df62cdeb023d362e1ca0b70d42c1a7791f..8f624b7af0ca8dd5e5ad8f198729f838e6869cc5 100644 --- a/sound/core/pcm.c +++ b/sound/core/pcm.c @@ -483,6 +483,19 @@ static void snd_pcm_substream_proc_status_read(struct snd_info_entry *entry, } #ifdef CONFIG_SND_PCM_XRUN_DEBUG +static void snd_pcm_xrun_injection_write(struct snd_info_entry *entry, + struct snd_info_buffer *buffer) +{ + struct snd_pcm_substream *substream = entry->private_data; + struct snd_pcm_runtime *runtime; + + 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_stream_unlock_irq(substream); +} + static void snd_pcm_xrun_debug_read(struct snd_info_entry *entry, struct snd_info_buffer *buffer) { @@ -614,6 +627,22 @@ static int snd_pcm_substream_proc_init(struct snd_pcm_substream *substream) } substream->proc_status_entry = entry; +#ifdef CONFIG_SND_PCM_XRUN_DEBUG + entry = snd_info_create_card_entry(card, "xrun_injection", + substream->proc_root); + if (entry) { + entry->private_data = substream; + entry->c.text.read = NULL; + entry->c.text.write = snd_pcm_xrun_injection_write; + entry->mode = S_IFREG | S_IWUSR; + if (snd_info_register(entry) < 0) { + snd_info_free_entry(entry); + entry = NULL; + } + } + substream->proc_xrun_injection_entry = entry; +#endif /* CONFIG_SND_PCM_XRUN_DEBUG */ + return 0; } @@ -627,6 +656,10 @@ static int snd_pcm_substream_proc_done(struct snd_pcm_substream *substream) substream->proc_sw_params_entry = NULL; snd_info_free_entry(substream->proc_status_entry); substream->proc_status_entry = NULL; +#ifdef CONFIG_SND_PCM_XRUN_DEBUG + snd_info_free_entry(substream->proc_xrun_injection_entry); + substream->proc_xrun_injection_entry = NULL; +#endif snd_info_free_entry(substream->proc_root); substream->proc_root = NULL; return 0; diff --git a/sound/core/pcm_lib.c b/sound/core/pcm_lib.c index dfc28542a007e6ef44f9ea670e3f1aec59032a0b..ec9e7866177feff13db582abc6007fa6f4a40932 100644 --- a/sound/core/pcm_lib.c +++ b/sound/core/pcm_lib.c @@ -32,6 +32,15 @@ #include #include +#ifdef CONFIG_SND_PCM_XRUN_DEBUG +#define CREATE_TRACE_POINTS +#include "pcm_trace.h" +#else +#define trace_hwptr(substream, pos, in_interrupt) +#define trace_xrun(substream) +#define trace_hw_ptr_error(substream, reason) +#endif + /* * fill ring buffer with silence * runtime->silence_start: starting pointer to silence area @@ -146,10 +155,6 @@ EXPORT_SYMBOL(snd_pcm_debug_name); #define XRUN_DEBUG_BASIC (1<<0) #define XRUN_DEBUG_STACK (1<<1) /* dump also stack */ #define XRUN_DEBUG_JIFFIESCHECK (1<<2) /* do jiffies check */ -#define XRUN_DEBUG_PERIODUPDATE (1<<3) /* full period update info */ -#define XRUN_DEBUG_HWPTRUPDATE (1<<4) /* full hwptr update info */ -#define XRUN_DEBUG_LOG (1<<5) /* show last 10 positions on err */ -#define XRUN_DEBUG_LOGONCE (1<<6) /* do above only once */ #ifdef CONFIG_SND_PCM_XRUN_DEBUG @@ -168,6 +173,7 @@ static void xrun(struct snd_pcm_substream *substream) { struct snd_pcm_runtime *runtime = substream->runtime; + trace_xrun(substream); if (runtime->tstamp_mode == SNDRV_PCM_TSTAMP_ENABLE) snd_pcm_gettime(runtime, (struct timespec *)&runtime->status->tstamp); snd_pcm_stop(substream, SNDRV_PCM_STATE_XRUN); @@ -180,97 +186,19 @@ static void xrun(struct snd_pcm_substream *substream) } #ifdef CONFIG_SND_PCM_XRUN_DEBUG -#define hw_ptr_error(substream, fmt, args...) \ +#define hw_ptr_error(substream, in_interrupt, reason, fmt, args...) \ do { \ + trace_hw_ptr_error(substream, reason); \ if (xrun_debug(substream, XRUN_DEBUG_BASIC)) { \ - xrun_log_show(substream); \ - pr_err_ratelimited("ALSA: PCM: " fmt, ##args); \ + pr_err_ratelimited("ALSA: PCM: [%c] " reason ": " fmt, \ + (in_interrupt) ? 'Q' : 'P', ##args); \ dump_stack_on_xrun(substream); \ } \ } while (0) -#define XRUN_LOG_CNT 10 - -struct hwptr_log_entry { - unsigned int in_interrupt; - unsigned long jiffies; - snd_pcm_uframes_t pos; - snd_pcm_uframes_t period_size; - snd_pcm_uframes_t buffer_size; - snd_pcm_uframes_t old_hw_ptr; - snd_pcm_uframes_t hw_ptr_base; -}; - -struct snd_pcm_hwptr_log { - unsigned int idx; - unsigned int hit: 1; - struct hwptr_log_entry entries[XRUN_LOG_CNT]; -}; - -static void xrun_log(struct snd_pcm_substream *substream, - snd_pcm_uframes_t pos, int in_interrupt) -{ - struct snd_pcm_runtime *runtime = substream->runtime; - struct snd_pcm_hwptr_log *log = runtime->hwptr_log; - struct hwptr_log_entry *entry; - - if (log == NULL) { - log = kzalloc(sizeof(*log), GFP_ATOMIC); - if (log == NULL) - return; - runtime->hwptr_log = log; - } else { - if (xrun_debug(substream, XRUN_DEBUG_LOGONCE) && log->hit) - return; - } - entry = &log->entries[log->idx]; - entry->in_interrupt = in_interrupt; - entry->jiffies = jiffies; - entry->pos = pos; - entry->period_size = runtime->period_size; - entry->buffer_size = runtime->buffer_size; - entry->old_hw_ptr = runtime->status->hw_ptr; - entry->hw_ptr_base = runtime->hw_ptr_base; - log->idx = (log->idx + 1) % XRUN_LOG_CNT; -} - -static void xrun_log_show(struct snd_pcm_substream *substream) -{ - struct snd_pcm_hwptr_log *log = substream->runtime->hwptr_log; - struct hwptr_log_entry *entry; - char name[16]; - unsigned int idx; - int cnt; - - if (log == NULL) - return; - if (xrun_debug(substream, XRUN_DEBUG_LOGONCE) && log->hit) - return; - snd_pcm_debug_name(substream, name, sizeof(name)); - for (cnt = 0, idx = log->idx; cnt < XRUN_LOG_CNT; cnt++) { - entry = &log->entries[idx]; - if (entry->period_size == 0) - break; - pr_info("hwptr log: %s: %sj=%lu, pos=%ld/%ld/%ld, " - "hwptr=%ld/%ld\n", - name, entry->in_interrupt ? "[Q] " : "", - entry->jiffies, - (unsigned long)entry->pos, - (unsigned long)entry->period_size, - (unsigned long)entry->buffer_size, - (unsigned long)entry->old_hw_ptr, - (unsigned long)entry->hw_ptr_base); - idx++; - idx %= XRUN_LOG_CNT; - } - log->hit = 1; -} - #else /* ! CONFIG_SND_PCM_XRUN_DEBUG */ #define hw_ptr_error(substream, fmt, args...) do { } while (0) -#define xrun_log(substream, pos, in_interrupt) do { } while (0) -#define xrun_log_show(substream) do { } while (0) #endif @@ -343,17 +271,15 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, if (printk_ratelimit()) { char name[16]; snd_pcm_debug_name(substream, name, sizeof(name)); - xrun_log_show(substream); pcm_err(substream->pcm, - "XRUN: %s, pos = %ld, buffer size = %ld, period size = %ld\n", + "BUG: %s, pos = %ld, buffer size = %ld, period size = %ld\n", name, pos, runtime->buffer_size, runtime->period_size); } pos = 0; } pos -= pos % runtime->min_align; - if (xrun_debug(substream, XRUN_DEBUG_LOG)) - xrun_log(substream, pos, in_interrupt); + trace_hwptr(substream, pos, in_interrupt); hw_base = runtime->hw_ptr_base; new_hw_ptr = hw_base + pos; if (in_interrupt) { @@ -388,22 +314,6 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, delta = new_hw_ptr - old_hw_ptr; if (delta < 0) delta += runtime->boundary; - if (xrun_debug(substream, in_interrupt ? - XRUN_DEBUG_PERIODUPDATE : XRUN_DEBUG_HWPTRUPDATE)) { - char name[16]; - snd_pcm_debug_name(substream, name, sizeof(name)); - pcm_dbg(substream->pcm, - "%s_update: %s: pos=%u/%u/%u, hwptr=%ld/%ld/%ld/%ld\n", - in_interrupt ? "period" : "hwptr", - name, - (unsigned int)pos, - (unsigned int)runtime->period_size, - (unsigned int)runtime->buffer_size, - (unsigned long)delta, - (unsigned long)old_hw_ptr, - (unsigned long)new_hw_ptr, - (unsigned long)runtime->hw_ptr_base); - } if (runtime->no_period_wakeup) { snd_pcm_sframes_t xrun_threshold; @@ -431,13 +341,10 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, /* something must be really wrong */ if (delta >= runtime->buffer_size + runtime->period_size) { - hw_ptr_error(substream, - "Unexpected hw_pointer value %s" - "(stream=%i, pos=%ld, new_hw_ptr=%ld, " - "old_hw_ptr=%ld)\n", - in_interrupt ? "[Q] " : "[P]", - substream->stream, (long)pos, - (long)new_hw_ptr, (long)old_hw_ptr); + hw_ptr_error(substream, in_interrupt, "Unexpected hw_ptr", + "(stream=%i, pos=%ld, new_hw_ptr=%ld, old_hw_ptr=%ld)\n", + substream->stream, (long)pos, + (long)new_hw_ptr, (long)old_hw_ptr); return 0; } @@ -474,11 +381,8 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, delta--; } /* align hw_base to buffer_size */ - hw_ptr_error(substream, - "hw_ptr skipping! %s" - "(pos=%ld, delta=%ld, period=%ld, " - "jdelta=%lu/%lu/%lu, hw_ptr=%ld/%ld)\n", - in_interrupt ? "[Q] " : "", + hw_ptr_error(substream, in_interrupt, "hw_ptr skipping", + "(pos=%ld, delta=%ld, period=%ld, jdelta=%lu/%lu/%lu, hw_ptr=%ld/%ld)\n", (long)pos, (long)hdelta, (long)runtime->period_size, jdelta, ((hdelta * HZ) / runtime->rate), hw_base, @@ -490,11 +394,9 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, } no_jiffies_check: if (delta > runtime->period_size + runtime->period_size / 2) { - hw_ptr_error(substream, - "Lost interrupts? %s" - "(stream=%i, delta=%ld, new_hw_ptr=%ld, " - "old_hw_ptr=%ld)\n", - in_interrupt ? "[Q] " : "", + hw_ptr_error(substream, in_interrupt, + "Lost interrupts?", + "(stream=%i, delta=%ld, new_hw_ptr=%ld, old_hw_ptr=%ld)\n", substream->stream, (long)delta, (long)new_hw_ptr, (long)old_hw_ptr); diff --git a/sound/core/pcm_native.c b/sound/core/pcm_native.c index 4d5795d8b9f7359fd9c6b7fdf580d8f165fd5f56..ca224fa2a33a043b1006dbd6c4de36fd9ac5291e 100644 --- a/sound/core/pcm_native.c +++ b/sound/core/pcm_native.c @@ -900,14 +900,19 @@ static int snd_pcm_action_single(struct action_ops *ops, return res; } -/* call in mutex-protected context */ -static int snd_pcm_action_mutex(struct action_ops *ops, - struct snd_pcm_substream *substream, - int state) +/* + * Note: call with stream lock + */ +static int snd_pcm_action(struct action_ops *ops, + struct snd_pcm_substream *substream, + int state) { int res; - if (snd_pcm_stream_linked(substream)) { + if (!snd_pcm_stream_linked(substream)) + return snd_pcm_action_single(ops, substream, state); + + if (substream->pcm->nonatomic) { if (!mutex_trylock(&substream->group->mutex)) { mutex_unlock(&substream->self_group.mutex); mutex_lock(&substream->group->mutex); @@ -916,24 +921,6 @@ static int snd_pcm_action_mutex(struct action_ops *ops, res = snd_pcm_action_group(ops, substream, state, 1); mutex_unlock(&substream->group->mutex); } else { - res = snd_pcm_action_single(ops, substream, state); - } - return res; -} - -/* - * Note: call with stream lock - */ -static int snd_pcm_action(struct action_ops *ops, - struct snd_pcm_substream *substream, - int state) -{ - int res; - - if (substream->pcm->nonatomic) - return snd_pcm_action_mutex(ops, substream, state); - - if (snd_pcm_stream_linked(substream)) { if (!spin_trylock(&substream->group->lock)) { spin_unlock(&substream->self_group.lock); spin_lock(&substream->group->lock); @@ -941,34 +928,10 @@ static int snd_pcm_action(struct action_ops *ops, } res = snd_pcm_action_group(ops, substream, state, 1); spin_unlock(&substream->group->lock); - } else { - res = snd_pcm_action_single(ops, substream, state); } return res; } -static int snd_pcm_action_lock_mutex(struct action_ops *ops, - struct snd_pcm_substream *substream, - int state) -{ - int res; - - down_read(&snd_pcm_link_rwsem); - if (snd_pcm_stream_linked(substream)) { - mutex_lock(&substream->group->mutex); - mutex_lock(&substream->self_group.mutex); - res = snd_pcm_action_group(ops, substream, state, 1); - mutex_unlock(&substream->self_group.mutex); - mutex_unlock(&substream->group->mutex); - } else { - mutex_lock(&substream->self_group.mutex); - res = snd_pcm_action_single(ops, substream, state); - mutex_unlock(&substream->self_group.mutex); - } - up_read(&snd_pcm_link_rwsem); - return res; -} - /* * Note: don't use any locks before */ @@ -978,22 +941,9 @@ static int snd_pcm_action_lock_irq(struct action_ops *ops, { int res; - if (substream->pcm->nonatomic) - return snd_pcm_action_lock_mutex(ops, substream, state); - - read_lock_irq(&snd_pcm_link_rwlock); - if (snd_pcm_stream_linked(substream)) { - spin_lock(&substream->group->lock); - spin_lock(&substream->self_group.lock); - res = snd_pcm_action_group(ops, substream, state, 1); - spin_unlock(&substream->self_group.lock); - spin_unlock(&substream->group->lock); - } else { - spin_lock(&substream->self_group.lock); - res = snd_pcm_action_single(ops, substream, state); - spin_unlock(&substream->self_group.lock); - } - read_unlock_irq(&snd_pcm_link_rwlock); + snd_pcm_stream_lock_irq(substream); + res = snd_pcm_action(ops, substream, state); + snd_pcm_stream_unlock_irq(substream); return res; } diff --git a/sound/core/pcm_trace.h b/sound/core/pcm_trace.h new file mode 100644 index 0000000000000000000000000000000000000000..b63b654da5ffafab4fb444a87cdab81e2a5b32e9 --- /dev/null +++ b/sound/core/pcm_trace.h @@ -0,0 +1,110 @@ +#undef TRACE_SYSTEM +#define TRACE_SYSTEM snd_pcm +#define TRACE_INCLUDE_FILE pcm_trace + +#if !defined(_PCM_TRACE_H) || defined(TRACE_HEADER_MULTI_READ) +#define _PCM_TRACE_H + +#include + +TRACE_EVENT(hwptr, + TP_PROTO(struct snd_pcm_substream *substream, snd_pcm_uframes_t pos, bool irq), + TP_ARGS(substream, pos, irq), + TP_STRUCT__entry( + __field( bool, in_interrupt ) + __field( unsigned int, card ) + __field( unsigned int, device ) + __field( unsigned int, number ) + __field( unsigned int, stream ) + __field( snd_pcm_uframes_t, pos ) + __field( snd_pcm_uframes_t, period_size ) + __field( snd_pcm_uframes_t, buffer_size ) + __field( snd_pcm_uframes_t, old_hw_ptr ) + __field( snd_pcm_uframes_t, hw_ptr_base ) + ), + TP_fast_assign( + __entry->in_interrupt = (irq); + __entry->card = (substream)->pcm->card->number; + __entry->device = (substream)->pcm->device; + __entry->number = (substream)->number; + __entry->stream = (substream)->stream; + __entry->pos = (pos); + __entry->period_size = (substream)->runtime->period_size; + __entry->buffer_size = (substream)->runtime->buffer_size; + __entry->old_hw_ptr = (substream)->runtime->status->hw_ptr; + __entry->hw_ptr_base = (substream)->runtime->hw_ptr_base; + ), + TP_printk("pcmC%dD%d%c/sub%d: %s: pos=%lu, old=%lu, base=%lu, period=%lu, buf=%lu", + __entry->card, __entry->device, + __entry->stream == SNDRV_PCM_STREAM_PLAYBACK ? 'p' : 'c', + __entry->number, + __entry->in_interrupt ? "IRQ" : "POS", + (unsigned long)__entry->pos, + (unsigned long)__entry->old_hw_ptr, + (unsigned long)__entry->hw_ptr_base, + (unsigned long)__entry->period_size, + (unsigned long)__entry->buffer_size) +); + +TRACE_EVENT(xrun, + TP_PROTO(struct snd_pcm_substream *substream), + TP_ARGS(substream), + TP_STRUCT__entry( + __field( unsigned int, card ) + __field( unsigned int, device ) + __field( unsigned int, number ) + __field( unsigned int, stream ) + __field( snd_pcm_uframes_t, period_size ) + __field( snd_pcm_uframes_t, buffer_size ) + __field( snd_pcm_uframes_t, old_hw_ptr ) + __field( snd_pcm_uframes_t, hw_ptr_base ) + ), + TP_fast_assign( + __entry->card = (substream)->pcm->card->number; + __entry->device = (substream)->pcm->device; + __entry->number = (substream)->number; + __entry->stream = (substream)->stream; + __entry->period_size = (substream)->runtime->period_size; + __entry->buffer_size = (substream)->runtime->buffer_size; + __entry->old_hw_ptr = (substream)->runtime->status->hw_ptr; + __entry->hw_ptr_base = (substream)->runtime->hw_ptr_base; + ), + TP_printk("pcmC%dD%d%c/sub%d: XRUN: old=%lu, base=%lu, period=%lu, buf=%lu", + __entry->card, __entry->device, + __entry->stream == SNDRV_PCM_STREAM_PLAYBACK ? 'p' : 'c', + __entry->number, + (unsigned long)__entry->old_hw_ptr, + (unsigned long)__entry->hw_ptr_base, + (unsigned long)__entry->period_size, + (unsigned long)__entry->buffer_size) +); + +TRACE_EVENT(hw_ptr_error, + TP_PROTO(struct snd_pcm_substream *substream, const char *why), + TP_ARGS(substream, why), + TP_STRUCT__entry( + __field( unsigned int, card ) + __field( unsigned int, device ) + __field( unsigned int, number ) + __field( unsigned int, stream ) + __field( const char *, reason ) + ), + TP_fast_assign( + __entry->card = (substream)->pcm->card->number; + __entry->device = (substream)->pcm->device; + __entry->number = (substream)->number; + __entry->stream = (substream)->stream; + __entry->reason = (why); + ), + TP_printk("pcmC%dD%d%c/sub%d: ERROR: %s", + __entry->card, __entry->device, + __entry->stream == SNDRV_PCM_STREAM_PLAYBACK ? 'p' : 'c', + __entry->number, __entry->reason) +); + +#endif /* _PCM_TRACE_H */ + +/* This part must be outside protection */ +#undef TRACE_INCLUDE_PATH +#define TRACE_INCLUDE_PATH . +#include