Open pyldin601 opened 2 years ago
pyldin601
commented
2 years ago It is also reproducible when I run example pipeline from README.md - Record website video + audio (with audiomixer). Just need to run some CPU heavy task in the background to trigger lags. After some time of lagging, it hangs forever.
MathieuDuponchelle
commented
2 years ago Both pipelines work with no issue on my end (gst main). What version of GStreamer are you using? Have you tried removing either audio or video ?
pyldin601
commented
2 years ago GStreamer 1.20.2 (GIT)
It is reproducible when cefbin starts dropping audio or video data due to CPU overload.
I've tried to remove audio/video tracks from muxer and also tried to remove cef.audio pad from audiomixer leaving only silence. In both cases, the issue was not reproducible. The only thing, that helped to make my pipeline with audio and video not hanging on overload is to make the queue between cef.audio and audiomixer leaky.
reinismu
commented
2 years ago Just a guess, but did you monitor memory usage? Maybe the queue feels up and the operating system starts to swap memory?
MathieuDuponchelle
commented
2 years ago Why would cefbin drop data?
pyldin601
commented
2 years ago Just a guess, but did you monitor memory usage? Maybe the queue feels up and the operating system starts to swap memory?
Yes, I can confirm that this happens when I have high CPU/memory usage. This causes the cefbin to start lagging. But at some point of time the pipeline completely stuck and never continues to play the pipeline. Even if CPU starts idling.
Why would cefbin drop data?
Sorry, I meant it starts lagging. But after a few seconds of lagging, the pipeline completely hangs.
Just a guess, can the "lagging" of audio/video pads on cefbin causing some pts desync on both pads?
hevc
commented
2 years ago Hi, I observe the same issue. When CPU usage is high then CEF starts producing bad audio PTS. Once the CPU usage stabilizes the audio never returns to normal. Record files then have erroneous audio. This manifests itself through very high crackling and distortion of the sound. The video looks fine. Recordings last ~1h or longer.
Moreover sometimes during low CPU usage I observe short audio crackles.
Maybe PTS calculation is wrong when gst buffer are created? Perhaps there is a PTS drift?
How to reproduce:
GST_DEBUG=3 gst-launch-1.0 -e mpegtsmux name=mux ! filesink location=test.ts cefbin name=cef cefsrc::url="https://www.youtube.com/embed/lEk1riUEdCQ?playlist=lEk1riUEdCQ&autoplay=1&loop=1" cefsrc::gpu=false cef.video ! videoconvert ! video/x-raw,framerate=30/1,format=I420 ! queue ! x264enc tune=zerolatency speed-preset=ultrafast ! h264parse ! queue ! mux. cef.audio ! queue ! audioconvert ! audiomixer ! queue ! fdkaacenc ! aacparse ! queue ! mux. after ~10 seconds it hangs.
With vbox 4 cpu pipeline works longer but the video is bad. CPU/ Mem:
Converted with ffmpeg -i test.ts -c copy out.mp4:
philn
commented
2 years ago In OnAudioStreamPacket() the pts from CEF is actually not used. We compute one based on the initial video framerate, incremented by audio packet duration afterwards. I wonder why?
philn
commented
2 years ago I experimented a bit in this branch, maybe some folks would like to give feedback! https://github.com/philn/gstcefsrc/tree/audio-things
hevc
commented
2 years ago I tested your branch. It brings a change from the previous behavior. Audio does not drift as before (however, it needs more testing). I have attached two files for comparison: "out_new.mp4" is with the latest changes. I tested on virtualbox with 2 cpu 2.5 GHz to show the problem faster.
With the new changes you can clearly hear crackling in the audio stream. Sometimes I also heard modulations of the sound.
hevc
commented
2 years ago Maybe I'm wrong, but it looks like the audio is synchronized to the video, and it should be the other way around. Maybe the audio PTS from CEF needs to be set as the video PTS.
MathieuDuponchelle
commented
2 years ago https://bitbucket.org/chromiumembedded/cef/issues/2995/audio-capture-susceptible-to-packet-loss#comment-59277083 sounds (hah) extremely related
MathieuDuponchelle
commented
2 years ago In
OnAudioStreamPacket()the pts from CEF is actually not used. We compute one based on the initial video framerate, incremented by audio packet duration afterwards. I wonder why?
I don't remember to be honest, but design wise my approach was: attach whatever audio was produced since the last video frame was produced, and assume CEF provides us with live, synchronized audio and video data.
hevc
commented
2 years ago I think the changes made by @philn improve a lot. The most important improvement is that using audio PTS from CEF allows the audio to fix itself after a heavy CPU load. The previous implementation had no way to fix itself.
I suggest that these changes should be merged.
MathieuDuponchelle
commented
2 years ago I think the patch makes sense too, but I would like to test too if you don't mind, using virtualbox is a nice trick thanks @hevc :) @pldin601 can you please try Phil's patch on your end?
I've added this to my TODO list in any case :)
pyldin601
commented
2 years ago @pldin601 can you please try Phil's patch on your end?
Yep, going to check.
UPD. It worked much better! I heard small cracks when CPU usage was intensive, but the sound seems to be recovered rapidly. One thing I noticed - when the first audio track has ended, the next one started very quickly, and it looked like the first second of audio was played instantly.
https://drive.google.com/file/d/1V_rjj8VyP0bqgX-jRdWdMfINXDwyWpjB/view?usp=sharing
Rewind to 06:00 to hear this. Maybe that happened because there was a time gap between first and next audio tracks, but pts logic assumes that audio plays endlessly?
UPD2. Tested again my pipeline with the same test. Still freezing at random time when I compile smthng in the background...
philn
commented
2 years ago I've got a new patch in https://github.com/centricular/gstcefsrc/pull/60 -- testing welcome ;)
hevc
commented
2 years ago Audio crackles can still occur in recordings. Look at ~7s. Tested on 4x2.5 GHz.
philn
commented
2 years ago Might be another bug.
MathieuDuponchelle
commented
2 years ago I imagine that's exactly what https://bitbucket.org/chromiumembedded/cef/issues/2995/audio-capture-susceptible-to-packet-loss#comment-59277083 is referring to. To be honest, I'm completely happy with a patch that causes us to not deadlock in these situations, if audio crackles do occur and are caused by CEF, I would conclude that:
1) CEF / chrome should be fixed (would be nice to know if Sean did open an issue with his proposed fix) 2) The user always has the option to run on a machine that is not CPU bound :)
@pldin601 can you test the updated version for freezes ?
reinismu
commented
2 years ago From what I can see the chrome issue is fixed https://chromium.googlesource.com/chromium/src/+/5b5632260b8fb40a07b350bb5a6b4e21b6bfda2e%5E%21/#F1 year and a half ago.
Assuming that we use 103.0.5060.114. It does contain those changes https://chromium.googlesource.com/chromium/src/+/refs/tags/103.0.5060.114/services/audio/owning_audio_manager_accessor.cc#123
I wonder if we should test audio crackling in isolation. (Only chrome, cef) Would help to point out where issue comes from
pyldin601
commented
2 years ago @MathieuDuponchelle Just tested with latest @philn patch. No freezes so far. Tested a few times. Will test in application for audio cracks soon...
MathieuDuponchelle
commented
2 years ago Thanks a lot for checking @reinismu :) Testing in isolation would be useful yes, for instance using the cef client example, I wonder if it was updated to also output audio.
@pldin601 that sounds like good news, were you able to reproduce reliably without the patch? If so, then I'm OK with getting the patch in, we can still keep tracking the exact source of the crackles after that.
Everyone OK with this?
hevc
commented
2 years ago @MathieuDuponchelle The cpu looked like this when the audio crackles occurred:
2.5 GHz is typical for virtual machines.
MathieuDuponchelle
commented
2 years ago @hevc that's good to know, can you try with the sample CEF application?
pyldin601
commented
2 years ago @pldin601 that sounds like good news, were you able to reproduce reliably without the patch? If so, then I'm OK with getting the patch in, we can still keep tracking the exact source of the crackles after that.
After a few more retries and after tune of CPU limits, I still able to reproduce the freeze. :(
Here is another backtrace of the process when it freezes: gdb.txt
Are we sure that those freezes are related to the cefsrc behavior or maybe it's matroska muxer bug? Why when I add "leaky" parameter to the queue it stops freezing?
UPD: Probably, I found the reason why freezes are happening.
0:00:17.459932841 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:1345:gst_collect_pads_check_collected:<collectpads0> All active pads (2 + 0 >= 2) have data, calling 0xffff72503b28
0:00:17.459937466 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:956:gst_collect_pads_peek:<collectpads0> Peeking at pad muxer:audio_0: buffer=buffer: 0xffff500136c0, pts 0:00:09.210000000, dts 99:99:99.999999999, dur 0:00:00.010000000, size 882, offset 406161, offset_end 406602, flags 0x800
0:00:17.459942591 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:956:gst_collect_pads_peek:<collectpads0> Peeking at pad muxer:video_0: buffer=buffer: 0xfffeec00d5a0, pts 0:00:09.200508583, dts 99:99:99.999999999, dur 0:00:00.033333333, size 8294400, offset none, offset_end none, flags 0x0
0:00:17.459946841 1145 0xaaab25551760 LOG collectpads gstcollectpads.c:1573:gst_collect_pads_default_compare_func:<collectpads0> comparing 0:00:09.200508583 and 0:00:09.210000000
0:00:17.459950258 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:1481:gst_collect_pads_find_best_pad:<collectpads0> best pad video_0, best time 0:00:09.200508583
0:00:17.459954300 1145 0xaaab25551760 LOG collectpads gstcollectpads.c:1573:gst_collect_pads_default_compare_func:<collectpads0> comparing 0:00:09.210000000 and 0:00:09.200508583
0:00:17.459957425 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:1220:gst_collect_pads_set_waiting:<collectpads0> Setting pad audio_0 to waiting 0, locked 1
0:00:17.459961675 1145 0xaaab25551760 LOG collectpads gstcollectpads.c:1573:gst_collect_pads_default_compare_func:<collectpads0> comparing 0:00:09.200508583 and 0:00:09.200508583
0:00:17.459964633 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:1220:gst_collect_pads_set_waiting:<collectpads0> Setting pad video_0 to waiting 1, locked 1
0:00:17.459968966 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:995:gst_collect_pads_pop:<collectpads0> Pop buffer on pad muxer:video_0: buffer=buffer: 0xfffeec00d5a0, pts 0:00:09.200508583, dts 99:99:99.999999999, dur 0:00:00.033333333, size 8294400, offset none, offset_end none, flags 0x0
>>>0:00:17.459988966 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:956:gst_collect_pads_peek:<collectpads0> Peeking at pad muxer:audio_0: buffer=buffer: 0xffff500136c0, pts 0:00:09.210000000, dts 99:99:99.999999999, dur 0:00:00.010000000, size 882, offset 406161, offset_end 406602, flags 0x800<<<
0:00:17.459992883 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:956:gst_collect_pads_peek:<collectpads0> Peeking at pad muxer:video_0: buffer=(NULL)
0:00:17.459996175 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:1481:gst_collect_pads_find_best_pad:<collectpads0> best pad audio_0, best time 0:00:09.210000000
0:00:17.459999925 1145 0xaaab25551760 LOG collectpads gstcollectpads.c:1573:gst_collect_pads_default_compare_func:<collectpads0> comparing 0:00:09.210000000 and 0:00:09.210000000
0:00:17.460003841 1145 0xaaab25551760 LOG collectpads gstcollectpads.c:1573:gst_collect_pads_default_compare_func:<collectpads0> comparing 0:00:09.200508583 and 0:00:09.210000000
0:00:17.460007758 1145 0xaaab25551760 DEBUG collectpads gstcollectpads.c:2235:gst_collect_pads_chain:<collectpads0> Pad muxer:audio_0 has a buffer queued, waiting
0:00:17.460028550 1145 0xaaab255514c0 DEBUG collectpads gstcollectpads.c:2247:gst_collect_pads_chain:<collectpads0> Pad muxer:video_0 resumingMaybe i'm wrong, but it looks like it happens because matroskamuxer awaits for a video buffer to arrive to muxer:video_0 to align it with the audio buffer that was peeked on muxer:audio_0 pad. This video buffer will never come from cef.video pad because cef element was completely blocked because audio buffers queue is full. So, pipeline has a lot of audio data, the muxer blocks pipeline on waiting for video buffer and also cef blocks pipeline on waiting for audio data to be consumed.
Probably, this happens because of audio mixer element. It produces "silence" even if cef element is lagging and this causes audio queues to overrun. That explains, why the leaky property helps. It drops audio data coming from cef when audiomixer not able to consume it in time.
MathieuDuponchelle
commented
2 years ago @pldin601 this is surprising, why is the audio queue going full in the first place? cefsrc should be producing video buffers on a tight schedule, as even if CEF doesn't provide it with a new frame, the old one will be reused and pushed out. We also don't even have to receive a first frame from CEF, as we zero-initialize a default first frame. cefsrc reports a fps_d / fps_n latency, so by default 1/30 second, that's far below queue's default duration, which I assume is the limit that gets triggered?
pyldin601
commented
2 years ago @MathieuDuponchelle Yes, it's unclear for me too. Here is another pipeline where freeze 100% reproducible. I just added names to each element so the gdb backtrace was easier to debug:
cefbin name=cef cefsrc::url="https://soundcloud.com/platform/sama" \
audiotestsrc name=test do-timestamp=true is-live=true volume=0.0 ! audiomixer name=mixer \
mixer. ! audioconvert name=c1 ! queue name=q1 ! matroskamux streamable=true name=muxer ! queue name=q2 ! fakesink sync=1 \
cef.audio ! queue name=q3 ! audioconvert name=c2 ! mixer. \
cef.video ! video/x-raw, width=1920, height=1080 ! videoconvert name=vc1 ! queue name=q4 ! muxer.
And here is gdb backtrace when pipeline was blocked:
Look at Thread 5 (q4:src). It's thread of the queue between cef.video and muxer:
Thread 5 (Thread 0xffff74eee980 (LWP 162) "q4:src"):
#0 syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1 0x0000ffff79ca571c in g_cond_wait () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#2 0x0000ffff7690a5a8 in gst_queue_loop (pad=0xaaab1e6a9b30 [GstPad|src]) at ../subprojects/gstreamer/plugins/elements/gstqueue.c:1529
#3 0x0000ffff79e4ed5c in gst_task_func (task=0xaaab1e6da290 [GstTask|q4:src]) at ../subprojects/gstreamer/gst/gsttask.c:384
#4 0x0000ffff79e502bc in default_func (tdata=0xaaab1e6a3d90, pool=0xaaab1e6d8520 [GstTaskPool|taskpool0]) at ../subprojects/gstreamer/gst/gsttaskpool.c:70
#5 0x0000ffff79c88678 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#6 0x0000ffff79c859a0 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#7 0x0000ffff79a4d5c8 in start_thread (arg=0x0) at ./nptl/pthread_create.c:442
#8 0x0000ffff79ab5d1c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:79It seems to be idle because no data in it.
Look at thread 4 (q1:src). This thread of the queue between audiomixer and muxer.
Thread 4 (Thread 0xffff756fe980 (LWP 161) "q1:src"):
#0 syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1 0x0000ffff79ca571c in g_cond_wait () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#2 0x0000ffff76b15934 in gst_collect_pads_chain (pad=0xaaab1e6a9d80 [GstPad|audio_0], parent=0xaaab1e6b6040 [GstObject|muxer], buffer=0xffff60032120) at ../subprojects/gstreamer/libs/gst/base/gstcollectpads.c:2244
#3 0x0000ffff79e07f28 in gst_pad_chain_data_unchecked (pad=0xaaab1e6a9d80 [GstPad|audio_0], type=4112, data=0xffff60032120) at ../subprojects/gstreamer/gst/gstpad.c:4447
#4 0x0000ffff79e08d18 in gst_pad_push_data (pad=0xaaab1e689c80 [GstPad|src], type=4112, data=0xffff60032120) at ../subprojects/gstreamer/gst/gstpad.c:4711
#5 0x0000ffff79e09480 in gst_pad_push (pad=0xaaab1e689c80 [GstPad|src], buffer=0xffff60032120) at ../subprojects/gstreamer/gst/gstpad.c:4830
#6 0x0000ffff76909bfc in gst_queue_push_one (queue=0xaaab1e690720 [GstQueue|q1]) at ../subprojects/gstreamer/plugins/elements/gstqueue.c:1388
#7 0x0000ffff7690a9d0 in gst_queue_loop (pad=0xaaab1e689c80 [GstPad|src]) at ../subprojects/gstreamer/plugins/elements/gstqueue.c:1541
#8 0x0000ffff79e4ed5c in gst_task_func (task=0xaaab1e6da170 [GstTask|q1:src]) at ../subprojects/gstreamer/gst/gsttask.c:384
#9 0x0000ffff79e502bc in default_func (tdata=0xaaab1e6c7dc0, pool=0xaaab1e6d8520 [GstTaskPool|taskpool0]) at ../subprojects/gstreamer/gst/gsttaskpool.c:70
#10 0x0000ffff79c88678 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#11 0x0000ffff79c859a0 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#12 0x0000ffff79a4d5c8 in start_thread (arg=0x0) at ./nptl/pthread_create.c:442
#13 0x0000ffff79ab5d1c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:79
It looks like it blocked on pushing data to the muxer's audio_0 pad.
And finally, Thread 7 of the queue between cef.audio and audiomixer:
Thread 7 (Thread 0xffff677ee980 (LWP 164) "q3:src"):
#0 syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1 0x0000ffff79ca571c in g_cond_wait () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#2 0x0000ffff76abfb58 in gst_aggregator_pad_chain_internal (self=0xaaab1e6a01d0 [GstAggregator|mixer], aggpad=0xaaab1e6d2280 [GstAggregatorPad|sink_1], buffer=0xffff5c014120, head=1) at ../subprojects/gstreamer/libs/gst/base/gstaggregator.c:3079
#3 0x0000ffff76ac03c8 in gst_aggregator_pad_chain (pad=0xaaab1e6d2280 [GstPad|sink_1], object=0xaaab1e6a01d0 [GstObject|mixer], buffer=0xffff5c014120) at ../subprojects/gstreamer/libs/gst/base/gstaggregator.c:3159
#4 0x0000ffff79e07f28 in gst_pad_chain_data_unchecked (pad=0xaaab1e6d2280 [GstPad|sink_1], type=4112, data=0xffff5c014120) at ../subprojects/gstreamer/gst/gstpad.c:4447
#5 0x0000ffff79e08d18 in gst_pad_push_data (pad=0xaaab1e6a91f0 [GstPad|src], type=4112, data=0xffff5c014120) at ../subprojects/gstreamer/gst/gstpad.c:4711
#6 0x0000ffff79e09480 in gst_pad_push (pad=0xaaab1e6a91f0 [GstPad|src], buffer=0xffff5c014120) at ../subprojects/gstreamer/gst/gstpad.c:4830
#7 0x0000ffff76b032c0 in gst_base_transform_chain (pad=0xaaab1e6a8fa0 [GstPad|sink], parent=0xaaab1e6bfd00 [GstObject|c2], buffer=0xffff5c014120) at ../subprojects/gstreamer/libs/gst/base/gstbasetransform.c:2377
#8 0x0000ffff79e07f28 in gst_pad_chain_data_unchecked (pad=0xaaab1e6a8fa0 [GstPad|sink], type=4112, data=0xffff5c014120) at ../subprojects/gstreamer/gst/gstpad.c:4447
#9 0x0000ffff79e08d18 in gst_pad_push_data (pad=0xaaab1e6a8d50 [GstPad|src], type=4112, data=0xffff5c014120) at ../subprojects/gstreamer/gst/gstpad.c:4711
#10 0x0000ffff79e09480 in gst_pad_push (pad=0xaaab1e6a8d50 [GstPad|src], buffer=0xffff5c014120) at ../subprojects/gstreamer/gst/gstpad.c:4830
#11 0x0000ffff76909bfc in gst_queue_push_one (queue=0xaaab1e690d20 [GstQueue|q3]) at ../subprojects/gstreamer/plugins/elements/gstqueue.c:1388
#12 0x0000ffff7690a9d0 in gst_queue_loop (pad=0xaaab1e6a8d50 [GstPad|src]) at ../subprojects/gstreamer/plugins/elements/gstqueue.c:1541
#13 0x0000ffff79e4ed5c in gst_task_func (task=0xaaab1e6da5f0 [GstTask|q3:src]) at ../subprojects/gstreamer/gst/gsttask.c:384
#14 0x0000ffff79e502bc in default_func (tdata=0xaaab1e6c7d80, pool=0xaaab1e6d8520 [GstTaskPool|taskpool0]) at ../subprojects/gstreamer/gst/gsttaskpool.c:70
#15 0x0000ffff79c88678 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#16 0x0000ffff79c859a0 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#17 0x0000ffff79a4d5c8 in start_thread (arg=0x0) at ./nptl/pthread_create.c:442
#18 0x0000ffff79ab5d1c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:79It stuck on pushing data to audiomixer.
There are some "audio-queue:src" and "video-queue:src" threads, but what's the element they belong to. It is part of cefbin?
pyldin601
commented
2 years ago Maybe the answer is somewhere in this thread:
Thread 24 (Thread 0xffff0b7ee980 (LWP 190) "cefsrc:src"):
#0 syscall () at ../sysdeps/unix/sysv/linux/aarch64/syscall.S:38
#1 0x0000ffff79ca571c in g_cond_wait () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#2 0x0000ffff7690935c in gst_queue_chain_buffer_or_list (pad=0xaaab1e688ea0 [GstPad|sink], parent=0xaaab1e690420 [GstObject|audio-queue], obj=0xffff60044c60, is_list=0) at ../subprojects/gstreamer/plugins/elements/gstqueue.c:1251
#3 0x0000ffff76909a80 in gst_queue_chain (pad=0xaaab1e688ea0 [GstPad|sink], parent=0xaaab1e690420 [GstObject|audio-queue], buffer=0xffff60044c60) at ../subprojects/gstreamer/plugins/elements/gstqueue.c:1349
#4 0x0000ffff79e07f28 in gst_pad_chain_data_unchecked (pad=0xaaab1e688ea0 [GstPad|sink], type=4112, data=0xffff60044c60) at ../subprojects/gstreamer/gst/gstpad.c:4447
#5 0x0000ffff79e08d18 in gst_pad_push_data (pad=0xaaab1e6887b0 [GstPad|audio], type=4112, data=0xffff60044c60) at ../subprojects/gstreamer/gst/gstpad.c:4711
#6 0x0000ffff79e09480 in gst_pad_push (pad=0xaaab1e6887b0 [GstPad|audio], buffer=0xffff60044c60) at ../subprojects/gstreamer/gst/gstpad.c:4830
#7 0x0000ffff76d506dc in gst_cef_demux_push_audio_buffer(_GstBuffer**, unsigned int, AudioPushData*) () at /usr/cef/libgstcef.so
#8 0x0000ffff79dab0c4 in gst_buffer_list_foreach (list=0xfffef4059030, func=0xffff76d50620 <gst_cef_demux_push_audio_buffer(_GstBuffer**, unsigned int, AudioPushData*)>, user_data=0xffff0b7edc18) at ../subprojects/gstreamer/gst/gstbufferlist.c:280
#9 0x0000ffff76d50ba8 in gst_cef_demux_chain(_GstPad*, _GstObject*, _GstBuffer*) () at /usr/cef/libgstcef.so
#10 0x0000ffff79e07f28 in gst_pad_chain_data_unchecked (pad=0xaaab1e688310 [GstPad|sink], type=4112, data=0xffff60044a20) at ../subprojects/gstreamer/gst/gstpad.c:4447
#11 0x0000ffff79e08d18 in gst_pad_push_data (pad=0xaaab1e6880c0 [GstPad|src], type=4112, data=0xffff60044a20) at ../subprojects/gstreamer/gst/gstpad.c:4711
#12 0x0000ffff79e09480 in gst_pad_push (pad=0xaaab1e6880c0 [GstPad|src], buffer=0xffff60044a20) at ../subprojects/gstreamer/gst/gstpad.c:4830
#13 0x0000ffff76af91d8 in gst_base_src_loop (pad=0xaaab1e6880c0 [GstPad|src]) at ../subprojects/gstreamer/libs/gst/base/gstbasesrc.c:3030
#14 0x0000ffff79e4ed5c in gst_task_func (task=0xaaab1e6da950 [GstTask|cefsrc:src]) at ../subprojects/gstreamer/gst/gsttask.c:384
#15 0x0000ffff79e502bc in default_func (tdata=0xaaab1e6a3ea0, pool=0xaaab1e6d8520 [GstTaskPool|taskpool0]) at ../subprojects/gstreamer/gst/gsttaskpool.c:70
#16 0x0000ffff79c88678 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#17 0x0000ffff79c859a0 in () at /lib/aarch64-linux-gnu/libglib-2.0.so.0
#18 0x0000ffff79a4d5c8 in start_thread (arg=0x0) at ./nptl/pthread_create.c:442
#19 0x0000ffff79ab5d1c in thread_start () at ../sysdeps/unix/sysv/linux/aarch64/clone.S:79It looks like audio and video from cefsrc are handled in a single thread, and gst_cef_demux_chain blocked on pushing audio data down the pipeline.
MathieuDuponchelle
commented
2 years ago It looks like audio and video from cefsrc are handled in a single thread, and gst_cef_demux_chain blocked on pushing audio data down the pipeline.
That is the case yes. That doesn't tell us why the audio queue runs full however, have you figured out which queue was running full exactly, and upon reaching which limit?
pyldin601
commented
2 years ago have you figured out which queue was running full exactly, and upon reaching which limit?
I'm not sure how can I monitor queue levels with gst-launch-1.0, but according to gdb backtrace it looks like all audio queues (q1 and q3) were overrun. They have tiny capacities by default, so they can be fulfilled very fast.
UPD: I've tested last @philn patch in our application and haven't heard any audio cracks so far. Maybe I'm lucky. Possible freezes I've workarounded with a leaky queue.
MathieuDuponchelle
commented
2 years ago @pldin601 you can monitor queue levels with appropriately picked log levels and filtering, I can't tell you the exact command but you should be able to find the relevant filter by looking at the queue:6 logs. The other question is what limit gets triggered? Is it max-size-time ?
pyldin601
commented
1 year ago Here's in queue logs:
0:00:28.501291013 868 0xaaaaed341760 LOG queue_dataflow gstqueue.c:1251:gst_queue_chain_buffer_or_list:<q3> (q3:sink) wait for DEL: 18 of 0-200 buffers, 147456 of 0-10485760 bytes, 1613220875 of 0-1000000000 ns, 18 items
0:00:29.394822597 868 0xaaaaed341700 LOG queue_dataflow gstqueue.c:1251:gst_queue_chain_buffer_or_list:<q4> (q4:sink) wait for DEL: 2 of 0-200 buffers, 16588800 of 0-10485760 bytes, 66666667 of 0-1000000000 ns, 2 items
0:00:38.594945268 868 0xaaaaed341580 LOG queue_dataflow gstqueue.c:1251:gst_queue_chain_buffer_or_list:<q1> (q1:sink) wait for DEL: 100 of 0-200 buffers, 88200 of 0-10485760 bytes, 1000000000 of 0-1000000000 ns, 100 itemsIf I understood, q3 and q1 were triggered with size-time, but q4 with size-bytes.
MathieuDuponchelle
commented
1 year ago The plot thickens :) If there is data in both queues feeding the muxer (q1 and q4) then why the hell is it not muxing ? :)
hevc
commented
1 year ago I found difference between main and proposed MR patch.
Run:
gst-launch-1.0 cefbin name=cef cefsrc::url=file:///home/test.html cef.video ! queue ! videoconvert ! ximagesink cef.audio ! queue ! fakesink
where test.html:
<html>
<body style="background-color:blue;">
</body>
</html>The pipeline will show a blue screen on the main branch. The pipeline hangs on MR patch. Adding audio will unlock the MR pipeline. e.g.
<html>
<body style="background-color:blue;">
<script>
var context = new AudioContext()
var o = context.createOscillator()
o.type = "sine"
o.connect(context.destination)
o.start()
</script>
</body>
</html>@hevc probably best to comment on the MR :)
philn
commented
1 year ago @hevc I updated the PR, please test and report issues there ;)
fairbairn
commented
1 year ago We have the same issue on the latest master using CEF_VERSION=112.3.0+gb09c4ca+chromium-112.0.5615.165.
Under heavy CPU load, the pipeline will stall and not recover. We are using an audiomixer per the example pipeline.
We'd like to determine how to get this resolved, as this is used in a commercial application.
SteveMcFarlin
commented
1 year ago I ran into this issue again today. I hacked a solution to fix my initial problem a while ago, but the issue is still there. This command will deadlock. Wait around 5 seconds and then send EOS. Note the FPS is 10.
gst-launch-1.0 -e \
cefsrc url="https://soundcloud.com/platform/sama" ! \
video/x-raw, width=1920, height=1080, framerate=10/1 ! \
cefdemux name=demux ! queue ! videoconvert ! \
queue max-size-bytes=0 max-size-buffers=0 max-size-time=3000000000 ! x264enc ! queue ! \
mp4mux name=muxer ! filesink location='test.mp4' \
audiotestsrc do-timestamp=true is-live=true volume=0.0 ! audiomixer name=mix ! \
queue max-size-bytes=0 max-size-buffers=0 max-size-time=3000000000 ! audioconvert ! \
audiorate ! audioresample ! avenc_aac bitrate=128000 ! queue ! muxer. \
demux. ! queue ! mix.If this were code and you connect to the overrun signal on the audio queues you will see a lot of callbacks. Running at 30 FPS is OK(ish), and the pipeline will not deadlock at least.
Running this command is fine
gst-launch-1.0 -e \
cefsrc url="https://soundcloud.com/platform/sama" ! \
video/x-raw, width=1920, height=1080, framerate=10/1 ! \
cefdemux name=demux ! queue ! videoconvert ! \
queue max-size-bytes=0 max-size-buffers=0 max-size-time=3000000000 ! nvh264enc ! h264parse ! queue ! \
mp4mux name=muxer ! filesink location='test.mp4' \
audiotestsrc do-timestamp=true is-live=true volume=0.0 ! audiomixer name=mix ! \
queue max-size-bytes=0 max-size-buffers=0 max-size-time=3000000000 ! audioconvert ! \
audiorate ! audioresample ! avenc_aac bitrate=128000 ! queue ! muxer. \
demux. ! queue ! mix.The only difference here is the the use of nvh264enc. I have not had time to dig into the debug logs. If I get a chance I will at some point.
SteveMcFarlin
commented
1 year ago I have not debug this yet, but setting threads=1 on x264enc mitigates the issue to an extent. I still see audio buffer overrun signals at regular intervals. This is certainly some issue with x264enc in the above pipeline. I also tried various muxers, and that did not make any difference. Note, I do not notice, by ear, any audio loss in the resulting file.
Test pipeline:
When I launch this pipeline with gst-launch-1.0 it stuck at random time positions. Here's gdb backtrace when it happens:
Can't reproduce the issue when GST_DEBUG=5 or higher, so can't provide detailed logs.