search

OpenVisualCloud / Media-Transport-Library

A real-time media transport(DPDK, AF_XDP, RDMA) stack for both raw and compressed video based on COTS hardware.
BSD 3-Clause "New" or "Revised" License
171 stars 55 forks source link

Lost frames when receiving. #618

Closed gizahNL closed 9 months ago

gizahNL commented 12 months ago

We're testing the receiving end of our application but we're seeing significant loss of frames consistently on the input, I'm seeing 20 incomplete frames in every stat report. The amount of incomplete frames per stat period seems to be the same regardless of the framerate we operate at. Which would suggest it's not related to performance. In our test equipment we've tested a single leg going over a switch back into the other port on our E810 card, and we've tested sending with a VF device and receiving with another VF device on the same physical device.

logs (RX):

MT: 2023-11-30 10:17:31, dev_eal_init(0), port_param: 0000:18:11.0
MT: 2023-11-30 10:17:31, dev_eal_init, wait eal_init_thread done
EAL: Detected CPU lcores: 64
EAL: Detected NUMA nodes: 1
EAL: Detected shared linkage of DPDK
EAL: Selected IOVA mode 'VA'
EAL: 4062 hugepages of size 2097152 reserved, but no mounted hugetlbfs found for that size
EAL: No free 1048576 kB hugepages reported on node 0
EAL: VFIO support initialized
EAL: Using IOMMU type 1 (Type 1)
EAL: Probe PCI driver: net_ice_dcf (8086:1889) device: 0000:18:11.0 (socket 0)
EAL: Releasing PCI mapped resource for 0000:18:11.0
EAL: Calling pci_unmap_resource for 0000:18:11.0 at 0x2180800000
EAL: Calling pci_unmap_resource for 0000:18:11.0 at 0x2180820000
EAL: Using IOMMU type 1 (Type 1)
EAL: Probe PCI driver: net_iavf (8086:1889) device: 0000:18:11.0 (socket 0)
TELEMETRY: No legacy callbacks, legacy socket not created
MT: 2023-11-30 10:17:31, st version: 23.12.0 Sun Nov 19 21:36:58 2023 2022.11.1-1272-gf4b85819-dirty gcc-12.2.0, dpdk version: DPDK 23.03.0
MT: 2023-11-30 10:17:31, mt_instance_init, succ
MT: 2023-11-30 10:17:31, mtl_init(0), socket_id 0 port 0000:18:11.0
MT: 2023-11-30 10:17:31, stat_thread, start
MT: 2023-11-30 10:17:31, mt_stat_init, stat period 10s
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), use mt ptp source
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), user request queues tx 0 rx 2
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), deprecated sessions tx 0 rx 0
MT: 2023-11-30 10:17:31, dev_config_port(0), tx_q(3 with 512 desc) rx_q (3 with 2048 desc)
MT: 2023-11-30 10:17:31, mt_mempool_create_by_ops(0), succ at 0x11804fdf00 size 3.234375m n 1536 d 2048 for T_P0_SYS_0
MT: 2023-11-30 10:17:31, dev_if_init_tx_queues(0), tx_queues 3 malloc succ
MT: 2023-11-30 10:17:31, mt_mempool_create_by_ops(0), succ at 0x1180afdf00 size 6.468750m n 3072 d 2048 for R_P0Q0_MBUF_1
MT: 2023-11-30 10:17:31, mt_mempool_create_by_ops(0), succ at 0x11814fdf00 size 4.968750m n 3072 d 1536 for R_P0Q1_MBUF_2
MT: 2023-11-30 10:17:31, mt_mempool_create_by_ops(0), succ at 0x1181cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q2_MBUF_3
MT: 2023-11-30 10:17:31, dev_if_init_rx_queues(0), rx_queues 3 malloc succ
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), port_id 0 port_type 1 drv_type 3
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), dev_capa 0x0, offload 0x119fbf:0x9266f queue offload 0x0:0x0, rss : 0x3ffc
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), system_rx_queues_end 1 hdr_split_rx_queues_end 1
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), sip: 192.168.200.51
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), netmask: 255.255.255.0
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), gateway: 0.0.0.0
MT: 2023-11-30 10:17:31, mt_dev_if_init(0), mac: da:3f:97:6b:be:54
iavf_configure_queues(): request RXDID[22] in Queue[0]
iavf_configure_queues(): request RXDID[22] in Queue[1]
iavf_configure_queues(): request RXDID[22] in Queue[2]
MT: 2023-11-30 10:17:31, dev_start_port(0), rx_defer 0
MT: 2023-11-30 10:17:31, mt_eth_link_dump(0), link_speed 10g link_status 1 link_duplex 1 link_autoneg 1
MT: 2023-11-30 10:17:31, dev_if_init_pacing(0), try rl as drv support
MT: 2023-11-30 10:17:31, dev_rl_shaper_add(0), bps 134217728 on shaper 1
MT: 2023-11-30 10:17:31, dev_init_ratelimit_all(0), q 0 link to shaper id 1
MT: 2023-11-30 10:17:31, dev_init_ratelimit_all(0), q 1 link to shaper id 1
MT: 2023-11-30 10:17:31, dev_init_ratelimit_all(0), q 2 link to shaper id 1
MT: 2023-11-30 10:17:31, mt_dev_create(0), feature 0x30, tx pacing ratelimit
MT: 2023-11-30 10:17:31, mt_sch_mrg_init, succ with data quota 31068 M, nb_tasklets 16
MT: 2023-11-30 10:17:31, mt_sch_add_quota(0:0), quota 0 total now 0
MT: 2023-11-30 10:17:31, mt_dev_get_tx_queue(0), q 0 with speed 1.073742g bps
MT: 2023-11-30 10:17:31, mt_mcast_init, report every 10 seconds
MT: 2023-11-30 10:17:31, mt_dev_get_rx_queue(0), q 0 ip 0.0.0.0 port 0
MT: 2023-11-30 10:17:31, cni_queues_init(0), rxq 0
MT: 2023-11-30 10:17:31, mt_sch_register_tasklet(0), tasklet cni registered into slot 0
MT: 2023-11-30 10:17:31, cni_traffic_thread, start
MT: 2023-11-30 10:17:31, st_plugins_init, succ
MT: 2023-11-30 10:17:31, admin_thread, start
MT: 2023-11-30 10:17:31, Warn: config_parse_json, open json file kahawai.json fail
MT: 2023-11-30 10:17:31, mt_ptp_port_id(0), port_number: 0000, clk_id: da:3f:97:ff:fe:6b:be:54
MT: 2023-11-30 10:17:31, mt_main_create, succ
MT: 2023-11-30 10:17:31, mtl_init, succ, tsc_hz 2300000000
MT: 2023-11-30 10:17:31, mtl_init, simd level avx512_vbmi, flags 0x0
MT: 2023-11-30 10:17:31, st20p_rx_create, start for TEST-VIDEO
MT: 2023-11-30 10:17:31, st20_get_converter, plugin not found, input fmt: YUV422RFC4175PG2BE10, output fmt: YUV422PLANAR10LE
MT: 2023-11-30 10:17:31, rx_st20p_get_converter(0), use internal converter
MT: 2023-11-30 10:17:31, rx_st20p_init_dst_fbs(0), size 8294400 fmt 0 with 8 frames
MT: 2023-11-30 10:17:31, mt_sch_add_quota(0:0), quota 2592 total now 2592
MT: 2023-11-30 10:17:31, mt_sch_get(0), succ with quota_mbs 2592
MT: 2023-11-30 10:17:31, mt_sch_register_tasklet(0), tasklet rvs_pkt_rx registered into slot 1
MT: 2023-11-30 10:17:31, mt_sch_register_tasklet(0), tasklet rvs_ctl registered into slot 2
MT: 2023-11-30 10:17:31, rvs_mgr_init(0), succ
MT: 2023-11-30 10:17:31, rte_rx_flow_create(0), queue 1 succ, ip 239.66.1.1 port 5000
MT: 2023-11-30 10:17:31, mt_dev_get_rx_queue(0), q 1 ip 239.66.1.1 port 5000
MT: 2023-11-30 10:17:31, rv_init_hw(0), port(l:0,p:0), queue 1 udp 5000
MT: 2023-11-30 10:17:31, mt_mcast_join(0), new group 239.66.1.1
MT: 2023-11-30 10:17:31, mt_rtcp_rx_create(RV_M0S0P0), suss
MT: 2023-11-30 10:17:31, rv_attach(0), 8 frames with size 5184000(810,0), type 0, progressive
MT: 2023-11-30 10:17:31, rv_attach(0), w 1920 h 1080 fmt ST20_FMT_YUV_422_10BIT packing 0 pt 112 flags 0x4 frame time 16.666667ms fps 60.000000
MT: 2023-11-30 10:17:31, mt_sch_add_quota(0:0), quota 1296 total now 3888
MT: 2023-11-30 10:17:31, st20_rx_create_with_mask, succ on sch 0 session 0
MT: 2023-11-30 10:17:31, st20p_rx_create(0), transport fmt ST20_FMT_YUV_422_10BIT, output fmt YUV422PLANAR10LE, dynamic_ext_frame false
MT: 2023-11-30 10:17:31, st30_rx_create, start for Test Audio
MT: 2023-11-30 10:17:31, mt_sch_add_quota(0:0), quota 31 total now 3919
MT: 2023-11-30 10:17:31, mt_sch_get(0), succ with quota_mbs 31
MT: 2023-11-30 10:17:31, mt_sch_register_tasklet(0), tasklet rx_audio_sessions_mgr registered into slot 3
MT: 2023-11-30 10:17:31, rx_audio_sessions_mgr_init(0), succ
MT: 2023-11-30 10:17:31, rte_rx_flow_create(0), queue 2 succ, ip 239.66.1.3 port 5000
MT: 2023-11-30 10:17:31, mt_dev_get_rx_queue(0), q 2 ip 239.66.1.3 port 5000
MT: 2023-11-30 10:17:31, rx_audio_session_init_hw(0), port(l:0,p:0), queue 2 udp 5000
MT: 2023-11-30 10:17:31, mt_mcast_join(0), new group 239.66.1.3
MT: 2023-11-30 10:17:31, rx_audio_session_attach(0), pkt_len 576 frame_size 576
MT: 2023-11-30 10:17:31, st30_rx_create(0,0), succ on 0x1180336140
WAIT NANOS: 26666667
MT: 2023-11-30 10:17:32, mt_calibrate_tsc, tscHz 2299999008
MT: 2023-11-30 10:17:32, sch_tasklet_func(0), start with 4 tasklets
MT: 2023-11-30 10:17:32, sch_start(0), succ on lcore 1
MT: 2023-11-30 10:17:32, mt_dev_start, succ
MT: 2023-11-30 10:17:32, _mt_start, succ, avail ports 1
MT: 2023-11-30 10:17:32, cni_traffic_thread, stop
MT: 2023-11-30 10:17:32, rvs_ctl_tasklet_start(0), succ
MT: 2023-11-30 10:17:32, rx_audio_sessions_tasklet_start(0), succ
MT: 2023-11-30 10:17:32, Error: rx_audio_session_get_frame(0), no free frame
**(^REPEATED^)**
MT: 2023-11-30 10:17:41, * *    M T    D E V   S T A T E   * * 
MT: 2023-11-30 10:17:41, DEV(0): Avr rate, tx: 0.000288 Mb/s, rx: 2607.738320 Mb/s, pkts, tx: 6, rx: 2134292
MT: 2023-11-30 10:17:41, Error: DEV(0): Status: rx_hw_dropped_packets 333240 rx_err_packets 0 rx_nombuf_packets 0 tx_err_packets 0
MT: 2023-11-30 10:17:41, Error: rx_good_packets: 525
MT: 2023-11-30 10:17:41, Error: rx_good_bytes: 694778
MT: 2023-11-30 10:17:41, Error: rx_bytes: 352420
MT: 2023-11-30 10:17:41, Error: rx_multicast_packets: 266
MT: 2023-11-30 10:17:41, CNI(0): eth_rx_rate 0.000661 Mb/s, eth_rx_cnt 2
MT: 2023-11-30 10:17:41, PTP(0): time 1701357461697874592, 2023-11-30 10:17:41
MT: 2023-11-30 10:17:41, RX_VIDEO_SESSION(0,0:TEST-VIDEO): fps 50.632904 frames 505 pkts 2125643
MT: 2023-11-30 10:17:41, RX_VIDEO_SESSION(0,0:TEST-VIDEO): throughput 2250.258886 Mb/s, cpu busy 2.724733
MT: 2023-11-30 10:17:41, RX_VIDEO_SESSION(0,0): incomplete frames 18, pkts (idx error: 0, offset error: 0, idx out of bitmap: 0, missed: 30076)
MT: 2023-11-30 10:17:41, RX_VIDEO_SESSION(0,0): out of order pkts 7
MT: 2023-11-30 10:17:41, rtcp_rx_stat(RV_M0S0P0), rtp recv 2125645 lost 288 nack sent 4
MT: 2023-11-30 10:17:41, RX_AUDIO_SESSION(0,0:Test Audio): fps 948.032120, st30 received frames 9441, received pkts 9441
MT: 2023-11-30 10:17:41, RX_AUDIO_SESSION(0,0): st30 dropped frames 0, dropped pkts 509
MT: 2023-11-30 10:17:41, * *    E N D    S T A T E   * * 

MT: 2023-11-30 10:17:51, * *    M T    D E V   S T A T E   * * 
MT: 2023-11-30 10:17:51, DEV(0): Avr rate, tx: 0.000192 Mb/s, rx: 2618.087397 Mb/s, pkts, tx: 4, rx: 2362429
MT: 2023-11-30 10:17:51, Error: DEV(0): Status: rx_hw_dropped_packets 115564 rx_err_packets 0 rx_nombuf_packets 0 tx_err_packets 0
MT: 2023-11-30 10:17:51, Error: rx_good_packets: 522
MT: 2023-11-30 10:17:51, Error: rx_good_bytes: 690806
MT: 2023-11-30 10:17:51, Error: rx_bytes: 348436
MT: 2023-11-30 10:17:51, Error: rx_multicast_packets: 262
MT: 2023-11-30 10:17:51, CNI(0): eth_rx_rate 0.000661 Mb/s, eth_rx_cnt 2
MT: 2023-11-30 10:17:51, PTP(0): time 1701357471697893324, 2023-11-30 10:17:51
MT: 2023-11-30 10:17:51, RX_VIDEO_SESSION(0,0:TEST-VIDEO): fps 56.000071 frames 560 pkts 2353441
MT: 2023-11-30 10:17:51, RX_VIDEO_SESSION(0,0:TEST-VIDEO): throughput 2491.410880 Mb/s, cpu busy 2.723031
MT: 2023-11-30 10:17:51, RX_VIDEO_SESSION(0,0): incomplete frames 20, pkts (idx error: 0, offset error: 0, idx out of bitmap: 0, missed: 33254)
MT: 2023-11-30 10:17:51, rtcp_rx_stat(RV_M0S0P0), rtp recv 2353436 lost 328 nack sent 3
MT: 2023-11-30 10:17:51, RX_AUDIO_SESSION(0,0:Test Audio): fps 1000.001844, st30 received frames 10000, received pkts 10000
MT: 2023-11-30 10:17:51, * *    E N D    S T A T E   * * 

MT: 2023-11-30 10:18:01, * *    M T    D E V   S T A T E   * * 
MT: 2023-11-30 10:18:01, DEV(0): Avr rate, tx: 0.000144 Mb/s, rx: 2618.067174 Mb/s, pkts, tx: 3, rx: 2362111
MT: 2023-11-30 10:18:01, Error: DEV(0): Status: rx_hw_dropped_packets 115862 rx_err_packets 0 rx_nombuf_packets 0 tx_err_packets 0
MT: 2023-11-30 10:18:01, Error: rx_good_packets: 527
MT: 2023-11-30 10:18:01, Error: rx_good_bytes: 694764
MT: 2023-11-30 10:18:01, Error: rx_bytes: 353746
MT: 2023-11-30 10:18:01, Error: rx_multicast_packets: 267
MT: 2023-11-30 10:18:01, CNI(0): eth_rx_rate 0.000661 Mb/s, eth_rx_cnt 2
MT: 2023-11-30 10:18:01, PTP(0): time 1701357481697944957, 2023-11-30 10:18:01
MT: 2023-11-30 10:18:01, RX_VIDEO_SESSION(0,0:TEST-VIDEO): fps 55.999881 frames 560 pkts 2353152
MT: 2023-11-30 10:18:01, RX_VIDEO_SESSION(0,0:TEST-VIDEO): throughput 2491.104883 Mb/s, cpu busy 2.711157
MT: 2023-11-30 10:18:01, RX_VIDEO_SESSION(0,0): incomplete frames 20, pkts (idx error: 0, offset error: 0, idx out of bitmap: 0, missed: 33552)
MT: 2023-11-30 10:18:01, rtcp_rx_stat(RV_M0S0P0), rtp recv 2353149 lost 208 nack sent 2
MT: 2023-11-30 10:18:01, RX_AUDIO_SESSION(0,0:Test Audio): fps 999.997456, st30 received frames 10000, received pkts 10000
MT: 2023-11-30 10:18:01, * *    E N D    S T A T E   * *

Since the sender is also an MTL utilizing application here are the TX logs:

MT: 2023-11-30 10:15:50, dev_eal_init(0), port_param: 0000:18:01.0
MT: 2023-11-30 10:15:50, dev_eal_init, wait eal_init_thread done
EAL: Detected CPU lcores: 64
EAL: Detected NUMA nodes: 1
EAL: Detected shared linkage of DPDK
EAL: Selected IOVA mode 'VA'
EAL: 4023 hugepages of size 2097152 reserved, but no mounted hugetlbfs found for that size
EAL: No free 1048576 kB hugepages reported on node 0
EAL: VFIO support initialized
EAL: Using IOMMU type 1 (Type 1)
EAL: Probe PCI driver: net_ice_dcf (8086:1889) device: 0000:18:01.0 (socket 0)
EAL: Releasing PCI mapped resource for 0000:18:01.0
EAL: Calling pci_unmap_resource for 0000:18:01.0 at 0x2180800000
EAL: Calling pci_unmap_resource for 0000:18:01.0 at 0x2180820000
EAL: Using IOMMU type 1 (Type 1)
EAL: Probe PCI driver: net_iavf (8086:1889) device: 0000:18:01.0 (socket 0)
TELEMETRY: No legacy callbacks, legacy socket not created
MT: 2023-11-30 10:15:56, st version: 23.12.0 Sun Nov 19 21:36:58 2023 2022.11.1-1272-gf4b85819-dirty gcc-12.2.0, dpdk version: DPDK 23.03.0
MT: 2023-11-30 10:15:56, mt_instance_init, succ
MT: 2023-11-30 10:15:56, mtl_init(0), socket_id 0 port 0000:18:01.0
MT: 2023-11-30 10:15:56, mt_stat_init, stat period 10s
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), use mt ptp source
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), user request queues tx 2 rx 0
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), deprecated sessions tx 0 rx 0
MT: 2023-11-30 10:15:56, stat_thread, start
MT: 2023-11-30 10:15:56, dev_config_port(0), tx_q(3 with 512 desc) rx_q (3 with 2048 desc)
MT: 2023-11-30 10:15:56, mt_mempool_create_by_ops(0), succ at 0x11804fdf00 size 3.234375m n 1536 d 2048 for T_P0_SYS_0
MT: 2023-11-30 10:15:56, dev_if_init_tx_queues(0), tx_queues 3 malloc succ
MT: 2023-11-30 10:15:56, mt_mempool_create_by_ops(0), succ at 0x1180afdf00 size 6.468750m n 3072 d 2048 for R_P0Q0_MBUF_1
MT: 2023-11-30 10:15:56, mt_mempool_create_by_ops(0), succ at 0x11814fdf00 size 4.968750m n 3072 d 1536 for R_P0Q1_MBUF_2
MT: 2023-11-30 10:15:56, mt_mempool_create_by_ops(0), succ at 0x1181cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q2_MBUF_3
MT: 2023-11-30 10:15:56, dev_if_init_rx_queues(0), rx_queues 3 malloc succ
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), port_id 0 port_type 1 drv_type 3
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), dev_capa 0x0, offload 0x119fbf:0x9266f queue offload 0x0:0x0, rss : 0x3ffc
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), system_rx_queues_end 1 hdr_split_rx_queues_end 1
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), sip: 192.168.200.50
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), netmask: 255.255.255.0
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), gateway: 0.0.0.0
MT: 2023-11-30 10:15:56, mt_dev_if_init(0), mac: 96:03:6d:60:4b:b7
iavf_configure_queues(): request RXDID[22] in Queue[0]
iavf_configure_queues(): request RXDID[22] in Queue[1]
iavf_configure_queues(): request RXDID[22] in Queue[2]
MT: 2023-11-30 10:15:56, dev_start_port(0), rx_defer 0
MT: 2023-11-30 10:15:56, mt_eth_link_dump(0), link_speed 10g link_status 1 link_duplex 1 link_autoneg 1
MT: 2023-11-30 10:15:56, dev_rl_shaper_add(0), bps 134217728 on shaper 1
MT: 2023-11-30 10:15:56, dev_init_ratelimit_all(0), q 0 link to shaper id 1
MT: 2023-11-30 10:15:56, dev_init_ratelimit_all(0), q 1 link to shaper id 1
MT: 2023-11-30 10:15:56, dev_init_ratelimit_all(0), q 2 link to shaper id 1
MT: 2023-11-30 10:15:56, mt_dev_create(0), feature 0x30, tx pacing ratelimit
MT: 2023-11-30 10:15:56, mt_sch_mrg_init, succ with data quota 31068 M, nb_tasklets 16
MT: 2023-11-30 10:15:56, mt_sch_add_quota(0:0), quota 0 total now 0
MT: 2023-11-30 10:15:56, mt_dev_get_tx_queue(0), q 0 with speed 1.073742g bps
MT: 2023-11-30 10:15:56, mt_mcast_init, report every 10 seconds
MT: 2023-11-30 10:15:56, mt_dev_get_rx_queue(0), q 0 ip 0.0.0.0 port 0
MT: 2023-11-30 10:15:56, cni_queues_init(0), rxq 0
MT: 2023-11-30 10:15:56, mt_sch_register_tasklet(0), tasklet cni registered into slot 0
MT: 2023-11-30 10:15:56, cni_traffic_thread, start
MT: 2023-11-30 10:15:56, st_plugins_init, succ
MT: 2023-11-30 10:15:56, admin_thread, start
MT: 2023-11-30 10:15:56, Warn: config_parse_json, open json file kahawai.json fail
MT: 2023-11-30 10:15:56, mt_ptp_port_id(0), port_number: 0000, clk_id: 96:03:6d:ff:fe:60:4b:b7
MT: 2023-11-30 10:15:56, mt_main_create, succ
MT: 2023-11-30 10:15:56, mtl_init, succ, tsc_hz 2300000000
MT: 2023-11-30 10:15:56, mtl_init, simd level avx512_vbmi, flags 0x0
MT: 2023-11-30 10:15:56, st20p_tx_create, start for TEST-VIDEO
MT: 2023-11-30 10:15:56, st20_get_converter, plugin not found, input fmt: YUV422PLANAR10LE, output fmt: YUV422RFC4175PG2BE10
MT: 2023-11-30 10:15:56, tx_st20p_get_converter(0), use internal converter
MT: 2023-11-30 10:15:56, tx_st20p_init_src_fbs(0), size 8294400 fmt 0 with 2 frames
MT: 2023-11-30 10:15:56, st20_tx_create, start for TEST-VIDEO
MT: 2023-11-30 10:15:56, mt_sch_add_quota(0:0), quota 2592 total now 2592
MT: 2023-11-30 10:15:56, mt_sch_get(0), succ with quota_mbs 2592
MT: 2023-11-30 10:15:56, mt_sch_register_tasklet(0), tasklet tx_video_sessions_mgr registered into slot 1
MT: 2023-11-30 10:15:56, tv_mgr_init(0), succ
MT: 2023-11-30 10:15:56, mt_sch_register_tasklet(0), tasklet video_transmitter registered into slot 2
MT: 2023-11-30 10:15:56, st_video_transmitter_init(0), succ
MT: 2023-11-30 10:15:56, tv_attach(0), st21_vrx_narrow: 9, st21_vrx_wide: 823
MT: 2023-11-30 10:15:56, mt_mempool_create_by_ops(0), succ at 0x11834fdf00 size 0.281250m n 1024 d 128 for TV_M0S0P0_HDR_0_4
MT: 2023-11-30 10:15:56, mt_mempool_create_by_ops(0), succ at 0x11836fdf00 size 0.125000m n 1024 d 0 for TV_M0S0_CHAIN_0_5
MT: 2023-11-30 10:15:56, dev_rl_shaper_add(0), bps 326401800 on shaper 2
MT: 2023-11-30 10:15:56, dev_tx_queue_set_rl_rate(0), q 1 link to shaper id 2(326401800)
MT: 2023-11-30 10:15:56, mt_dev_get_tx_queue(0), q 1 with speed 2.611214g bps
MT: 2023-11-30 10:15:56, tv_init_hw(0,0), port(l:0,p:0), queue 1, count 512
MT: 2023-11-30 10:15:56, tv_init_hw(0), type 0 number 3086 size 1322
MT: 2023-11-30 10:15:56, tv_init_hw(0), type 1 number 1028 size 1328
MT: 2023-11-30 10:15:56, tv_init_hw(0), type 2 number 1 size 422
MT: 2023-11-30 10:15:56, tv_init_hdr(0,0), ip 239.66.1.1 port 5000:5000
MT: 2023-11-30 10:15:56, tv_init_hdr(0), mac: 01:00:5e:42:01:01, ssrc 1193040
MT: 2023-11-30 10:15:57, mt_calibrate_tsc, tscHz 2300002421
MT: 2023-11-30 10:15:57, tv_train_pacing(0,0), trained pad_interval 350.673340 pkts_per_frame 4126.734567 with time 0.636767s
MT: 2023-11-30 10:15:57, tv_init_pacing[00], trs 3888.213852 trOffset 637037.037037 vrx 5 warm_pkts 128 frame time 16.666667ms fps 60.000000
MT: 2023-11-30 10:15:57, tv_attach(0), len 1260(1322) total 4115 each line 0 type 0 flags 0x10, progressive
MT: 2023-11-30 10:15:57, tv_attach(0), w 1920 h 1080 fmt ST20_FMT_YUV_422_10BIT packing 0 pt 112, pacing way: ratelimit
MT: 2023-11-30 10:15:57, st20_tx_create(0,0), succ on 0x11803368c0
MT: 2023-11-30 10:15:57, st20p_tx_create(0), transport fmt ST20_FMT_YUV_422_10BIT, input fmt: YUV422PLANAR10LE
MT: 2023-11-30 10:15:57, st30_tx_create, start for Test Audio
MT: 2023-11-30 10:15:57, mt_sch_add_quota(0:0), quota 103 total now 2695
MT: 2023-11-30 10:15:57, mt_sch_get(0), succ with quota_mbs 103
MT: 2023-11-30 10:15:57, mt_sch_register_tasklet(0), tasklet tx_audio_sessions_build registered into slot 3
MT: 2023-11-30 10:15:57, mt_sch_register_tasklet(0), tasklet tx_audio_sessions_trans registered into slot 4
MT: 2023-11-30 10:15:57, tx_audio_sessions_mgr_init(0), succ
MT: 2023-11-30 10:15:57, mt_sch_register_tasklet(0), tasklet audio_transmitter registered into slot 5
MT: 2023-11-30 10:15:57, st_audio_transmitter_init(0), succ
MT: 2023-11-30 10:15:57, mt_dev_get_tx_queue(0), q 2 with speed 1.073742g bps
MT: 2023-11-30 10:15:57, tx_audio_sessions_mgr_init_hw(0,0), succ, queue 2
MT: 2023-11-30 10:15:57, tx_audio_session_init_pacing[00], trs 1000000.000000 pkt_time_sampling 48.000000
MT: 2023-11-30 10:15:57, tx_audio_session_init_hdr(0,0), ip 239.66.1.3 port 5000:5000
MT: 2023-11-30 10:15:57, tx_audio_session_init_hdr(0), mac: 01:00:5e:42:01:03, ssrc 2241616
MT: 2023-11-30 10:15:57, mt_mempool_create_by_ops(0), succ at 0x1183e0c480 size 0.421875m n 1536 d 128 for TA_M0S0P0_HDR_0_6
MT: 2023-11-30 10:15:57, mt_mempool_create_by_ops(0), succ at 0x118380c480 size 1.125000m n 1536 d 640 for TA_M0S0_CHAIN_0_7
MT: 2023-11-30 10:15:57, tx_audio_session_init_trans_ring(0,0), trans_ring_thresh 10
MT: 2023-11-30 10:15:57, tx_audio_session_attach(0), pkt_len 576 frame_size 576 fps 1000.000000
MT: 2023-11-30 10:15:57, st30_tx_create(0,0), succ on 0x1181e00b00
MT: 2023-11-30 10:15:57, sch_tasklet_func(0), start with 6 tasklets
MT: 2023-11-30 10:15:57, sch_start(0), succ on lcore 2
MT: 2023-11-30 10:15:57, mt_dev_start, succ
MT: 2023-11-30 10:15:57, _mt_start, succ, avail ports 1
MT: 2023-11-30 10:15:57, cni_traffic_thread, stop
MT: 2023-11-30 10:15:57, video_trs_tasklet_start(0), succ
MT: 2023-11-30 10:15:57, st_audio_trs_tasklet_start(0), succ
MT: 2023-11-30 10:16:06, * *    M T    D E V   S T A T E   * * 
MT: 2023-11-30 10:16:06, DEV(0): Avr rate, tx: 2278.404974 Mb/s, rx: 0.000661 Mb/s, pkts, tx: 2156798, rx: 2
MT: 2023-11-30 10:16:06, CNI(0): eth_rx_rate 0.000661 Mb/s, eth_rx_cnt 2
MT: 2023-11-30 10:16:06, PTP(0): time 1701357366037212709, 2023-11-30 10:16:06
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0:TEST-VIDEO): fps 59.081732, frame 522 pkts 2150156:2149119 inflight 128877:128940
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0): throughput 2575.046148 Mb/s: 0.000000 Mb/s, cpu busy 76.093338
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0): dummy pkts 522, burst 522
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0): mismatch epoch troffset 3
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0): epoch drop 7
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0): build timeout frames 1
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0): busy as no ready frame from user 2
MT: 2023-11-30 10:16:06, TX_VIDEO_SESSION(0,0): tx done for cleanup 512
MT: 2023-11-30 10:16:06, TX_AUDIO_SESSION(0,0:Test Audio): fps 987.870845 frame cnt 8728, pkt cnt 8728, inflight count 0: 0
MT: 2023-11-30 10:16:06, TX_AUDIO_SESSION(0,0): epoch mismatch 10
MT: 2023-11-30 10:16:06, TX_AUDIO_SESSION(0,0): epoch drop 117
MT: 2023-11-30 10:16:06, TX_AUDIO_MGR(0), pkts burst 8716
MT: 2023-11-30 10:16:06, * *    E N D    S T A T E   * * 

MT: 2023-11-30 10:16:16, * *    M T    D E V   S T A T E   * * 
MT: 2023-11-30 10:16:16, DEV(0): Avr rate, tx: 2618.222990 Mb/s, rx: 0.000661 Mb/s, pkts, tx: 2478470, rx: 2
MT: 2023-11-30 10:16:16, CNI(0): eth_rx_rate 0.000661 Mb/s, eth_rx_cnt 2
MT: 2023-11-30 10:16:16, PTP(0): time 1701357376037226446, 2023-11-30 10:16:16
MT: 2023-11-30 10:16:16, TX_VIDEO_SESSION(0,0:TEST-VIDEO): fps 60.000128, frame 600 pkts 2469608:2469008 inflight 148099:148206
MT: 2023-11-30 10:16:16, TX_VIDEO_SESSION(0,0): throughput 2613.757093 Mb/s: 0.000000 Mb/s, cpu busy 76.087547
MT: 2023-11-30 10:16:16, TX_VIDEO_SESSION(0,0): dummy pkts 600, burst 600
MT: 2023-11-30 10:16:16, TX_AUDIO_SESSION(0,0:Test Audio): fps 1000.004050 frame cnt 10000, pkt cnt 10000, inflight count 0: 0
MT: 2023-11-30 10:16:16, TX_AUDIO_SESSION(0,0): epoch mismatch 10
MT: 2023-11-30 10:16:16, TX_AUDIO_MGR(0), pkts burst 10000
MT: 2023-11-30 10:16:16, * *    E N D    S T A T E   * * 

MT: 2023-11-30 10:16:26, * *    M T    D E V   S T A T E   * * 
MT: 2023-11-30 10:16:26, DEV(0): Avr rate, tx: 2618.230398 Mb/s, rx: 0.000661 Mb/s, pkts, tx: 2478477, rx: 2
MT: 2023-11-30 10:16:26, CNI(0): eth_rx_rate 0.000661 Mb/s, eth_rx_cnt 2
MT: 2023-11-30 10:16:26, PTP(0): time 1701357386037286801, 2023-11-30 10:16:26
MT: 2023-11-30 10:16:26, TX_VIDEO_SESSION(0,0:TEST-VIDEO): fps 59.999835, frame 600 pkts 2469608:2469008 inflight 147865:147974
MT: 2023-11-30 10:16:26, TX_VIDEO_SESSION(0,0): throughput 2613.744322 Mb/s: 0.000000 Mb/s, cpu busy 76.091873
MT: 2023-11-30 10:16:26, TX_VIDEO_SESSION(0,0): dummy pkts 600, burst 600
MT: 2023-11-30 10:16:26, TX_AUDIO_SESSION(0,0:Test Audio): fps 999.997600 frame cnt 10000, pkt cnt 10000, inflight count 0: 0
MT: 2023-11-30 10:16:26, TX_AUDIO_SESSION(0,0): epoch mismatch 10
MT: 2023-11-30 10:16:26, TX_AUDIO_MGR(0), pkts burst 10000
MT: 2023-11-30 10:16:26, * *    E N D    S T A T E   * *
frankdjx commented 12 months ago

There are many rx_hw_dropped_packets errors which usually caused by software is not fetching the packet in time.

Can you run below command and share us the log to analyze the possible cause? Tweak the PCIE port in 1080p59_1v.json to the actual ports in your setup.

./build/app/RxTxApp --config_file tests/script/loop_json/1080p59_1v.json --tasklet_time
sammirata commented 9 months ago

This was solved. It was an issue inside our app related with thread priorities under linux. Please feel free to close this issue.

frankdjx commented 9 months ago

Thanks to let's know the cause. We has a ebpf tool https://github.com/OpenVisualCloud/Media-Transport-Library/blob/main/tools/ebpf/lcore_monitor.c which can be used to monitor the IMTL lcore status.

Free to open a new one if any other issue.