ALSA: pcm_lib - add possibility to log last 10 DMA ring buffer positions

In some debug cases, it might be usefull to see previous ring buffer
positions to determine position problems from the lowlevel drivers.

Signed-off-by: Jaroslav Kysela <perex@perex.cz>

diff --git a/include/sound/pcm.h b/include/sound/pcm.h
index c83a4a79f16b2646279fa1e68e7516bd73f2c122..4e18a6dbe69081ae7a0331c850b5097d3cf7b385 100644 (file)
--- a/include/sound/pcm.h
+++ b/include/sound/pcm.h
@@ -262,6 +262,8 @@ struct snd_pcm_hw_constraint_list {
        unsigned int mask;
 };
 
+struct snd_pcm_hwptr_log;
+
 struct snd_pcm_runtime {
        /* -- Status -- */
        struct snd_pcm_substream *trigger_master;
@@ -340,6 +342,10 @@ struct snd_pcm_runtime {
        /* -- OSS things -- */
        struct snd_pcm_oss_runtime oss;
 #endif
+
+#ifdef CONFIG_SND_PCM_XRUN_DEBUG
+       struct snd_pcm_hwptr_log *hwptr_log;
+#endif
 };
 
 struct snd_pcm_group {         /* keep linked substreams */

diff --git a/sound/core/pcm.c b/sound/core/pcm.c
index 6884ae031f6fc4975c52fb4beb026aeaa61f2248..df57a0e30bf2f7535d678a49d1d49f1c8cac6928 100644 (file)
--- a/sound/core/pcm.c
+++ b/sound/core/pcm.c
@@ -921,6 +921,10 @@ void snd_pcm_detach_substream(struct snd_pcm_substream *substream)
        snd_free_pages((void*)runtime->control,
                       PAGE_ALIGN(sizeof(struct snd_pcm_mmap_control)));
        kfree(runtime->hw_constraints.rules);
+#ifdef CONFIG_SND_PCM_XRUN_DEBUG
+       if (runtime->hwptr_log)
+               kfree(runtime->hwptr_log);
+#endif
        kfree(runtime);
        substream->runtime = NULL;
        put_pid(substream->pid);

diff --git a/sound/core/pcm_lib.c b/sound/core/pcm_lib.c
index 9621236b2fefc890ae28a2822b90c18a87520e73..1990afb8a73546b113826a54c6919156c8425197 100644 (file)
--- a/sound/core/pcm_lib.c
+++ b/sound/core/pcm_lib.c
@@ -126,34 +126,34 @@ void snd_pcm_playback_silence(struct snd_pcm_substream *substream, snd_pcm_ufram
        }
 }
 
+static void pcm_debug_name(struct snd_pcm_substream *substream,
+                          char *name, size_t len)
+{
+       snprintf(name, len, "pcmC%dD%d%c:%d",
+                substream->pcm->card->number,
+                substream->pcm->device,
+                substream->stream ? 'c' : 'p',
+                substream->number);
+}
+
 #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
+
 #define xrun_debug(substream, mask) \
                        ((substream)->pstr->xrun_debug & (mask))
-#else
-#define xrun_debug(substream, mask)    0
-#endif
 
 #define dump_stack_on_xrun(substream) do {                     \
                if (xrun_debug(substream, XRUN_DEBUG_STACK))    \
                        dump_stack();                           \
        } while (0)
 
-static void pcm_debug_name(struct snd_pcm_substream *substream,
-                          char *name, size_t len)
-{
-       snprintf(name, len, "pcmC%dD%d%c:%d",
-                substream->pcm->card->number,
-                substream->pcm->device,
-                substream->stream ? 'c' : 'p',
-                substream->number);
-}
-
 static void xrun(struct snd_pcm_substream *substream)
 {
        struct snd_pcm_runtime *runtime = substream->runtime;
@@ -169,6 +169,102 @@ static void xrun(struct snd_pcm_substream *substream)
        }
 }
 
+#define hw_ptr_error(substream, fmt, args...)                          \
+       do {                                                            \
+               if (xrun_debug(substream, XRUN_DEBUG_BASIC)) {          \
+                       if (printk_ratelimit()) {                       \
+                               snd_printd("PCM: " fmt, ##args);        \
+                       }                                               \
+                       dump_stack_on_xrun(substream);                  \
+               }                                                       \
+       } while (0)
+
+#define XRUN_LOG_CNT   10
+
+struct hwptr_log_entry {
+       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;
+       snd_pcm_uframes_t hw_ptr_interrupt;
+};
+
+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)
+{
+       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->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;
+       entry->hw_ptr_interrupt = runtime->hw_ptr_interrupt;;
+       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;
+       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;
+               snd_printd("hwptr log: %s: j=%lu, pos=0x%lx/0x%lx/0x%lx, "
+                          "hwptr=0x%lx, hw_base=0x%lx, hw_intr=0x%lx\n",
+                          name, 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,
+                          (unsigned long)entry->hw_ptr_interrupt);
+               idx++;
+               idx %= XRUN_LOG_CNT;
+       }
+       log->hit = 1;
+}
+
+#else /* ! CONFIG_SND_PCM_XRUN_DEBUG */
+
+#define xrun_debug(substream, mask)    0
+#define xrun(substream)                        do { } while (0)
+#define hw_ptr_error(substream, fmt, args...) do { } while (0)
+#define xrun_log(substream, pos)       do { } while (0)
+#define xrun_log_show(substream)       do { } while (0)
+
+#endif
+
 static snd_pcm_uframes_t
 snd_pcm_update_hw_ptr_pos(struct snd_pcm_substream *substream,
                          struct snd_pcm_runtime *runtime)
@@ -182,6 +278,7 @@ snd_pcm_update_hw_ptr_pos(struct snd_pcm_substream *substream,
                if (printk_ratelimit()) {
                        char name[16];
                        pcm_debug_name(substream, name, sizeof(name));
+                       xrun_log_show(substream);
                        snd_printd(KERN_ERR  "BUG: %s, pos = 0x%lx, "
                                   "buffer size = 0x%lx, period size = 0x%lx\n",
                                   name, pos, runtime->buffer_size,
@@ -190,6 +287,8 @@ snd_pcm_update_hw_ptr_pos(struct snd_pcm_substream *substream,
                pos = 0;
        }
        pos -= pos % runtime->min_align;
+       if (xrun_debug(substream, XRUN_DEBUG_LOG))
+               xrun_log(substream, pos);
        return pos;
 }
 
@@ -220,16 +319,6 @@ static int snd_pcm_update_hw_ptr_post(struct snd_pcm_substream *substream,
        return 0;
 }
 
-#define hw_ptr_error(substream, fmt, args...)                          \
-       do {                                                            \
-               if (xrun_debug(substream, XRUN_DEBUG_BASIC)) {          \
-                       if (printk_ratelimit()) {                       \
-                               snd_printd("PCM: " fmt, ##args);        \
-                       }                                               \
-                       dump_stack_on_xrun(substream);                  \
-               }                                                       \
-       } while (0)
-
 static int snd_pcm_update_hw_ptr_interrupt(struct snd_pcm_substream *substream)
 {
        struct snd_pcm_runtime *runtime = substream->runtime;
@@ -270,6 +359,7 @@ static int snd_pcm_update_hw_ptr_interrupt(struct snd_pcm_substream *substream)
                if (runtime->periods == 1 || new_hw_ptr < old_hw_ptr)
                        delta += runtime->buffer_size;
                if (delta < 0) {
+                       xrun_log_show(substream);
                        hw_ptr_error(substream, 
                                     "Unexpected hw_pointer value "
                                     "(stream=%i, pos=%ld, intr_ptr=%ld)\n",
@@ -315,6 +405,7 @@ static int snd_pcm_update_hw_ptr_interrupt(struct snd_pcm_substream *substream)
                delta = jdelta /
                        (((runtime->period_size * HZ) / runtime->rate)
                                                                + HZ/100);
+               xrun_log_show(substream);
                hw_ptr_error(substream,
                             "hw_ptr skipping! [Q] "
                             "(pos=%ld, delta=%ld, period=%ld, "
@@ -334,6 +425,7 @@ static int snd_pcm_update_hw_ptr_interrupt(struct snd_pcm_substream *substream)
        }
  no_jiffies_check:
        if (delta > runtime->period_size + runtime->period_size / 2) {
+               xrun_log_show(substream);
                hw_ptr_error(substream,
                             "Lost interrupts? "
                             "(stream=%i, delta=%ld, intr_ptr=%ld)\n",
@@ -397,6 +489,7 @@ int snd_pcm_update_hw_ptr(struct snd_pcm_substream *substream)
        if (delta < 0) {
                delta += runtime->buffer_size;
                if (delta < 0) {
+                       xrun_log_show(substream);
                        hw_ptr_error(substream, 
                                     "Unexpected hw_pointer value [2] "
                                     "(stream=%i, pos=%ld, old_ptr=%ld, jdelta=%li)\n",
@@ -416,6 +509,7 @@ int snd_pcm_update_hw_ptr(struct snd_pcm_substream *substream)
                goto no_jiffies_check;
        delta -= runtime->delay;
        if (((delta * HZ) / runtime->rate) > jdelta + HZ/100) {
+               xrun_log_show(substream);
                hw_ptr_error(substream,
                             "hw_ptr skipping! "
                             "(pos=%ld, delta=%ld, period=%ld, jdelta=%lu/%lu)\n",