Commit 4d96eb255c53ab5e39b37fd4d484ea3dc39ab456

Authored by Jaroslav Kysela
1 parent 741b20cfb9

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>

Showing 3 changed files with 127 additions and 23 deletions Side-by-side Diff

... ... @@ -262,6 +262,8 @@
262 262 unsigned int mask;
263 263 };
264 264  
  265 +struct snd_pcm_hwptr_log;
  266 +
265 267 struct snd_pcm_runtime {
266 268 /* -- Status -- */
267 269 struct snd_pcm_substream *trigger_master;
... ... @@ -339,6 +341,10 @@
339 341 #if defined(CONFIG_SND_PCM_OSS) || defined(CONFIG_SND_PCM_OSS_MODULE)
340 342 /* -- OSS things -- */
341 343 struct snd_pcm_oss_runtime oss;
  344 +#endif
  345 +
  346 +#ifdef CONFIG_SND_PCM_XRUN_DEBUG
  347 + struct snd_pcm_hwptr_log *hwptr_log;
342 348 #endif
343 349 };
344 350  
... ... @@ -921,6 +921,10 @@
921 921 snd_free_pages((void*)runtime->control,
922 922 PAGE_ALIGN(sizeof(struct snd_pcm_mmap_control)));
923 923 kfree(runtime->hw_constraints.rules);
  924 +#ifdef CONFIG_SND_PCM_XRUN_DEBUG
  925 + if (runtime->hwptr_log)
  926 + kfree(runtime->hwptr_log);
  927 +#endif
924 928 kfree(runtime);
925 929 substream->runtime = NULL;
926 930 put_pid(substream->pid);
sound/core/pcm_lib.c
... ... @@ -126,34 +126,34 @@
126 126 }
127 127 }
128 128  
  129 +static void pcm_debug_name(struct snd_pcm_substream *substream,
  130 + char *name, size_t len)
  131 +{
  132 + snprintf(name, len, "pcmC%dD%d%c:%d",
  133 + substream->pcm->card->number,
  134 + substream->pcm->device,
  135 + substream->stream ? 'c' : 'p',
  136 + substream->number);
  137 +}
  138 +
129 139 #define XRUN_DEBUG_BASIC (1<<0)
130 140 #define XRUN_DEBUG_STACK (1<<1) /* dump also stack */
131 141 #define XRUN_DEBUG_JIFFIESCHECK (1<<2) /* do jiffies check */
132 142 #define XRUN_DEBUG_PERIODUPDATE (1<<3) /* full period update info */
133 143 #define XRUN_DEBUG_HWPTRUPDATE (1<<4) /* full hwptr update info */
  144 +#define XRUN_DEBUG_LOG (1<<5) /* show last 10 positions on err */
  145 +#define XRUN_DEBUG_LOGONCE (1<<6) /* do above only once */
134 146  
135 147 #ifdef CONFIG_SND_PCM_XRUN_DEBUG
  148 +
136 149 #define xrun_debug(substream, mask) \
137 150 ((substream)->pstr->xrun_debug & (mask))
138   -#else
139   -#define xrun_debug(substream, mask) 0
140   -#endif
141 151  
142 152 #define dump_stack_on_xrun(substream) do { \
143 153 if (xrun_debug(substream, XRUN_DEBUG_STACK)) \
144 154 dump_stack(); \
145 155 } while (0)
146 156  
147   -static void pcm_debug_name(struct snd_pcm_substream *substream,
148   - char *name, size_t len)
149   -{
150   - snprintf(name, len, "pcmC%dD%d%c:%d",
151   - substream->pcm->card->number,
152   - substream->pcm->device,
153   - substream->stream ? 'c' : 'p',
154   - substream->number);
155   -}
156   -
157 157 static void xrun(struct snd_pcm_substream *substream)
158 158 {
159 159 struct snd_pcm_runtime *runtime = substream->runtime;
... ... @@ -169,6 +169,102 @@
169 169 }
170 170 }
171 171  
  172 +#define hw_ptr_error(substream, fmt, args...) \
  173 + do { \
  174 + if (xrun_debug(substream, XRUN_DEBUG_BASIC)) { \
  175 + if (printk_ratelimit()) { \
  176 + snd_printd("PCM: " fmt, ##args); \
  177 + } \
  178 + dump_stack_on_xrun(substream); \
  179 + } \
  180 + } while (0)
  181 +
  182 +#define XRUN_LOG_CNT 10
  183 +
  184 +struct hwptr_log_entry {
  185 + unsigned long jiffies;
  186 + snd_pcm_uframes_t pos;
  187 + snd_pcm_uframes_t period_size;
  188 + snd_pcm_uframes_t buffer_size;
  189 + snd_pcm_uframes_t old_hw_ptr;
  190 + snd_pcm_uframes_t hw_ptr_base;
  191 + snd_pcm_uframes_t hw_ptr_interrupt;
  192 +};
  193 +
  194 +struct snd_pcm_hwptr_log {
  195 + unsigned int idx;
  196 + unsigned int hit: 1;
  197 + struct hwptr_log_entry entries[XRUN_LOG_CNT];
  198 +};
  199 +
  200 +static void xrun_log(struct snd_pcm_substream *substream,
  201 + snd_pcm_uframes_t pos)
  202 +{
  203 + struct snd_pcm_runtime *runtime = substream->runtime;
  204 + struct snd_pcm_hwptr_log *log = runtime->hwptr_log;
  205 + struct hwptr_log_entry *entry;
  206 +
  207 + if (log == NULL) {
  208 + log = kzalloc(sizeof(*log), GFP_ATOMIC);
  209 + if (log == NULL)
  210 + return;
  211 + runtime->hwptr_log = log;
  212 + } else {
  213 + if (xrun_debug(substream, XRUN_DEBUG_LOGONCE) && log->hit)
  214 + return;
  215 + }
  216 + entry = &log->entries[log->idx];
  217 + entry->jiffies = jiffies;
  218 + entry->pos = pos;
  219 + entry->period_size = runtime->period_size;
  220 + entry->buffer_size = runtime->buffer_size;;
  221 + entry->old_hw_ptr = runtime->status->hw_ptr;
  222 + entry->hw_ptr_base = runtime->hw_ptr_base;
  223 + entry->hw_ptr_interrupt = runtime->hw_ptr_interrupt;;
  224 + log->idx = (log->idx + 1) % XRUN_LOG_CNT;
  225 +}
  226 +
  227 +static void xrun_log_show(struct snd_pcm_substream *substream)
  228 +{
  229 + struct snd_pcm_hwptr_log *log = substream->runtime->hwptr_log;
  230 + struct hwptr_log_entry *entry;
  231 + char name[16];
  232 + unsigned int idx;
  233 + int cnt;
  234 +
  235 + if (log == NULL)
  236 + return;
  237 + if (xrun_debug(substream, XRUN_DEBUG_LOGONCE) && log->hit)
  238 + return;
  239 + pcm_debug_name(substream, name, sizeof(name));
  240 + for (cnt = 0, idx = log->idx; cnt < XRUN_LOG_CNT; cnt++) {
  241 + entry = &log->entries[idx];
  242 + if (entry->period_size == 0)
  243 + break;
  244 + snd_printd("hwptr log: %s: j=%lu, pos=0x%lx/0x%lx/0x%lx, "
  245 + "hwptr=0x%lx, hw_base=0x%lx, hw_intr=0x%lx\n",
  246 + name, entry->jiffies, (unsigned long)entry->pos,
  247 + (unsigned long)entry->period_size,
  248 + (unsigned long)entry->buffer_size,
  249 + (unsigned long)entry->old_hw_ptr,
  250 + (unsigned long)entry->hw_ptr_base,
  251 + (unsigned long)entry->hw_ptr_interrupt);
  252 + idx++;
  253 + idx %= XRUN_LOG_CNT;
  254 + }
  255 + log->hit = 1;
  256 +}
  257 +
  258 +#else /* ! CONFIG_SND_PCM_XRUN_DEBUG */
  259 +
  260 +#define xrun_debug(substream, mask) 0
  261 +#define xrun(substream) do { } while (0)
  262 +#define hw_ptr_error(substream, fmt, args...) do { } while (0)
  263 +#define xrun_log(substream, pos) do { } while (0)
  264 +#define xrun_log_show(substream) do { } while (0)
  265 +
  266 +#endif
  267 +
172 268 static snd_pcm_uframes_t
173 269 snd_pcm_update_hw_ptr_pos(struct snd_pcm_substream *substream,
174 270 struct snd_pcm_runtime *runtime)
... ... @@ -182,6 +278,7 @@
182 278 if (printk_ratelimit()) {
183 279 char name[16];
184 280 pcm_debug_name(substream, name, sizeof(name));
  281 + xrun_log_show(substream);
185 282 snd_printd(KERN_ERR "BUG: %s, pos = 0x%lx, "
186 283 "buffer size = 0x%lx, period size = 0x%lx\n",
187 284 name, pos, runtime->buffer_size,
... ... @@ -190,6 +287,8 @@
190 287 pos = 0;
191 288 }
192 289 pos -= pos % runtime->min_align;
  290 + if (xrun_debug(substream, XRUN_DEBUG_LOG))
  291 + xrun_log(substream, pos);
193 292 return pos;
194 293 }
195 294  
... ... @@ -220,16 +319,6 @@
220 319 return 0;
221 320 }
222 321  
223   -#define hw_ptr_error(substream, fmt, args...) \
224   - do { \
225   - if (xrun_debug(substream, XRUN_DEBUG_BASIC)) { \
226   - if (printk_ratelimit()) { \
227   - snd_printd("PCM: " fmt, ##args); \
228   - } \
229   - dump_stack_on_xrun(substream); \
230   - } \
231   - } while (0)
232   -
233 322 static int snd_pcm_update_hw_ptr_interrupt(struct snd_pcm_substream *substream)
234 323 {
235 324 struct snd_pcm_runtime *runtime = substream->runtime;
... ... @@ -270,6 +359,7 @@
270 359 if (runtime->periods == 1 || new_hw_ptr < old_hw_ptr)
271 360 delta += runtime->buffer_size;
272 361 if (delta < 0) {
  362 + xrun_log_show(substream);
273 363 hw_ptr_error(substream,
274 364 "Unexpected hw_pointer value "
275 365 "(stream=%i, pos=%ld, intr_ptr=%ld)\n",
... ... @@ -315,6 +405,7 @@
315 405 delta = jdelta /
316 406 (((runtime->period_size * HZ) / runtime->rate)
317 407 + HZ/100);
  408 + xrun_log_show(substream);
318 409 hw_ptr_error(substream,
319 410 "hw_ptr skipping! [Q] "
320 411 "(pos=%ld, delta=%ld, period=%ld, "
... ... @@ -334,6 +425,7 @@
334 425 }
335 426 no_jiffies_check:
336 427 if (delta > runtime->period_size + runtime->period_size / 2) {
  428 + xrun_log_show(substream);
337 429 hw_ptr_error(substream,
338 430 "Lost interrupts? "
339 431 "(stream=%i, delta=%ld, intr_ptr=%ld)\n",
... ... @@ -397,6 +489,7 @@
397 489 if (delta < 0) {
398 490 delta += runtime->buffer_size;
399 491 if (delta < 0) {
  492 + xrun_log_show(substream);
400 493 hw_ptr_error(substream,
401 494 "Unexpected hw_pointer value [2] "
402 495 "(stream=%i, pos=%ld, old_ptr=%ld, jdelta=%li)\n",
... ... @@ -416,6 +509,7 @@
416 509 goto no_jiffies_check;
417 510 delta -= runtime->delay;
418 511 if (((delta * HZ) / runtime->rate) > jdelta + HZ/100) {
  512 + xrun_log_show(substream);
419 513 hw_ptr_error(substream,
420 514 "hw_ptr skipping! "
421 515 "(pos=%ld, delta=%ld, period=%ld, jdelta=%lu/%lu)\n",