Independent mutex to check and remove timer from scheduled timer by peterpena · Pull Request #1168 · ros2/rclcpp

peterpena · 2020-06-11T20:14:17Z

This PR tries to fix issue #1148. An independent mutex is added to protect the scheduled_timer_ set. This enables one thread to remove a timer from scheduled_timer_ while the other thread asynchronously tries to find the next executable. This removes the issue where one thread cannot remove the timer while the other thread keeps waking up and tries to get the timer but cannot execute it because the other thread is locked by the mutex. I ran tests to verify single and multi threaded executors can run the timer callbacks without any issues:

-- run_test.py: extra environment variables to append:
 - LD_LIBRARY_PATH+=/home/peter/ros2_foxy/build/rclcpp
-- run_test.py: invoking following command in '/home/peter/ros2_foxy/build/rclcpp':
 - /home/peter/ros2_foxy/build/rclcpp/test_wait_mutex --gtest_output=xml:/home/peter/ros2_foxy/build/rclcpp/test_results/rclcpp/test_wait_mutex.gtest.xml

Running main() from /home/peter/ros2_foxy/install/gtest_vendor/src/gtest_vendor/src/gtest_main.cc
[==========] Running 2 tests from 1 test case.
[----------] Global test environment set-up.
[----------] 2 tests from TestWaitMutex
[ RUN      ] TestWaitMutex.set_timer_wait_mutex_multi_threaded
[       OK ] TestWaitMutex.set_timer_wait_mutex_multi_threaded (12031 ms)
[ RUN      ] TestWaitMutex.set_timer_wait_mutex_single_threaded
[       OK ] TestWaitMutex.set_timer_wait_mutex_single_threaded (12024 ms)
[----------] 2 tests from TestWaitMutex (24055 ms total)

[----------] Global test environment tear-down
[==========] 2 tests from 1 test case ran. (24062 ms total)
[  PASSED  ] 2 tests.


-- run_test.py: return code 0
-- run_test.py: inject classname prefix into gtest result file '/home/peter/ros2_foxy/build/rclcpp/test_results/rclcpp/test_wait_mutex.gtest.xml'
-- run_test.py: verify result file '/home/peter/ros2_foxy/build/rclcpp/test_results/rclcpp/test_wait_mutex.gtest.xml'

fujitatomoya

There are some minor comments.

rclcpp/test/test_wait_mutex.cpp

fujitatomoya · 2020-06-12T02:42:10Z

rclcpp/test/test_wait_mutex.cpp

+
+using namespace std::chrono_literals;
+
+class TestWaitMutex : public ::testing::Test


I think that this test is to check wall_timer if the user callback is issued as expected times? if so, it would be better to change the file name and class name? like test_wall_timer_count.cpp or something?

I changed it to test_time_call_count.cpp

rclcpp/include/rclcpp/executors/multi_threaded_executor.hpp

fujitatomoya · 2020-06-12T06:37:46Z

@peterpena

btw, i confirmed the following difference between before and after,

before

[INFO] [1591939878.346141939] [multi_timer]: Timer executed!
[DEBUG] [1591939878.346165295] [rcl]: Timeout calculated based on next scheduled timer: false
[DEBUG] [1591939878.346255275] [rcl]: Guard condition in wait set is ready
[DEBUG] [1591939878.346336561] [rcl]: Waiting with timeout: 1s + 997190395ns
[DEBUG] [1591939878.346362808] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591939880.343696436] [rcl]: Timer in wait set is ready
[DEBUG] [1591939880.343978198] [rcl]: Waiting with timeout: 0s + 0ns
[DEBUG] [1591939880.344031401] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591939880.344079956] [rcl]: Timer in wait set is ready
[DEBUG] [1591939880.344231231] [rcl]: Waiting with timeout: 0s + 0ns
[DEBUG] [1591939880.344254341] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591939880.344274941] [rcl]: Timer in wait set is ready
[DEBUG] [1591939880.344339097] [rcl]: Waiting with timeout: 0s + 0ns
[DEBUG] [1591939880.344353732] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591939880.344371500] [rcl]: Timer in wait set is ready
[DEBUG] [1591939880.344482527] [rcl]: Waiting with timeout: 0s + 0ns
[DEBUG] [1591939880.344898532] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591939880.344935506] [rcl]: Timer in wait set is ready
[DEBUG] [1591939880.345049010] [rcl]: Waiting with timeout: 0s + 0ns
[DEBUG] [1591939880.345086660] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591939880.345131275] [rcl]: Timer in wait set is ready
[DEBUG] [1591939880.345275321] [rcl]: Waiting with timeout: 0s + 0ns
[DEBUG] [1591939880.345309318] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591939880.345347118] [rcl]: Timer in wait set is ready
[DEBUG] [1591939880.345414981] [rcl]: Calling timer
[INFO] [1591939880.345447669] [multi_timer]: Timer executed!

after

[INFO] [1591941505.293213375] [multi_timer]: Timer executed!
[DEBUG] [1591941505.293298531] [rcl]: Waiting without timeout
[DEBUG] [1591941505.293502878] [rcl]: Timeout calculated based on next scheduled timer: false
[DEBUG] [1591941505.293542102] [rcl]: Guard condition in wait set is ready
[DEBUG] [1591941505.293691008] [rcl]: Waiting with timeout: 1s + 999020401ns
[DEBUG] [1591941505.293723050] [rcl]: Timeout calculated based on next scheduled timer: true
[DEBUG] [1591941507.292893558] [rcl]: Timer in wait set is ready
[DEBUG] [1591941507.293109779] [rcl]: Calling timer
[INFO] [1591941507.293163348] [multi_timer]: Timer executed!

fujitatomoya

lgtm, but there seems to be a confliction.

fujitatomoya

lgtm, I'd like someone else to check.

ivanpauno · 2020-06-16T12:26:35Z

This removes the issue where one thread cannot remove the timer while the other thread keeps waking up and tries to get the timer but cannot execute it because the other thread is locked by the mutex

This was only a performance problem, right?
At some point the first thread unlocked the mutex and the others can start executing.

ivanpauno

Using two mutexes LGTM!

rclcpp/test/rclcpp/test_timer_call_count.cpp

ivanpauno · 2020-06-16T12:35:52Z

@ivanpauno ivanpauno deleted a comment from fujitatomoya 2 minutes ago

I was deleting a couple comments I did when reviewing (that were wrong), and by accident I deleted your comment @fujitatomoya 😁 . I don't know how to restore a comment, hope you remember what it was about.

peterpena · 2020-06-19T19:11:45Z

This removes the issue where one thread cannot remove the timer while the other thread keeps waking up and tries to get the timer but cannot execute it because the other thread is locked by the mutex

This was only a performance problem, right?
At some point the first thread unlocked the mutex and the others can start executing.

Yes, that is correct. After some number of iterations, the first thread is able to remove the timer from the scheduled_timers_.

ivanpauno

LGTM

ivanpauno · 2020-06-19T19:31:45Z

rclcpp/test/rclcpp/test_timer_call_count.cpp

+
+  executor.add_node(node);
+  executor.spin();
+}


nit: missing new line before EOF

ivanpauno · 2020-06-19T19:33:15Z

Yes, that is correct. After some number of iterations, the first thread is able to remove the timer from the scheduled_timers_.

Thanks for clarifying!!

ivanpauno · 2020-06-29T14:10:30Z

@peterpena is this ready?

(edit) there seems to be a bunch of liner failures

peterpena · 2020-07-01T23:30:30Z

@ivanpauno I still have to check why I am getting errors that were not there before.

Signed-off-by: Pedro Pena <peter.a.pena@gmail.com>

peterpena · 2020-07-06T21:41:36Z

Its good to go now. I believe @wjwwood wanted to take a look before I merge it though.

wjwwood

lgtm! sorry for the delay in reviewing.

peterpena · 2020-07-23T22:11:09Z

CI:

Linux
Linux-aarch64
macOS
Windows

peterpena · 2020-07-27T21:01:45Z

Linux
Linux-aarch64
macOS
Windows

peterpena · 2020-07-28T20:46:16Z

Linux
Linux-aarch64
macOS
Windows

peterpena · 2020-08-06T17:47:15Z

Linux
Linux-aarch64
macOS
Windows

fujitatomoya

I think get_next_executable and scheduled_timers_ should be protected by the same mutex, unless there will be possibility that the same timer is executed multiple times.

fujitatomoya · 2020-10-01T11:33:20Z

rclcpp/src/rclcpp/executors/multi_threaded_executor.cpp

-          }
-          continue;
+    }
+


context switch here with already scheduled timer by Thread-1. (Thread-2)

fujitatomoya · 2020-10-01T11:33:59Z

rclcpp/src/rclcpp/executors/multi_threaded_executor.cpp


    if (any_exec.timer) {
-      std::lock_guard<std::mutex> wait_lock(wait_mutex_);
+      std::lock_guard<std::mutex> wait_lock(scheduled_timers_mutex_);


execute timer and remove it from scheduled_timers_mutex_ (Thread-1)

fujitatomoya · 2020-10-01T11:36:02Z

rclcpp/src/rclcpp/executors/multi_threaded_executor.cpp

+    }
+
+    if (any_exec.timer) {
+      std::lock_guard<std::mutex> wait_lock(scheduled_timers_mutex_);


the same timer will be scheduled again and executed. (Thread-2)

peterpena requested a review from wjwwood June 11, 2020 20:14

peterpena force-pushed the peterpena/timer-mutex branch from 8743230 to 40fdb8e Compare June 11, 2020 20:15

fujitatomoya requested changes Jun 12, 2020

View reviewed changes

fujitatomoya reviewed Jun 13, 2020

View reviewed changes

wjwwood assigned peterpena Jun 15, 2020

peterpena force-pushed the peterpena/timer-mutex branch 2 times, most recently from 61e37df to f0a59be Compare June 15, 2020 22:56

fujitatomoya reviewed Jun 16, 2020

View reviewed changes

ros2 deleted a comment from fujitatomoya Jun 16, 2020

ivanpauno reviewed Jun 16, 2020

View reviewed changes

rclcpp/test/rclcpp/test_timer_call_count.cpp Show resolved Hide resolved

ivanpauno approved these changes Jun 19, 2020

View reviewed changes

peterpena force-pushed the peterpena/timer-mutex branch 2 times, most recently from f0a59be to fedf242 Compare June 19, 2020 22:20

peterpena force-pushed the peterpena/timer-mutex branch 5 times, most recently from 0a40fcf to 4345721 Compare July 6, 2020 20:59

peterpena added 5 commits July 6, 2020 17:05

scheduled timer mutex

7b1335d

Signed-off-by: Pedro Pena <peter.a.pena@gmail.com>

fixed test results (uncrustify)

44efcf7

Signed-off-by: Pedro Pena <peter.a.pena@gmail.com>

uncrustify fixes

39c7ca3

Signed-off-by: Pedro Pena <peter.a.pena@gmail.com>

fixed conversion

c0f7eb3

Signed-off-by: Pedro Pena <peter.a.pena@gmail.com>

fixing warnings

425a794

Signed-off-by: Pedro Pena <peter.a.pena@gmail.com>

changed type

a4fe5a5

Signed-off-by: Pedro Pena <peter.a.pena@gmail.com>

peterpena force-pushed the peterpena/timer-mutex branch from 4345721 to a4fe5a5 Compare July 6, 2020 21:06

fujitatomoya approved these changes Jul 7, 2020

View reviewed changes

wjwwood approved these changes Jul 23, 2020

View reviewed changes

fujitatomoya requested changes Oct 1, 2020

View reviewed changes

ivanpauno mentioned this pull request Oct 5, 2020

Timers being executed more than once by the multithread executor #1374

Closed

fujitatomoya mentioned this pull request Dec 11, 2020

Publishing is slow in Docker with MutliThreadedExecutor #1487

Closed

destogl mentioned this pull request Dec 20, 2020

MutliThreadedExecutor update rate is unstable ros-controls/ros2_control#260

Closed

ivanpauno mentioned this pull request Jan 15, 2021

Allow timers to keep up the intended rate in MultiThreadedExecutor #1516

Merged

destogl mentioned this pull request Feb 16, 2021

Restore using MutliThreadedExecutor once #260 is resolved in rclcpp ros-controls/ros2_control#277

Closed

clalancette mentioned this pull request Apr 16, 2021

Inconsistent namespaces for memory strategies #1186

Open

audrow changed the base branch from master to rolling June 28, 2022 14:21


		using namespace std::chrono_literals;

		class TestWaitMutex : public ::testing::Test

Conversation

peterpena commented Jun 11, 2020

Uh oh!

fujitatomoya left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

Uh oh!

fujitatomoya Jun 12, 2020

Choose a reason for hiding this comment

Uh oh!

peterpena Jun 15, 2020

Choose a reason for hiding this comment

Uh oh!

Uh oh!

fujitatomoya commented Jun 12, 2020

Uh oh!

fujitatomoya left a comment

Choose a reason for hiding this comment

Uh oh!

fujitatomoya left a comment

Choose a reason for hiding this comment

Uh oh!

ivanpauno commented Jun 16, 2020

Uh oh!

ivanpauno left a comment

Choose a reason for hiding this comment

Uh oh!

Uh oh!

ivanpauno commented Jun 16, 2020

Uh oh!

peterpena commented Jun 19, 2020

Uh oh!

ivanpauno left a comment

Choose a reason for hiding this comment

Uh oh!

ivanpauno Jun 19, 2020

Choose a reason for hiding this comment

Uh oh!

ivanpauno commented Jun 19, 2020

Uh oh!

ivanpauno commented Jun 29, 2020 • edited Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Uh oh!

peterpena commented Jul 1, 2020

Uh oh!

peterpena commented Jul 6, 2020

Uh oh!

wjwwood left a comment

Choose a reason for hiding this comment

Uh oh!

peterpena commented Jul 23, 2020

Uh oh!

peterpena commented Jul 27, 2020

Uh oh!

peterpena commented Jul 28, 2020

Uh oh!

peterpena commented Aug 6, 2020

Uh oh!

fujitatomoya left a comment

Choose a reason for hiding this comment

Uh oh!

fujitatomoya Oct 1, 2020

Choose a reason for hiding this comment

Uh oh!

fujitatomoya Oct 1, 2020

Choose a reason for hiding this comment

Uh oh!

fujitatomoya Oct 1, 2020

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

ivanpauno commented Jun 29, 2020 •

edited

Loading