[alsa-devel] Audio Driver -- too much data, coming in two quickly
I have a TI Davinci DM365/368 board that uses a cirrus logic cs4272 decoder. The decoder will only output 32bit pcm ( 24 bits valid) @ 48khz. I've modified the Davinci-* drivers and added a codec driver, and it worked fine for the 2.6.18 kernel ( using oss emulation). The apps aplay & arecord worked as well.
MCBSP (davinci-i2s.c) is set to capture 32bit left, then 32bit right from the I2S stream, and the EDMA (davinci-pcm) driver is set to capture 8k buffers ( 16 buffers for a total of 128k buffers). Since I am capturing 2x4 bytes per sample it's 1024 frames at 48khz, or 48 times a second or about 21ms per DMA buffer.
We've updated the kernel, and I've put in my driver mods for a newer kernel ( 2.6.32-rc2-psp37, from TI), but now I'm seeing the following problem:
Data starts coming in fine, then about one time per second, I see a large amount of frames/captures all at once. Instead of 21ms, per 1024 frames, I see several reads of 1024 frames in less than 5 ms. It's almost like I get the whole ring buffer ( ie get pointer overlapped the put pointer).
I've put in debug in the edma driver that indicates we are inserting data into ALSA at 21ms, so the data is coming in at a steady rate. But the data out has these large spews of data about once a second.
BTW our capture program is capturing 16bit pcm stereo at 48khz using plughw:0,0.
I see this with our application as well as a simple app based on the tutorial.
We are using alsa-lib 1.0.23.
How can I figure out what is happening, or fix this problem? Any suggestions? any similar problems fixed lately? Is there a way I can get the current ring buffer pointers ( either from driver or application?)
Here is a sample run. a tick is a microsecond, so most captures are about 21ms. During capture, the the number on the left is a timstamp in ticks.
~ # alsa_capture alsa_capture: v0.1b delay calibration:0=266 10=152 100=233 1000=1129 10000=10138 100000=100150 ticks ( 112075 11925 1787 658 425 273 7) ticks Returned 1024 frames per period ---------------------------after set hw params 1 PCM handle name = 'plughw:0,0' PCM state = PREPARED access type = RW_INTERLEAVED format = 'S16_LE' (Signed 16 bit Little Endian) subformat = 'STD' (Standard) channels = 2 rate = 48000 bps period time = 21333 us period size = 1024 frames !! buffer time = 341333 us buffer size = 16384 frames periods per buffer = 16 frames exact rate = 48000/1 bps significant bits = 16 is batch = 0 is block transfer = 1 is double = 0 is half duplex = 0 is joint duplex = 0 can overrange = 0 can mmap = 0 can pause = 1 can resume = 0 can sync start = 0 ......................................... loops is 93/0x5d, period_time is 21333/5355, frames=1024/400 157321-l0092:1024 frames 22445 ticks read, 64 ticks process 180009-l0091:1024 frames 20415 ticks read, 20 ticks process 200614-l0090:1024 frames 21074 ticks read, 19 ticks process 221881-l0089:1024 frames 21136 ticks read, 19 ticks process 243209-l0088:1024 frames 21147 ticks read, 18 ticks process 264545-l0087:1024 frames 21132 ticks read, 19 ticks process 285866-l0086:1024 frames 2023 ticks read, 13 ticks process 288049-l0085:1024 frames 456 ticks read, 12 ticks process 288656-l0084:1024 frames 459 ticks read, 12 ticks process 289264-l0083:1024 frames 455 ticks read, 12 ticks process 289868-l0082:1024 frames 451 ticks read, 12 ticks process 290463-l0081:1024 frames 483 ticks read, 13 ticks process 291103-l0080:1024 frames 457 ticks read, 11 ticks process 291705-l0079:1024 frames 454 ticks read, 11 ticks process 292306-l0078:1024 frames 457 ticks read, 13 ticks process 292911-l0077:1024 frames 563 ticks read, 15 ticks process 293649-l0076:1024 frames 466 ticks read, 14 ticks process 294268-l0075:1024 frames 457 ticks read, 10 ticks process 294874-l0074:1024 frames 453 ticks read, 14 ticks process 295474-l0073:1024 frames 453 ticks read, 12 ticks process 296076-l0072:1024 frames 454 ticks read, 11 ticks process 296680-l0071:1024 frames 452 ticks read, 12 ticks process 297278-l0070:1024 frames 9735 ticks read, 18 ticks process 307196-l0069:1024 frames 21163 ticks read, 19 ticks process 328577-l0068:1024 frames 21104 ticks read, 19 ticks process 349869-l0067:1024 frames 21168 ticks read, 19 ticks process 371223-l0066:1024 frames 21157 ticks read, 18 ticks process 392568-l0065:1024 frames 21112 ticks read, 20 ticks process 413871-l0064:1024 frames 21161 ticks read, 19 ticks process 435247-l0063:1024 frames 21113 ticks read, 19 ticks process 456556-l0062:1024 frames 21041 ticks read, 18 ticks process 477785-l0061:1024 frames 21155 ticks read, 19 ticks process 499123-l0060:1024 frames 21106 ticks read, 18 ticks process 520416-l0059:1024 frames 21169 ticks read, 18 ticks process 541770-l0058:1024 frames 21119 ticks read, 20 ticks process 563080-l0057:1024 frames 21167 ticks read, 19 ticks process 584434-l0056:1024 frames 21149 ticks read, 18 ticks process 605770-l0055:1024 frames 21155 ticks read, 19 ticks process 627112-l0054:1024 frames 21148 ticks read, 19 ticks process 648468-l0053:1024 frames 21180 ticks read, 19 ticks process 669836-l0052:1024 frames 21090 ticks read, 19 ticks process 691111-l0051:1024 frames 21236 ticks read, 20 ticks process 712645-l0050:1024 frames 20952 ticks read, 19 ticks process 733783-l0049:1024 frames 21117 ticks read, 18 ticks process 755088-l0048:1024 frames 21158 ticks read, 18 ticks process 776452-l0047:1024 frames 21117 ticks read, 19 ticks process 797752-l0046:1024 frames 6071 ticks read, 17 ticks process 804001-l0045:1024 frames 461 ticks read, 12 ticks process 804620-l0044:1024 frames 456 ticks read, 13 ticks process 805223-l0043:1024 frames 454 ticks read, 12 ticks process 805823-l0042:1024 frames 456 ticks read, 13 ticks process 806428-l0041:1024 frames 452 ticks read, 12 ticks process 807028-l0040:1024 frames 452 ticks read, 11 ticks process 807627-l0039:1024 frames 483 ticks read, 13 ticks process 808266-l0038:1024 frames 455 ticks read, 14 ticks process 808869-l0037:1024 frames 453 ticks read, 13 ticks process 809469-l0036:1024 frames 734 ticks read, 20 ticks process 810400-l0035:1024 frames 469 ticks read, 13 ticks process 811025-l0034:1024 frames 460 ticks read, 11 ticks process 811636-l0033:1024 frames 456 ticks read, 12 ticks process 812239-l0032:1024 frames 458 ticks read, 13 ticks process 812846-l0031:1024 frames 566 ticks read, 16 ticks process 813586-l0030:1024 frames 5340 ticks read, 14 ticks process 819096-l0029:1024 frames 21161 ticks read, 16 ticks process 840440-l0028:1024 frames 21118 ticks read, 19 ticks process 861744-l0027:1024 frames 21167 ticks read, 18 ticks process 883095-l0026:1024 frames 21220 ticks read, 19 ticks process 904504-l0025:1024 frames 21089 ticks read, 16 ticks process 925775-l0024:1024 frames 21124 ticks read, 19 ticks process 947085-l0023:1024 frames 21153 ticks read, 17 ticks process 968423-l0022:1024 frames 21142 ticks read, 20 ticks process 989754-l0021:1024 frames 21164 ticks read, 18 ticks process 1011134-l0020:1024 frames 21126 ticks read, 18 ticks process 1032444-l0019:1024 frames 21153 ticks read, 18 ticks process 1053786-l0018:1024 frames 21129 ticks read, 18 ticks process 1075123-l0017:1024 frames 21115 ticks read, 19 ticks process 1096429-l0016:1024 frames 21162 ticks read, 18 ticks process 1117806-l0015:1024 frames 21175 ticks read, 20 ticks process 1139171-l0014:1024 frames 21093 ticks read, 18 ticks process 1160452-l0013:1024 frames 19131 ticks read, 18 ticks process 1179789-l0012:1024 frames 461 ticks read, 13 ticks process 1180410-l0011:1024 frames 455 ticks read, 12 ticks process 1181016-l0010:1024 frames 456 ticks read, 159 ticks process overrun occurred PIPE ALSA lib pcm.c:7245:(snd_pcm_recover) overrun occured 1181786-l0009:1024 frames 24 ticks read, 935 ticks process 1182911-l0008:1024 frames 22105 ticks read, 19 ticks process 1205210-l0007:1024 frames 20603 ticks read, 19 ticks process 1226000-l0006:1024 frames 21102 ticks read, 18 ticks process 1247285-l0005:1024 frames 21123 ticks read, 17 ticks process 1268588-l0004:1024 frames 21146 ticks read, 18 ticks process 1289920-l0003:1024 frames 21138 ticks read, 17 ticks process 1311244-l0002:1024 frames 21158 ticks read, 18 ticks process 1332585-l0001:1024 frames 21148 ticks read, 18 ticks process 1353922-l0000:1024 frames 5404 ticks read, 15 ticks process .end .drain .pcm_close .free ~ #
Timestamps?
Here's the source code for the example program I ran in the last message.
/* * This example reads from the default PCM device */
/* Use the newer ALSA API */ #define ALSA_PCM_NEW_HW_PARAMS_API
#include <alsa/asoundlib.h> #include <sys/time.h>
static snd_output_t *log;
double arg_duration_ms = 2000.0; // milliseconds int arg_sampling_rate = 48000; char arg_device_name[128] = "plughw:0,0"; char arg_output_fname[128] = "/dev/null"; int arg_frames = 16*1024; // 16k
int verbose = 1;
/* @brief get number of seconds since timer reset * */ unsigned long base_tm; unsigned long get_time() { // faster method? struct timeval tv; unsigned long tm; gettimeofday( &tv, NULL); tm = 1000l*1000l*tv.tv_sec; tm += tv.tv_usec; return tm - base_tm; }
void args( int argc, char *argv[]) { //int flags; int opt;
// getopt while (( opt = getopt( argc, argv,"f:r:d:o:t:")) != -1) { switch (opt) { case 'f': arg_frames = atoi(optarg); printf(" -- frames ( time samples) requested set to %d\n", arg_frames); break; case 'r': arg_sampling_rate = atoi(optarg); printf(" -- samping rate set to %d\n", arg_sampling_rate); break; case 'd': strcpy( arg_device_name, optarg); printf(" -- device_name set to '%s'\n", arg_device_name); break; case 't': printf("t optarg is %s\n", optarg); arg_duration_ms = (double) atoi(optarg); printf(" -- duration set to %fms\n", arg_duration_ms); break; case 'o': strcpy( arg_output_fname, optarg); printf(" -- output file name set to '%s'\n", arg_output_fname); break; default: fprintf(stderr, "Usage: %s \n" " -r <rate>\n" " -d <input_device_name>\n" " -o <output_file_name>\n" "", argv[0]); exit( -1); } } }
/*** * * ***/ void dump_params( snd_pcm_t *handle, snd_pcm_hw_params_t *params ) {
unsigned int val, val2; int dir;
printf("PCM handle name = '%s'\n", snd_pcm_name(handle));
printf("PCM state = %s\n", snd_pcm_state_name(snd_pcm_state(handle)));
snd_pcm_hw_params_get_access(params, (snd_pcm_access_t *) &val);
printf("access type = %s\n", snd_pcm_access_name((snd_pcm_access_t)val));
// changed val to fmt snd_pcm_format_t fmt; snd_pcm_hw_params_get_format(params, &fmt); printf("format = '%s' (%s)\n", snd_pcm_format_name(fmt), snd_pcm_format_description(fmt));
snd_pcm_hw_params_get_subformat(params, (snd_pcm_subformat_t *)&val); printf("subformat = '%s' (%s)\n", snd_pcm_subformat_name((snd_pcm_subformat_t)val), snd_pcm_subformat_description( (snd_pcm_subformat_t)val));
snd_pcm_hw_params_get_channels(params, &val); printf("channels = %d\n", val);
snd_pcm_hw_params_get_rate(params, &val, &dir); printf("rate = %d bps\n", val);
snd_pcm_hw_params_get_period_time(params, &val, &dir); printf("period time = %d us\n", val);
snd_pcm_uframes_t uframes; snd_pcm_hw_params_get_period_size(params, &uframes, &dir); printf("period size = %d frames !!\n", (int)uframes);
snd_pcm_hw_params_get_buffer_time(params, &val, &dir); printf("buffer time = %d us\n", val);
snd_pcm_hw_params_get_buffer_size(params, (snd_pcm_uframes_t *) &val); printf("buffer size = %d frames\n", val);
snd_pcm_hw_params_get_periods(params, &val, &dir); printf("periods per buffer = %d frames\n", val);
snd_pcm_hw_params_get_rate_numden(params, &val, &val2); printf("exact rate = %d/%d bps\n", val, val2);
val = snd_pcm_hw_params_get_sbits(params); printf("significant bits = %d\n", val);
#if 0 snd_pcm_hw_params_get_tick_time(params, &val, &dir); printf("tick time = %d us\n", val); #endif
val = snd_pcm_hw_params_is_batch(params); printf("is batch = %d\n", val);
val = snd_pcm_hw_params_is_block_transfer(params); printf("is block transfer = %d\n", val);
val = snd_pcm_hw_params_is_double(params); printf("is double = %d\n", val);
val = snd_pcm_hw_params_is_half_duplex(params); printf("is half duplex = %d\n", val);
val = snd_pcm_hw_params_is_joint_duplex(params); printf("is joint duplex = %d\n", val);
val = snd_pcm_hw_params_can_overrange(params); printf("can overrange = %d\n", val);
val = snd_pcm_hw_params_can_mmap_sample_resolution(params); printf("can mmap = %d\n", val);
val = snd_pcm_hw_params_can_pause(params); printf("can pause = %d\n", val);
val = snd_pcm_hw_params_can_resume(params); printf("can resume = %d\n", val);
val = snd_pcm_hw_params_can_sync_start(params); printf("can sync start = %d\n", val); }
int main( int argc, char *argv[]) { long loops; int rc; int size; snd_pcm_t *handle; snd_pcm_hw_params_t *params; unsigned int val, val2; int dir; snd_pcm_uframes_t frames; char *buffer;
fprintf(stderr, "alsa_capture: v0.1b\n");
args(argc, argv);
base_tm = get_time();
unsigned long ttim[10]; ttim[0] = get_time(); usleep (0); ttim[1] = get_time(); usleep (10); ttim[2] = get_time(); usleep (100); ttim[3] = get_time(); usleep (1000); ttim[4] = get_time(); usleep (10000); ttim[5] = get_time(); usleep (100000); ttim[6] = get_time(); printf("delay calibration:" "0=%ld 10=%ld 100=%ld 1000=%ld 10000=%ld 100000=%ld ticks " "( %ld %ld %ld %ld %ld %ld %ld) ticks\n",
ttim[1] - ttim[0], ttim[2] - ttim[1], ttim[3] - ttim[2], ttim[4] - ttim[3], ttim[5] - ttim[4], ttim[6] - ttim[5],
ttim[6], ttim[5], ttim[4], ttim[3], ttim[2], ttim[1], ttim[0]);
/* Open PCM device for recording (capture). */ rc = snd_pcm_open(&handle, arg_device_name, SND_PCM_STREAM_CAPTURE, 0); if (rc < 0) { fprintf(stderr, "unable to open pcm device: %s\n", snd_strerror(rc)); exit(1); }
snd_output_stdio_attach(&log, stderr, 0);
/* Allocate a hardware parameters object. */ snd_pcm_hw_params_alloca(¶ms);
/* Fill it in with default values. */ snd_pcm_hw_params_any(handle, params);
/* Set the desired hardware parameters. */
/* Interleaved mode */ snd_pcm_hw_params_set_access(handle, params, SND_PCM_ACCESS_RW_INTERLEAVED);
/* Signed 16-bit little-endian format */ snd_pcm_hw_params_set_format(handle, params, SND_PCM_FORMAT_S16_LE);
/* Two channels (stereo) */ snd_pcm_hw_params_set_channels(handle, params, 2);
/* sampling rate in time_samples/second : cd=44100, dat=48000 */ val = arg_sampling_rate; snd_pcm_hw_params_set_rate_near(handle, params, &val, &dir);
/* Set period size to 32 frames. */ frames = arg_frames; printf("Requesting %d frames per period\n", frames); snd_pcm_hw_params_set_period_size_near(handle, params, &frames, &dir); printf("Returned %d frames per period\n", frames);
/* Write the parameters to the driver */ rc = snd_pcm_hw_params(handle, params); if (rc < 0) { fprintf(stderr, "unable to set hw parameters: %s\n", snd_strerror(rc)); exit(1); }
printf("---------------------------after set hw params 1\n"); dump_params( handle, params); printf(".........................................\n");
int fout; fout = open(arg_output_fname, O_CREAT | O_WRONLY | O_TRUNC); if ( fout < 0) { printf("could not open output file\n"); exit(-1); }
/* Use a buffer large enough to hold one period */ snd_pcm_hw_params_get_period_size(params, &frames, &dir);
size = frames * 4; /* 2 bytes/sample, 2 channels */ buffer = (char *) malloc(size);
/* We want to loop for duration_ms */ snd_pcm_hw_params_get_period_time(params, &val, &dir);
loops = (int) (arg_duration_ms*1000 / val); printf("loops is %d/0x%x, period_time is %d/%x, frames=%d/%x\n", loops, loops, val, val, frames,frames);
while (loops > 0) { snd_htimestamp_t ts1; snd_pcm_uframes_t frames1;
snd_pcm_htimestamp( handle, &frames1, &ts1); loops--;
ttim[0] = get_time(); rc = snd_pcm_readi(handle, buffer, frames); ttim[1] = get_time(); if (rc == -EPIPE) { /* EPIPE means overrun */ fprintf(stderr, "overrun occurred\n"); printf("PIPE\n"); //snd_pcm_prepare(handle); //snd_pcm_drop(handle); snd_pcm_recover(handle, rc, 0); snd_pcm_drain(handle); } else if (rc < 0) { printf("ERR\n"); fprintf(stderr, "error from read: %s\n", snd_strerror(rc)); } else if (rc != (int)frames) { printf("SR\n"); fprintf(stderr, "short read, read %d frames\n", rc); }
// write out a file rc = write(fout, buffer, size); if (rc != size) fprintf(stderr, "short write: wrote %d bytes\n", rc); ttim[2]= get_time();
printf("%8d-l%04d:%d frames %12ld ticks read, %8ld ticks process\n", ttim[0], loops, frames, ttim[1] - ttim[0], ttim[2] - ttim[1]); }
printf(".end\n"); close(fout);
printf(".drain\n"); snd_pcm_drain(handle); printf(".pcm_close\n"); snd_pcm_close(handle); printf(".free\n"); free(buffer);
snd_output_close(log);
return 0; }
On Wed, 1 Sep 2010, Brett Bolen wrote:
How can I figure out what is happening, or fix this problem? Any suggestions? any similar problems fixed lately? Is there a way I can get the current ring buffer pointers ( either from driver or application?)
The xrun_debug should help you to see the problem with the PCM ring buffer pointer in the driver side:
http://www.alsa-project.org/main/index.php/XRUN_Debug
Try value 27 and look for big hw_ptr changes.
Jaroslav
----- Jaroslav Kysela perex@perex.cz Linux Kernel Sound Maintainer ALSA Project, Red Hat, Inc.
participants (2)
-
Brett Bolen -
Jaroslav Kysela