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
161 stars 51 forks source link

Incomplete frames at Rx in the very beginning #930

Closed weic6 closed 1 month ago

weic6 commented 1 month ago

Dear MTL team,

Thanks for sharing your great work. I am trying to set up MTL library in both of my servers. i plan to use the FFmpeg plugin to transport ST2110 media.

I have two servers (A, B), where server A uses Ethernet Controller 10-Gigabit X540-AT2 1528 and server B uses Ethernet Controller 10G X550T 1563. Both NICs use ixgbe driver, which is supported by DPDK. For now, I connected X540-AT2 NIC port to X550 port directly with a cable 5e, just for testing purpose.

To run your application, I have followed the build guide (except that I choose to bind PF to DPDK PMD, not VF) and run guide. I have added MT_DRV_IXGBE in enum mt_driver_type, and I also add the following in struct mt_dev_driver_info dev_drvs

    {
        .name = "net_ixgbe", /* For ixgbe */
        .port_type = MT_PORT_PF,
        .drv_type = MT_DRV_IXGBE,
        .flow_type = MT_FLOW_NONE, /* tried MT_FLOW_ALL, but did not work in my case */
    },

The sample application RxTxApp can run successfully between the two servers using commands.

#Rx 
serverA $ ./build/app/RxTxApp --config_file config/rx_1v.json

#Tx
serverB $ ./build/app/RxTxApp --config_file config/tx_1v.json

I can also view the transmitted video at the Rx side using python3 python/example/st20p_rx.py.

However, when i try to run the MTL-built FFmpeg with the following commands, the Rx side always gets incomplete frames at the beginning of transmission. I wonder if you could provide any insight about how to make ffmpeg work for my case. Thank you.

FFmpeg Commands

Tx command

# Tx at server B
serverB $ ffmpeg -f lavfi -i "smptehdbars=rate=30:size=1920x1080" -f rawvideo -pix_fmt yuv422p10le -p_port 0000:01:00.0 -p_sip 192.168.30.10 -p_tx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -f mtl_st20p -

Tx output

ffmpeg version n6.1.1-157-gbbbc5d67f0 Copyright (c) 2000-2023 the FFmpeg developers
  built with gcc 9 (Ubuntu 9.4.0-1ubuntu1~20.04.2)
  configuration: --enable-shared --disable-static --enable-nonfree --enable-pic --enable-gpl --enable-libopenh264 --enable-encoder=libopenh264 --enable-mtl
  libavutil      58. 29.100 / 58. 29.100
  libavcodec     60. 31.102 / 60. 31.102
  libavformat    60. 16.100 / 60. 16.100
  libavdevice    60.  3.100 / 60.  3.100
  libavfilter     9. 12.100 /  9. 12.100
  libswscale      7.  5.100 /  7.  5.100
  libswresample   4. 12.100 /  4. 12.100
  libpostproc    57.  3.100 / 57.  3.100
Input #0, lavfi, from 'smptehdbars=rate=30:size=1920x1080':
  Duration: N/A, start: 0.000000, bitrate: N/A
  Stream #0:0: Video: wrapped_avframe, yuv420p, 1920x1080 [SAR 1:1 DAR 16:9], 30 fps, 30 tbr, 30 tbn
Stream mapping:
  Stream #0:0 -> #0:0 (wrapped_avframe (native) -> rawvideo (native))
Press [q] to stop, [?] for help
MTL: 2024-07-16 17:06:05, dev_eal_init(0), port_param: 0000:01:00.0
MTL: 2024-07-16 17:06:05, dev_eal_init, main_lcore: 0
MTL: 2024-07-16 17:06:05, dev_eal_init, wait eal_init_thread done
EAL: Detected CPU lcores: 12
EAL: Detected NUMA nodes: 1
EAL: Detected shared linkage of DPDK
EAL: Selected IOVA mode 'VA'
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_ixgbe (8086:1563) device: 0000:01:00.0 (socket -1)
TELEMETRY: No legacy callbacks, legacy socket not created
MTL: 2024-07-16 17:06:05, mtl_init, MTL version: 24.12.0.DEV Thu Jun 27 14:56:51 2024 bbf9847d-dirty gcc-9.4.0, dpdk version: DPDK 23.11.0
MTL: 2024-07-16 17:06:05, mtl_init, MTL_HAS_USDT is defined for this build
MTL: 2024-07-16 17:06:05, mt_dev_get_socket_id, direct soc_id from SOCKET_ID_ANY to 0 for 0000:01:00.0
MTL: 2024-07-16 17:06:05, Warn: mt_instance_init, connect to manager fail, assume single instance mode
MTL: 2024-07-16 17:06:05, mtl_init(0), socket_id 0 port 0000:01:00.0
MTL: 2024-07-16 17:06:05, stat_thread, start
MTL: 2024-07-16 17:06:05, mt_stat_init, stat period 10s
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), use mt ptp source
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), user request queues tx 8 rx 8
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), deprecated sessions tx 0 rx 0
MTL: 2024-07-16 17:06:05, dev_config_port(0), tx_q(9 with 512 desc) rx_q (9 with 2048 desc)
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x118043b6c0 size 3.234375m n 1536 d 2048 for T_P0_SYS_0
MTL: 2024-07-16 17:06:05, dev_if_init_tx_queues(0), tx_queues 9 malloc succ
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x1180218580 size 6.468750m n 3072 d 2048 for R_P0Q0_MBUF_1
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x11814fdf00 size 4.968750m n 3072 d 1536 for R_P0Q1_MBUF_2
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x1181cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q2_MBUF_3
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x11824fdf00 size 4.968750m n 3072 d 1536 for R_P0Q3_MBUF_4
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x1182cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q4_MBUF_5
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x11834fdf00 size 4.968750m n 3072 d 1536 for R_P0Q5_MBUF_6
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x1183cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q6_MBUF_7
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x11844fdf00 size 4.968750m n 3072 d 1536 for R_P0Q7_MBUF_8
MTL: 2024-07-16 17:06:05, mt_mempool_create_by_ops(0), succ at 0x1184cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q8_MBUF_9
MTL: 2024-07-16 17:06:05, dev_if_init_rx_queues(0), rx_queues 9 malloc succ
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), port_id 0 port_type 2 drv_type 2
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), dev_capa 0x0, offload 0x280bf:0x9a65f queue offload 0x0:0x1, rss : 0x38d34
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), system_rx_queues_end 1 hdr_split_rx_queues_end 1
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), sip: 192.168.30.10
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), netmask: 255.255.255.0
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), gateway: 0.0.0.0
MTL: 2024-07-16 17:06:05, mt_dev_if_init(0), mac: 98:b7:85:01:95:14
MTL: 2024-07-16 17:06:06, dev_config_rss_reta(0), reta size 512
MTL: 2024-07-16 17:06:06, dev_start_port(0), rx_defer 0
MTL: 2024-07-16 17:06:15, * *    M T    D E V   S T A T E   * * 
MTL: 2024-07-16 17:06:15, * *    E N D    S T A T E   * * 

MTL: 2024-07-16 17:06:16, mt_eth_link_dump(0), link_speed 0g link_status 0 link_duplex 0 link_autoneg 1
MTL: 2024-07-16 17:06:16, Error: dev_detect_link(0), link not connected for 0000:01:00.0
MTL: 2024-07-16 17:06:16, Error: mt_dev_create(0), dev_detect_link fail -5 retry 0
MTL: 2024-07-16 17:06:16, dev_config_port(0), tx_q(9 with 512 desc) rx_q (9 with 2048 desc)
MTL: 2024-07-16 17:06:16, dev_config_rss_reta(0), reta size 512
MTL: 2024-07-16 17:06:16, dev_start_port(0), rx_defer 0
MTL: 2024-07-16 17:06:16, Error: mt_dev_create(0), sleep 5s before detect link
MTL: 2024-07-16 17:06:21, mt_eth_link_dump(0), link_speed 10g link_status 1 link_duplex 1 link_autoneg 1
MTL: 2024-07-16 17:06:21, dev_if_init_pacing(0), use tsc as default
MTL: 2024-07-16 17:06:21, mt_dev_create(0), feature 0x30, tx pacing tsc
MTL: 2024-07-16 17:06:21, sch_lcore_shm_init, clear shm as we are the first user
MTL: 2024-07-16 17:06:21, sch_lcore_shm_init, shared memory attached at 0x7f1d401dc000 nattch 1 shm_id 196614 key 0x15050005
MTL: 2024-07-16 17:06:21, mt_sch_mrg_init, succ with data quota 31068 M
MTL: 2024-07-16 17:06:21, sch_request(0), name sch_0 with 16 tasklets, type 0 socket 0
MTL: 2024-07-16 17:06:21, mt_sch_add_quota(0:0), quota 0 total now 0
MTL: 2024-07-16 17:06:21, mt_sch_add_quota(0:0), quota 0 total now 0
MTL: 2024-07-16 17:06:21, mt_sch_get_by_socket(0), succ with quota_mbs 0 socket 0
MTL: 2024-07-16 17:06:21, mtl_sch_register_tasklet(0), tasklet shared_rss registered into slot 0
MTL: 2024-07-16 17:06:21, mt_srss_init(0), sch 0 with queues start 0 end 9
MTL: 2024-07-16 17:06:21, mt_srss_init(0), succ with shared rss mode
MTL: 2024-07-16 17:06:21, srss_traffic_thread, start
MTL: 2024-07-16 17:06:21, mt_dev_get_tx_queue(0), q 0 without rl
MTL: 2024-07-16 17:06:21, mt_mcast_init, report every 10 seconds
MTL: 2024-07-16 17:06:21, mt_srss_get(0), entry 0.0.0.0:(dst)0 on 0 of list 0
MTL: 2024-07-16 17:06:21, cni_queues_init(0), rxq 0
MTL: 2024-07-16 17:06:21, cni_traffic_thread, start
MTL: 2024-07-16 17:06:21, st_plugins_init, succ
MTL: 2024-07-16 17:06:21, admin_thread, start
MTL: 2024-07-16 17:06:21, config_parse_json, parse kahawai.json with json-c version: 0.16
MTL: 2024-07-16 17:06:21, st22_decoder_register(0), st22_decoder_sample registered, device 1 cap(0x300000000000000:0x70000402b)
MTL: 2024-07-16 17:06:21, st22_encoder_register(0), st22_encoder_sample registered, device 1 cap(0x70000402b:0x300000000000000)
st_plugin_create, succ with st22 sample plugin
MTL: 2024-07-16 17:06:21, st_plugin_register(0), /usr/local/lib/x86_64-linux-gnu/libst_plugin_st22_sample.so registered, version 1
MTL: 2024-07-16 17:06:21, Warn: st_plugin_register, dlopen /usr/local/lib64/libst_plugin_st22_sample.so fail
MTL: 2024-07-16 17:06:21, mt_ptp_port_id(0), port_number: 0000, clk_id: 98:b7:85:ff:fe:01:95:14
MTL: 2024-07-16 17:06:21, mt_main_create, succ
MTL: 2024-07-16 17:06:21, mtl_init, succ, tsc_hz 3700000000
MTL: 2024-07-16 17:06:21, mtl_init, simd level avx2, flags 0x1d
[mtl_st20p @ 0x5578836c58c0] mtl_dev_get, handle 0x1180541a00 ref cnt 1
MTL: 2024-07-16 17:06:22, mt_calibrate_tsc, tscHz 3696031179
MTL: 2024-07-16 17:06:22, mt_sch_get_lcore, succ on shm lcore 1 for lib_sch socket 0
MTL: 2024-07-16 17:06:22, sch_start(0), succ on lcore 1 socket 0
MTL: 2024-07-16 17:06:22, mt_dev_start, succ
MTL: 2024-07-16 17:06:22, sch_tasklet_func(0), start with 1 tasklets, t_pid 191902
MTL: 2024-07-16 17:06:22, _mt_start, succ, avail ports 1
MTL: 2024-07-16 17:06:22, st20p_tx_create, start for st20p_ffmpge
MTL: 2024-07-16 17:06:22, st20_get_converter, plugin not found, input fmt: YUV422PLANAR10LE, output fmt: YUV422RFC4175PG2BE10
MTL: 2024-07-16 17:06:22, tx_st20p_get_converter(0), use internal converter
MTL: 2024-07-16 17:06:22, srss_traffic_thread, stop
MTL: 2024-07-16 17:06:22, tx_st20p_init_src_fbs(0), size 8294400 fmt 0 with 3 frames
MTL: 2024-07-16 17:06:22, st20_tx_create, start for st20p_ffmpge
MTL: 2024-07-16 17:06:22, mt_sch_add_quota(0:0), quota 1296 total now 1296
MTL: 2024-07-16 17:06:22, mt_sch_get_by_socket(0), succ with quota_mbs 1296 socket 0
MTL: 2024-07-16 17:06:22, mtl_sch_register_tasklet(0), tasklet tx_video_sessions_mgr registered into slot 1
MTL: 2024-07-16 17:06:22, tv_mgr_init(0), succ
MTL: 2024-07-16 17:06:22, video_trs_tasklet_start(0), succ
MTL: 2024-07-16 17:06:22, mtl_sch_register_tasklet(0), tasklet video_transmitter registered into slot 2
MTL: 2024-07-16 17:06:22, st_video_transmitter_init(0), succ
MTL: 2024-07-16 17:06:22, tv_attach(0), st21_vrx_narrow: 8, st21_vrx_wide: 720
MTL: 2024-07-16 17:06:22, mt_mempool_create_by_ops(0), succ at 0x1186cfdf00 size 0.281250m n 1024 d 128 for TV_M0S0P0_HDR_0_10
MTL: 2024-07-16 17:06:22, mt_mempool_create_by_ops(0), succ at 0x1186efdf00 size 0.125000m n 1024 d 0 for TV_M0S0_CHAIN_0_11
MTL: 2024-07-16 17:06:22, mt_dev_get_tx_queue(0), q 1 without rl
MTL: 2024-07-16 17:06:22, tv_init_hw(0,0), port(l:0,p:0), queue 1, count 512
MTL: 2024-07-16 17:06:22, tv_init_hw(0), type 0 number 3086 size 1322
MTL: 2024-07-16 17:06:22, tv_init_hw(0), type 1 number 1028 size 1328
MTL: 2024-07-16 17:06:22, tv_init_hw(0), type 2 number 1 size 422
MTL: 2024-07-16 17:06:22, tv_init_hdr(0,0), ip 239.1.1.1 port 20000:20000
MTL: 2024-07-16 17:06:22, tv_init_hdr(0), mac: 01:00:5e:01:01:01, ssrc 1193040
MTL: 2024-07-16 17:06:22, tv_init_pacing[00], trs 7776.427704 trOffset 1274074.074074 vrx 5 warm_pkts 0 frame time 33.333333ms fps 30.000000
MTL: 2024-07-16 17:06:22, tv_attach(0), len 1260(1322) total 4115 each line 0 type 0 flags 0x0, progressive
MTL: 2024-07-16 17:06:22, tv_attach(0), w 1920 h 1080 fmt ST20_FMT_YUV_422_10BIT packing 0 pt 112, pacing way: tsc
MTL: 2024-07-16 17:06:22, st20_tx_create(0,0), succ on 0x1184600b80
MTL: 2024-07-16 17:06:22, st20p_tx_create(0), transport fmt ST20_FMT_YUV_422_10BIT, input fmt: YUV422PLANAR10LE, flags 0x8000
[mtl_st20p @ 0x5578836c58c0] mtl_st20p_write_header(0), tx_handle 0x1184602f40
Output #0, mtl_st20p, to 'pipe:':
  Metadata:
    encoder         : Lavf60.16.100
  Stream #0:0: Video: rawvideo (Y3[10][10] / 0xA0A3359), yuv422p10le(tv, bt709/unknown/unknown, progressive), 1920x1080 [SAR 1:1 DAR 16:9], q=2-31, 1244160 kb/s, 30 fps, 30 tbn
    Metadata:
      encoder         : Lavc60.31.102 rawvideo
MTL: 2024-07-16 17:06:25, * *    M T    D E V   S T A T E   * *  speed=0.143x     x    
MTL: 2024-07-16 17:06:25, DEV(0): Avr rate, tx: 376.747746 Mb/s, rx: 0.000000 Mb/s, pkts, tx: 355886, rx: 0
MTL: 2024-07-16 17:06:25, SCH(0:sch_0): tasklets 3, lcore 1(t_pid: 191902), avg loop 164 ns
MTL: 2024-07-16 17:06:25, srss_stat(0,0,0), enqueue 0 dequeue 0
MTL: 2024-07-16 17:06:25, srss_stat(0,0), pkts rx 0
MTL: 2024-07-16 17:06:25, CNI(0): eth_rx_rate 0.000000 Mb/s, eth_rx_cnt 0
MTL: 2024-07-16 17:06:25, PTP(0): time 1721167585950507748, 2024-07-16 17:06:25
MTL: 2024-07-16 17:06:25, TX_VIDEO_SESSION(0,0:st20p_ffmpge): fps 28.841305 frames 86 pkts 356458:0 inflight 88496:89008
MTL: 2024-07-16 17:06:25, TX_VIDEO_SESSION(0,0): throughput 1263.682297 Mb/s: 0.000000 Mb/s, cpu busy 0.000000
MTL: 2024-07-16 17:06:25, TX_VIDEO_SESSION(0,0): mismatch epoch troffset 2
MTL: 2024-07-16 17:06:25, TX_VIDEO_SESSION(0,0): epoch drop 2
MTL: 2024-07-16 17:06:25, TX_VIDEO_SESSION(0,0): build timeout frames 1
MTL: 2024-07-16 17:06:25, TX_VIDEO_SESSION(0,0): busy as no ready frame from user 1
MTL: 2024-07-16 17:06:25, TX_st20p(0,st20p_ffmpge), p(2:in_transmitting) c(0:converted)
MTL: 2024-07-16 17:06:25, TX_st20p(0), frame get try 90 succ 89, put 89
MTL: 2024-07-16 17:06:25, * *    E N D    S T A T E   * * 

MTL: 2024-07-16 17:06:33, Error: video_trs_burst_fail(0,0), hang duration 1000 ms
MTL: 2024-07-16 17:06:33, mt_ring_dequeue_clean, count 508 for ring TV_M0S0P0
MTL: 2024-07-16 17:06:33, Error: mt_dev_tx_queue_fatal_error(0), q 1 masked as fatal error
MTL: 2024-07-16 17:06:33, mt_dev_put_tx_queue(0), q 1
MTL: 2024-07-16 17:06:33, mt_dev_get_tx_queue(0), q 2 without rl
MTL: 2024-07-16 17:06:33, st20_tx_queue_fatal_error(0,0), new queue_id 2
MTL: 2024-07-16 17:06:33, st20_tx_queue_fatal_error(0,0), stop frame 1
MTL: 2024-07-16 17:06:33, Warn: mt_mempool_free, still has 260 mbuf in mempool TV_M0S0_CHAIN_0_11
MTL: 2024-07-16 17:06:33, Warn: mt_mempool_free, still has 261 mbuf in mempool TV_M0S0P0_HDR_0_10
MTL: 2024-07-16 17:06:33, mt_mempool_create_by_ops(0), succ at 0x1187c0c480 size 0.281250m n 1024 d 128 for TV_M0S0P0_HDR_1_12
MTL: 2024-07-16 17:06:33, mt_mempool_create_by_ops(0), succ at 0x118760c480 size 0.125000m n 1024 d 0 for TV_M0S0_CHAIN_1_13
[mtl_st20p @ 0x5578836c58c0] mtl_st20p_write_packet(0), st20p_tx_get_frame timeout
[vost#0:0/rawvideo @ 0x5578836c6680] Error submitting a packet to the muxer: Input/output error
[out#0/mtl_st20p @ 0x5578836c5440] Error muxing a packet
MTL: 2024-07-16 17:06:34, st20p_tx_free(0), start.16 bitrate=N/A speed=0.356x    
MTL: 2024-07-16 17:06:34, Error: video_trs_burst_fail(0,0), hang duration 1000 ms
MTL: 2024-07-16 17:06:34, mt_ring_dequeue_clean, count 508 for ring TV_M0S0P0
MTL: 2024-07-16 17:06:34, Error: mt_dev_tx_queue_fatal_error(0), q 2 masked as fatal error
MTL: 2024-07-16 17:06:34, mt_dev_put_tx_queue(0), q 2
MTL: 2024-07-16 17:06:34, mt_dev_get_tx_queue(0), q 3 without rl
MTL: 2024-07-16 17:06:34, st20_tx_queue_fatal_error(0,0), new queue_id 3
MTL: 2024-07-16 17:06:34, st20_tx_queue_fatal_error(0,0), stop frame 2
MTL: 2024-07-16 17:06:34, Warn: mt_mempool_free, still has 256 mbuf in mempool TV_M0S0_CHAIN_1_13
MTL: 2024-07-16 17:06:34, Warn: mt_mempool_free, still has 256 mbuf in mempool TV_M0S0P0_HDR_1_12
MTL: 2024-07-16 17:06:34, mt_mempool_create_by_ops(0), succ at 0x118700c480 size 0.281250m n 1024 d 128 for TV_M0S0P0_HDR_2_14
MTL: 2024-07-16 17:06:34, mt_mempool_create_by_ops(0), succ at 0x11882fdf00 size 0.125000m n 1024 d 0 for TV_M0S0_CHAIN_2_15
MTL: 2024-07-16 17:06:35, Error: video_trs_burst_fail(0,0), hang duration 1000 ms
MTL: 2024-07-16 17:06:35, mt_ring_dequeue_clean, count 508 for ring TV_M0S0P0
MTL: 2024-07-16 17:06:35, Error: mt_dev_tx_queue_fatal_error(0), q 3 masked as fatal error
MTL: 2024-07-16 17:06:35, mt_dev_put_tx_queue(0), q 3
MTL: 2024-07-16 17:06:35, mt_dev_get_tx_queue(0), q 4 without rl
MTL: 2024-07-16 17:06:35, st20_tx_queue_fatal_error(0,0), new queue_id 4
MTL: 2024-07-16 17:06:35, st20_tx_queue_fatal_error(0,0), stop frame 0
MTL: 2024-07-16 17:06:35, Warn: mt_mempool_free, still has 256 mbuf in mempool TV_M0S0_CHAIN_2_15
MTL: 2024-07-16 17:06:35, Warn: mt_mempool_free, still has 256 mbuf in mempool TV_M0S0P0_HDR_2_14
MTL: 2024-07-16 17:06:35, mt_mempool_create_by_ops(0), succ at 0x11884fdf00 size 0.281250m n 1024 d 128 for TV_M0S0P0_HDR_3_16
MTL: 2024-07-16 17:06:35, mt_mempool_create_by_ops(0), succ at 0x11886fdf00 size 0.125000m n 1024 d 0 for TV_M0S0_CHAIN_3_17
MTL: 2024-07-16 17:06:35, st20_tx_free(0,0), start
MTL: 2024-07-16 17:06:35, TX_VIDEO_SESSION(0,0:st20p_ffmpge): fps 20.648179 frames 206 pkts 848282:0 inflight 211238:211738
MTL: 2024-07-16 17:06:35, TX_VIDEO_SESSION(0,0): throughput 898.494772 Mb/s: 0.000000 Mb/s, cpu busy 0.507945
MTL: 2024-07-16 17:06:35, TX_VIDEO_SESSION(0,0): mismatch epoch troffset 3
MTL: 2024-07-16 17:06:35, TX_VIDEO_SESSION(0,0): epoch drop 90
MTL: 2024-07-16 17:06:35, TX_VIDEO_SESSION(0,0): recoverable_error 3 
MTL: 2024-07-16 17:06:35, mt_ring_dequeue_clean, count 508 for ring TV_M0S0P0
MTL: 2024-07-16 17:06:35, mt_dpdk_flush_tx_queue(0), queue 4 burst_pkts 1024
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, * *    M T    D E V   S T A T E   * * 
MTL: 2024-07-16 17:06:35, DEV(0): Avr rate, tx: 895.197307 Mb/s, rx: 0.000000 Mb/s, pkts, tx: 845619, rx: 0
MTL: 2024-07-16 17:06:35, SCH(0:sch_0): tasklets 3, lcore 1(t_pid: 191902), avg loop 177 ns
MTL: 2024-07-16 17:06:35, srss_stat(0,0,0), enqueue 0 dequeue 0
MTL: 2024-07-16 17:06:35, srss_stat(0,0), pkts rx 0
MTL: 2024-07-16 17:06:35, CNI(0): eth_rx_rate 0.000000 Mb/s, eth_rx_cnt 0
MTL: 2024-07-16 17:06:35, PTP(0): time 1721167595950603519, 2024-07-16 17:06:35
MTL: 2024-07-16 17:06:35, * *    E N D    S T A T E   * * 

MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:35, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
...
...
[many lines of messages: Warn: mt_dpdk_tx_burst_busy(0), fail as timeout to 1 ms]
...
...
MTL: 2024-07-16 17:06:37, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:37, Warn: mt_dpdk_tx_burst_busy(4), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:37, mt_dev_put_tx_queue(0), q 4
MTL: 2024-07-16 17:06:37, Warn: mt_mempool_free, still has 251 mbuf in mempool TV_M0S0_CHAIN_3_17
MTL: 2024-07-16 17:06:37, Warn: mt_mempool_free, still has 251 mbuf in mempool TV_M0S0P0_HDR_3_16
MTL: 2024-07-16 17:06:37, Warn: st_frame_trans_uinit(1), sh_info still active, refcnt 251
MTL: 2024-07-16 17:06:37, Warn: st_frame_trans_uinit(1), refcnt not zero 1
MTL: 2024-07-16 17:06:37, sch_free_quota(0), quota 1296 total now 0
MTL: 2024-07-16 17:06:37, st20_tx_free(0,0), succ
MTL: 2024-07-16 17:06:37, Warn: tx_st20p_uinit_src_fbs(0), frame 1 are still in in_transmitting
MTL: 2024-07-16 17:06:37, st20p_tx_free(0), succ
[mtl_st20p @ 0x5578836c58c0] mtl_instance_put, handle 0x1180541a00 ref cnt 0
[mtl_st20p @ 0x5578836c58c0] mtl_instance_put, ref cnt reach zero, uninit mtl device
MTL: 2024-07-16 17:06:37, video_trs_tasklet_stop(0), succ
MTL: 2024-07-16 17:06:37, sch_tasklet_func(0), end with 3 tasklets
MTL: 2024-07-16 17:06:37, srss_traffic_thread, start
MTL: 2024-07-16 17:06:37, mt_sch_put_lcore, succ on shm lcore 1 for lib_sch
MTL: 2024-07-16 17:06:37, sch_stop(0), succ
MTL: 2024-07-16 17:06:37, mt_sch_stop_all, succ
MTL: 2024-07-16 17:06:37, _mt_stop, succ
MTL: 2024-07-16 17:06:37, st22_decoder_unregister(0), unregister st22_decoder_sample
MTL: 2024-07-16 17:06:37, st22_encoder_unregister(0), unregister st22_encoder_sample
st_plugin_free, succ with st22 sample plugin
MTL: 2024-07-16 17:06:37, admin_thread, stop
MTL: 2024-07-16 17:06:37, cni_traffic_thread, stop
MTL: 2024-07-16 17:06:37, mt_srss_put(0), delete cni_entry 0
MTL: 2024-07-16 17:06:37, mt_srss_put(0), succ on 0
MTL: 2024-07-16 17:06:37, mt_cni_uinit, succ
MTL: 2024-07-16 17:06:37, sch_free_quota(0), quota 0 total now 0
MTL: 2024-07-16 17:06:37, mt_dpdk_flush_tx_queue(0), queue 0 burst_pkts 1024
MTL: 2024-07-16 17:06:38, Warn: mt_dpdk_tx_burst_busy(0), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:38, Warn: mt_dpdk_tx_burst_busy(0), fail as timeout to 1 ms
...
...
[many lines of messages: Warn: mt_dpdk_tx_burst_busy(0), fail as timeout to 1 ms]
...
...
MTL: 2024-07-16 17:06:39, Warn: mt_dpdk_tx_burst_busy(0), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:39, Warn: mt_dpdk_tx_burst_busy(0), fail as timeout to 1 ms
MTL: 2024-07-16 17:06:39, mt_dev_put_tx_queue(0), q 0
MTL: 2024-07-16 17:06:39, srss_traffic_thread, stop
MTL: 2024-07-16 17:06:39, mtl_sch_unregister_tasklet(0), tasklet shared_rss(0) unregistered
MTL: 2024-07-16 17:06:39, sch_free_quota(0), quota 0 total now 0
MTL: 2024-07-16 17:06:39, mt_sch_put(0), ref_cnt now zero
MTL: 2024-07-16 17:06:39, Warn: sch_stop(0), not started
MTL: 2024-07-16 17:06:39, mtl_sch_unregister_tasklet(0), tasklet video_transmitter(2) unregistered
MTL: 2024-07-16 17:06:39, st_video_transmitter_uinit(0), succ
MTL: 2024-07-16 17:06:39, mtl_sch_unregister_tasklet(0), tasklet tx_video_sessions_mgr(1) unregistered
MTL: 2024-07-16 17:06:39, tv_mgr_uinit(0), succ
MTL: 2024-07-16 17:06:39, sch_free(0), start to free sch: sch_0 
MTL: 2024-07-16 17:06:39, sch_lcore_shm_uinit, remove shared memory as we are the last user
MTL: 2024-07-16 17:06:39, dev_stop_port(0), succ
MTL: 2024-07-16 17:06:39, mt_dev_free, succ
MTL: 2024-07-16 17:06:39, mt_main_free, succ
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q0_MBUF_1
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q1_MBUF_2
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q2_MBUF_3
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q3_MBUF_4
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q4_MBUF_5
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q5_MBUF_6
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q6_MBUF_7
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q7_MBUF_8
MTL: 2024-07-16 17:06:39, mt_mempool_free, free mempool R_P0Q8_MBUF_9
MTL: 2024-07-16 17:06:39, Warn: mt_mempool_free, still has 2 mbuf in mempool T_P0_SYS_0
MTL: 2024-07-16 17:06:39, dev_close_port(0), succ
MTL: 2024-07-16 17:06:39, stat_thread, stop
MTL: 2024-07-16 17:06:39, mt_dev_uinit, succ
MTL: 2024-07-16 17:06:39, mtl_uninit, succ
[mtl_st20p @ 0x5578836c58c0] mtl_st20p_write_close(0), frame_counter 296
[out#0/mtl_st20p @ 0x5578836c5440] video:2405700kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
frame=  297 fps=8.6 q=-0.0 Lsize=N/A time=00:00:10.30 bitrate=N/A speed= 0.3x    
Conversion failed!

Rx command

# Rx at server A
serverA $ ffmpeg -p_port 0000:01:00.0 -p_sip 192.168.30.12 -p_rx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -fps 30 -pix_fmt yuv422p10le -video_size 1920x1080 -f mtl_st20p -i "k" -f rawvideo /dev/null -y

Rx output

ffmpeg version n6.1.1-157-gc60414a93d Copyright (c) 2000-2023 the FFmpeg developers
  built with gcc 9 (Ubuntu 9.4.0-1ubuntu1~20.04.2)
  configuration: --enable-shared --disable-static --enable-nonfree --enable-pic --enable-gpl --enable-libopenh264 --enable-encoder=libopenh264 --enable-mtl
  libavutil      58. 29.100 / 58. 29.100
  libavcodec     60. 31.102 / 60. 31.102
  libavformat    60. 16.100 / 60. 16.100
  libavdevice    60.  3.100 / 60.  3.100
  libavfilter     9. 12.100 /  9. 12.100
  libswscale      7.  5.100 /  7.  5.100
  libswresample   4. 12.100 /  4. 12.100
  libpostproc    57.  3.100 / 57.  3.100
MTL: 2024-07-16 17:06:11, dev_eal_init(0), port_param: 0000:01:00.0
MTL: 2024-07-16 17:06:11, dev_eal_init, main_lcore: 0
MTL: 2024-07-16 17:06:11, dev_eal_init, wait eal_init_thread done
EAL: Detected CPU lcores: 16
EAL: Detected NUMA nodes: 1
EAL: Detected shared linkage of DPDK
EAL: Selected IOVA mode 'VA'
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_ixgbe (8086:1528) device: 0000:01:00.0 (socket -1)
TELEMETRY: No legacy callbacks, legacy socket not created
MTL: 2024-07-16 17:06:12, mtl_init, MTL version: 24.12.0.DEV Tue Jul  9 17:50:43 2024 bbf9847d-dirty gcc-9.4.0, dpdk version: DPDK 23.11.0
MTL: 2024-07-16 17:06:12, mtl_init, MTL_HAS_USDT is defined for this build
MTL: 2024-07-16 17:06:12, mt_dev_get_socket_id, direct soc_id from SOCKET_ID_ANY to 0 for 0000:01:00.0
MTL: 2024-07-16 17:06:12, Warn: mt_instance_init, connect to manager fail, assume single instance mode
MTL: 2024-07-16 17:06:12, mtl_init(0), socket_id 0 port 0000:01:00.0
MTL: 2024-07-16 17:06:12, stat_thread, start
MTL: 2024-07-16 17:06:12, mt_stat_init, stat period 10s
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), use mt ptp source
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), user request queues tx 8 rx 8
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), deprecated sessions tx 0 rx 0
MTL: 2024-07-16 17:06:12, dev_config_port(0), tx_q(9 with 512 desc) rx_q (9 with 2048 desc)
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x118043b6c0 size 3.234375m n 1536 d 2048 for T_P0_SYS_0
MTL: 2024-07-16 17:06:12, dev_if_init_tx_queues(0), tx_queues 9 malloc succ
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x1180218580 size 6.468750m n 3072 d 2048 for R_P0Q0_MBUF_1
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x11814fdf00 size 4.968750m n 3072 d 1536 for R_P0Q1_MBUF_2
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x1181cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q2_MBUF_3
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x11824fdf00 size 4.968750m n 3072 d 1536 for R_P0Q3_MBUF_4
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x1182cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q4_MBUF_5
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x11834fdf00 size 4.968750m n 3072 d 1536 for R_P0Q5_MBUF_6
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x1183cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q6_MBUF_7
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x11844fdf00 size 4.968750m n 3072 d 1536 for R_P0Q7_MBUF_8
MTL: 2024-07-16 17:06:12, mt_mempool_create_by_ops(0), succ at 0x1184cfdf00 size 4.968750m n 3072 d 1536 for R_P0Q8_MBUF_9
MTL: 2024-07-16 17:06:12, dev_if_init_rx_queues(0), rx_queues 9 malloc succ
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), port_id 0 port_type 2 drv_type 2
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), dev_capa 0x0, offload 0x2a03f:0x9a69f queue offload 0x0:0x1, rss : 0x38d34
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), system_rx_queues_end 1 hdr_split_rx_queues_end 1
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), sip: 192.168.30.12
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), netmask: 255.255.255.0
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), gateway: 0.0.0.0
MTL: 2024-07-16 17:06:12, mt_dev_if_init(0), mac: 98:b7:85:01:ad:46
MTL: 2024-07-16 17:06:12, dev_config_rss_reta(0), reta size 128
MTL: 2024-07-16 17:06:12, dev_start_port(0), rx_defer 0
MTL: 2024-07-16 17:06:21, mt_eth_link_dump(0), link_speed 10g link_status 1 link_duplex 1 link_autoneg 1
MTL: 2024-07-16 17:06:21, dev_if_init_pacing(0), use tsc as default
MTL: 2024-07-16 17:06:21, mt_dev_create(0), feature 0x30, tx pacing tsc
MTL: 2024-07-16 17:06:21, sch_lcore_shm_init, clear shm as we are the first user
MTL: 2024-07-16 17:06:21, sch_lcore_shm_init, shared memory attached at 0x7f78706d2000 nattch 1 shm_id 32783 key 0x15050005
MTL: 2024-07-16 17:06:21, mt_sch_mrg_init, succ with data quota 31068 M
MTL: 2024-07-16 17:06:21, sch_request(0), name sch_0 with 16 tasklets, type 0 socket 0
MTL: 2024-07-16 17:06:21, mt_sch_add_quota(0:0), quota 0 total now 0
MTL: 2024-07-16 17:06:21, mt_sch_add_quota(0:0), quota 0 total now 0
MTL: 2024-07-16 17:06:21, mt_sch_get_by_socket(0), succ with quota_mbs 0 socket 0
MTL: 2024-07-16 17:06:21, mtl_sch_register_tasklet(0), tasklet shared_rss registered into slot 0
MTL: 2024-07-16 17:06:21, mt_srss_init(0), sch 0 with queues start 0 end 9
MTL: 2024-07-16 17:06:21, mt_srss_init(0), succ with shared rss mode
MTL: 2024-07-16 17:06:21, srss_traffic_thread, start
MTL: 2024-07-16 17:06:21, mt_dev_get_tx_queue(0), q 0 without rl
MTL: 2024-07-16 17:06:21, mt_mcast_init, report every 10 seconds
MTL: 2024-07-16 17:06:21, mt_srss_get(0), entry 0.0.0.0:(dst)0 on 0 of list 0
MTL: 2024-07-16 17:06:21, cni_queues_init(0), rxq 0
MTL: 2024-07-16 17:06:21, cni_traffic_thread, start
MTL: 2024-07-16 17:06:21, st_plugins_init, succ
MTL: 2024-07-16 17:06:21, admin_thread, start
MTL: 2024-07-16 17:06:21, Warn: config_parse_json, open json file kahawai.json fail
MTL: 2024-07-16 17:06:21, mt_ptp_port_id(0), port_number: 0000, clk_id: 98:b7:85:ff:fe:01:ad:46
MTL: 2024-07-16 17:06:21, mt_main_create, succ
MTL: 2024-07-16 17:06:21, mtl_init, succ, tsc_hz 3790000000
MTL: 2024-07-16 17:06:21, mtl_init, simd level avx2, flags 0x1d
[mtl_st20p @ 0x563691737c80] mtl_dev_get, handle 0x1180541a00 ref cnt 1
MTL: 2024-07-16 17:06:21, st20p_rx_create, start for st20p_rx_ffmpeg
MTL: 2024-07-16 17:06:21, st20_get_converter, plugin not found, input fmt: YUV422RFC4175PG2BE10, output fmt: YUV422PLANAR10LE
MTL: 2024-07-16 17:06:21, rx_st20p_get_converter(0), use internal converter
MTL: 2024-07-16 17:06:21, rx_st20p_init_dst_fbs(0), size 8294400 fmt 0 with 3 frames
MTL: 2024-07-16 17:06:21, mt_sch_add_quota(0:1), quota 1296 total now 1296
MTL: 2024-07-16 17:06:21, mt_sch_get_by_socket(0), succ with quota_mbs 1296 socket 0
MTL: 2024-07-16 17:06:21, mtl_sch_register_tasklet(0), tasklet rvs_pkt_rx registered into slot 1
MTL: 2024-07-16 17:06:21, rvs_mgr_init(0), succ
MTL: 2024-07-16 17:06:21, mt_srss_get(0), entry 239.1.1.1:(dst)20000 on 1 of list 29
MTL: 2024-07-16 17:06:21, rv_init_hw(0), port(l:0,p:0), queue 1 udp 20000
MTL: 2024-07-16 17:06:21, rv_init_dma(0), fail, can not request dma dev
MTL: 2024-07-16 17:06:21, mcast_membership_report_on_action(0), send join pkt, mb_report_len 16
MTL: 2024-07-16 17:06:21, mt_mcast_join(0), join group 239.1.1.1
MTL: 2024-07-16 17:06:21, rv_attach(0), 3 frames with size 5184000(810,0), type 0, progressive
MTL: 2024-07-16 17:06:21, rv_attach(0), w 1920 h 1080 fmt ST20_FMT_YUV_422_10BIT packing 0 pt 112 flags 0x20000 frame time 33.333333ms fps 30.000000
MTL: 2024-07-16 17:06:21, mt_sch_add_quota(0:1), quota 648 total now 1944
MTL: 2024-07-16 17:06:21, st20_rx_create_with_mask, succ on sch 0 session 0
MTL: 2024-07-16 17:06:21, st20p_rx_create(0), transport fmt ST20_FMT_YUV_422_10BIT, output fmt YUV422PLANAR10LE, flags 0x28000
MTL: 2024-07-16 17:06:22, * *    M T    D E V   S T A T E   * * 
MTL: 2024-07-16 17:06:22, DEV(0): Avr rate, tx: 0.000096 Mb/s, rx: 0.000000 Mb/s, pkts, tx: 2, rx: 0
MTL: 2024-07-16 17:06:22, SCH(0:sch_0): tasklets 2, lcore 0(t_pid: 0), avg loop 0 ns
MTL: 2024-07-16 17:06:22, SCH(0): active but still not started
MTL: 2024-07-16 17:06:22, srss_stat(0,0,0), enqueue 0 dequeue 0
MTL: 2024-07-16 17:06:22, srss_stat(0,29,1), enqueue 0 dequeue 0
MTL: 2024-07-16 17:06:22, srss_stat(0,0), pkts rx 0
MTL: 2024-07-16 17:06:22, CNI(0): eth_rx_rate 0.000000 Mb/s, eth_rx_cnt 0
MTL: 2024-07-16 17:06:22, PTP(0): time 1721167582335658141, 2024-07-16 17:06:22
MTL: 2024-07-16 17:06:22, RX_VIDEO_SESSION(0,0:st20p_rx_ffmpeg): fps 0.000000 frames 0 pkts 0
MTL: 2024-07-16 17:06:22, RX_VIDEO_SESSION(0,0): throughput 0.000000 Mb/s, cpu busy 0.000000
MTL: 2024-07-16 17:06:22, RX_st20p(0,st20p_rx_ffmpeg), p(0:free) c(0:free)
MTL: 2024-07-16 17:06:22, RX_st20p(0), frame get try 0 succ 0, put 0
MTL: 2024-07-16 17:06:22, * *    E N D    S T A T E   * * 

MTL: 2024-07-16 17:06:22, mt_calibrate_tsc, tscHz 3791999633
MTL: 2024-07-16 17:06:22, mt_sch_get_lcore, succ on shm lcore 1 for lib_sch socket 0
MTL: 2024-07-16 17:06:22, sch_tasklet_func(0), start with 2 tasklets, t_pid 20725
MTL: 2024-07-16 17:06:22, sch_start(0), succ on lcore 1 socket 0
MTL: 2024-07-16 17:06:22, mt_dev_start, succ
MTL: 2024-07-16 17:06:22, _mt_start, succ, avail ports 1
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_header(0), rx handle 0x1182600d80
MTL: 2024-07-16 17:06:22, srss_traffic_thread, stop
MTL: 2024-07-16 17:06:22, rvs_pkt_rx_tasklet_start(0), succ
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 1
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 2
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 3
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 4
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 5
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0), st20p_rx_get_frame timeout
Input #0, mtl_st20p, from 'k':
  Duration: N/A, bitrate: 1990656 kb/s
  Stream #0:0: Video: rawvideo (Y3[10][10] / 0xA0A3359), yuv422p10le, 1920x1080, 1990656 kb/s, 30 tbr, 30 tbn
Stream mapping:
  Stream #0:0 -> #0:0 (rawvideo (native) -> rawvideo (native))
Press [q] to stop, [?] for help
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 1
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 2
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 3
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 4
MTL: 2024-07-16 17:06:32, * *    M T    D E V   S T A T E   * * 
MTL: 2024-07-16 17:06:32, DEV(0): Avr rate, tx: 0.000048 Mb/s, rx: 1210.553245 Mb/s, pkts, tx: 1, rx: 1143515
MTL: 2024-07-16 17:06:32, SCH(0:sch_0): tasklets 2, lcore 1(t_pid: 20725), avg loop 112 ns
MTL: 2024-07-16 17:06:32, srss_stat(0,0,0), enqueue 0 dequeue 0
MTL: 2024-07-16 17:06:32, srss_stat(0,29,1), enqueue 1143583 dequeue 1143583
MTL: 2024-07-16 17:06:32, srss_stat(0,0), pkts rx 1143583
MTL: 2024-07-16 17:06:32, CNI(0): eth_rx_rate 0.000000 Mb/s, eth_rx_cnt 0
MTL: 2024-07-16 17:06:32, PTP(0): time 1721167592335856990, 2024-07-16 17:06:32
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0:st20p_rx_ffmpeg): fps 0.000000 frames 0 pkts 277
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): throughput 0.067182 Mb/s, cpu busy 0.460768
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): incomplete frames 276, pkts (idx error: 0, offset error: 0, idx out of bitmap: 0, missed: 3974124)
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): multi segments pkts 1143306
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): succ burst max 8, avg 1.000918
MTL: 2024-07-16 17:06:32, RX_st20p(0,st20p_rx_ffmpeg), p(0:free) c(0:free)
MTL: 2024-07-16 17:06:32, RX_st20p(0), frame get try 10 succ 0, put 0
MTL: 2024-07-16 17:06:32, * *    E N D    S T A T E   * * 

[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0) session initialization retry 5
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_packet(0), st20p_rx_get_frame timeout
[in#0/mtl_st20p @ 0x563691737b40] Error during demuxing: Input/output error
[in#0/mtl_st20p @ 0x563691737b40] Error retrieving a packet from demuxer: Input/output error
[vost#0:0/rawvideo @ 0x563691745840] No filtered frames for output stream, trying to initialize anyway.
Output #0, rawvideo, to '/dev/null':
  Metadata:
    encoder         : Lavf60.16.100
  Stream #0:0: Video: rawvideo (Y3[10][10] / 0xA0A3359), yuv422p10le(progressive), 1920x1080, q=2-31, 1244160 kb/s, 30 fps, 30 tbn
    Metadata:
      encoder         : Lavc60.31.102 rawvideo
[out#0/rawvideo @ 0x56369170cac0] video:0kB audio:0kB subtitle:0kB other streams:0kB global headers:0kB muxing overhead: unknown
[out#0/rawvideo @ 0x56369170cac0] Output file is empty, nothing was encoded(check -ss / -t / -frames parameters if used)
frame=    0 fps=0.0 q=0.0 Lsize=       0kB time=N/A bitrate=N/A speed=N/A    
MTL: 2024-07-16 17:06:32, st20p_rx_free(0), start
MTL: 2024-07-16 17:06:32, st20_rx_free(0,0), start
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0:st20p_rx_ffmpeg): fps 0.000000 frames 0 pkts 6
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): throughput 0.001350 Mb/s, cpu busy 0.460768
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): incomplete frames 6, pkts (idx error: 0, offset error: 0, idx out of bitmap: 0, missed: 86394)
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): multi segments pkts 25037
MTL: 2024-07-16 17:06:32, RX_VIDEO_SESSION(0,0): succ burst max 4, avg 1.001079
MTL: 2024-07-16 17:06:32, mt_mcast_leave(0), delete group 10101ef
MTL: 2024-07-16 17:06:32, mcast_membership_report_on_action(0), send leave pkt, mb_report_len 16
MTL: 2024-07-16 17:06:32, mt_mcast_leave(0), leave group 239.1.1.1
MTL: 2024-07-16 17:06:32, mt_ring_dequeue_clean, count 5 for ring SR_P0_1
MTL: 2024-07-16 17:06:32, mt_srss_put(0), succ on 1
MTL: 2024-07-16 17:06:32, sch_free_quota(0), quota 1944 total now 0
MTL: 2024-07-16 17:06:32, st20_rx_free, succ on sch 0 session 0
MTL: 2024-07-16 17:06:32, st20p_rx_free(0), succ
[mtl_st20p @ 0x563691737c80] mtl_instance_put, handle 0x1180541a00 ref cnt 0
[mtl_st20p @ 0x563691737c80] mtl_instance_put, ref cnt reach zero, uninit mtl device
MTL: 2024-07-16 17:06:32, sch_tasklet_func(0), end with 2 tasklets
MTL: 2024-07-16 17:06:32, srss_traffic_thread, start
MTL: 2024-07-16 17:06:32, mt_sch_put_lcore, succ on shm lcore 1 for lib_sch
MTL: 2024-07-16 17:06:32, sch_stop(0), succ
MTL: 2024-07-16 17:06:32, mt_sch_stop_all, succ
MTL: 2024-07-16 17:06:32, _mt_stop, succ
MTL: 2024-07-16 17:06:32, admin_thread, stop
MTL: 2024-07-16 17:06:32, cni_traffic_thread, stop
MTL: 2024-07-16 17:06:32, mt_srss_put(0), delete cni_entry 0
MTL: 2024-07-16 17:06:32, mt_srss_put(0), succ on 0
MTL: 2024-07-16 17:06:32, mt_cni_uinit, succ
MTL: 2024-07-16 17:06:32, sch_free_quota(0), quota 0 total now 0
MTL: 2024-07-16 17:06:32, mt_dpdk_flush_tx_queue(0), queue 0 burst_pkts 1024
MTL: 2024-07-16 17:06:32, mt_dev_put_tx_queue(0), q 0
MTL: 2024-07-16 17:06:32, srss_traffic_thread, stop
MTL: 2024-07-16 17:06:32, mtl_sch_unregister_tasklet(0), tasklet shared_rss(0) unregistered
MTL: 2024-07-16 17:06:32, sch_free_quota(0), quota 0 total now 0
MTL: 2024-07-16 17:06:32, mt_sch_put(0), ref_cnt now zero
MTL: 2024-07-16 17:06:32, Warn: sch_stop(0), not started
MTL: 2024-07-16 17:06:32, mtl_sch_unregister_tasklet(0), tasklet rvs_pkt_rx(1) unregistered
MTL: 2024-07-16 17:06:32, rvs_mgr_uinit(0), succ
MTL: 2024-07-16 17:06:32, sch_free(0), start to free sch: sch_0 
MTL: 2024-07-16 17:06:32, sch_lcore_shm_uinit, remove shared memory as we are the last user
MTL: 2024-07-16 17:06:32, dev_stop_port(0), succ
MTL: 2024-07-16 17:06:32, mt_dev_free, succ
MTL: 2024-07-16 17:06:32, mt_main_free, succ
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q0_MBUF_1
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q1_MBUF_2
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q2_MBUF_3
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q3_MBUF_4
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q4_MBUF_5
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q5_MBUF_6
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q6_MBUF_7
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q7_MBUF_8
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool R_P0Q8_MBUF_9
MTL: 2024-07-16 17:06:32, mt_mempool_free, free mempool T_P0_SYS_0
MTL: 2024-07-16 17:06:32, dev_close_port(0), succ
MTL: 2024-07-16 17:06:32, stat_thread, stop
MTL: 2024-07-16 17:06:32, mt_dev_uinit, succ
MTL: 2024-07-16 17:06:32, mtl_uninit, succ
[mtl_st20p @ 0x563691737c80] mtl_st20p_read_close(0), frame_counter 0

Logs obtained from ./script/status_report.sh

Rx at serverA (with intel X540-AT2)

Rx kernel_log.txt

[12453.297594] ixgbe 0000:01:00.0: removed PHC on enp1s0f0
[12453.773729] ixgbe 0000:01:00.0: complete
[12458.315141] ixgbe 0000:01:00.1: removed PHC on enp1s0f1
[12458.797486] ixgbe 0000:01:00.1: complete

Rx system_info.txt Rx_system_info.txt

Tx at serverB (with intel X550-AT2)

Tx kernel_log.txt


[539806.818134] ixgbe 0000:01:00.1: removed PHC on enp1s0f1
[539809.902811] ixgbe 0000:01:00.0: removed PHC on enp1s0f0
[540161.711104] vfio-pci 0000:01:00.0: Masking broken INTx support
[540161.711241] vfio-pci 0000:01:00.0: vfio_ecap_init: hiding ecap 0x19@0x1d0

Tx system_info.txt Tx_system_info.txt

frankdjx commented 1 month ago

I see there are some critical errors(queue can't burst any packets to network) in the FFMpeg TX side.

MTL: 2024-07-16 17:06:33, Error: video_trs_burst_fail(0,0), hang duration 1000 ms
MTL: 2024-07-16 17:06:33, mt_ring_dequeue_clean, count 508 for ring TV_M0S0P0
MTL: 2024-07-16 17:06:33, Error: mt_dev_tx_queue_fatal_error(0), q 1 masked as fatal error

Then the TX stop working after many retries.

It's weird that ./build/app/RxTxApp --config_file config/tx_1v.json is working well, can you paste the working log also?

And can you try start RX first and then TX? Is it the same behavior?

weic6 commented 1 month ago

Dear Frank,

Thanks for your reply.

It's weird that ./build/app/RxTxApp --config_file config/tx_1v.json is working well, can you paste the working log also?

Below are the outputs for RxTxApp.

Run RxTxApp:

tx_1v.json

{
    "interfaces": [
        {
            "name": "0000:01:00.0",
            "ip": "192.168.30.10"
        }
    ],
    "tx_sessions": [
        {
            "dip": [
                "239.1.1.1"
            ],
            "interface": [
                0
            ],
            "st20p": [
                {
                    "replicas": 1,
                    "start_port": 20000,
                    "payload_type": 112,
                    "width": 1920,
                    "height": 1080,
                    "fps": "p59",
                    "device": "AUTO",
                    "input_format": "YUV422PLANAR10LE",
                    "transport_format": "YUV_422_10bit",
                    "st20p_url": "./bunny_yuv422p10le_1080p_60fps_60frame.yuv"
                }
            ]
        }
    ]
}

rx_1v.json

{
    "interfaces": [
        {
            "name": "0000:01:00.0",
            "ip": "192.168.30.12"
        }
    ],
    "rx_sessions": [
        {
            "ip": [
                "239.1.1.1"
            ],
            "interface": [
                0
            ],
            "st20p": [
                {
                    "replicas": 1,
                    "start_port": 20000,
                    "payload_type": 112,
                    "width": 1920,
                    "height": 1080,
                    "fps": "p59",
                    "device": "AUTO",
                    "output_format": "YUV422PLANAR10LE",
                    "transport_format": "YUV_422_10bit",
                    "display": false,
                    "measure_latency": true
                }
            ]
        }
    ]
}

First Tx and then Rx

First Tx

serverB $ ./build/app/RxTxApp --config_file config/tx_1v.json

Tx output Tx output-1.txt

kernel buffer logs for Tx

$ sudo dmesg
[601399.928285] vfio-pci 0000:01:00.0: Masking broken INTx support
[601399.928422] vfio-pci 0000:01:00.0: vfio_ecap_init: hiding ecap 0x19@0x1d0

Then Rx

serverA $ ./build/app/RxTxApp --config_file config/rx_1v.json

Rx output Rx output-1.txt

No new kernel buffer logs for Rx

First Rx and then Tx

First Rx

serverA $ ./build/app/RxTxApp --config_file config/rx_1v.json

Rx output Rx output-2.txt

No new kernel buffer logs for Rx

Then Tx

serverB $ ./build/app/RxTxApp --config_file config/tx_1v.json

Tx output Tx output-2.txt

kernel buffer logs for Tx

$ sudo dmesg
[603161.708825] vfio-pci 0000:01:00.0: Masking broken INTx support
[603161.708962] vfio-pci 0000:01:00.0: vfio_ecap_init: hiding ecap 0x19@0x1d0

FFmpeg command

And can you try start RX first and then TX? Is it the same behavior?

Yes, i also see incomplete frames at Rx, and i still see Error: video_trs_burst_fail at Tx side. Below are the detail outputs.

Run Rx first

serverA $ ffmpeg -p_port 0000:01:00.0 -p_sip 192.168.30.12 -p_rx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -fps 30 -pix_fmt yuv422p10le -video_size 1920x1080 -f mtl_st20p -i "k" -f rawvideo /dev/null -y

Rx output ffmpeg-Rx output.txt

No new kernel buffer logs for Rx

Run Tx later

serverB $ ffmpeg -f lavfi -i "smptehdbars=rate=30:size=1920x1080" -f rawvideo -pix_fmt yuv422p10le -p_port 0000:01:00.0 -p_sip 192.168.30.10 -p_tx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -f mtl_st20p -

Tx output ffmpeg-Tx output.txt

kernel buffer logs for Tx

[603884.234316] vfio-pci 0000:01:00.0: Masking broken INTx support
[603884.234453] vfio-pci 0000:01:00.0: vfio_ecap_init: hiding ecap 0x19@0x1d0
frankdjx commented 1 month ago

Seems the problem is FFMpeg TX is not working well as some unknow reason.

Can you try run FFMpeg RX on server A and ./build/app/RxTxApp --config_file config/tx_1v.json on server B?

And I has compared Tx.output-1.txt and ffmpeg-Tx.output.txt, the initial log is nearly very similar. ffmpeg-Tx is sending 127 frames successfully but then suddenly get fatal error.

MTL: 2024-07-17 10:47:05, TX_VIDEO_SESSION(0,0:st20p_ffmpge): fps 29.734454 frames 127 pkts 525553:0 inflight 130777:131292
MTL: 2024-07-17 10:47:05, TX_VIDEO_SESSION(0,0): throughput 1301.332531 Mb/s: 0.000000 Mb/s, cpu busy 0.000000
MTL: 2024-07-17 10:47:05, TX_VIDEO_SESSION(0,0): busy as no ready frame from user 1
MTL: 2024-07-17 10:47:05, TX_st20p(0,st20p_ffmpge), p(1:in_transmitting) c(2:converted)
MTL: 2024-07-17 10:47:05, TX_st20p(0), frame get try 131 succ 130, put 130
MTL: 2024-07-17 10:47:05, * *    E N D    S T A T E   * * 

[mtl_st20p @ 0x560c5be9b8c0] mtl_st20p_write_packet(0), st20p_tx_get_frame timeout
[vost#0:0/rawvideo @ 0x560c5be9c680] Error submitting a packet to the muxer: Input/output error
[out#0/mtl_st20p @ 0x560c5be9b440] Error muxing a packet
MTL: 2024-07-17 10:47:12, st20p_tx_free(0), start
MTL: 2024-07-17 10:47:12, Error: video_trs_burst_fail(0,0), hang duration 1000 ms
MTL: 2024-07-17 10:47:12, mt_ring_dequeue_clean, count 508 for ring TV_M0S0P0
weic6 commented 1 month ago

Thanks for your reply. I have conducted more tests according to your suggestions. Based on the results, i am more inclined to believe that the whole transmission aborts when Rx, using FFmpeg, sees incomplete frames at the beginning. Maybe this issue is not caused by Tx side?

Tx using RxTxApp and Rx using FFmpeg

First Rx then Tx: Rx receives incomplete frames at the beginning, and then the transmission aborts.

First Rx

serverA $ ffmpeg -p_port 0000:01:00.0 -p_sip 192.168.30.12 -p_rx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -fps 60 -pix_fmt yuv422p10le -video_size 1920x1080 -f mtl_st20p -i "k" -f rawvideo /dev/null -y
ffmpeg version n6.1.1-157-g1b7ddd6747 Copyright (c) 2000-2023 the FFmpeg developers

Rx output-3.txt

Then Tx

serverB $ ./build/app/RxTxApp --config_file config/tx_1v.json

Tx output-3.txt

First Tx then Rx: Rx receives incomplete frames at the beginning, and then the transmission aborts.

First Tx

serverB $ ./build/app/RxTxApp --config_file config/tx_1v.json

Tx output-4.txt

Then Rx

serverA $ ffmpeg -p_port 0000:01:00.0 -p_sip 192.168.30.12 -p_rx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -fps 60 -pix_fmt yuv422p10le -video_size 1920x1080 -f mtl_st20p -i "k" -f rawvideo /dev/null -y

Rx output-4.txt

Tx using FFmpeg and Rx using RxTxApp

First Rx and then Tx: Transmission is successful.

First Rx

serverA $ ./build/app/RxTxApp --config_file config/rx_1v.json

Rx output-5.txt

Then Tx

serverB $ ffmpeg -f lavfi -i "smptehdbars=rate=60:size=1920x1080" -f rawvideo -pix_fmt yuv422p10le -p_port 0000:01:00.0 -p_sip 192.168.30.10 -p_tx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -f mtl_st20p -

Tx output-5.txt

First Tx and then Rx: Transmission is successful.

First Tx

serverB $ ffmpeg -f lavfi -i "smptehdbars=rate=60:size=1920x1080" -f rawvideo -pix_fmt yuv422p10le -p_port 0000:01:00.0 -p_sip 192.168.30.10 -p_tx_ip 239.1.1.1 -udp_port 20000 -payload_type 112 -f mtl_st20p -

Tx output-6.txt

Then Rx

serverA $ ./build/app/RxTxApp --config_file config/rx_1v.json

Rx output-6.txt

frankdjx commented 1 month ago

I see there are multi segments pkts logs in the FFMpeg RX which are not supported by current MTL RX logical.

MTL: 2024-07-18 14:12:08, RX_VIDEO_SESSION(0,0): multi segments pkts 255068

MT_DRV_IGC has similar problem, can you change https://github.com/OpenVisualCloud/Media-Transport-Library/blob/main/lib/src/dev/mt_dev.c#L1271 to adding the WA for MT_DRV_IXGBE also?

/* to avoid igc/igxbe nic split mbuf */
if (inf->drv_info.drv_type == MT_DRV_IGC || inf->drv_info.drv_type == MT_DRV_IXGBE)

Not sure if it will fix the issue or not. But multi segments is definitely a problem.

weic6 commented 1 month ago

Dear Frank,

Thanks for pointing this out. i make relevant modification according to your suggestion. I see that now FFmpeg Rx and FFmpeg Tx is working normally, in either order. i am happy to submit a PR for ixgbe support if you think it is necessary.

I really appreciate your help. Orz.

Best Wei

File attached is a screenshot for "Running FFmpeg Rx first and then FFmpeg Tx" image

frankdjx commented 1 month ago

Great to know it's the root cause.

Appreciate if you could help to upstream the fix. The latter IGXBE people can survive from this kind of weird issue. Thanks.

weic6 commented 1 month ago

Dear Frank, i just created a PR #932 . Thank for the help again. I am closing this issue now.