[Bug 785937] alsasrc timestamps is sensitive to context switches.

[GStreamer (GNOME Bugzilla)]

https://bugzilla.gnome.org/show_bug.cgi?id=785937

--- Comment #8 from Göran Jönsson <goran.jonsson at axis.com> ---
Hi,

When you write "I think this is quite error prone" , I assume you mean my
analyze and fix. I also aware that the code I complain about is around 5 
years old according to git blame. So I am understanding your concerns. 

So I suggest we take first thing first and I will try
to convince you, that the current implementation have problems.  
Then after that I am more then willing to discuss another solutions. 

Previously I showed with my Ftrace that snd_pcm_readi and 
snd_pcm_status_get_state
is updating the tstamp .

If you now with that knowlage take a look at the code in gstalsasrc.c
functions gst_alsasrc_read and gst_alsasrc_get_timestamp and imagine that
a context-switch occur as in example below. Let say the thread don't
execute for 10 ms . 


gst_alsasrc_get_timestamp (GstAlsaSrc * asrc)
{
  snd_pcm_status_t *status;
  snd_htimestamp_t audiostamp;
  GstClockTime timestamp;
  snd_pcm_uframes_t avail;
  gint err = -EPIPE;

  if (G_UNLIKELY (!asrc)) {
    GST_ERROR_OBJECT (asrc, "No alsa handle created yet !");
    return GST_CLOCK_TIME_NONE;
  }

  if (G_UNLIKELY (snd_pcm_status_malloc (&status) != 0)) {
    GST_ERROR_OBJECT (asrc, "snd_pcm_status_malloc failed");
    return GST_CLOCK_TIME_NONE;
  }

  <---- context switch ------->

  if (G_UNLIKELY (snd_pcm_status (asrc->handle, status) != 0)) {
    GST_ERROR_OBJECT (asrc, "snd_pcm_status failed");
    return GST_CLOCK_TIME_NONE;
  }


Will the timestamp be affected by the context switch ?
Answer: Yes and that is the problem .

This part is also worth  looking at.

  /* max available frames sets the depth of the buffer */
  avail = snd_pcm_status_get_avail (status);

  /* calculate the timestamp of the next sample to be read */
  timestamp -= gst_util_uint64_scale_int (avail, GST_SECOND, asrc->rate);


Hier there are some handling that are compensate for long time context switch.
avail will be zero if the context switch is smaller than the time between two
IRQs . In the case I am investigate we have configured is so each packet 
represent 64ms audio. This mean that the timestamp can be 63.999,,, ms 
wrong in worst case .

I have also done some more instrumentation to simulate context-switchar

static gint test = 0;

gst_alsasrc_get_timestamp (GstAlsaSrc * asrc)
{
  snd_pcm_status_t *status;
  snd_htimestamp_t audiostamp;
  GstClockTime timestamp;
  snd_pcm_uframes_t avail;
  gint err = -EPIPE;

  if (G_UNLIKELY (!asrc)) {
    GST_ERROR_OBJECT (asrc, "No alsa handle created yet !");
    return GST_CLOCK_TIME_NONE;
  }

  if (G_UNLIKELY (snd_pcm_status_malloc (&status) != 0)) {
    GST_ERROR_OBJECT (asrc, "snd_pcm_status_malloc failed");
    return GST_CLOCK_TIME_NONE;
  }

  /* Simulate contex-switch */
  test++;
  if ((test%5) == 0) {
    GST_ERROR("Hello Simulated context-switch");
    g_usleep(50000); 
  }  


  if (G_UNLIKELY (snd_pcm_status (asrc->handle, status) != 0)) {
    GST_ERROR_OBJECT (asrc, "snd_pcm_status failed");
    return GST_CLOCK_TIME_NONE;
  }

,,,,

  avail = snd_pcm_status_get_avail (status);

  GST_ERROR("Hello avail %d",avail);

,,,,

  GST_ERROR_OBJECT (asrc, "ALSA timestamp : %" GST_TIME_FORMAT
      ", delay %lu", GST_TIME_ARGS (timestamp), avail);


Please find part of log attached timestamps.txt
In this log you can see that the timestamps after the 
"Hello Simulated context-switch" print are affected .
Normallt there are around 64ms between timestamps but after that simulated 
contex-switch the delta is much higher.

Do you agree on that current implementation have problems ?

-- 
You are receiving this mail because:
You are the QA Contact for the bug.
You are the assignee for the bug.