Repository navigation
Receive path allocates and frees a payload-sized buffer per message: glibc trims the heap and the next message page-faults it back in #84
Description
Generated by Generative AI
Claude Code (Claude Opus 5.5). The profiling, the experiments and this write-up were done with Claude Code; every number comes from the local runs described below.
Operating System:
Linux 6.8.0-142-generic #142-Ubuntu SMP PREEMPT_DYNAMIC x86_64 GNU/Linux
ROS 2 distro:
jazzy
rmw_unix_socket_cpp version or commit hash:
Measured on devel @ 3ca379b (includes #83). The code paths below are unchanged on devel @ ba97253.
Client library (if applicable):
rclcpp
Executor (if applicable):
SingleThreadedExecutor
Does the same reproducer work with another RMW?
Yes — it works with another RMW, so the bug looks specific to rmw_unix_socket_cpp
QoS profile (if applicable):
No response (irobot_benchmark defaults)
'ros2 doctor --report' output
No response
Steps to reproduce issue
- Get the iRobot benchmark tools (
irobot_benchmarkfrom irobot-ros/ros2-performance, as built in irobot-ros/ros2-benchmark-container) and the topologybenchmark/topologies/pub-sub/topology_multi_5_topics_1000hz.json. It puts 5 publishers of 1 MB messages (44, 158, 540, 37 and 393 Hz, about 1.17 GB/s together) and one subscriber node on all 5 topics in one process. - Run it with intra-process communication off, so every message goes through the RMW:
RMW_IMPLEMENTATION=rmw_unix_socket_cpp irobot_benchmark topology_multi_5_topics_1000hz.json \ --executor 1 --ipc off -t 20 -s 1000 --csv-out on --results-dir out - Read
out/topology_multi_5_topics_1000hz_log/latency_all.txt, then repeat withRMW_IMPLEMENTATION=rmw_fastrtps_cpp.
This is the 5_process case of the suite's multi_process_scalability_pub_sub matrix.
Expected behavior
Latency in the range of the other RMWs: Fast DDS 256–277 µs mean, 56–99 µs standard deviation per topic.
Actual behavior
724–727 µs mean, 677–1 075 µs standard deviation per topic, single messages delayed by up to 14 ms, and the process uses 55 % of a core against 35 % for Fast DDS. All ~23 400 messages arrive with both RMWs, so the difference is latency and CPU, not loss.
Additional information
Summary
Each received payload goes into a new std::vector<uint8_t> (ReceivedMessage::payload, filled by shm_fetch_payload in drain_socket), and rmw_take_with_info frees it when the message goes out of scope after deserializing. For a 1 MB payload, glibc trims the heap on that free (madvise(MADV_DONTNEED)), so the next message page-faults the whole buffer back in, and the kernel zeroes it again. In the 5-publisher fan-in this is the single biggest cost: it roughly doubles the mean latency and causes most of the multi-millisecond delays. Disabling trimming alone cut the mean from 724–727 µs to 393–398 µs and process CPU from 55 % to 44 %.
rmw_unix_socket_cpp/rmw_unix_socket_cpp/src/types.hpp
Lines 138 to 143 in ba97253
rmw_unix_socket_cpp/rmw_unix_socket_cpp/src/shm_transport.cpp
Lines 461 to 517 in ba97253
rmw_unix_socket_cpp/rmw_unix_socket_cpp/src/rmw_subscription.cpp
Lines 430 to 495 in ba97253
Possible solutions
- Reuse the buffer instead of freeing it per message. Keep a small per-subscription free list of payload vectors, hand one to
drain_socketand return it afterrmw_take.assign()into a vector that already has the capacity doesn't reallocate, so the trims and page faults disappear. Smallest change, but it keeps the copy from Shared-memory receive path copies every large payload into a heap buffer before deserializing (shm_fetch_payload) #86. - Deserialize straight from the shm ring in
rmw_take. Queue only the descriptor, check the slot's sequence after deserializing, and drop the sample (counting it as lost) if the publisher lapped it. This removes both the buffer and the copy from Shared-memory receive path copies every large payload into a heap buffer before deserializing (shm_fetch_payload) #86. It's more work and has to keep KEEP_LAST semantics. - Stopgap only: users can set the
GLIBC_TUNABLESbelow (measured −46 % latency). The RMW itself shouldn't callmallopt, since that's process-wide.
The datagram path allocates a vector per message the same way. Above glibc's mmap threshold (128 KB by default) the same trim-and-fault cycle may also explain part of the 16–256 KB gap in perf_test. That part isn't measured.
How this was found
Everything ran in a container pinned to 12 logical CPUs (Ryzen 7 5700X), with devel built RelWithDebInfo -fno-omit-frame-pointer and libc6-dbg installed so libc symbols resolve. Profiling needed CAP_PERFMON because the host has perf_event_paranoid=4.
- Benchmark. The iRobot suite ranked unix_socket last on this case: devel 1 236–1 990 µs over 3 runs, 668–799 µs after fix(rmw_wait): keep the wait timeout's sub-millisecond resolution #83, against Fast DDS 278 µs, Fast DDS zero-copy 207 µs, Cyclone 494 µs and Zenoh 222 µs.
- Per-thread CPU (
/proc/<pid>/task/*/statdeltas over 5 s). With either RMW all the work runs on the one executor thread: unix_socket 54.6 %, Fast DDS 35.4 %. Fast DDS's 14 other threads stay idle because it delivers in-process without a transport. On one thread, every extra microsecond per message also delays the messages queued behind it. perf record -F 1999 -gon the process for 6 s, thenperf script, attributing eachmemmove/memsetsample to its first caller outside libc.perf statfor task-clock and page faults over 3 s.strace -c -f -p <pid>over a 4 s window to count syscalls.strace -f -k -e trace=madviseover 6 s, to get call stacks for every heap trim.- A/B experiments, two 20 s runs each: glibc trimming disabled with
GLIBC_TUNABLES=glibc.malloc.trim_threshold=1073741824:glibc.malloc.mmap_threshold=1073741824, an experimental guard-condition patch (see rmw_wait reads every guard condition's eventfd twice per call: ~38 failing read() syscalls per wait #85), and both together.
Results
A/B experiments (2 runs each):
| variant | mean latency | process CPU | per-topic sd | max delay |
|---|---|---|---|---|
| unix_socket devel | 724–727 µs | 55 % | 677–1 075 µs | 6.0–13.9 ms |
| + glibc trimming disabled | 393–398 µs | 44 % | 129–294 µs | 3.2–10.9 ms |
| + guard-condition pending flag only | 815–828 µs | 56 % | 822–1 347 µs | 5.8–13.8 ms |
| + both | 347–351 µs | 38 % | 114–257 µs | 2.3–11.3 ms |
| Fast DDS | 256–277 µs | 35 % | 56–99 µs | 0.6–3.4 ms |
Where the CPU goes (perf, % of the process's samples). CPU per message: unix_socket 1 370 ms task-clock in 3 s ≈ 390 µs; Fast DDS 1 084 ms ≈ 308 µs.
| work | unix_socket | Fast DDS |
|---|---|---|
deserialize the 1 MB array (Cdr::deserialize_array → memmove) |
20.1 % | 26.6 % |
serialize the 1 MB array (Cdr::serialize_array → memmove) |
12.8 % | 12.1 % |
benchmark fills the message (std::fill → memset) |
15.9 % | 22.4 % |
shm_fetch_payload copy, shm ring → heap buffer |
9.6 % | – |
| kernel, total | 22.8 % | ~0 (futex only) |
↳ read() from rmw_wait |
12.5 % | – |
↳ sendmsg, recv, epoll_pwait2, page faults during the fill |
2.5 %, 2.1 %, 1.9 %, 1.8 % | – |
Syscalls in 4 s (strace -c, about 4 700 messages):
| syscall | unix_socket | Fast DDS |
|---|---|---|
read |
88 789 (88 781 EAGAIN) | 8 |
madvise |
638 (69 µs each) | 0 |
recvfrom |
17 916 (8 912 EAGAIN) | 2 |
sendmsg |
4 502 | – |
epoll_pwait2 |
2 336 | – |
futex |
– | 7 660 |
Page faults in 3 s (perf stat): 15 247 for unix_socket (about 4.3 per message), 0 for Fast DDS.
madvise call stacks (strace -k, 6 s): all 351 calls are MADV_DONTNEED on the executor thread. 288 come from rmw_take_with_info freeing the received payload; the other 63 come from the benchmark freeing its own 1 MB message.
What's left after both experimental fixes: about 80 µs of mean latency, plus occasional multi-millisecond maxima that aren't explained yet. Removing the copy in #86 should account for part of it.
Related issues: #84 (buffer per message), #85 (guard-condition polling), #86 (extra copy).
Activity