diff options
Diffstat (limited to 'sound')
| -rw-r--r-- | sound/core/Makefile | 3 | ||||
| -rw-r--r-- | sound/core/pcm_lib.c | 146 | ||||
| -rw-r--r-- | sound/core/pcm_trace.h | 110 |
3 files changed, 137 insertions, 122 deletions
diff --git a/sound/core/Makefile b/sound/core/Makefile index 394a389..4daf2f5 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_lib.c b/sound/core/pcm_lib.c index 7b9e2fb..ec9e786 100644 --- a/sound/core/pcm_lib.c +++ b/sound/core/pcm_lib.c @@ -32,6 +32,15 @@ #include <sound/pcm_params.h> #include <sound/timer.h> +#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,7 +271,6 @@ 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, "BUG: %s, pos = %ld, buffer size = %ld, period size = %ld\n", name, pos, runtime->buffer_size, @@ -352,8 +279,7 @@ static int snd_pcm_update_hw_ptr0(struct snd_pcm_substream *substream, 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_trace.h b/sound/core/pcm_trace.h new file mode 100644 index 0000000..b63b654 --- /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 <linux/tracepoint.h> + +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 <trace/define_trace.h> |