Fix nodes spins rather than blocking and waiting, using 100% CPU [kinetic] #1557

meyerj · 2018-12-06T01:49:18Z

Fixes #1343, and other potential issues. ~~Most likely SteadyTimer never has been steady.~~

As commented in the original issue, there is no guarantee that the compiler will inline the calls to boost::condition_variable constructor, boost::condition_variable::timed_wait() and boost::condition_variable::wait_for() and it might or might not use the backported version from Boost 1.61 introduced in #1014. The namespace has not been changed and even within roscpp some compilation units used the patched and some used the unpatched implementation (by including or not including boost_161_condition_variable.h). If those methods are mixed, because one gets inlined and the other not, or because the same instance is used in different compilation units with different includes and preprocessor macros defined, the underlying pthread condition variable gets initialized with CLOCK_MONOTONIC but is called with system clock timestamps or vice-versa. This situation ultimately leads to the 100% busy-wait problem in CallbackQueue::callAvailable() as reported in #1343, if the CallbackQueue constructor for whatever reason calls the boost::condition_variable constructor from a compilation unit where BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC was not defined.

The first patch resolves this link ambiguity by changing the namespace of the included condition_variable and condition_variable_any implementations to boost_161. New preprocessor macros ROSCPP_BOOST_CONDITION_VARIABLE_HEADER and ROSCPP_BOOST_CONDITION_VARIABLE have been introduced and exposed in ros/common.h to select the implementation when roscpp is compiled. Because the memory layout does not change, I would carefully claim that the patch is fully ABI compatible. I copied libroscpp.so compiled from a patched workspace to /opt/ros/kinetic/lib and used it as a drop-in replacement over the past days, without having to recompile any other package installed from debians.

The second patch, 56ecdfa, fixes an issue with ROS timers that popped up in combination with the first. The boost::condition_variable::timed_wait() methods are considered deprecated and uses boost::get_system_time() (system clock) unconditionally to calculate the absolute timestamp here - as called by TimerManager::threadFunc(). If the condition variable would have been constructed as expected, with the implementation from Boost 1.61 or above and BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC defined, this call blocks the thread almost indefinitely and breaks timers (failing unit tests in roscpp_tests) - the inverse problem. It has already been reported here and marked as wontfix. The solution is to switch to the Boost Chrono interface as already done in #1250 for ros::CallbackQueue. I have no good explanation why this problem has not been triggered before. It only makes sense if the backported constructor of boost::condition_variable would have never been called because of the order of source files in the roscpp library and hence SteadyTimer never has been fully steady (#1014). Any better ideas?

Last but not least, fdca164 applies the patch from #1464 to the other timer types and adds WallTimer::hasStarted() and SteadyTimer::hasStarted(), just for completeness and to match the three interfaces except for the time, duration and event types. (replaced by #1565)

To be absolutely certain that TimerManager<T, D, E> will never be instantiated outside of a compilation unit that defines BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC (see timer_manager.h:215), I suggest to move the implementation of the constructor and member functions to a source file timer_manager.cpp with explicit template instantiation for the three timer types. I tested this approach to exclude that TimerManager<T, D, E> and the internal condition variable is constructed elsewhere, without the definition of BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC. But at the end I reverted that patch because this was not the case. An alternative, but more intrusive solution would be to move the timer_manager.h header to the src folder and to not expose it at all.

Sorry for targeting kinetic-devel although it should probably be melodic-devel, but this is the version I have been working on. In general, the patch applies to all versions since kinetic (not tested yet).

…tion_variable (fix ros#1343) ros#1014 and ros#1250 introduced a backported version of boost::condition_variable, where support for steady (monotonic) clocks has been added in version 1.61. But the namespace of the backported version was not changed and the symbol names might clash with the original version. Because the underlying clock used for the condition_variable is set in the constructor and must be consistent with the the expectations within member variables. The compiler might choose to inline one or the other or both, and is more likely to do so for optimized Release builds. But if it does not, the symbol ends up in the symbol table of roscpp and depending on which other libraries will be linked into the process it is unpredictable which of the two versions will be actually called at the end. In case the constructor defined in `/usr/include/boost/thread/pthread/condition_variable.hpp` was called and did not configure the internal pthread condition variable for monotonic clock, each call to the backported do_wait_until() method with a monotonic timestamp will return immediately and hence causes `CallbackQueue::callOne(timeout)` or `CallbackQueue::callAvailable(timeout)` to return immediately. This patch changes the namespace of the backported condition_variable implementation to boost_161. This removes the ambiguity with the original definition if both are used in the same process.

…ed timed_wait() This fixes ROS timers in combination with 2c18b9f. The timer callbacks were not called because the TimerManager's thread function blocked indefinitely on boost::condition_variable::timed_wait(). Relative timed_wait() uses the system clock (boost::get_system_time()) unconditionally to calculate the absolute timestamp for do_wait_until(). If the condition variable has been initialized with BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC, it compares this timestamp with the monotonic clock and therefore blocks. This issue has been reported in https://svn.boost.org/trac10/ticket/12728 and will not be fixed. The timed_wait interface is apparently deprecated.

fujitatomoya · 2018-12-07T01:29:12Z

confirmed #1343 is fixed with this patch.

flixr · 2018-12-11T12:17:27Z

Thanks a lot for digging into this!
Looks like a much better/cleaner solution to me, will try to also test this asap.

flixr · 2018-12-13T17:53:32Z

clients/roscpp/include/ros/steady_timer.h

   */
  void setPeriod(const WallDuration& period, bool reset=true);

+  bool hasStarted() const { return impl_->hasStarted(); }


The corresponding Impl::hasStarted() seem to be still missing in steady_timer.cpp

Thanks, fixed in c37a75b.

flixr · 2018-12-13T18:46:51Z

Fixes #1343, and other potential issues. Most likely SteadyTimer never has been steady.

Maybe I never ran into any issues like this, because I'm always using Release builds and then the SteadyTimer works as expected.

Sorry for targeting kinetic-devel although it should probably be melodic-devel

Melodic (or rather Ubuntu bionic) already has boost 1.65, so at least the problem with the backported headers should not arise there.

meyerj · 2018-12-14T14:13:04Z

Maybe I never ran into any issues like this, because I'm always using Release builds and then the SteadyTimer works as expected.

I overlooked the specialization of TimerManager<T,D,E>::threadFunc() in steady_timer.cpp. This one already used the Boost Chrono interface and was working as expected.

However, the code duplication is not required anymore now that the general definition of threadFunc() in timer_manager.h also uses Boost Chrono. It has some additional checks whether time jumped backwards which are not required for the steady timer, but they also should not hurt. I merged the two implementations in bb1c24f.

flixr · 2018-12-14T14:57:17Z

I guess it would actually make sense to create a separate PR for the added hasStarted methods...
They have nothing to do with the rest and can then more easily be reviewed/merged separately.

…eadFunc() in steady_timer.cpp The updated generic definition in timer_manager.h should do the same with a minor update. In all cases we can call boost::condition_variable::wait_until() with an absolute time_point of the respective clock. The conversion from system_clock to steady_clock for Time and WallTime is done internally in boost::condition_variable::wait_until(lock_type& lock, const chrono::time_point<Clock, Duration>& t).

meyerj · 2018-12-14T19:29:10Z

I guess it would actually make sense to create a separate PR for the added hasStarted methods...
They have nothing to do with the rest and can then more easily be reviewed/merged separately.

Done: #1565

meyerj · 2018-12-14T19:58:50Z

Result of running abi-compliance-checker on libroscpp.so compiled from 1.12.14 and fix-1343 (this PR) on Ubuntu Xenial, compiled in RelWithDebInfo mode:
https://gistpreview.github.io/?e7db43ad2f12f9c44a1df0336983d131/compat_report.html

As expected, the type of two condition variable members has been changed, but because the memory layout did not, this should not be a problem.

meyerj · 2019-01-10T22:28:38Z

Regarding the failing unit test:

13:19:44 [ RUN      ] CallbackQueue.raceConditionCallback
13:19:45 /tmp/ws/src/ros_comm/test/test_roscpp/test/test_callback_queue.cpp:466: Failure
13:19:45 Value of: condition_object.condition_one.load()
13:19:45   Actual: true
13:19:45 Expected: false
13:19:45 [  FAILED  ] CallbackQueue.raceConditionCallback (61 ms)

(http://build.ros.org/job/Kpr__ros_comm__ubuntu_xenial_amd64/464)

I could reproduce the same failure locally when running with kinetic-devel (fb6a6bd). The test case fails approx. 1 out of 20 times. The test case was introduced in #1054. From the description, I would assume that it is not related to #1343 or this patch.

Ah, kinetic is missing the patch from 507299f. Are there plans to backport bug fixes from lunar or melodic to kinetic or even indigo?

meyerj · 2019-01-10T22:54:13Z

Ah, kinetic is missing the patch from 507299f. Are there plans to backport bug fixes from lunar or melodic to kinetic or even indigo?

I opened another PR to backport this one: #1578

dirk-thomas · 2019-02-01T18:52:12Z

Sorry for targeting kinetic-devel although it should probably be melodic-devel

Please retarget the melodic-devel branch with this PR. In general patches are only accepted to the default branch (except if a patch is only necessary for older distros).

@meyerj Can you please check #1608 and comment how this patch compares to the other one.

dirk-thomas · 2019-02-22T17:06:01Z

@meyerj Friendly ping.

ahoarau · 2019-02-25T15:55:27Z

Does not seem to like the PR with a c++14 library (unique_lock from boost/std)

install/include/boost_161_pthread_condition_variable_fwd.h:52:13: error: reference to ‘unique_lock’ is ambiguous
             unique_lock<mutex>& lock,

peci1 · 2019-02-25T15:58:52Z

This PR is against ROS Kinetic, which does not officially support C++14, if I'm not mistaken

ahoarau · 2019-02-25T16:00:41Z

c++11 causes the same problems. Very identical compatibility

ahoarau · 2019-02-25T17:49:02Z

I removed all the using namespace, and now it builds fine.
fix-fix-1343.tar.gz

dirk-thomas · 2019-03-08T18:20:10Z

@meyerj Another friendly ping. If this should be included in an upcoming release please consider rebasing this against melodic-devel.

fix namespaces

meyerj · 2019-03-12T23:49:56Z

I merged the patch from @ahoarau in meyerj#1, which seems to solve the C++11/C++14 compatibility issues according to #1557 (comment). Thanks for the patch!

Unfortunately I do not have the time at the moment to test this myself or to compare with the solution proposed in #1608.

Please retarget the melodic-devel branch with this PR. In general patches are only accepted to the default branch (except if a patch is only necessary for older distros).

I opened another PR against melodic-devel: #1651

However, if melodic normally demands at least Boost 1.62 according to REP-3, it might not be necessary to apply the patch there and we could rather remove the Boost 1.61 backports only required for older versions completely. See my comment in the new PR.

…n timer_manager.h Since Boost 1.67 BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC became the default if the platform supports it and the macro is not defined anymore. Instead, check for BOOST_THREAD_INTERNAL_CLOCK_IS_MONO.

…ITION_VARIABLE_HEADER macros by a typedef in internal_condition_variable.h

flixr · 2019-11-12T19:41:58Z

We can close this in favor of #1651

meyerj · 2019-11-13T15:03:24Z

We can close this in favor of #1651

The backport of #1651 to kinetic-devel is non-trivial. I am fine with closing this PR, but I would be happy if the patch could be backported and released in ROS kinetic, too. In that case the diff here could serve as a reference.

meyerj · 2020-07-31T01:17:06Z

See #2011 for a newer patch targeting kinetic-devel that is supposed to fix the same issue.

meyerj added 2 commits December 4, 2018 22:17

meyerj mentioned this pull request Dec 6, 2018

Regression in 1.12.13: rosout node spins rather than blocking and waiting, using 100% CPU #1343

Closed

flixr reviewed Dec 13, 2018

View reviewed changes

meyerj mentioned this pull request Dec 14, 2018

Add hasStarted() const to WallTimer and SteadyTimer API #1565

Merged

meyerj added 2 commits December 14, 2018 20:27

roscpp: do not use boost_161_condition_variable.h on Windows (untested)

76a6de9

meyerj force-pushed the fix-1343 branch from bb1c24f to ef785cc Compare December 14, 2018 19:29

fix compiler warnings about unused variables (ros#1428)

d51ba50

meyerj mentioned this pull request Jan 10, 2019

fix compiler warnings about unused variables (backport to kinetic-devel) #1576

Merged

Merge branch 'fix-compiler-warnings-kinetic' into fix-1343

9ffec1b

dirk-thomas changed the title ~~Fix nodes spins rather than blocking and waiting, using 100% CPU~~ Fix nodes spins rather than blocking and waiting, using 100% CPU [kinetic] Jan 31, 2019

dirk-thomas added the bug label Jan 31, 2019

dirk-thomas mentioned this pull request Feb 1, 2019

[WIP] Fix subscription busy wait (melodic-devel) #1608

Closed

dirk-thomas added the hitlist label Feb 5, 2019

This comment has been minimized.

Sign in to view

fix namespaces

3e69d27

ahoarau mentioned this pull request Feb 25, 2019

fix namespaces meyerj/ros_comm#1

Merged

ahoarau and others added 2 commits February 26, 2019 11:21

add more explicit namespaces

42ef216

add missing ns

0745e71

Merge pull request #1 from ahoarau/fix-1343

175dcbd

fix namespaces

meyerj mentioned this pull request Mar 12, 2019

Fix nodes spins rather than blocking and waiting, using 100% CPU [melodic] #1651

Closed

meyerj added 2 commits April 5, 2019 20:41

roscpp: replace ROSCPP_BOOST_CONDITION_VARIABLE and ROSCPP_BOOST_COND…

4c78380

…ITION_VARIABLE_HEADER macros by a typedef in internal_condition_variable.h

dirk-thomas closed this Feb 3, 2020

meyerj mentioned this pull request Jul 31, 2020

Use an internal implementation of boost::condition_variable with monotonic clock [kinetic-devel] #2011

Merged

meyerj deleted the fix-1343 branch July 31, 2020 01:17

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Fix nodes spins rather than blocking and waiting, using 100% CPU [kinetic] #1557

Fix nodes spins rather than blocking and waiting, using 100% CPU [kinetic] #1557

meyerj commented Dec 6, 2018 •

edited

Loading

fujitatomoya commented Dec 7, 2018

flixr commented Dec 11, 2018

flixr Dec 13, 2018

meyerj Dec 14, 2018

flixr commented Dec 13, 2018

meyerj commented Dec 14, 2018

flixr commented Dec 14, 2018

meyerj commented Dec 14, 2018

meyerj commented Dec 14, 2018

meyerj commented Jan 10, 2019 •

edited

Loading

meyerj commented Jan 10, 2019

dirk-thomas commented Feb 1, 2019

dirk-thomas commented Feb 22, 2019

This comment has been minimized.

This comment has been minimized.

ahoarau commented Feb 25, 2019

peci1 commented Feb 25, 2019

ahoarau commented Feb 25, 2019

ahoarau commented Feb 25, 2019

dirk-thomas commented Mar 8, 2019

meyerj commented Mar 12, 2019

flixr commented Nov 12, 2019

meyerj commented Nov 13, 2019

meyerj commented Jul 31, 2020

Fix nodes spins rather than blocking and waiting, using 100% CPU [kinetic] #1557

Fix nodes spins rather than blocking and waiting, using 100% CPU [kinetic] #1557

Conversation

meyerj commented Dec 6, 2018 • edited Loading

fujitatomoya commented Dec 7, 2018

flixr commented Dec 11, 2018

flixr Dec 13, 2018

Choose a reason for hiding this comment

meyerj Dec 14, 2018

Choose a reason for hiding this comment

flixr commented Dec 13, 2018

meyerj commented Dec 14, 2018

flixr commented Dec 14, 2018

meyerj commented Dec 14, 2018

meyerj commented Dec 14, 2018

meyerj commented Jan 10, 2019 • edited Loading

meyerj commented Jan 10, 2019

dirk-thomas commented Feb 1, 2019

dirk-thomas commented Feb 22, 2019

This comment has been minimized.

This comment has been minimized.

ahoarau commented Feb 25, 2019

peci1 commented Feb 25, 2019

ahoarau commented Feb 25, 2019

ahoarau commented Feb 25, 2019

dirk-thomas commented Mar 8, 2019

meyerj commented Mar 12, 2019

flixr commented Nov 12, 2019

meyerj commented Nov 13, 2019

meyerj commented Jul 31, 2020

meyerj commented Dec 6, 2018 •

edited

Loading

meyerj commented Jan 10, 2019 •

edited

Loading