Unexpected browser frame rendering lag (~100ms)

285 views
Skip to first unread message

Robert Ayrapetyan

unread,
Sep 18, 2023, 2:41:37 AM9/18/23
to discuss-webrtc
Greetings,

I'm using a GStreamer pipeline in which ximagesrc is responsible for producing frames, which are then transmitted to the web browser through WebRTC using gst-plugins-rs. Additionally, there is an event handler for navigation events, specifically for mouse movement. I tracked a single event, starting from the moment it is sent by the browser via the data channel to the point when the browser receives the most recent UDP packet containing this frame. The anticipated delay for this process is approximately 17 ms. Here are the observed timings:
- Transmission of the navigation event from the browser to the server-side event handler: ~1 ms.
ximagesrc generates a new buffer reflecting the change in cursor position: ~1 ms.
- The frame is encoded and passed into appsink from WebRTC: ~13 ms.
- The frame is sent to the browser in multiple UDP packets: ~2 ms.

Despite these timings, the visual feedback for mouse cursor movements suggests that there is a lag of ~100 ms (which you can test at https://www.skytopia.com/stuff/lag.html).
Do you have any insights into the possible source of this lag? Based on the trace logs, it seems that the only place where this delay might be occurring is within the browser itself.

Trace logs:

browser triggers a mouse movement event:

470808:50:57.584: sending navigation event: {"event":"MouseMove","x":1005,"y":543.75,"modifier_state":""}

~1ms

events handler processes event:

2023-09-17 00:50:57,584 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.894115431 41 0x7f367c00c180 WARN ximagesrc gstximagesrc.c:1251:gst_ximage_src_event:<ximagesrc0> Processing event navigation event: 0x7f365414e0a0, time 99:99:99.999999999, seq-num 14198, application/x-gst-navigation, event=(string)mouse-move, pointer_x=(double)1005, pointer_y=(double)543.75, state=(GstNavigationModifierType)GST_NAVIGATION_MODIFIER_NONE;

~1ms

ximagesrc creates a new buffer:

2023-09-17 00:50:57,585 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.894902790 41 0x557e25cfe060 WARN ximagesrc gstximagesrc.c:945:gst_ximage_src_create: created buffer. wallclock: 470808:50:57.585443000 pts: 0:00:33.850000000 pts-int 33850000000 dts: 99:99:99.999999999 size: 8294400 next_frame_no: 2031

~13ms

frame encoding is completed here:

2023-09-17 00:50:57,598 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.907916987 41 0x557e25cfe060 TRACE utilsrs-stream-producer streamproducer.rs:252:gstreamer_utils::streamproducer::StreamProducer::process_sample:<appsink0> processing sample Some(Buffer { ptr: 0x7f365414a850, pts: 1000:00:33.840148943, dts: 1000:00:33.840148943, duration: 0:00:00.016666666, size: 23513, offset: 18446744073709551615, offset_end: 18446744073709551615, flags: BufferFlags(MARKER | DELTA_UNIT), metas: [] })

starting h264 payloading and UDP sending:

2023-09-17 00:50:57,598 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.908010372 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1468:gst_rtp_h264_pay_handle_buffer:<rtph264pay1> got 23513 bytes

0:00:33.908016795 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1488:gst_rtp_h264_pay_handle_buffer:<rtph264pay1> got NAL of size 2

0:00:33.908022994 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:952:gst_rtp_h264_pay_payload_nal:<rtph264pay1> payloading NAL Unit: datasize=2 type=9 pts=1000:00:33.840148943

0:00:33.908025413 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1340:gst_rtp_h264_pay_payload_nal_bundle:<rtph264pay1> creating new STAP-A aggregate

0:00:33.908028156 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1346:gst_rtp_h264_pay_payload_nal_bundle:<rtph264pay1> bundling NAL Unit: bundlesize=1 datasize=2+2 mtu=1200

0:00:33.908030226 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1488:gst_rtp_h264_pay_handle_buffer:<rtph264pay1> got NAL of size 5501

0:00:33.908032949 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:952:gst_rtp_h264_pay_payload_nal:<rtph264pay1> payloading NAL Unit: datasize=5501 type=1 pts=1000:00:33.840148943

0:00:33.908034604 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1315:gst_rtp_h264_pay_payload_nal_bundle:<rtph264pay1> NAL Unit cannot fit in a bundle

0:00:33.908036252 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1220:gst_rtp_h264_pay_send_bundle:<rtph264pay1> sending NAL Unit unaggregated: datasize=3

0:00:33.908070078 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62445, ssrc: FBF76958

2023-09-17 00:50:57,598 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.908285614 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1063:gst_rtp_h264_pay_payload_nal_fragment:<rtph264pay1> using FU-A fragmentation for NAL Unit: datasize=5501 mtu=1200

0:00:33.908290631 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1081:gst_rtp_h264_pay_payload_nal_fragment:<rtph264pay1> creating FU-A packet 1/5, size 1186


2023-09-17 00:50:57,598 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.908295118 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1081:gst_rtp_h264_pay_payload_nal_fragment:<rtph264pay1> creating FU-A packet 2/5, size 1186

0:00:33.908297572 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1081:gst_rtp_h264_pay_payload_nal_fragment:<rtph264pay1> creating FU-A packet 3/5, size 1186

0:00:33.908300510 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1081:gst_rtp_h264_pay_payload_nal_fragment:<rtph264pay1> creating FU-A packet 4/5, size 1186

0:00:33.908303218 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1081:gst_rtp_h264_pay_payload_nal_fragment:<rtph264pay1> creating FU-A packet 5/5, size 756

0:00:33.908305909 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1132:gst_rtp_h264_pay_payload_nal_fragment:<rtph264pay1> sending FU-A fragments: n=5 datasize=5501 mtu=1200

0:00:33.908337308 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62446, ssrc: FBF76958


2023-09-17 00:50:57,598 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.908406990 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62447, ssrc: FBF76958


2023-09-17 00:50:57,599 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.908463999 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62448, ssrc: FBF76958


2023-09-17 00:50:57,599 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.908525167 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62449, ssrc: FBF76958


2023-09-17 00:50:57,599 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.908574596 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62450, ssrc: FBF7695


2023-09-17 00:50:57,599 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.909219231 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:1488:gst_rtp_h264_pay_handle_buffer:<rtph264pay1> got NAL of size 5186

0:00:33.909224570 41 0x7f3654002120 DEBUG rtph264pay gstrtph264pay.c:952:gst_rtp_h264_pay_payload_nal:<rtph264pay1> payloading NAL Unit: datasize=5186 type=1 pts=1000:00:33.840148943

2023-09-17 00:50:57,600 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.910344200 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62488, ssrc: FBF76958

last udp packets sent:


2023-09-17 00:50:57,600 DEBG 'yag-webrtc-streamer' stdout output:

0:00:33.910379279 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62489, ssrc: FBF76958

0:00:33.910412318 41 0x7f3654002120 TRACE rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 62490, ssrc: FBF76958

browser received the last UDP packet containing our frame:

[910418:11:0916/175057.601126:INFO:rtp_video_stream_receiver2.cc(1269)] Packet received on SSRC: 4227295576 with payload type: 96, timestamp: 1018901582, sequence number: 62490, arrival time: -inf ms

Robert Ayrapetyan

unread,
Sep 20, 2023, 1:08:36 AM9/20/23
to discuss-webrtc
Few more measurements with a custom built Chromium instance (with a certain min/maxDelays set to 0):

Last 3 RTP packets sent from the client (RTP timestamp: 2226378701):
2023-09-20 00:47:51,884 DEBG 'yag-webrtc-streamer' stdout output:
0:00:31.601745066    42 0x7fc688002120 TRACE             rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 2145, ssrc: 946673CC, rtptime: 2226378701
2023-09-20 00:47:51,884 DEBG 'yag-webrtc-streamer' stdout output:
0:00:31.601792866    42 0x7fc688002120 TRACE             rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 2146, ssrc: 946673CC, rtptime: 2226378701
2023-09-20 00:47:51,884 DEBG 'yag-webrtc-streamer' stdout output:
0:00:31.601837612    42 0x7fc688002120 TRACE             rtprtxsend gstrtprtxsend.c:1031:process_buffer:<rtprtxsend0> Processing buffer seqnum: 2147, ssrc: 946673CC, rtptime: 2226378701

Received and processed on the browser side (logged from the OnFrameBufferUpdated function):
[390437:13:0919/174751.886521:VERBOSE1:frame_decode_timing.cc(51)] Selected frame with rtp 2226378701 render time 0 us with a max wait of 2977278 us clamped to 0 us

Note the wall clock diff (all processes are running on the same host) between these events is just about 2.5ms.

But the frame on the screen will be refreshed only after ~80ms.

I'm uncertain about the extent to which this can be further investigated and what is responsible for the time lag between the OnFrameBufferUpdated event and the screen refreshing with the actual frame.
Any help is appreciated!

Haichao Zhu

unread,
Sep 20, 2023, 5:29:28 AM9/20/23
to discuss-webrtc

Most of the lag happens because it has buffer to avoid jitter. You can maually set  PlayoutDelay to 0 if you do not care about it. Check the comments in  third_party/webrtc/api/video/video_timing.h.

Robert Ayrapetyan

unread,
Sep 21, 2023, 1:43:18 AM9/21/23
to discuss...@googlegroups.com
Hello.

Replaced:

static constexpr TimeDelta kMax = TimeDelta::Millis(10) * 0xFFF;

with:

static constexpr TimeDelta kMax = TimeDelta::Zero();

This makes no difference at all - the visual lag is still around 100 ms.
Am I missing any other parameters?
> --
> This list falls under the WebRTC Code of Conduct - https://webrtc.org/support/code-of-conduct.
> ---
> You received this message because you are subscribed to a topic in the Google Groups "discuss-webrtc" group.
> To unsubscribe from this topic, visit https://groups.google.com/d/topic/discuss-webrtc/wuGQ0GpxMz4/unsubscribe.
> To unsubscribe from this group and all its topics, send an email to discuss-webrt...@googlegroups.com.
> To view this discussion on the web visit https://groups.google.com/d/msgid/discuss-webrtc/80dfe0bf-f213-461d-bb85-d9f8d50ef15bn%40googlegroups.com.

Robert Ayrapetyan

unread,
Oct 14, 2023, 5:51:16 AM10/14/23
to discuss-webrtc
Ok, it appears that the rendering delay is stemming from an audio synchronization problem. In the absence of an audio track, the glass-to-glass latency is approximately 25ms
which aligns with our expectations and is considered reasonable. However, when an audio track is introduced, we've noticed an additional delay of approximately 80ms, resulting in a total delay of around 100ms.

At absl::optional<Syncable::Info> ChannelReceive::GetSyncInfo(), we can see:

info.current_delay_ms = jitter_buffer_delay + playout_delay_ms_;

For Audio stream, jitter_buffer_delay is around 66ms, playout_delay_ms_ is around 50ms.

Each of these values is derived from a composite of several other values. For instance, playout_delay_ms_ is the result of a combination of:

PulseAudioOutputStream::FulfillWriteRequest(): pulse::GetHardwareLatency(): ~30ms (seems it's out of our control, on IOS it's about the same: ~27ms)
OnMoreDataConverter::ProvideInput(): AudioTimestampHelper::FramesToTime(frames_delayed, input_samples_per_second_): ~10ms (this value never changes)
OutputController::OnMoreData(): AudioTimestampHelper::FramesToTime(frames, params_.sample_rate()): ~10ms (this value varies slightly)

jitter_buffer_delay is a result mainly of:

NetEqImpl::FilteredCurrentDelayMs(): delay_samples = controller_->GetFilteredBufferLevel() + sync_buffer_->FutureLength();
, where controller_->GetFilteredBufferLevel() is a composition of span samples (PacketBuffer::GetSpanSamples()).

So the source of my delay is identified, but I'm wondering how it can be minimized, particularly when it comes to reducing jitter_buffer_delay, without necessitating alterations to the browser's source code?
Has anyone tried to resolve this issue before?


Robert Ayrapetyan

unread,
Oct 16, 2023, 3:06:48 AM10/16/23
to discuss-webrtc
Now, I believe the sole method to minimize the glass-to-glass latency in my situation involves disabling audio/video synchronization. 
I see three potential approaches to achieve this:

1. Reducing the audio delay to zero, but this is not feasible since the client machine's GetHardwareLatency() cannot be altered.
2. Employing unconventional methods or "dirty hacks" akin to what Amazon Luna does, such as inducing crashes within the RtpStreamsSynchronizer::UpdateDelay() function.
3. Exploring documented procedures for achieving this goal.

Seeking assistance with option 3. I am aware of a new extension that allows the definition of playout delays, but I am uncertain if it will address my particular issue.
I kindly request suggestions for established methods to disable lip synchronization without making modifications to the browser. Your input would be greatly appreciated.

Rajneesh Soni

unread,
Oct 18, 2023, 1:29:53 PM10/18/23
to discuss-webrtc
If audio and video are sent over separate mediaStream, then browser will not try to synchronize them and play them independently.

Robert Ayrapetyan

unread,
Oct 22, 2023, 10:16:20 AM10/22/23
to discuss...@googlegroups.com
I've used different msids for audio and video streams so they come up as:

a=mid:audio0
a=ssrc:992908233 cname:user992908233@host-777d8777
a=ssrc:992908233 msid:user992908233@host-777d8777 webrtctransceiver0

m=video 0 UDP/TLS/RTP/SAVPF 96 98 99 100 101 (30 more lines) mid=video1
a=ssrc-group:FID 1254059569 2177990972
a=ssrc:1254059569 cname:user1435624891@host-c9157b13
a=ssrc:1254059569 msid:user1435624891@host-c9157b13 webrtctransceiver1
a=ssrc:2177990972 cname:user1435624891@host-c9157b13
a=ssrc:2177990972 msid:user1435624891@host-c9157b13 webrtctransceiver1

Synchronization doesn't happen, but sound is not played either.
> To view this discussion on the web visit https://groups.google.com/d/msgid/discuss-webrtc/3786d830-5135-4fd8-a189-a583a560f205n%40googlegroups.com.

Harald Alvestrand

unread,
Oct 22, 2023, 11:43:46 PM10/22/23
to discuss...@googlegroups.com
Your SDP looks like Plan B. This is not a forward looking choice.

You received this message because you are subscribed to the Google Groups "discuss-webrtc" group.
To unsubscribe from this group and stop receiving emails from it, send an email to discuss-webrt...@googlegroups.com.
To view this discussion on the web visit https://groups.google.com/d/msgid/discuss-webrtc/CAAboi9v4qt-LnuPxKDEePOKeSghn1Xk5edYqhgfZwbh_2wvn_g%40mail.gmail.com.
Reply all
Reply to author
Forward
0 new messages