Need Help: Repeated Jackhammer noise after several hours of play and heavy cpu usage in snd_pcm_dmix_sync_area

Need Help: Repeated Jackhammer noise after several hours of play and heavy cpu usage in snd_pcm_dmix_sync_area

[Adarsh]

[-- Attachment #1: Type: text/plain, Size: 8397 bytes --]

Hi,

We are facing a issue where if gdb is attached to the our long running
sound process and continued,
jackhammer sound is played over and over again abusing the speakers.

Process details:
1. We are using RW_INTERLEAVED access as described in write_loop method in
/test/pcm.c and opening 'default' device.
2. However to disable the underruns, the
snd_pcm_sw_params_set_stop_threshold is set to 0x7fffffff which is greater
than boundary
value.
3.Period size is 1024 and buffer size is 2048. We try to write period_size
no of frames using snd_pcm_writei.
(I am attaching a sample program which shows this behaviour.)

Steps to Reproduce:
1. Left process running for over 12 hours.
2. gdb is attached to the process and continued inside gdb.
3. At this point, the thread went into a tight loop taking >100% cpu and
repeatedly playing same sound. It did not recover for a long time.

Stack trace shows that 'snd_pcm_dmix_sync_area' in pcm_dmix.c is taking a
very long time to return because the 'size' is
a large unsinged interger and mix_areas is getting called with 'transfer'
value of <=2048.

If snd_pcm_sw_params_set_stop_threshold is not set or when application is
running for shorter duration,
attaching gdb does not show this behaviour.

Is it that setting of stop threshold to 0x7fffffff is triggering this and
attaching gdb is making the buffer pointers misbehave?
If so, what can be done if we do not want PCM to stop? I have tried by
setting silence threshold and silence size to let alsa
play silence by itself but still observed the issue.



Below is the stack trace and PCM dump:

(gdb) bt
#0  0xb7c44463 in mix_areas_32_smp (size=1360, dst=0xb6855000,
src=0x84a7510, sum=0xb6845000, dst_step=4, src_step=4, sum_step=4) at
pcm_dmix_i386.h:261
#1  0xb7c44d2b in mix_areas (dmix=0x84a7110, src_areas=0x84a51d0,
dst_areas=0x84a6f00, src_ofs=0, dst_ofs=7168, size=1024) at pcm_dmix.c:193
#2  0xb7c45422 in snd_pcm_dmix_sync_area (pcm=0x84a71e0) at pcm_dmix.c:371
#3  0xb7c46680 in snd_pcm_dmix_mmap_commit (pcm=0x84a71e0, offset=0,
size=1024) at pcm_dmix.c:813
#4  0xb7c07033 in snd_pcm_mmap_commit (pcm=0x84a71e0, offset=0,
frames=1024) at pcm.c:6501
#5  0xb7c1804e in snd_pcm_plugin_mmap_commit (pcm=0x84a6d18, offset=0,
size=1024) at pcm_plugin.c:434
#6  0xb7c07033 in snd_pcm_mmap_commit (pcm=0x84a6d18, offset=0,
frames=1024) at pcm.c:6501
#7  0xb7c17956 in snd_pcm_plugin_write_areas (pcm=0x84a5390,
areas=0xb68362b0, offset=0, size=1024) at pcm_plugin.c:290
#8  0xb7c074bb in snd1_pcm_write_areas (pcm=0x84a5390, areas=0xb68362b0,
offset=0, size=1024, func=0xb7c177fc <snd_pcm_plugin_write_areas>) at
pcm.c:6667
#9  0xb7c17cd5 in snd_pcm_plugin_writei (pcm=0x84a5390, buffer=0x84ab518,
size=1024) at pcm_plugin.c:361
#10 0xb7bff1a7 in _snd_pcm_writei (pcm=0x84a6b18, buffer=0x84ab518,
size=1024) at pcm_local.h:516
#11 0xb7bff16c in snd_pcm_writei (pcm=0x84a6b18, buffer=0x84ab518,
size=1024) at pcm.c:1258

(gdb) f 2
#2  0xb7c45422 in snd_pcm_dmix_sync_area (pcm=0x84a71e0) at pcm_dmix.c:371
  371     pcm_dmix.c: No such file or directory.
(gdb) info locals
  dmix = 0x84a7110
  slave_hw_ptr = 234156032
  slave_appl_ptr = 7168
  slave_size = 1057171456
  appl_ptr = 0
  size = 1018295296
  transfer = 1024
  src_areas = 0x84a51d0
  dst_areas = 0x84a6f00
(gdb) p *dmix
  $1 = {type = SND_PCM_TYPE_DMIX, ipc_key = 5678293, ipc_perm = 432,
ipc_gid = 17, semid = 32768, shmid = 65536, shmptr = 0xb6859000, spcm =
0x84a7340,
    appl_ptr = 217121792, last_appl_ptr = 233882624, hw_ptr = 233875428,
avail_max = 0, slave_appl_ptr = 234156032, slave_hw_ptr = 234147996,
    slave_period_size = 1024, slave_buffer_size = 8192, slave_boundary =
1073741824, sync_ptr = 0xb7c4557c <snd_pcm_dmix_sync_ptr>,
    state = SND_PCM_STATE_RUNNING, trigger_tstamp = {tv_sec = 1392384066,
tv_nsec = 8308000}, server = 0, client = 0, comm_fd = 0, hw_fd = 4,
timer_fd = {
      fd = 3, events = 41, revents = 0}, poll_fd = 3, tread = 1,
timer_need_poll = 0, timer_event_suspend = 131072, timer_event_resume =
262144,
    server_fd = 0, server_pid = 0, timer = 0x8496b90, interleaved = 1,
slowptr = 1, max_periods = 0, channels = 2, bindings = 0x0, u = {dmix = {
      shmid_sum = 98305, sum_buffer = 0xb6837000, mix_areas_16 = 0xb7c443a8
<mix_areas_16_smp_mmx>, mix_areas_32 = 0xb7c44415 <mix_areas_32_smp>,
      mix_areas_24 = 0xb7c4451b <mix_areas_24_smp_cmov>, mix_areas_u8 = 0,
remix_areas_16 = 0xb7c44638 <remix_areas_16_smp_mmx>,
      remix_areas_32 = 0xb7c446a5 <remix_areas_32_smp>, remix_areas_24 =
0xb7c447ab <remix_areas_24_smp_cmov>, remix_areas_u8 = 0},
    dsnoop = {<No data fields>}, dshare = {chn_mask =
13151478482154389505}}, server_free = 0}
(gdb) p *pcm
$2 = {dl_handle = 0x0, name = 0x84a6e48 "dmix:0", type = SND_PCM_TYPE_DMIX,
stream = SND_PCM_STREAM_PLAYBACK, mode = 0, poll_fd_count = 1, poll_fd = 3,
  poll_events = 1, setup = -1, monotonic = 0, access =
SND_PCM_ACCESS_MMAP_INTERLEAVED, format = SND_PCM_FORMAT_S32_LE, subformat
= SND_PCM_SUBFORMAT_STD,
  channels = 2, rate = 44100, period_size = 1024, period_time = 23219,
periods = {min = 0, max = 0, openmin = 0, openmax = 0, integer = 0, empty =
0},
  tstamp_mode = SND_PCM_TSTAMP_NONE, period_step = 1, avail_min = 1024,
period_event = 0, start_threshold = 1024, stop_threshold = 2147483647,
  silence_threshold = 0, silence_size = 0, boundary = 1073741824, info =
2151743747, msbits = 32, rate_num = 44100, rate_den = 1, hw_flags = 0,
  fifo_size = 0, buffer_size = 2048, buffer_time = {min = 0, max = 0,
openmin = 0, openmax = 0, integer = 0, empty = 0}, sample_bits = 32,
  frame_bits = 64, appl = {master = 0x0, ptr = 0x84a7130, fd = -1, offset =
0, link_dst_count = 0, link_dst = 0x0, private_data = 0x0, changed = 0}, hw
= {
    master = 0x0, ptr = 0x84a7138, fd = -1, offset = 0, link_dst_count = 0,
link_dst = 0x0, private_data = 0x0, changed = 0}, min_align = 1, mmap_rw =
1,
  mmap_shadow = 0, donot_close = 0, mmap_channels = 0x84a54a0,
running_areas = 0x84a51d0, stopped_areas = 0x0, ops = 0xb7c91860, fast_ops
= 0xb7c918a0,
  op_arg = 0x84a71e0, fast_op_arg = 0x84a71e0, private_data = 0x84a7110,
async_handlers = {next = 0x84a72e4, prev = 0x84a72e4}}


PCM dump:
Plug PCM: Linear conversion PCM (S32_LE)
Its setup is:
  stream       : PLAYBACK
  access       : RW_INTERLEAVED
  format       : S16_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 16
  buffer_size  : 2048
  period_size  : 1024
  period_time  : 23219
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 1024
  period_event : 0
  start_threshold  : 1024
  stop_threshold   : 2147483647
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
Slave: Soft volume PCM
Control: PCM Playback Volume
min_dB: -51
max_dB: 0
resolution: 256
Its setup is:
  stream       : PLAYBACK
  access       : MMAP_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 32
  buffer_size  : 2048
  period_size  : 1024
  period_time  : 23219
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 1024
  period_event : 0
  start_threshold  : 1024
  stop_threshold   : 2147483647
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
Slave: Direct Stream Mixing PCM
Its setup is:
  stream       : PLAYBACK
  access       : MMAP_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 32
  buffer_size  : 2048
  period_size  : 1024
  period_time  : 23219
  tstamp_mode  : NONE
  period_step  : 1
  avail_min    : 1024
  period_event : 0
  start_threshold  : 1024
  stop_threshold   : 2147483647
  silence_threshold: 0
  silence_size : 0
  boundary     : 1073741824
Hardware PCM card 0 'HDA Intel PCH' device 0 subdevice 0
Its setup is:
  stream       : PLAYBACK
  access       : MMAP_INTERLEAVED
  format       : S32_LE
  subformat    : STD
  channels     : 2
  rate         : 44100
  exact rate   : 44100 (44100/1)
  msbits       : 32
  buffer_size  : 8192
  period_size  : 1024
  period_time  : 23219
  tstamp_mode  : ENABLE
  period_step  : 1
  avail_min    : 1024
  period_event : 0
  start_threshold  : 1
  stop_threshold   : 1073741824
  silence_threshold: 0
  silence_size : 1073741824
  boundary     : 1073741824
  appl_ptr     : 0
  hw_ptr       : 0

Thanks

[-- Attachment #2: alsatest.c --]
[-- Type: text/x-csrc, Size: 15747 bytes --]

/*
   * This small demo sends a simple sinusoidal wave to your speakers.
   */
#include <stdio.h>
#include <stdlib.h>
#include <string.h>
#include <sched.h>
#include <errno.h>
#include <getopt.h>
#include "/usr/include/alsa/asoundlib.h"
#include <sys/time.h>
#include <math.h>

static char *device = "default"; /* playback device */
static snd_pcm_format_t format = SND_PCM_FORMAT_S16_LE; /* sample format */
static unsigned int rate = 44100; /* stream rate */
static unsigned int channels = 2; /* count of channels */
static unsigned int buffer_time = 500000; /* ring buffer length in us */
static unsigned int period_time = 100000; /* period time in us */
static double freq = 440; /* sinusoidal wave frequency in Hz */
static int verbose = 0; /* verbose flag */
static int resample = 0; /* enable alsa-lib resampling */
static int period_event = 0; /* produce poll event after each period */
static snd_pcm_sframes_t buffer_size;
static snd_pcm_sframes_t period_size;
static snd_output_t *output = NULL;

static void generate_sine(const snd_pcm_channel_area_t *areas,
    snd_pcm_uframes_t offset,
    int count, double *_phase)
{
  static double max_phase = 2. * M_PI;
  double phase = *_phase;
  double step = max_phase*freq/(double)rate;
  unsigned char *samples[channels];
  int steps[channels];
  unsigned int chn;
  int format_bits = snd_pcm_format_width(format);
  unsigned int maxval = (1 << (format_bits - 1)) - 1;
  int bps = format_bits / 8; /* bytes per sample */
  int phys_bps = snd_pcm_format_physical_width(format) / 8;
  int big_endian = snd_pcm_format_big_endian(format) == 1;
  int to_unsigned = snd_pcm_format_unsigned(format) == 1;
  int is_float = (format == SND_PCM_FORMAT_FLOAT_LE ||
      format == SND_PCM_FORMAT_FLOAT_BE);
  /* verify and prepare the contents of areas */
  for (chn = 0; chn < channels; chn++) {
    if ((areas[chn].first % 8) != 0) {
      printf("areas[%i].first == %i, aborting...\n", chn, areas[chn].first);
      exit(EXIT_FAILURE);
    }
    samples[chn] = /*(signed short *)*/(((unsigned char *)areas[chn].addr) + (areas[chn].first / 8));
    if ((areas[chn].step % 16) != 0) {
      printf("areas[%i].step == %i, aborting...\n", chn, areas[chn].step);
      exit(EXIT_FAILURE);
    }
    steps[chn] = areas[chn].step / 8;
    samples[chn] += offset * steps[chn];
  }
  /* fill the channel areas */
  while (count-- > 0) {
    union {
      float f;
      int i;
    } fval;
    int res, i;
    if (is_float) {
      fval.f = sin(phase) * maxval;
      res = fval.i;
    } else
      res = sin(phase) * maxval;
    if (to_unsigned)
      res ^= 1U << (format_bits - 1);
    for (chn = 0; chn < channels; chn++) {
      /* Generate data in native endian format */
      if (big_endian) {
        for (i = 0; i < bps; i++)
          *(samples[chn] + phys_bps - 1 - i) = (res >> i * 8) & 0xff;
      } else {
        for (i = 0; i < bps; i++)
          *(samples[chn] + i) = (res >> i * 8) & 0xff;
      }
      samples[chn] += steps[chn];
    }
    phase += step;
    if (phase >= max_phase)
      phase -= max_phase;
  }
  *_phase = phase;
}
static int set_hwparams(snd_pcm_t *handle,
    snd_pcm_hw_params_t *params,
    snd_pcm_access_t access)
{
  unsigned int rrate;
  snd_pcm_uframes_t size;
  int err, dir;
  /* choose all parameters */
  err = snd_pcm_hw_params_any(handle, params);
  if (err < 0) {
    printf("Broken configuration for playback: no configurations available: %s\n", snd_strerror(err));
    return err;
  }
  /* set hardware resampling */
  /*err = snd_pcm_hw_params_set_rate_resample(handle, params, resample);
  if (err < 0) {
    printf("Resampling setup failed for playback: %s\n", snd_strerror(err));
    return err;
  }*/
  /* set the interleaved read/write format */
  err = snd_pcm_hw_params_set_access(handle, params, access);
  if (err < 0) {
    printf("Access type not available for playback: %s\n", snd_strerror(err));
    return err;
  }
  /* set the sample format */
  err = snd_pcm_hw_params_set_format(handle, params, format);
  if (err < 0) {
    printf("Sample format not available for playback: %s\n", snd_strerror(err));
    return err;
  }
  /* set the count of channels */
  err = snd_pcm_hw_params_set_channels(handle, params, channels);
  if (err < 0) {
    printf("Channels count (%i) not available for playbacks: %s\n", channels, snd_strerror(err));
    return err;
  }
  /* set the stream rate */
  rrate = rate;
  err = snd_pcm_hw_params_set_rate_near(handle, params, &rrate, 0);
  if (err < 0) {
    printf("Rate %iHz not available for playback: %s\n", rate, snd_strerror(err));
    return err;
  }
  if (rrate != rate) {
    printf("Rate doesn't match (requested %iHz, get %iHz)\n", rate, err);
    return -EINVAL;
  }
  /* set the buffer time */
  //err = snd_pcm_hw_params_set_buffer_time_near(handle, params, &buffer_time, &dir);
  size = 2048;
  err = snd_pcm_hw_params_set_buffer_size_near(handle, params, &size);
  if (err < 0) {
    printf("Unable to set buffer time %i for playback: %s\n", size, snd_strerror(err));
    return err;
  }
  err = snd_pcm_hw_params_get_buffer_size(params, &size);
  if (err < 0) {
    printf("Unable to get buffer size for playback: %s\n", snd_strerror(err));
    return err;
  }
  buffer_size = size;
  /* set the period time */
  //err = snd_pcm_hw_params_set_period_time_near(handle, params, &period_time, &dir);
  size = 1024;
  err = snd_pcm_hw_params_set_period_size_near(handle, params, &size, 0);
  if (err < 0) {
    printf("Unable to set period time %i for playback: %s\n", size, snd_strerror(err));
    return err;
  }
  err = snd_pcm_hw_params_get_period_size(params, &size, &dir);
  if (err < 0) {
    printf("Unable to get period size for playback: %s\n", snd_strerror(err));
    return err;
  }
  period_size = size;
  /* write the parameters to device */
  err = snd_pcm_hw_params(handle, params);
  if (err < 0) {
    printf("Unable to set hw params for playback: %s\n", snd_strerror(err));
    return err;
  }
  return 0;
}
static int set_swparams(snd_pcm_t *handle, snd_pcm_sw_params_t *swparams)
{
  int err;
  /* get the current swparams */
  err = snd_pcm_sw_params_current(handle, swparams);
  if (err < 0) {
    printf("Unable to determine current swparams for playback: %s\n", snd_strerror(err));
    return err;
  }
  /* start the transfer when the buffer is almost full: */
  /* (buffer_size / avail_min) * avail_min */
  err = snd_pcm_sw_params_set_start_threshold(handle, swparams, period_size);
  if (err < 0) {
    printf("Unable to set start threshold mode for playback: %s\n", snd_strerror(err));
    return err;
  }

  err = snd_pcm_sw_params_set_stop_threshold(handle, swparams, 0x7fffffff);
  if (err < 0) {
    printf("Unable to set stop threshold mode for playback: %s\n", snd_strerror(err));
    return err;
  }

  /* allow the transfer when at least period_size samples can be processed */
  /* or disable this mechanism when period event is enabled (aka interrupt like style processing) */
  /*err = snd_pcm_sw_params_set_avail_min(handle, swparams, period_event ? buffer_size : period_size);
  if (err < 0) {
    printf("Unable to set avail min for playback: %s\n", snd_strerror(err));
    return err;
  }*/
  /* enable period events when requested */
  /*if (period_event) {
    err = snd_pcm_sw_params_set_period_event(handle, swparams, 1);
    if (err < 0) {
      printf("Unable to set period event: %s\n", snd_strerror(err));
      return err;
    }
  }*/
  /* write the parameters to the playback device */
  err = snd_pcm_sw_params(handle, swparams);
  if (err < 0) {
    printf("Unable to set sw params for playback: %s\n", snd_strerror(err));
    return err;
  }
  return 0;
}
/*
   * Underrun and suspend recovery
   */
static int xrun_recovery(snd_pcm_t *handle, int err)
{
  if (verbose)
    printf("stream recovery\n");
  if (err == -EPIPE) { /* under-run */
    err = snd_pcm_prepare(handle);
    if (err < 0)
      printf("Can't recovery from underrun, prepare failed: %s\n", snd_strerror(err));
    return 0;
  } else if (err == -ESTRPIPE) {
    while ((err = snd_pcm_resume(handle)) == -EAGAIN)
      sleep(1); /* wait until the suspend flag is released */
    if (err < 0) {
      err = snd_pcm_prepare(handle);
      if (err < 0)
        printf("Can't recovery from suspend, prepare failed: %s\n", snd_strerror(err));
    }
    return 0;
  }
  return err;
}
/*
   * Transfer method - write only
   */
static int write_loop(snd_pcm_t *handle,
    signed short *samples,
    snd_pcm_channel_area_t *areas)
{
  double phase = 0;
  signed short *ptr;
  int err;
  unsigned int cptr;
  int ccptr;
  while (1) {
    generate_sine(areas, 0, period_size, &phase);
    ptr = samples;
    cptr = period_size;
    ccptr = period_size;
    while (cptr > 0) 
    {
      err = snd_pcm_writei(handle, ptr, cptr);
      if (err == -EAGAIN)
      {
        usleep(1000);
        continue;
      }
      if (err < 0) 
      {
        printf("calling xrun_recovery\n");
        if (xrun_recovery(handle, err) < 0) 
        {
          printf("Write error: %s\n", snd_strerror(err));
          exit(EXIT_FAILURE);
        }
        else
          continue;
       // break; /* skip one period */
      }
      ptr += err * channels;
      cptr -= err;
      ccptr -= err;
      if(ccptr < 0)
        printf("!!! cptr < 0 !!!\n");
    }
  }
}
/*
   *
   */
struct transfer_method {
  const char *name;
  snd_pcm_access_t access;
  int (*transfer_loop)(snd_pcm_t *handle,
      signed short *samples,
      snd_pcm_channel_area_t *areas);
};
static struct transfer_method transfer_methods[] = {
  { "write", SND_PCM_ACCESS_RW_INTERLEAVED, write_loop },
/*  { "write_and_poll", SND_PCM_ACCESS_RW_INTERLEAVED, write_and_poll_loop },
  { "async", SND_PCM_ACCESS_RW_INTERLEAVED, async_loop },
  { "async_direct", SND_PCM_ACCESS_MMAP_INTERLEAVED, async_direct_loop },
  { "direct_interleaved", SND_PCM_ACCESS_MMAP_INTERLEAVED, direct_loop },
  { "direct_noninterleaved", SND_PCM_ACCESS_MMAP_NONINTERLEAVED, direct_loop },
  { "direct_write", SND_PCM_ACCESS_MMAP_INTERLEAVED, direct_write_loop },*/
  { NULL, SND_PCM_ACCESS_RW_INTERLEAVED, NULL }
};
static void help(void)
{
  int k;
  printf(
      "Usage: pcm [OPTION]... [FILE]...\n"
      "-h,--help help\n"
      "-D,--device playback device\n"
      "-r,--rate stream rate in Hz\n"
      "-c,--channels count of channels in stream\n"
      "-f,--frequency sine wave frequency in Hz\n"
      "-b,--buffer ring buffer size in us\n"
      "-p,--period period size in us\n"
      "-m,--method transfer method\n"
      "-o,--format sample format\n"
      "-v,--verbose show the PCM setup parameters\n"
      "-n,--noresample do not resample\n"
      "-e,--pevent enable poll event after each period\n"
      "\n");
  printf("Recognized sample formats are:");
  for (k = 0; k < SND_PCM_FORMAT_LAST; ++k) {
    const char *s = snd_pcm_format_name(k);
    if (s)
      printf(" %s", s);
  }
  printf("\n");
  printf("Recognized transfer methods are:");
  for (k = 0; transfer_methods[k].name; k++)
    printf(" %s", transfer_methods[k].name);
  printf("\n");
}
int main(int argc, char *argv[])
{
  struct option long_option[] =
  {
    {"help", 0, NULL, 'h'},
    {"device", 1, NULL, 'D'},
    {"rate", 1, NULL, 'r'},
    {"channels", 1, NULL, 'c'},
    {"frequency", 1, NULL, 'f'},
    {"buffer", 1, NULL, 'b'},
    {"period", 1, NULL, 'p'},
    {"method", 1, NULL, 'm'},
    {"format", 1, NULL, 'o'},
    {"verbose", 1, NULL, 'v'},
    {"noresample", 1, NULL, 'n'},
    {"pevent", 1, NULL, 'e'},
    {NULL, 0, NULL, 0},
  };
  snd_pcm_t *handle;
  int err, morehelp;
  snd_pcm_hw_params_t *hwparams;
  snd_pcm_sw_params_t *swparams;
  int method = 0;
  signed short *samples;
  unsigned int chn;
  snd_pcm_channel_area_t *areas;
  snd_pcm_hw_params_alloca(&hwparams);
  snd_pcm_sw_params_alloca(&swparams);
  morehelp = 0;
  while (1) {
    int c;
    if ((c = getopt_long(argc, argv, "hD:r:c:f:b:p:m:o:vne", long_option, NULL)) < 0)
      break;
    switch (c) {
      case 'h':
        morehelp++;
        break;
      case 'D':
        device = strdup(optarg);
        break;
      case 'r':
        rate = atoi(optarg);
        rate = rate < 4000 ? 4000 : rate;
        rate = rate > 196000 ? 196000 : rate;
        break;
      case 'c':
        channels = atoi(optarg);
        channels = channels < 1 ? 1 : channels;
        channels = channels > 1024 ? 1024 : channels;
        break;
      case 'f':
        freq = atoi(optarg);
        freq = freq < 50 ? 50 : freq;
        freq = freq > 5000 ? 5000 : freq;
        break;
      case 'b':
        buffer_time = atoi(optarg);
        buffer_time = buffer_time < 1000 ? 1000 : buffer_time;
        buffer_time = buffer_time > 1000000 ? 1000000 : buffer_time;
        break;
      case 'p':
        period_time = atoi(optarg);
        period_time = period_time < 1000 ? 1000 : period_time;
        period_time = period_time > 1000000 ? 1000000 : period_time;
        break;
      case 'm':
        for (method = 0; transfer_methods[method].name; method++)
          if (!strcasecmp(transfer_methods[method].name, optarg))
            break;
        if (transfer_methods[method].name == NULL)
          method = 0;
        break;
      case 'o':
        for (format = 0; format < SND_PCM_FORMAT_LAST; format++) {
          const char *format_name = snd_pcm_format_name(format);
          if (format_name)
            if (!strcasecmp(format_name, optarg))
              break;
        }
        if (format == SND_PCM_FORMAT_LAST)
          format = SND_PCM_FORMAT_S16;
        if (!snd_pcm_format_linear(format) &&
            !(format == SND_PCM_FORMAT_FLOAT_LE ||
              format == SND_PCM_FORMAT_FLOAT_BE)) {
          printf("Invalid (non-linear/float) format %s\n",
              optarg);
          return 1;
        }
        break;
      case 'v':
        verbose = 1;
        break;
      case 'n':
        resample = 0;
        break;
      case 'e':
        period_event = 1;
        break;
    }
  }
  if (morehelp) {
    help();
    return 0;
  }
  err = snd_output_stdio_attach(&output, stdout, 0);
  if (err < 0) {
    printf("Output failed: %s\n", snd_strerror(err));
    return 0;
  }
  printf("Playback device is %s\n", device);
  printf("Stream parameters are %iHz, %s, %i channels\n", rate, snd_pcm_format_name(format), channels);
  printf("Sine wave rate is %.4fHz\n", freq);
  printf("Using transfer method: %s\n", transfer_methods[method].name);
  if ((err = snd_pcm_open(&handle, device, SND_PCM_STREAM_PLAYBACK, 0)) < 0) {
    printf("Playback open error: %s\n", snd_strerror(err));
    return 0;
  }
  if ((err = set_hwparams(handle, hwparams, transfer_methods[method].access)) < 0) {
    printf("Setting of hwparams failed: %s\n", snd_strerror(err));
    exit(EXIT_FAILURE);
  }
  if ((err = set_swparams(handle, swparams)) < 0) {
    printf("Setting of swparams failed: %s\n", snd_strerror(err));
    exit(EXIT_FAILURE);
  }
  if (verbose > 0)
    snd_pcm_dump(handle, output);
  samples = malloc((period_size * channels * snd_pcm_format_physical_width(format)) / 8);
  if (samples == NULL) {
    printf("No enough memory\n");
    exit(EXIT_FAILURE);
  }
  areas = calloc(channels, sizeof(snd_pcm_channel_area_t));
  if (areas == NULL) {
    printf("No enough memory\n");
    exit(EXIT_FAILURE);
  }
  for (chn = 0; chn < channels; chn++) {
    areas[chn].addr = samples;
    areas[chn].first = chn * snd_pcm_format_physical_width(format);
    areas[chn].step = channels * snd_pcm_format_physical_width(format);
  }
  err = transfer_methods[method].transfer_loop(handle, samples, areas);
  if (err < 0)
    printf("Transfer failed: %s\n", snd_strerror(err));
  free(areas);
  free(samples);
  snd_pcm_close(handle);
  return 0;
}

[-- Attachment #3: Type: text/plain, Size: 0 bytes --]

Re: Need Help: Repeated Jackhammer noise after several hours of play and heavy cpu usage in snd_pcm_dmix_sync_area

[Gabriel M. Beddingfield]

Hi Adarsh,

On 02/19/2014 04:07 AM, Adarsh wrote:
> Hi,
>
> We are facing a issue where if gdb is attached to the our long running
> sound process and continued,
> jackhammer sound is played over and over again abusing the speakers.
>
> Process details:
> 1. We are using RW_INTERLEAVED access as described in write_loop method in
> /test/pcm.c and opening 'default' device.
> 2. However to disable the underruns, the
> snd_pcm_sw_params_set_stop_threshold is set to 0x7fffffff which is greater
> than boundary
> value.

This doesn't prevent underruns. Underruns happen when the software 
doesn't keep up with the hardware.

What this disables is your ability to detect and recover from an 
underrun. So, what you're experiencing is expected behavior.  If you 
never reach the stop threshold but userspace fails to write new audio to 
the buffer.  Since you instructed the driver/hardware to *not* stop in 
the event of an underrun, it repeatedly cycles on the same, stale 
buffer. This gives you the "jackhammer" sound.

> 3.Period size is 1024 and buffer size is 2048. We try to write period_size
> no of frames using snd_pcm_writei.
> (I am attaching a sample program which shows this behaviour.)
>
> Steps to Reproduce:
> 1. Left process running for over 12 hours.
> 2. gdb is attached to the process and continued inside gdb.

When gdb attached to the process, you certainly stopped writing new 
audio to the buffer because your process got a SIGSTOP... causing all 
threads to freeze.

> 3. At this point, the thread went into a tight loop taking >100% cpu and
> repeatedly playing same sound. It did not recover for a long time.

...I'm not sure what you're seeing here.  Possibly dmix is trying to 
make the best of a bad situation.

> Is it that setting of stop threshold to 0x7fffffff is triggering this and
> attaching gdb is making the buffer pointers misbehave?
> If so, what can be done if we do not want PCM to stop? I have tried by
> setting silence threshold and silence size to let alsa
> play silence by itself but still observed the issue.

It depends on what you're trying to solve by attaching with gdb.

GDB is good for a lot of things, but solving problems in real-time 
systems (like audio) has never been one of them. So, chances are that 
gdb is the wrong tool for what you're trying to do.

-gabe

Re: Need Help: Repeated Jackhammer noise after several hours of play and heavy cpu usage in snd_pcm_dmix_sync_area

[Clemens Ladisch]

Adarsh wrote:
> 2. However to disable the underruns, the
> snd_pcm_sw_params_set_stop_threshold is set to 0x7fffffff

This does not disable underruns; it just disables stopping the device
when an underrun happens.

> which is greater than boundary value.

Guess what happens on a 64-bit machine.

> 3.Period size is 1024 and buffer size is 2048.

Do you actually need that low a latency?

> 2. gdb is attached to the process and continued inside gdb.

This will result in an underrun.

When an underrun happens, the buffer is reported to contain less than
zero frames (i.e., the "avail" value is larger than the buffer size).

The program has to write samples _faster_ than normally to catch up.
Alternately, it could advance the pointer by calling snd_pcm_forward
(which might be a better idea because those samples won't be played
at the correct time anyway.)

You should reconsider setting the stop threshold.

> 3. At this point, the thread went into a tight loop taking >100% cpu

This is probably because of all the 'catch-up' samples that are being
mixed.

> Stack trace shows that 'snd_pcm_dmix_sync_area' in pcm_dmix.c is taking a
> very long time to return because the 'size' is
> a large unsinged interger and mix_areas is getting called with 'transfer'
> value of <=2048.

Hmmm, this might be a bug in the dmix plugin.


Regards,
Clemens

Re: Need Help: Repeated Jackhammer noise after several hours of play and heavy cpu usage in snd_pcm_dmix_sync_area

[Adarsh]

Hi Gabe and Clemens, Thanks for your replies.
There is still some confusion about why alsa is behaving in this manner.

> GDB is good for a lot of things, but solving problems in real-time systems (like audio) has never been one of them. So, chances are that gdb is the wrong tool for what you're trying to do.
A brief background:
Yes, you are right, gdb is not the proper tool. We are trying to solve
random jackhammer issue happening on some production systems. One way
to reproduce this is thread starvation for cpu which we are inducing
by either SIGSTOP/SIGCONT or gdb or lowering
the priority of sound thread.

> This is probably because of all the 'catch-up' samples that are being mixed.
What we have observed is that when the process is freshly started and
has not run for significant amount of time,
sending SIGSTOP/SIGCONT to sound process properly stops and resumes sound.

However when run for over 12 hours, any starvation or stopping of
sound thread sends dmix into a tight loop inside
'snd_pcm_dmix_sync_area' function of pcm_dmix.c. Dmix calculates the
'size' that needs to be transferred to be a huge
value.

Here is the piece of code from snd_pcm_dmix_sync_area that starts the
size calculations:

  /* calculate the size to transfer */
  /* check the available size in the local buffer
   * last_appl_ptr keeps the last updated position
   */
  size = dmix->appl_ptr - dmix->last_appl_ptr;
  if (! size)
    return;
  if (size >= pcm->boundary / 2)
    size = pcm->boundary - size;
    .
    .
    .
When the issue happens value of dmix->last_appl_ptr is greater than
dmix->appl_ptr and subsequent calcualtion of
size turns out to be very large number probably because of wrap around
behavior of unsigned arithmetic.
A typical case is:
dmix->appl_ptr = 217121792, dmix->last_appl_ptr = 233882624
size = 1018295296
This causes 'mix_areas' to be called repeatedly until this size is exhausted.

When process is running for shorter duration, dmix->appl_ptr is always
bigger than dmix->last_appl_ptr.
For eg. dmix->appl_ptr = 26124288, dmix->last_appl_ptr = 26123264

The software boundary is 1 GB.

> Hmmm, this might be a bug in the dmix plugin.
So, is it possible that the buffer wrap around could cause the
pointer/size miscalcualtions inside dmix?
Is it expected to have dmix->last_appl_ptr greater than
dmix->appl_ptr? If so, why the issue seen only when
the thread is stopped.

Please suggest. Thanks.
Adarsh


On Thu, Feb 20, 2014 at 3:27 PM, Clemens Ladisch <clemens@ladisch.de> wrote:
> Adarsh wrote:
>> 2. However to disable the underruns, the
>> snd_pcm_sw_params_set_stop_threshold is set to 0x7fffffff
>
> This does not disable underruns; it just disables stopping the device
> when an underrun happens.
>
>> which is greater than boundary value.
>
> Guess what happens on a 64-bit machine.
>
>> 3.Period size is 1024 and buffer size is 2048.
>
> Do you actually need that low a latency?
>
>> 2. gdb is attached to the process and continued inside gdb.
>
> This will result in an underrun.
>
> When an underrun happens, the buffer is reported to contain less than
> zero frames (i.e., the "avail" value is larger than the buffer size).
>
> The program has to write samples _faster_ than normally to catch up.
> Alternately, it could advance the pointer by calling snd_pcm_forward
> (which might be a better idea because those samples won't be played
> at the correct time anyway.)
>
> You should reconsider setting the stop threshold.
>
>> 3. At this point, the thread went into a tight loop taking >100% cpu
>
> This is probably because of all the 'catch-up' samples that are being
> mixed.
>
>> Stack trace shows that 'snd_pcm_dmix_sync_area' in pcm_dmix.c is taking a
>> very long time to return because the 'size' is
>> a large unsinged interger and mix_areas is getting called with 'transfer'
>> value of <=2048.
>
> Hmmm, this might be a bug in the dmix plugin.
>
>
> Regards,
> Clemens