0
$\begingroup$

Rosanswers logo

Hello, I have an odd one here and am trying to figure out a possible root cause!

The Situation

I am running a custom Linux version made using Buildroot, with application ROS code containerized. I have noticed some odd behavior with both roscore and roslaunch delaying between log messages and ultimately taking minutes to execute. This behavior occurs only with ROS kinetic, lunar, and melodic versions of roscore and roslaunch on Linux kernel 6.1. ROS noetic behaves as expected.

Note: the same configuration on Linux kernel 5.15 does not exhibit this behavior.


Test Summary

On Linux kernel 6.1, using the ros:kinetic/ros:lunar/ros:melodic Docker images from Docker Hub.

Run docker run -it --network host --entrypoint bash ros:kinetic, then from within the container run source /opt/ros/${ROS_DISTRO}/setup.bash && roscore -v

The terminal displays:

... logging to /root/.ros/log/0dfbd9a8-c533-11ed-998a-78d0042ad370/roslaunch-oc-general-68.log
Checking log directory for disk usage. This may take awhile.
 Press Ctrl-C to interrupt
Done checking log file disk usage. Usage is <1GB. 

... loading XML file [/opt/ros/kinetic/etc/ros/roscore.xml]
... executing command param [rosversion roslaunch]
Added parameter [/rosversion]
... executing command param [rosversion -d]
Added parameter [/rosdistro]
Added core node of type [rosout/rosout] in namespace [/]
started roslaunch server http://localhost:40105/
ros_comm version 1.12.17


SUMMARY
========

PARAMETERS
* /rosdistro: kinetic
* /rosversion: 1.12.17

NODES

auto-starting new master

And it hangs on auto-starting new master for ~100 seconds. The CPU% from htop is 100%.

After the initial ~100 seconds, roscore printed:

process[master]: started with pid [78]
ROS_MASTER_URI=http://localhost:11311/

setting /run_id to 0dfbd9a8-c533-11ed-998a-78d0042ad370

And hangs for another ~100 seconds on setting /run_id .... The CPU% from htop is also 100%.

Finally roscore finished with:

process[rosout-1]: started with pid [91]
started core service [/rosout]

Similar behavior exists when running roslaunch ... with the ~100 second wait occurring on the ROS_MASTER_URI=http://localhost:11311 output.

ROS Environment Variable

ROS_ROOT=/opt/ros/kinetic/share/ros
ROS_PACKAGE_PATH=/opt/ros/kinetic/share
ROS_MASTER_URI=http://localhost:11311
ROS_PYTHON_VERSION=2
ROS_VERSION=1
ROSLISP_PACKAGE_DIRECTORIES=
ROS_DISTRO=kinetic
ROS_ETC_DIR=/opt/ros/kinetic/etc/ros

Interestingly enough, if I use rosmon to launch I do not see the ~100 second wait. Could this point to a python issue shared by roscore and roslaunch since rosmon is written in C++?

Any advice would be greatly appreciated!


Update

Using pdb running roscore in the ros:melodic container, I have narrowed it down to the following call in the roslaunch/nodeprocess.py file:

/opt/ros/melodic/lib/python2.7/dist-packages/roslaunch/nodeprocess.py(340)

Which is a call to subprocess.Popen (see https://github.com/ros/ros_comm/blob/melodic-devel/tools/roslaunch/src/roslaunch/nodeprocess.py#L340)

Stepping into the subprocess.Popen call it seems to be here:

> /usr/lib/python2.7/subprocess.py(394)__init__()
-> errread, errwrite)

After executing that subprocess function the output from ps -aux is:

root         160  0.1  0.0 377148 63644 pts/0    Sl+  01:35   0:00 python -m pdb roscore
root         174 99.2  0.0 377148 54332 ?        Rs   01:38   0:53 python -m pdb roscore

Which eventually turns into:

root         174 96.3  0.0 435416 60136 ?        Ssl  01:38   1:40 /usr/bin/python /opt/ros/melodic/bin/rosmaster --core -p 11311 -w 3 __log:=/root/.ros

Maybe unrelated, I did notice that after the rosmaster subprocess is spawn, it gradually decreases it's CPU% over time.


Update #2

I built the melodic ros_base variant from source with Python3 support, and do not see delays in roscore or roslaunch. Just to double-check, I made sure Python3 was being used to run roscore

root    199  0.5  0.0 348944 40940 pts/0    Sl+  21:22   0:00 /usr/bin/python3 /opt/ros/melodic/bin/roscore -v
root    209  0.4  0.0 561516 37780 ?        Ssl  21:22   0:00 /usr/bin/python3 /opt/ros/melodic/bin/rosmaster --core -p 11311 -w 3 __log:=...

Definitely seems like an issue with Python2 and Linux kernel 6.1...bummer.


Update #3

After some additional debugging, I determined that the issue occurs only when the close_fds argument of the Python2 subprocess.Popen is set to True.

close_file_descriptor = True
...
self.popen = subprocess.Popen(self.args, cwd=cwd, stdout=logfileout, stderr=logfileerr, env=full_env, close_fds=close_file_descriptor, preexec_fn=preexec_function)

This issue is not strictly related ROS as I tested using a base ubuntu image with a test Python2 script that called subprocess.Popen.

After digging around the internet, I found that there have been issues with Python2's subprocess module causing deadlocks and race conditions. Google released a package called subprocess32 that is a direct replacement for subprocess that addresses the issues as well as backports Python3's implementation of fork and exec using the C module (see https://stackoverflow.com/a/25213194).

So I tested this by replacing the subprocess Python2.7 module with subprocess32 in the ros:kinetic-ros-base container:

# Install subprocess32, replace subprocess
RUN pip install --no-cache subprocess32
RUN cp /usr/local/lib/python2.7/dist-packages/subprocess32.py /usr/lib/python2.7/subprocess.py
RUN cp /usr/local/lib/python2.7/dist-packages/_posixsubprocess32.so /usr/lib/python2.7/lib-dynload/_posixsubprocess32.so

and ran it on my original Buildroot configuration with Kernel 6.1 and did not have any issues with the roscore delays.

My best guess at why I saw this issue in my updated Buildroot configuration was due to some race condition or deadlock interaction between Python2.7 subprocess and the updated version of glibc. In the new configuration glibc was at version 2.36-81 vs 2.34-109.


Update #4

After doing more investigation and running into OOM issues caused by every ROS nodes consuming ~8GB of memory (similar to issues in https://answers.ros.org/question/336963/rosout-high-memory-usage/), I think I might have found the real culprit to the underlying issue.

It turns out newer versions of docker and containerd set LimitNOFILE=infinity in the corresponding systemd unit: https://github.com/containerd/containerd/pull/7566.

This then evaluates to a ulimit within the container of:

:~# ulimit -Hn
1073741816
:~# ulimit -Sn
1073741816

Where the host evaluates to:

:~# ulimit -Hn
524288
:~# ulimit -Sn
1024

The Python2 submodule.Popen call with close_fd=True most likely iterates through all file descriptors to find the fds owned by the Popen call to close (which would be roughly 1073741816), per https://github.com/containerd/containerd/pull/7566#issuecomment-1461140261.

This is problematic for some software. A common daemon practice is to close all inherited file descriptors (typically 1024 from the standard soft limit) - which in Docker looks like a stalled / hanging process (but is actually performing over a billion close() syscalls IIRC):

subprocess32 probably does a much better job at determining the fd to close and therefore resolves this issue:

For the closing inherited FDs practice that daemons perform, there are more modern approaches

"modern approaches" -> https://stackoverflow.com/questions/899038/getting-the-highest-allocated-file-descriptor/918469#918469

The real solution is to limit the soft/hard nofiles that docker/containerd provides to its containers and there has been some significant discussion on this in https://github.com/containerd/containerd/pull/7566.


Originally posted by danambrosio on ROS Answers with karma: 106 on 2023-03-17

Post score: 2


Original comments

Comment by gvdhoorn on 2023-03-18:
If it hangs for multiple minutes, seeing what it's hanging on should not be too difficult with something like ptrace, or perhaps even pdb in case of Python scripts/packages.

That might lead to results faster than speculation. Might be worth a try.

Comment by danambrosio on 2023-03-18:
@gvdhoorn using pdb running roscore in the ros:melodic container, I have narrowed it down to the following call in the roslaunch/nodeprocess.py file:

/opt/ros/melodic/lib/python2.7/dist-packages/roslaunch/nodeprocess.py(340)

Which is a call to subprocess.Popen (see here)

Stepping into the subprocess.Popen call it seems to be here:

> /usr/lib/python2.7/subprocess.py(394)__init__()
-> errread, errwrite)

After executing that subprocess function the output from ps -aux is:

root         160  0.1  0.0 377148 63644 pts/0    Sl+  01:35   0:00 python -m pdb roscore
root         174 99.2  0.0 377148 54332 ?        Rs   01:38   0:53 python -m pdb roscore

Which eventually turns into:

root         174 96.3  0.0 435416 60136 ?        Ssl  01:38   1:40 /usr/bin/python /opt/ros/melodic/bin/rosmaster --core -p 11311 -w 3 __log:=/root/.ros

Comment by danambrosio on 2023-03-18:
Maybe unrelated, I did notice that after the rosmaster subprocess is spawn, it gradually decreases it's CPU% over time.

As regular posts don't have max lengths, please also include context around the subprocess.Popen(..) call. Especially the call chain leading to it. roscore starts multiple processes, and it'd be interesting to know which is causing the issue (could be all of them, or a specific one).

Comment by gvdhoorn on 2023-03-19:
Please add this to your initial post. Please also update all links to code to permalinks.

Comment by gvdhoorn on 2023-03-19:
Seeing as there don't appear to be any really interesting changes to the file you mention (git diff melodic-devel...noetic-devel -- tools/roslaunch/src/roslaunch/nodeprocess.py), I'm wondering whether this could be due to some incompatibility between Python 2.7 and kernel 6.1. You mention Noetic works, so that would be Python 3. Melodic is Python 2.

You could consider building a minimal Melodic with Python 3 support and starting roscore. There are a couple of Q&As here on ROS Answers which document how to do that. Seeing as you only need ros_comm that should not be too much work (ie: you won't be building anything which actually needs Python-bindings, which is where it gets more complex).

ptrace might show you exactly what is happening at the point of the hang though -- on the OS level, below what pdb can show you. subprocess can hang for various reasons, and with the very recent kernel, it might be something at the OS-level.

Comment by Mike Scheutzow on 2023-03-19:
Is it possible that another roscore process is already running on this machine? Only one port 11311 is available per machine.

Comment by danambrosio on 2023-03-19:
@gvdhoorn, updated the original post with the above comments, sorry about that. Feel free to remove the comments.

Comment by danambrosio on 2023-03-19:
@Mike Scheutzow there is only a single roscore being run. If there was multiple I would expect to see:

RLException: roscore cannot run as another roscore/master is already running. 
Please kill other roscore/master processes before relaunching.
The ROS_MASTER_URI is http://localhost:11311/
The traceback for the exception was written to the log file

Comment by danambrosio on 2023-03-19:
@gvdhoorn, see the update in the original post, seems like this is an issue with Python2 and Linux kernel 6.1. Suggest we close this as path forward would be to migrate to noetic.

Comment by gvdhoorn on 2023-03-20:
There's another possible cause, and that could be a Python 2 idiom (or pattern) doesn't work with kernel 6.1 any more. I'd say something like subprocess.Popen(..) would be especially "vulnerable" to that, as it deals with starting, monitoring and stopping processes as well as stdin, stdout, etc.

Suggest we close this as path forward would be to migrate to noetic.

This could indeed be an option.

Or use a from-source Melodic-with-Python3. It's not too difficult to build those.

There's probably a way to fix the problem you're seeing though. It would just require more debugging.

Comment by danambrosio on 2023-03-20:
Still digging into this, I have started to convince myself this may not be an issue with Kernel 6.1 but a package or packages that come with the Buildroot LTS that provides 6.1.

Comment by danambrosio on 2023-03-25:
@gvdhoorn let me know if you want to mark this closed or add an answer based on my recent update. Thank you for all your help!

Comment by gvdhoorn on 2023-03-25:
I would suggest to post your last edit as the answer, as it seems like it is the answer.

+1 for getting to the bottom of it. I'm sure this will save some users (quite) some time when they try to do something similar.

Comment by Mike Scheutzow on 2023-03-25:
@danambrosio That was a difficult one! Well done.

$\endgroup$

1 Answer 1

0
$\begingroup$

Rosanswers logo

Update #3 in the original post is a bandaid solution for the delays in roscore and roslaunch.

Update #4 highlights the underlying issue with nofile ulimits within a docker container. To override the values docker passes to containers for nofile soft and hard limits perform one of the following:

docker run ... --ulimit nofile=1024:524288

If you want this for all containers consider adding:

"default-ulimits": {
    "nofile": {
        "Name": "nofile",
        "Hard": 524288,
        "Soft": 1024
    }
}

Originally posted by danambrosio with karma: 106 on 2023-03-25

This answer was ACCEPTED on the original site

Post score: 2


Original comments

Comment by ruffsl on 2023-04-07:
Wow, what a deep rabbit hole! Congrats on finding the root cause. That containerd ticket you linked seem to have impacted a lot of projects, and was an interesting read. Thanks!

If I understood correctly, your issue was an unfortunate syzygy of using an older Python2 Popen submodule, with a modern linux kernel, and the latest containerd runtime? Should I expect to see such symptoms with modern or future distros (Ubuntu >= 22.04 LTS) and ROS releases (ROS 2 >= Humble) ?

Comment by danambrosio on 2023-04-10:
@ruffsl the issue was really that the newer buildroot LTS (2023.02) brought in a docker/containerd change that increased the container nofile soft and hard limits to infinity (over 1 billion). The python2 popen call with close_fd=True seemed to loop through all of these file descriptors causing it to hang as well as a XmlRpc issue that caused large memory allocation in ROS1 post kinetic. I tested this with Humble and buildroot (2023.02) and did not run into any issue. Also seems as if the fix is going into the future releases of docker, containderd and go.

$\endgroup$

Your Answer

By clicking “Post Your Answer”, you agree to our terms of service and acknowledge you have read our privacy policy.