[ros2 humble]:very large delay in transferring images with ros2 service

[shuguangzhao01]

Bug report

Required Info:

• Operating System:
  • ubuntu22.04
• Installation type:
  • binaries
• Version or commit hash:
  • ros2 humble
• DDS implementation:
  • Fast-RTPS
• Client library (if applicable):
  • rclcpp

Steps to reproduce issue

int main(int argc, char** argv) {
    rclcpp::init(argc, argv);

    std::shared_ptr<rclcpp::Node> node =
        rclcpp::Node::make_shared("udf_test_c");
    rclcpp::Client<UdfAccessSRV>::SharedPtr client =
        node->create_client<UdfAccessSRV>("udf_access_srv");
    // rclcpp::executors::MultiThreadedExecutor executor;
    long i = 1;
    std::string file =
        "/home/marco/workspace/material/video/1080050990-1-208.mp4";
    while (i < 1000000000000000) {
        cv::VideoCapture sensor(file);
        sensor.open(file);
        if (!sensor.isOpened()) {
            // RCLCPP_INFO(rclcpp::get_logger("test"),
            //             "open sensor................");
            sensor.open(file);
        }
        cv::Mat img;
        while (sensor.read(img)) {
            i += 1;
            boost::uuids::uuid a_uuid = boost::uuids::random_generator()();
            std::string uuid_string = boost::uuids::to_string(a_uuid);
            RCLCPP_INFO(rclcpp::get_logger("test"), "[%s] get a frame....i=%d", uuid_string.c_str(), i);
            if (!img.empty()) {
                RCLCPP_INFO(rclcpp::get_logger("test"), "send this image....", uuid_string.c_str());
                auto req = std::make_shared<UdfAccessSRV::Request>();

                sensor_msgs::msg::Image _img_msg;
                std_msgs::msg::Header _header;
                cv_bridge::CvImage _cv_bridge;
                _header.stamp = node->get_clock()->now();
                _cv_bridge = cv_bridge::CvImage(
                    _header, sensor_msgs::image_encodings::BGR8, img);
                _cv_bridge.toImageMsg(_img_msg);

                req->img = _img_msg;
                req->uuid = uuid_string;

                RCLCPP_INFO(rclcpp::get_logger("rclcpp"),
                    "[%s] service_name=udf_access_srv", uuid_string.c_str());
                while (!client->wait_for_service(
                    std::chrono::milliseconds(1000))) {
                    if (!rclcpp::ok()) {
                        RCLCPP_ERROR(rclcpp::get_logger("rclcpp"),
                            "[%s] Interrupted while waiting for the "
                            "service. Exiting.", uuid_string.c_str());
                        throw std::runtime_error("Interrupted while waiting "
                            "for the service. Exiting.");
                    }
                    RCLCPP_INFO(rclcpp::get_logger("rclcpp"),
                        "[%s] service not available, waiting again...", uuid_string.c_str());
                }

                RCLCPP_INFO(rclcpp::get_logger("UdfInferenceService"),
                    "[%s] begin call async_send_request.......", uuid_string.c_str());
                auto result = client->async_send_request(req);
                RCLCPP_INFO(rclcpp::get_logger("UdfInferenceService"),
                    "[%s] call async_send_request finish.......", uuid_string.c_str());
                if (rclcpp::spin_until_future_complete(
                    node->get_node_base_interface(), result,
                    std::chrono::milliseconds(10000)) ==
                    rclcpp::FutureReturnCode::SUCCESS) {
                    RCLCPP_INFO(rclcpp::get_logger("UdfInferenceService"),
                        "[%s] call async_send_request finish and get a flag "
                        "of success.......", uuid_string.c_str());
                    // result_obj = result.get()->result_obj;
                    // param_obj = result.get()->param_obj;

                }
                else {
                    RCLCPP_ERROR(rclcpp::get_logger("rclcpp"),
                        "[%s] Connet timeout!,the service "
                        "unavailable,service name=222", uuid_string.c_str());
                    throw UdfRuntimeException(
                        "Get Response timeout! the service unavailable,service "
                        "name=333");
                }

                RCLCPP_INFO(rclcpp::get_logger("test"),
                    "[%s] this frame finished................", uuid_string.c_str());
            }
            else {
                RCLCPP_ERROR(rclcpp::get_logger("test"),
                    "[%s] this capture read error................", uuid_string.c_str());
            }
            img.release();
        }
        RCLCPP_ERROR(rclcpp::get_logger("test"), "a epoch over..........");
        sensor.release();
    }
    rclcpp::shutdown();
    return 0;
}

[INFO] [1691565196.771440781] [test]: [6d415829-163b-4159-bb30-4094311212a7] get a frame....i=11393
[INFO] [1691565196.771467339] [test]: send this image....
---------3------------
[INFO] [1691565196.774480256] [rclcpp]: [6d415829-163b-4159-bb30-4094311212a7] service_name=udf_access_srv
[INFO] [1691565196.774525343] [UdfInferenceService]: [6d415829-163b-4159-bb30-4094311212a7] begin call async_send_request.......
[DEBUG] [1691565196.774541661] [rcl]: Client sending service request
[INFO] [1691565196.777880810] [UdfInferenceService]: [6d415829-163b-4159-bb30-4094311212a7] call async_send_request finish.......
[DEBUG] [1691565196.777914055] [rcl]: Initializing wait set with '0' subscriptions, '2' guard conditions, '0' timers, '0' clients, '0' services
[DEBUG] [1691565196.783423899] [rcl]: Client taking service response
[DEBUG] [1691565196.783469595] [rcl]: Client take response succeeded: true
[INFO] [1691565196.783519505] [UdfInferenceService]: [6d415829-163b-4159-bb30-4094311212a7] call async_send_request finish and get a flag of success.......
[INFO] [1691565196.783531199] [test]: [6d415829-163b-4159-bb30-4094311212a7] this frame finished................
[INFO] [1691565196.786158914] [test]: [0688780a-a38a-483d-884d-828d82d8b0c7] get a frame....i=11394
[INFO] [1691565196.786178811] [test]: send this image....
---------3------------
[INFO] [1691565196.788508240] [rclcpp]: [0688780a-a38a-483d-884d-828d82d8b0c7] service_name=udf_access_srv
[INFO] [1691565196.788542575] [UdfInferenceService]: [0688780a-a38a-483d-884d-828d82d8b0c7] begin call async_send_request.......
[DEBUG] [1691565196.788552692] [rcl]: Client sending service request
[INFO] [1691565196.790921418] [UdfInferenceService]: [0688780a-a38a-483d-884d-828d82d8b0c7] call async_send_request finish.......
[DEBUG] [1691565196.790949868] [rcl]: Initializing wait set with '0' subscriptions, '2' guard conditions, '0' timers, '0' clients, '0' services
[DEBUG] [1691565198.936368542] [rcl]: Client taking service response
[DEBUG] [1691565198.936401153] [rcl]: Client take response succeeded: true
[INFO] [1691565198.936432120] [UdfInferenceService]: [0688780a-a38a-483d-884d-828d82d8b0c7] call async_send_request finish and get a flag of success.......
[INFO] [1691565198.936439903] [test]: [0688780a-a38a-483d-884d-828d82d8b0c7] this frame finished................
[INFO] [1691565198.939358797] [test]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] get a frame....i=11395
[INFO] [1691565198.939399646] [test]: send this image....
---------3------------
[INFO] [1691565198.943197087] [rclcpp]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] service_name=udf_access_srv
[INFO] [1691565198.943230232] [UdfInferenceService]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] begin call async_send_request.......
[DEBUG] [1691565198.943240302] [rcl]: Client sending service request
[INFO] [1691565198.945444819] [UdfInferenceService]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] call async_send_request finish.......
[DEBUG] [1691565198.945471990] [rcl]: Initializing wait set with '0' subscriptions, '2' guard conditions, '0' timers, '0' clients, '0' services
[DEBUG] [1691565201.931784927] [rcl]: Client taking service response
[DEBUG] [1691565201.931820007] [rcl]: Client take response succeeded: true
[INFO] [1691565201.931853762] [UdfInferenceService]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] call async_send_request finish and get a flag of success.......
[INFO] [1691565201.931862110] [test]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] this frame finished................

namespace UDF_INFERENCE_SERVER {

    UdfInferenceServer::UdfInferenceServer(const std::string& node_name,
        const rclcpp::NodeOptions& options)
        : _node_name(node_name), Node(node_name, options) {

        // create multi-thread service
        RCLCPP_INFO(this->get_logger(),
            "the main thread of the ros is starting...................");
        this->callbackGroup1_ =
            this->create_callback_group(rclcpp::CallbackGroupType::Reentrant);
        rmw_qos_profile_t custom_qos_profile = rmw_qos_profile_default;

        // create service void
        this->udfAccessSRVPtr_ = this->create_service<UdfAccessSRV>(
            "udf_access_srv",
            std::bind(&UdfInferenceServer::udfAccessSRV_callback, this,
                std::placeholders::_1, std::placeholders::_2),
            custom_qos_profile, this->callbackGroup1_);
        RCLCPP_INFO(this->get_logger(), "UdfInferenceServer started finish...");
    }

    void UdfInferenceServer::udfAccessSRV_callback(
        const UdfAccessSRV::Request::SharedPtr request,
        const UdfAccessSRV::Response::SharedPtr response) {

        std::string uuid = request->uuid;
        RCLCPP_INFO(this->get_logger(), "[%s] receive a image", uuid.c_str());
        sensor_msgs::msg::Image img_msg = request->img;

        cv_bridge::CvImagePtr cv_ptr;
        try {
            cv_ptr = cv_bridge::toCvCopy(img_msg, img_msg.encoding);
        }
        catch (cv_bridge::Exception& e) {
            RCLCPP_ERROR(this->get_logger(), "cv_bridge exception: %s", e.what());
        }
        cv::Mat mat = cv_ptr->image;
        cv::imshow("ros server test image", cv_ptr->image);
        cv::waitKey(1);
        RCLCPP_INFO(this->get_logger(),
            "[%s] ****img.width=%d,img.hight=%d,img.channel=%d", uuid.c_str(), mat.cols,
            mat.rows, mat.channels());
        mat.release();
    }
    UdfInferenceServer::~UdfInferenceServer() {}
} // namespace UDF_INFERENCE_SERVER
int main(int argc, char** argv) {
    (void)argc;
    (void)argv;
    rclcpp::init(argc, argv);
    rclcpp::spin(std::make_shared<UDF_INFERENCE_SERVER::UdfInferenceServer>());
    rclcpp::shutdown();
    printf("hello world udf_inference_server package\n");
    return 0;
}

[DEBUG] [1691565196.768640293] [rcl]: Sending service response
[DEBUG] [1691565196.778010718] [rcl]: Service server taking service request
[DEBUG] [1691565196.779105101] [rcl]: Service take request succeeded: true
[INFO] [1691565196.779123537] [udf_server]: [6d415829-163b-4159-bb30-4094311212a7] receive a image
[INFO] [1691565196.782993242] [udf_server]: [6d415829-163b-4159-bb30-4094311212a7] ****img.width=1920,img.hight=1080,img.channel=3
[DEBUG] [1691565196.783044742] [rcl]: Sending service response
[DEBUG] [1691565198.927586977] [rcl]: Service server taking service request
[DEBUG] [1691565198.932197639] [rcl]: Service take request succeeded: true
[INFO] [1691565198.932249026] [udf_server]: [0688780a-a38a-483d-884d-828d82d8b0c7] receive a image
[INFO] [1691565198.935974553] [udf_server]: [0688780a-a38a-483d-884d-828d82d8b0c7] ****img.width=1920,img.hight=1080,img.channel=3
[DEBUG] [1691565198.936002508] [rcl]: Sending service response
[DEBUG] [1691565201.926497360] [rcl]: Service server taking service request
[DEBUG] [1691565201.927646480] [rcl]: Service take request succeeded: true
[INFO] [1691565201.927663745] [udf_server]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] receive a image
[INFO] [1691565201.931548321] [udf_server]: [262277d5-d7ed-467a-bdf8-960b9c10ff5c] ****img.width=1920,img.hight=1080,img.channel=3
[DEBUG] [1691565201.931582847] [rcl]: Sending service response
[DEBUG] [1691565201.947481547] [rcl]: Service server taking service request
[DEBUG] [1691565201.948585700] [rcl]: Service take request succeeded: true
[INFO] [1691565201.948601542] [udf_server]: [903f83cb-1c7f-42c9-a98f-eb4726898ab6] receive a image
[INFO] [1691565201.952043025] [udf_server]: [903f83cb-1c7f-42c9-a98f-eb4726898ab6] ****img.width=1920,img.hight=1080,img.channel=3
[DEBUG] [1691565201.952080348] [rcl]: Sending service response
[DEBUG] [1691565201.958807461] [rcl]: Service server taking service request
[DEBUG] [1691565201.959840853] [rcl]: Service take request succeeded: true
[INFO] [1691565201.959858131] [udf_server]: [48c850c9-3125-4272-be22-2576a461c771] receive a image
[INFO] [1691565201.963241185] [udf_server]: [48c850c9-3125-4272-be22-2576a461c771] ****img.width=1920,img.hight=1080,img.channel=3
[DEBUG] [1691565201.963260722] [rcl]: Sending service response

Expected behavior

The client uses OpenCV to read the 1920*1080 video transmission image, and the server receives the image with low latency.

Actual behavior

At first, the image transmission delay is about 15-20 milliseconds, and after about a few minutes, the receiving delay image delay becomes larger, about 1-3 seconds, as the log above shows

[fujitatomoya]

• Service Client

[DEBUG] [1691565196.788552692] [rcl]: Client sending service request
[INFO] [1691565196.790921418] [UdfInferenceService]: [0688780a-a38a-483d-884d-828d82d8b0c7] call async_send_request finish.......
[DEBUG] [1691565196.790949868] [rcl]: Initializing wait set with '0' subscriptions, '2' guard conditions, '0' timers, '0' clients, '0' services
[DEBUG] [1691565198.936368542] [rcl]: Client taking service response

• Service Server

[DEBUG] [1691565198.927586977] [rcl]: Service server taking service request
[DEBUG] [1691565198.932197639] [rcl]: Service take request succeeded: true
[INFO] [1691565198.932249026] [udf_server]: [0688780a-a38a-483d-884d-828d82d8b0c7] receive a image
[INFO] [1691565198.935974553] [udf_server]: [0688780a-a38a-483d-884d-828d82d8b0c7] ****img.width=1920,img.hight=1080,img.channel=3
[DEBUG] [1691565198.936002508] [rcl]: Sending service response

according to the above timestamp information, it seems that 2-3 sec delay is in the process under RMW implementation.

i have a couple of questions,

• is this happening via network or localhost transport? if using with network interface, it would be nice to check the network resource is enough.
• out of curiosity, can you reproduce the issue with https://github.com/ros2/rmw_cyclonedds?

[shuguangzhao01]

@fujitatomoya Thanks very much for reply

• is this happening via network or localhost transport? if using with network interface, it would be nice to check the network resource is enough.
  it is via localhost
• out of curiosity, can you reproduce the issue with https://github.com/ros2/rmw_cyclonedds?
  Reproducible, will appear every time, is mandatory with fastdds in Ubuntu22.04, but not with Cyclonedds.

[clalancette]

@MiguelCompany @EduPonz Any chance you could take a look here? Thanks.