search

ros2 / rclcpp

rclcpp (ROS Client Library for C++)
Apache License 2.0
536 stars 417 forks source link

refactor and improve the parameterized spin_some tests for executors #2460

Closed wjwwood closed 6 months ago

wjwwood commented 6 months ago

After working on https://github.com/ros2/rclcpp/pull/2142 I came to realize that the parameterized spinSome (always should have been spin_some to match our style and the name of the method being tested) tests were testing some false assumptions and in general were very fragile.

I reworked the nominal test to check that it does not block when there's no work, that it works with one ready item, and that it also executes multiple ready items when they are available.

$ ./build/rclcpp/test/rclcpp/test_executors --gtest_filter=*spin_some
Running main() from /home/william/ros2_ws/install/gtest_vendor/src/gtest_vendor/src/gtest_main.cc
Note: Google Test filter = *spin_some
[==========] Running 4 tests from 4 test suites.
[----------] Global test environment set-up.
[----------] 1 test from TestExecutors/SingleThreadedExecutor, where TypeParam = rclcpp::executors::SingleThreadedExecutor
[ RUN      ] TestExecutors/SingleThreadedExecutor.spin_some
[       OK ] TestExecutors/SingleThreadedExecutor.spin_some (53 ms)
[----------] 1 test from TestExecutors/SingleThreadedExecutor (53 ms total)

[----------] 1 test from TestExecutors/MultiThreadedExecutor, where TypeParam = rclcpp::executors::MultiThreadedExecutor
[ RUN      ] TestExecutors/MultiThreadedExecutor.spin_some
[       OK ] TestExecutors/MultiThreadedExecutor.spin_some (19 ms)
[----------] 1 test from TestExecutors/MultiThreadedExecutor (19 ms total)

[----------] 1 test from TestExecutors/StaticSingleThreadedExecutor, where TypeParam = rclcpp::executors::StaticSingleThreadedExecutor
[ RUN      ] TestExecutors/StaticSingleThreadedExecutor.spin_some
[       OK ] TestExecutors/StaticSingleThreadedExecutor.spin_some (19 ms)
[----------] 1 test from TestExecutors/StaticSingleThreadedExecutor (19 ms total)

[----------] 1 test from TestExecutors/EventsExecutor, where TypeParam = rclcpp::experimental::executors::EventsExecutor
[ RUN      ] TestExecutors/EventsExecutor.spin_some
[       OK ] TestExecutors/EventsExecutor.spin_some (19 ms)
[----------] 1 test from TestExecutors/EventsExecutor (19 ms total)

[----------] Global test environment tear-down
[==========] 4 tests from 4 test suites ran. (110 ms total)
[  PASSED  ] 4 tests.

I also added a test which checks the max_duration option is being respected, and I found that the StaticSingleThreadedExecutor and the EventsExecutor do not implement this correctly. I think at least the StaticSingleThreadedExecutor should be fixed in https://github.com/ros2/rclcpp/pull/2142, but I've disabled that new test for both of them for now, with a TODO. I will also open issues about it.

$ ./build/rclcpp/test/rclcpp/test_executors --gtest_filter=*spin_some_max_duration
Running main() from /home/william/ros2_ws/install/gtest_vendor/src/gtest_vendor/src/gtest_main.cc
Note: Google Test filter = *spin_some_max_duration
[==========] Running 4 tests from 4 test suites.
[----------] Global test environment set-up.
[----------] 1 test from TestExecutors/SingleThreadedExecutor, where TypeParam = rclcpp::executors::SingleThreadedExecutor
[ RUN      ] TestExecutors/SingleThreadedExecutor.spin_some_max_duration
[       OK ] TestExecutors/SingleThreadedExecutor.spin_some_max_duration (2065 ms)
[----------] 1 test from TestExecutors/SingleThreadedExecutor (2066 ms total)

[----------] 1 test from TestExecutors/MultiThreadedExecutor, where TypeParam = rclcpp::executors::MultiThreadedExecutor
[ RUN      ] TestExecutors/MultiThreadedExecutor.spin_some_max_duration
[       OK ] TestExecutors/MultiThreadedExecutor.spin_some_max_duration (2038 ms)
[----------] 1 test from TestExecutors/MultiThreadedExecutor (2038 ms total)

[----------] 1 test from TestExecutors/StaticSingleThreadedExecutor, where TypeParam = rclcpp::executors::StaticSingleThreadedExecutor
[ RUN      ] TestExecutors/StaticSingleThreadedExecutor.spin_some_max_duration
/home/william/ros2_ws/src/ros2/rclcpp/rclcpp/test/rclcpp/executors/test_executors.cpp:616: Failure
Expected: (to_nanoseconds_helper(spin_some_run_time)) < (to_nanoseconds_helper(waitable_callback_duration * 2)), actual: 4004709489 vs 4000000000
spin_some() took longer than expected to execute by a significant margin, but this could be a false positive on a very slow computer
/home/william/ros2_ws/src/ros2/rclcpp/rclcpp/test/rclcpp/executors/test_executors.cpp:624: Failure
Expected equality of these values:
  number_of_waitables_executed
    Which is: 2
  1u
    Which is: 1
expected exactly one of the two waitables to be executed, but my_waitable1->get_count(): 1 and my_waitable2->get_count(): 1
[  FAILED  ] TestExecutors/StaticSingleThreadedExecutor.spin_some_max_duration, where TypeParam = rclcpp::executors::StaticSingleThreadedExecutor (4042 ms)
[----------] 1 test from TestExecutors/StaticSingleThreadedExecutor (4042 ms total)

[----------] 1 test from TestExecutors/EventsExecutor, where TypeParam = rclcpp::experimental::executors::EventsExecutor
[ RUN      ] TestExecutors/EventsExecutor.spin_some_max_duration
/home/william/ros2_ws/src/ros2/rclcpp/rclcpp/test/rclcpp/executors/test_executors.cpp:610: Failure
Expected: (to_nanoseconds_helper(spin_some_run_time)) > (to_nanoseconds_helper(waitable_callback_duration / 2)), actual: 55376 vs 1000000000
spin_some() took less than half the expected time to execute a single waitable, which implies it did not actually execute one when it was expected to
/home/william/ros2_ws/src/ros2/rclcpp/rclcpp/test/rclcpp/executors/test_executors.cpp:624: Failure
Expected equality of these values:
  number_of_waitables_executed
    Which is: 0
  1u
    Which is: 1
expected exactly one of the two waitables to be executed, but my_waitable1->get_count(): 0 and my_waitable2->get_count(): 0
[  FAILED  ] TestExecutors/EventsExecutor.spin_some_max_duration, where TypeParam = rclcpp::experimental::executors::EventsExecutor (22 ms)
[----------] 1 test from TestExecutors/EventsExecutor (22 ms total)

[----------] Global test environment tear-down
[==========] 4 tests from 4 test suites ran. (8169 ms total)
[  PASSED  ] 2 tests.
[  FAILED  ] 2 tests, listed below:
[  FAILED  ] TestExecutors/StaticSingleThreadedExecutor.spin_some_max_duration, where TypeParam = rclcpp::executors::StaticSingleThreadedExecutor
[  FAILED  ] TestExecutors/EventsExecutor.spin_some_max_duration, where TypeParam = rclcpp::experimental::executors::EventsExecutor

 2 FAILED TESTS

Note that I will also reduce the max_duration being tested, but in the above output I had increased it to 1s to see if it's a data race issue, but it doesn't appear to be the case.

I also took the opportunity to clarify the docstring for spin_some even though the text that was there previously already agreed with these tests, but I just made it extra clear what the expectation was (so clarified, but not a change in expected behavior).

wjwwood commented 6 months ago

CI:

wjwwood commented 6 months ago

CI: