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