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

[NickZ]

Introduced in faab4cb. This is a bug in the roscpp client.

In callAvailable() in callback_queue.cpp, if no callback is available, wait_for() (located in boost_161_pthread_condition_variable_fwd.h) is called on the condition variable, and is told to wait for a specified amount of time (usually 0.1 seconds). However, instead of waiting for the specified amount of time, it returns immediately, turning this into a spin wait rather than a blocking wait. This leads to the rosout node chewing up 100% of the CPU core.

[NickZ]

The issue is that, on linux systems and every other platform with monotonic clock set, wait_for() calls steady_clock.now() to get the system time. "steady_clock" is a monotonic time clock that is a relative clock (usually whenever the system booted up.) However, wait_for() => wait_until() => do_wait_until() ultimately calls pthread_cond_timedwait() with a timeout value based on that relative clock value. pthread_cond_timedwait() only takes in absolute system time values. Thus, it immediately returns with a timeout, since the relative time is guaranteed to be smaller than the system time.

[NickZ]

Ok, I've discovered the root cause. It's nasty, nasty compiler/linker behavior. Also, the bug is different across boost versions.

pthread_cond_timedwait() does not normally take monotonic clock values. However, when creating the condition_variable, it can set the condition attributes of the pthread condition to accept Monotonic clock values:

However, this never actually gets called.

On systems that have boost <1.61 (tested on Ubuntu 16.04), it's supposed to use the condition_variable defined in boost_161_pthread_condition_variable_fwd.h. However, the constructor for the condition variable as defined in that file does not actually get used, it uses the constructor in the system boost library, which does not call the pthread_cond_init function:

This is especially bizarre, since I have observed in debugging that it's using the wait_for() and wait_until() function calls in boost_161_pthread_condition_variable_fwd.h.

On systems that have boost >=1.61 (tested on Ubuntu 18.04), it uses the system boost library. Normally, the pthread condition attribute would be set, since we set BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC in callback_queue.cpp. However, we can see that's not the case:

It uses the preprocessor else block instead. This is even more bizarre, since it hits numerous other code blocks that require that preprocessor definition.

I don't know how to fix this, unfortunately, but hopefully someone here knows enough compiler/linker juju to fix it.

[flixr]

However, wait_for() => wait_until() => do_wait_until() ultimately calls pthread_cond_timedwait() with a timeout value based on that relative clock value. pthread_cond_timedwait() only takes in absolute system time values. Thus, it immediately returns with a timeout, since the relative time is guaranteed to be smaller than the system time.

That should not really be possible to happen, wait_for(duration) always basically calls wait_until(current_time + duration) where current_time is either derived from system clock or monotonic clock dependent on the BOOST_THREAD_HAS_CONDATTR_SET_CLOCK_MONOTONIC define.

I cannot reproduce this issue, could you please provide some more information?

Tried with latest versions from shadow-fixed (ros-kinetic-roscpp 1.12.13 and so on) and the simple listener from ros-kinetic-roscpp-tutorials and it works fine.

[kjaget]

I saw this same issue building roscpp from source just recently. Same symptom - near 100% cpu usage in every node. Reverting to 1.12.12 fixed the problem immediately. I can pull info off my system to help diagnose but I'm not sure what might be useful. It is a Ubuntu 16.04 system which is up to date with apt-get but with not much custom built - let me know what info would be useful.

[NickZ]

I did some further testing, and apparently this issue does not occur if you build the entire ros_comm stack from scratch; It only occurs if you either already have the base 1.12.12 system packaging installed and you only build ros_comm and roscpp_core, or if you rebuild only the ros_comm part for a source installation. So, some sort of compiler/linker issue. I have to set up some sort of testing apparatus to track the cause down with more specificity.

[flixr]

Hm.. strange. I still can not reproduce this...
What I tried on Ubuntu 16.04 with the released kinetic packages (1.12.12) as base:

• create a clean catkin workspace based on /opt/ros/kinetic
• add ros_comm, roscpp_core and ros_tutorials repos with kinetic-devel branch
• build only rostime, roscpp and ros_tutorials
• run any of the talker/listeners from the tutorials

I built the parts to be tested and used the rest from /opt/ros/kinetic

catkin build --no-deps rostime
catkin build --no-deps roscpp
catkin build --no-deps roscpp_tutorials

It still works as expected, regardless if I run the listener from the binaries or the rebuilt tutorials...

[NickZ]

Ok, this is what I did to reproduce consistently:

1. Get a fresh Ubuntu 16.04 image (in either a VM, bare-metal, or a lxc/docker container).
2. Install the ros-base package (sudo apt-get install ros-kinetic-ros-base)
3. create a clean catkin workspace based on /opt/ros/kinetic
4. Populate it with ros_comm, roscpp_core, and ros_tutorials repos on the kinetic-devel branch
5. Either run catkin_make, or use the build process you describe above, I've reproduced it with both.
6. source devel/setup.bash, run roscore, observe the cpu in top.

[flixr]

Could it be that this is a problem with catkin_make, as I was using catkin from the catkin_tools package...
Does this problem also occur with catkin_make_isolated?

[NickZ]

as I've said, I've done this using both the build process described in your post, just usingcatkin, and with catkin_make. I get the same bug.

It does not occur when I have built the whole ros_comm stack from source, using catkin_make_isolated.

[flixr]

Hm.... I used the install space when testing this... will try again with the devel space.
But this still sounds like basically a known issue with caktin_make to me...

[NickZ]

Just for reference, what catkin bugs should I be aware of?

[flixr]

Should have phrased it more precisely: known limitation.
Currently I can't find this anywhere in the catkin docs, but it's nicely summarized here: http://catkin-tools.readthedocs.io/en/latest/migration.html