search

insight-platform / Savant

Python Computer Vision & Video Analytics Framework With Batteries Included
https://savant-ai.io
Apache License 2.0
553 stars 45 forks source link

Module processing the last frames in a source very slow #799

Closed tomskikh closed 2 months ago

tomskikh commented 3 months ago

To reproduce run the following pipeline: image-source (20 images) -> (dealer-router) -> module.

The first few frames module processing normally. The last frames are processed at 1 FPS.

Log snippet from savant_rs_video_demux:

2024-06-28T04:48:37.744188608Z    DEBUG     Start eviction loop
2024-06-28T04:48:37.744231648Z    DEBUG     Waiting 1 seconds for the next eviction loop
...
2024-06-28T04:48:37.856290205Z    DEBUG     Pushing frame with IDX 7 and PTS 199999998 from source coco-images
2024-06-28T04:48:38.213663749Z    DEBUG     Frame with IDX 7 and PTS 199999998 from source coco-images has been pushed: <enum GST_FLOW_OK of type Gst.FlowReturn>
...
2024-06-28T04:48:38.245554551Z    DEBUG     Checking if source coco-images is blacklisted
2024-06-28T04:48:39.245676436Z    DEBUG     Start eviction loop
2024-06-28T04:48:39.245812839Z    DEBUG     Source coco-images is not blacklisted

Log snippet around 2024-06-28T04:48:38.245554551Z DEBUG Checking if source coco-images is blacklisted log:

2024-06-28T04:48:38.243198077Z  DEBUG savant_rs::zeromq::reader                                             > Checking if source 'coco-images' is blacklisted for endpoint 'ipc:///tmp/zmq-sockets/input.ipc'
2024-06-28T04:48:38.243201143Z  DEBUG savant_rs::zeromq::reader                                             > Received end of stream message from ZeroMQ socket for endpoint ipc:///tmp/zmq-sockets/input.ipc
2024-06-28T04:48:38.243250845Z  DEBUG insight::savant::zeromq_src::zeromq_src+zeromqsrc0                    > Received message from topic [99, 111, 99, 111, 45, 105, 109, 97, 103, 101, 115].
2024-06-28T04:48:38.243300537Z  INFO  insight::savant::zeromq_src::zeromq_src+zeromqsrc0                    > Received EOS from source coco-images.
2024-06-28T04:48:38.243465763Z  DEBUG savant_rs::zeromq::reader                                             > Waiting for message from ZeroMQ socket for endpoint ipc:///tmp/zmq-sockets/input.ipc
2024-06-28T04:48:38.244191026Z  DEBUG insight::savant::savant_rs_video_demux                                > Frame with IDX 13 and PTS 299999997 from source coco-images has been pushed: <enum GST_FLOW_OK of type Gst.FlowReturn>
2024-06-28T04:48:38.244241920Z  DEBUG insight::savant::savant_rs_video_demux                                > Source coco-images lock released
2024-06-28T04:48:38.244296120Z  DEBUG insight::savant::savant_rs_video_demux                                > Frame with PTS 299999997 from source coco-images has been processed (<enum GST_FLOW_OK of type Gst.FlowReturn>).
2024-06-28T04:48:38.244433445Z  DEBUG insight::savant::deepstream::buffer_processor::NvDsRawBufferProcessor > Preparing input for buffer with PTS 99999999.
2024-06-28T04:48:38.244603840Z  DEBUG insight::savant::savant_rs_video_demux                                > Handling buffer of size 180751 with timestamp 333333330
2024-06-28T04:48:38.244641660Z 0:00:06.091153390     1 0x7ebab801f520 WARN              video-info video-info.c:760:gst_video_info_to_caps: invalid matrix 4 for RGB format, using RGB
2024-06-28T04:48:38.244654303Z 0:00:06.091177755     1 0x7ebab801f520 WARN              video-info video-info.c:760:gst_video_info_to_caps: invalid matrix 4 for RGB format, using RGB
2024-06-28T04:48:38.244657389Z  DEBUG insight::savant::deepstream::buffer_processor::NvDsRawBufferProcessor > Preparing input for frame of source coco-images with IDX 4 and PTS 99999999.
2024-06-28T04:48:38.244686513Z  DEBUG insight::savant::savant_rs_video_demux                                > Getting video frame for frame 14
2024-06-28T04:48:38.244786158Z  DEBUG insight::savant::deepstream::buffer_processor::NvDsRawBufferProcessor > Adding transformations for frame of source coco-images with IDX 4 and PTS 99999999.
2024-06-28T04:48:38.244935504Z  DEBUG insight::savant::savant_rs_video_demux                                > Handling frame 333333330/333333330 from source coco-images; frame is a keyframe
2024-06-28T04:48:38.244967594Z  DEBUG insight::savant::deepstream::buffer_processor::NvDsRawBufferProcessor > Adding scale transformation for frame of source coco-images with IDX 4 and PTS 99999999.
2024-06-28T04:48:38.245013208Z  DEBUG insight::savant::savant_rs_video_demux                                > Moving frame 14 to source-demuxer
2024-06-28T04:48:38.245064433Z  DEBUG insight::savant::deepstream::buffer_processor::NvDsRawBufferProcessor > Init primary bbox for frame with PTS 99999999: "RBBox { xc: 640.0, yc: 360.0, width: 1280.0, height: 720.0, angle: None }"
2024-06-28T04:48:38.245185597Z  DEBUG insight::savant::savant_rs_video_demux                                > Checking if demuxer is running
2024-06-28T04:48:38.245223508Z  DEBUG insight::savant::deepstream::buffer_processor::NvDsRawBufferProcessor > Add primary object to frame meta with PTS 99999999, bbox: "RBBox { xc: 640.0, yc: 360.0, width: 1280.0, height: 720.0, angle: None }"
2024-06-28T04:48:38.245554551Z  DEBUG insight::savant::savant_rs_video_demux                                > Checking if source coco-images is blacklisted
2024-06-28T04:48:39.217352059Z  INFO  savant_core::pipeline::stats                                          > Time-based FPS counter triggered: FPS = 3.00, OPS = 0.00, frame_delta = 3, time_delta = 1 sec , period=[1719550118217, 1719550119217] ms
2024-06-28T04:48:39.244466145Z  DEBUG savant_rs::zeromq::reader                                             > Received message from ZeroMQ socket for endpoint ipc:///tmp/zmq-sockets/input.ipc
2024-06-28T04:48:39.244507111Z  DEBUG savant_rs::zeromq::reader                                             > Failed to receive message from ZeroMQ socket due to timeout (EAGAIN)
2024-06-28T04:48:39.244517821Z  DEBUG savant_rs::zeromq::reader                                             > Checking if source 'coco-images' is blacklisted for endpoint 'ipc:///tmp/zmq-sockets/input.ipc'
2024-06-28T04:48:39.244756222Z  DEBUG insight::savant::demo                                                 > Prepare meta output for buffer with PTS 99999999
2024-06-28T04:48:39.245676436Z  DEBUG insight::savant::savant_rs_video_demux                                > Start eviction loop
2024-06-28T04:48:39.245761604Z  DEBUG insight::savant::utils::zeromq                                        > Timeout exceeded when receiving the next frame
2024-06-28T04:48:39.245812839Z  DEBUG insight::savant::savant_rs_video_demux                                > Source coco-images is not blacklisted
2024-06-28T04:48:39.246019271Z  DEBUG savant_rs::zeromq::reader                                             > Waiting for message from ZeroMQ socket for endpoint ipc:///tmp/zmq-sockets/input.ipc
2024-06-28T04:48:39.246029290Z  DEBUG insight::savant::demo                                                 > Preparing output for frame of source coco-images with IDX 4 and PTS 99999999.
2024-06-28T04:48:39.246281156Z  DEBUG insight::savant::savant_rs_video_demux                                > Waiting 1 seconds for the next eviction loop
2024-06-28T04:48:39.246319307Z  DEBUG insight::savant::savant_rs_video_demux                                > Building frame info for frame 14
tomskikh commented 2 months ago

@bwsw Methods BlockingReader.is_blacklisted() and BlockingReader.is_started() is savant-rs wait until BlockingReader.receive() is completed. I.e. when reader don't receive any messages, it those methods wait receive_timeout milliseconds.

Reducing receive_timeout to 10 ms or removing is_blacklisted() from savant_rs_video_demux solves the issue with last frames.

Scripts to reproduce this issue with ZMQ separately: https://github.com/insight-platform/Savant/commit/ebcbf9fc775bc7bc02b149f80d7a01fde94cf0c7

bwsw commented 2 months ago

@tomskikh please test with the current develop after savant-rs upgrade.

tomskikh commented 2 months ago

@bwsw The issue fixed.