Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Execution rate becomes unstable when using component_container_mt #298

Closed
isamu-takagi opened this issue Apr 8, 2021 · 2 comments
Closed

Comments

@isamu-takagi
Copy link

Bug report

Required Info:

  • Operating System:
    • Ubuntu 20.04 (ros2 foxy)
  • Installation type:
    • binaries
  • Version or commit hash:
    • ros-foxy-rmw-cyclonedds-cpp 0.7.6-1focal.20210225.205739
  • DDS implementation:
    • Cyclone DDS
  • Client library (if applicable):
    • rclcpp

Steps to reproduce issue

  1. cyclonedds setting

    <?xml version="1.0" encoding="UTF-8" ?>
    <CycloneDDS xmlns="https://cdds.io/config" xmlns:xsi="http://www.w3.org/2001/XMLSchema-instance" xsi:schemaLocation="https://cdds.io/config https://raw.githubusercontent.com/eclipse-cyclonedds/cyclonedds/master/etc/cyclonedds.xsd">
      <Domain id="any">
        <General>
          <NetworkInterfaceAddress>lo</NetworkInterfaceAddress>
        </General>
        <Internal>
          <MinimumSocketReceiveBufferSize>10MB</MinimumSocketReceiveBufferSize>
        </Internal>
      </Domain>
    </CycloneDDS>
    
  2. execute this command

    sudo ifconfig lo multicast
    sudo sysctl -w net.core.rmem_max=1073741824
    
  3. clone test code and build

    git clone https://github.com/isamu-takagi/ros2_sandbox.git
    cd ros2_sandbox
    colcon build --cmake-args -DCMAKE_BUILD_TYPE=Release
    

    Note: This code is for testing intra-process communication, but it occurs even if extra_arguments=[{"use_intra_process_comms": False}].

  4. launch

    ros2 launch intra_process intra_process_mt.launch.py 
    

Expected behavior

Pub/sub logs are displayed at 1 second intervals like component_container_mt (with Fast RTPS) or component_container.

Actual behavior

[component_container_mt-1] [INFO] [1617870280.957945625] [producer]: produce: 000, 0x7f3980002820
[component_container_mt-1] [INFO] [1617870280.959009007] [consumer]: consume: 000, 0x7f3980002820
[component_container_mt-1] [INFO] [1617870286.735421036] [producer]: produce: 001, 0x7f3980007540
[component_container_mt-1] [INFO] [1617870286.735549483] [consumer]: consume: 001, 0x7f3980007540
[component_container_mt-1] [INFO] [1617870288.502073432] [producer]: produce: 002, 0x7f398000a210
[component_container_mt-1] [INFO] [1617870288.502231392] [consumer]: consume: 002, 0x7f398000a210
[component_container_mt-1] [INFO] [1617870288.963999505] [producer]: produce: 003, 0x7f3980007520
[component_container_mt-1] [INFO] [1617870288.964246320] [consumer]: consume: 003, 0x7f3980007520
[component_container_mt-1] [INFO] [1617870293.143865129] [producer]: produce: 004, 0x7f39800027e0
[component_container_mt-1] [INFO] [1617870293.144053451] [consumer]: consume: 004, 0x7f39800027e0
[component_container_mt-1] [INFO] [1617870294.283863572] [producer]: produce: 005, 0x7f3984001270
[component_container_mt-1] [INFO] [1617870294.283985213] [consumer]: consume: 005, 0x7f3984001270
[component_container_mt-1] [INFO] [1617870295.615888104] [producer]: produce: 006, 0x7f3984036e60
[component_container_mt-1] [INFO] [1617870295.616056000] [consumer]: consume: 006, 0x7f3984036e60
[component_container_mt-1] [INFO] [1617870297.315833995] [producer]: produce: 007, 0x7f3980051630
[component_container_mt-1] [INFO] [1617870297.315942915] [consumer]: consume: 007, 0x7f3980051630
[component_container_mt-1] [INFO] [1617870298.619926925] [producer]: produce: 008, 0x7f3980013120
[component_container_mt-1] [INFO] [1617870298.620142584] [consumer]: consume: 008, 0x7f3980013120
[component_container_mt-1] [INFO] [1617870299.547879448] [producer]: produce: 009, 0x7f3980008ee0
[component_container_mt-1] [INFO] [1617870299.548019557] [consumer]: consume: 009, 0x7f3980008ee0
@fujitatomoya
Copy link
Contributor

@isamu-takagi thanks for posting issue.

i confirmed that source build with ros2/ros2@0e6cc1c, the problem CANNOT be observed in mainline.

  • ros2 launch intra_process intra_process_mt.launch.py
[component_container_mt-1] [INFO] [1617927524.587156965] [producer]: produce: 004, 0x7f3b70023140
[component_container_mt-1] [INFO] [1617927524.587316806] [consumer]: consume: 004, 0x7f3b70023140
[component_container_mt-1] [INFO] [1617927525.587494242] [producer]: produce: 005, 0x7f3b500011f0
[component_container_mt-1] [INFO] [1617927525.587620083] [consumer]: consume: 005, 0x7f3b500011f0
[component_container_mt-1] [INFO] [1617927526.586748026] [producer]: produce: 006, 0x7f3b50001120
[component_container_mt-1] [INFO] [1617927526.586872937] [consumer]: consume: 006, 0x7f3b50001120
[component_container_mt-1] [INFO] [1617927527.586752922] [producer]: produce: 007, 0x7f3b50001120
[component_container_mt-1] [INFO] [1617927527.586878123] [consumer]: consume: 007, 0x7f3b50001120
[component_container_mt-1] [INFO] [1617927528.587181825] [producer]: produce: 008, 0x7f3b50001120
[component_container_mt-1] [INFO] [1617927528.587379966] [consumer]: consume: 008, 0x7f3b50001120
  • ros2 launch intra_process intra_process.launch.py
[component_container-1] [INFO] [1617927535.959378536] [producer]: produce: 000, 0x55f5c7dc69d0
[component_container-1] [INFO] [1617927535.959552437] [consumer]: consume: 000, 0x55f5c7dc69d0
[component_container-1] [INFO] [1617927536.959364671] [producer]: produce: 001, 0x55f5c7dc69d0
[component_container-1] [INFO] [1617927536.959492992] [consumer]: consume: 001, 0x55f5c7dc69d0
[component_container-1] [INFO] [1617927537.958930075] [producer]: produce: 002, 0x55f5c7d9ca70
[component_container-1] [INFO] [1617927537.959062356] [consumer]: consume: 002, 0x55f5c7d9ca70
[component_container-1] [INFO] [1617927538.959381064] [producer]: produce: 003, 0x55f5c7d9ca70
[component_container-1] [INFO] [1617927538.959526865] [consumer]: consume: 003, 0x55f5c7d9ca70

i believe that ros2/rclcpp#1516 can fix this problem, introducing gradual mutex locks gives some time window to take the executables.

  • Nitpick

there is a couple of warning for your test sample.

/root/ros2_ws/colcon_ws/src/ros2/ros2_sandbox/src/intra_process/src/producer.cpp:20:33: warning: format ‘%p’ expects argument of type ‘void*’, but argument 6 has type ‘std::unique_ptr<std_msgs::msg::Int32_<std::allocator<void> >, std::default_delete<std_msgs::msg::Int32_<std::allocator<void> > > >::pointer’ {aka ‘std_msgs::msg::Int32_<std::allocator<void> >*’} [-Wformat=]
   20 |       RCLCPP_INFO(get_logger(), "produce: %03d, %p", msg->data, msg.get());
      |                                 ^~~~~~~~~~~~~~~~~~~             ~~~~~~~~~
      |                                                                        |
      |                                                                        std::unique_ptr<std_msgs::msg::Int32_<std::allocator<void> >, std::default_delete<std_msgs::msg::Int32_<std::allocator<void> > > >::pointer {aka std_msgs::msg::Int32_<std::allocator<void> >*}
/root/ros2_ws/colcon_ws/src/ros2/ros2_sandbox/src/intra_process/src/producer.cpp:20:50: note: format string is defined here
   20 |       RCLCPP_INFO(get_logger(), "produce: %03d, %p", msg->data, msg.get());
      |                                                 ~^
      |                                                  |
      |                                                  void*

the following patch can get rid of the warning.

diff --git a/src/intra_process/src/consumer.cpp b/src/intra_process/src/consumer.cpp
index edfad97..930c01d 100644
--- a/src/intra_process/src/consumer.cpp
+++ b/src/intra_process/src/consumer.cpp
@@ -10,7 +10,7 @@ class ConsumerComponent : public rclcpp::Node
       sub_ = create_subscription<std_msgs::msg::Int32>("intra_topic", 10,
         [this](const std_msgs::msg::Int32::UniquePtr msg)
         {
-          RCLCPP_INFO(get_logger(), "consume: %03d, %p", msg->data, msg.get());
+          RCLCPP_INFO(get_logger(), "consume: %03d, %p", msg->data, (void *)msg.get());
         }
       );
     }
diff --git a/src/intra_process/src/producer.cpp b/src/intra_process/src/producer.cpp
index 1dfcaf3..1a693b1 100644
--- a/src/intra_process/src/producer.cpp
+++ b/src/intra_process/src/producer.cpp
@@ -17,7 +17,7 @@ class ProducerComponent : public rclcpp::Node
     {
       std_msgs::msg::Int32::UniquePtr msg = std::make_unique<std_msgs::msg::Int32>();
       msg->data = counter_++;
-      RCLCPP_INFO(get_logger(), "produce: %03d, %p", msg->data, msg.get());
+      RCLCPP_INFO(get_logger(), "produce: %03d, %p", msg->data, (void *)msg.get());
       pub_->publish(std::move(msg));
     }

@isamu-takagi
Copy link
Author

@fujitatomoya Thank you for answering. I confirmed that it is executed every 1 second using ros2 source build. I'll close this issue.

[component_container_mt-1] [INFO] [1617947718.983052027] [producer]: produce: 000, 0x557ec032ae80
[component_container_mt-1] [INFO] [1617947718.984381999] [consumer]: consume: 000, 0x557ec032ae80
[component_container_mt-1] [INFO] [1617947719.982971228] [producer]: produce: 001, 0x7fa834000b60
[component_container_mt-1] [INFO] [1617947719.983570810] [consumer]: consume: 001, 0x7fa834000b60
[component_container_mt-1] [INFO] [1617947720.982807486] [producer]: produce: 002, 0x7fa838001b00
[component_container_mt-1] [INFO] [1617947720.983418393] [consumer]: consume: 002, 0x7fa838001b00
[component_container_mt-1] [INFO] [1617947721.982790298] [producer]: produce: 003, 0x557ec033e000
[component_container_mt-1] [INFO] [1617947721.983400814] [consumer]: consume: 003, 0x557ec033e000
[component_container_mt-1] [INFO] [1617947722.982761100] [producer]: produce: 004, 0x7fa834003410
[component_container_mt-1] [INFO] [1617947722.983378241] [consumer]: consume: 004, 0x7fa834003410

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

2 participants