Choppy audio with cefsrc @ 60fps and infinite queue

[vivia]

gst-launch-1.0 cefsrc url=https://ahiru.eu/~vivia/barsandtones.mp4 ! cefdemux name=d d.video ! queue max-size-time=0 max-size-bytes=0 max-size-buffers=0 ! video/x-raw,width=1920,height=1080,framerate=60/1 ! videoconvert ! queue ! autovideosink d.audio ! queue ! audioconvert ! queue ! autoaudiosink

Reproduced on both main and 1.26.9

[MathieuDuponchelle]

playback of the mp4 doesn't start for me, are you perhaps passing autoplay flags? you should also use an audiomixer force-live=true on the audio path I think :)

[vivia]

Should be reproducible with any source URL as long as it can autoplay, in fact I first reproduced it with something else and had to create my own file instead, because everything else I could find online required me to accept cookies first. And the issue persists after injecting audiomixer force-live=true on the audio path.

[MathieuDuponchelle]

It's strange, won't autoplay on my end, are you using main of this repository?

[vivia]

Oh right, we have a build with H264 enabled. Just reproduced with master of this repository, GStreamer main as of a couple of days ago, and VP8/webm instead of H264/MP4.

gst-launch-1.0 cefsrc url=https://ahiru.eu/~vivia/barsandtones.webm ! cefdemux name=d d.video ! queue max-size-time=0 max-size-bytes=0 max-size-buffers=0 ! video/x-raw,width=1920,height=1080,framerate=60/1 ! videoconvert ! queue ! autovideosink d.audio ! queue ! audiomixer force-live=true ! queue ! autoaudiosink

basically s/mp4/webm/ from the previous pipeline, and audiomixer force-live=true instead of audioconvert.

[MathieuDuponchelle]

ah gotcha, I'll test this now :)

[MathieuDuponchelle]

indeed sounds like morse code :D

[vivia]

Now try making that queue default instead of infinite 😅 It's not the queue size BTW, I've found other random downstream things that sometimes make it work but then the whole thing collapses if you breathe next to it, it seems to be some weird race condition that depends on what's downstream on each path and the queue size seems to be a red herring.

[MathieuDuponchelle]

@vivia just comment out the setting of PTS on the audio buffers in demux and you should get better output. I don't really remember the logic behind this code, but that also seems related to what @aiden-jeffrey was interested in, we should try and figure out how to use the timestamps provided by cef somehow :)

[aiden-jeffrey]

I think we need to do something like this. I still need to debug it, but pushing it up so it's available to comment on.

[MathieuDuponchelle]

@aiden-jeffrey ooc does your patch in its present state address the issue @vivia reported?

[aiden-jeffrey]

@aiden-jeffrey ooc does your patch in its present state address the issue?

No, currently it makes things worse. If you log out the audio PTSs you were writing out before though the dt between them fluctuates +/- 20ms either side of the 23ms you'd expect. With my change the dt between the buffers is constant.

[aiden-jeffrey]

Ok. Got it working (I needed to add a bit of latency to the pts values provided by CEF), #104 does indeed fix this issue.

[vivia]

It works in gst-launch but something is still wrong in my application. Looking at it currently.

[vivia]

This is an attempt at getting correct timestamps

diff --git a/gstcefdemux.cc b/gstcefdemux.cc
index b4ff8b8..399af26 100644
--- a/gstcefdemux.cc
+++ b/gstcefdemux.cc
@@ -144,9 +144,7 @@ gst_element_get_current_running_time (GstElement * element)
 static gboolean
 gst_cef_demux_push_audio_buffer (GstBuffer **buffer, guint idx, AudioPushData *push_data)
 {
-  push_data->demux->last_audio_time = gst_element_get_current_running_time (GST_ELEMENT_CAST (push_data->demux));
-  GST_BUFFER_DTS (*buffer) = push_data->demux->last_audio_time;
-  GST_BUFFER_PTS (*buffer) = push_data->demux->last_audio_time;
+  push_data->demux->last_audio_time = GST_BUFFER_PTS (*buffer);
 
   GST_BUFFER_FLAG_UNSET (*buffer, GST_BUFFER_FLAG_DISCONT);
   if (push_data->demux->need_discont) {
diff --git a/gstcefsrc.cc b/gstcefsrc.cc
index 5440f96..d19303a 100644
--- a/gstcefsrc.cc
+++ b/gstcefsrc.cc
@@ -263,6 +263,21 @@ class RenderHandler : public CefRenderHandler
       new_buffer = gst_buffer_new_allocate (NULL, src->vinfo.width * src->vinfo.height * 4, NULL);
       gst_buffer_fill (new_buffer, 0, buffer, w * h * 4);
 
+      GstClock *clock = gst_element_get_clock (GST_ELEMENT (src));
+      GstClockTime base_time = gst_element_get_base_time (GST_ELEMENT (src));
+      GstClockTime now_gst = gst_clock_get_time (clock);
+      GstClockTime gst_pts;
+
+      if (now_gst > base_time)
+        gst_pts = now_gst - base_time;
+      else
+        gst_pts = 0;
+      gst_object_unref (clock);
+
+      GST_BUFFER_PTS (new_buffer) = gst_pts;
+      GST_ERROR ("@@@@@@ video pts %lu", gst_pts);
+      // FIXME: this is temporary until we have the queue in place
+      GST_BUFFER_DURATION (new_buffer) = gst_util_uint64_scale (GST_SECOND, src->vinfo.fps_d, src->vinfo.fps_n);
       GST_OBJECT_LOCK (src);
       gst_buffer_replace (&(src->current_buffer), new_buffer);
       gst_buffer_unref (new_buffer);
@@ -330,8 +345,39 @@ class AudioHandler : public CefAudioHandler
         memcpy (info.data + j * 4 * mChannels + i * 4, &cdata[j], 4);
       }
     }
+
+    //@@@
     gst_buffer_unmap (buf, &info);
 
+    GstClock *clock = gst_element_get_clock (GST_ELEMENT (src));
+    GstClockTime base_time = gst_element_get_base_time (GST_ELEMENT (src));
+    GstClockTime now_unix = g_get_real_time () * 1000; // nsec
+    GstClockTime now_gst = gst_clock_get_time (clock);
+    GstClockTime capture_unix = pts * 1000000; // pts is in msec
+    GstClockTime capture_gst;
+
+    if (capture_unix > now_unix) {
+      GstClockTime diff = capture_unix - now_unix;
+      capture_gst = now_gst + diff;
+      GST_ERROR ("@@@@@@@@@@@@@ diff %lu", diff);
+    } else {
+      GstClockTime diff = now_unix - capture_unix;
+      if (now_gst > diff)
+        capture_gst = now_gst - diff;
+      else
+        capture_gst = 0;
+      GST_ERROR ("@@@@@@@@@@@@@ diff -%lu", diff);
+    }
+    GstClockTime gst_pts;
+    if (capture_gst > base_time)
+      gst_pts = capture_gst - base_time;
+    else
+      gst_pts = 0;
+    gst_object_unref (clock);
+
+    GST_BUFFER_PTS (buf) = gst_pts;
+    GST_ERROR ("@@@@@@ audio pts %lu", gst_pts);
+
     GST_OBJECT_LOCK (src);
 
     GST_BUFFER_DURATION (buf) = gst_util_uint64_scale (frames, GST_SECOND, mRate);
@@ -661,6 +707,7 @@ static GstFlowReturn gst_cef_src_create(GstPushSrc *push_src, GstBuffer **buf)
 
   GST_OBJECT_LOCK (src);
 
+  // FIXME: do not push events downstream while holding object lock!
   if (src->audio_events) {
     for (tmp = src->audio_events; tmp; tmp = tmp->next) {
       gst_pad_push_event (GST_BASE_SRC_PAD (src), (GstEvent *) tmp->data);
@@ -670,6 +717,9 @@ static GstFlowReturn gst_cef_src_create(GstPushSrc *push_src, GstBuffer **buf)
     src->audio_events = NULL;
   }
 
+  // FIXME: this should use a queue and a condition variable, whenever a new
+  // video frame is available this should be woken up and then you take a
+  // frame out of the queue
   g_assert (src->current_buffer);
   *buf = gst_buffer_copy (src->current_buffer);
 
@@ -677,9 +727,6 @@ static GstFlowReturn gst_cef_src_create(GstPushSrc *push_src, GstBuffer **buf)
     gst_buffer_add_cef_audio_meta (*buf, src->audio_buffers);
     src->audio_buffers = NULL;
   }
-
-  GST_BUFFER_PTS (*buf) = gst_util_uint64_scale (src->n_frames, src->vinfo.fps_d * GST_SECOND, src->vinfo.fps_n);
-  GST_BUFFER_DURATION (*buf) = gst_util_uint64_scale (GST_SECOND, src->vinfo.fps_d, src->vinfo.fps_n);
   src->n_frames++;
   GST_OBJECT_UNLOCK (src);
 
@@ -999,6 +1046,7 @@ gst_cef_src_stop (GstBaseSrc *base_src)
   return TRUE;
 }
 
+// FIXME: when the queue is added this should not exist
 static void
 gst_cef_src_get_times (GstBaseSrc * base_src, GstBuffer * buffer,
     GstClockTime * start, GstClockTime * end)
@@ -1025,8 +1073,9 @@ gst_cef_src_query (GstBaseSrc * base_src, GstQuery * query)
 
       if (src->vinfo.fps_n) {
         latency = gst_util_uint64_scale (GST_SECOND, src->vinfo.fps_d, src->vinfo.fps_n);
+        // FIXME: just wrong
         GST_DEBUG_OBJECT (src, "Reporting latency: %" GST_TIME_FORMAT, GST_TIME_ARGS (latency));
-        gst_query_set_latency (query, TRUE, latency, GST_CLOCK_TIME_NONE);
+        gst_query_set_latency (query, TRUE, 2 * latency, GST_CLOCK_TIME_NONE);
       }
       res = TRUE;
       break;
@@ -1075,7 +1124,10 @@ gst_cef_src_set_caps (GstBaseSrc * base_src, GstCaps * caps)
   GST_OBJECT_LOCK (src);
   gst_video_info_from_caps (&src->vinfo, caps);
   if (src->vinfo.width != src->width || src->vinfo.height != src->height) {
+    // FIXME: this is not necessary once we have the queue
     new_buffer = gst_buffer_new_allocate (NULL, src->vinfo.width * src->vinfo.height * 4, NULL);
+    GST_BUFFER_PTS (new_buffer) = 0;
+    GST_BUFFER_DURATION (new_buffer) = 0;
     gst_buffer_replace (&(src->current_buffer), new_buffer);
     gst_buffer_unref (new_buffer);
   }

[aiden-jeffrey]

@vivia - unless I've introduced a typo somewhere, I don't think your diff actually fixes this specific issue. Please test and confirm. For now I will take the video buffer pts stuff from your diff into my PR.