Post Mortem: Ceph v18.2.7 OSD High CPU Usage Caused by the Messenger
A single object was being requested by >100 clients triggered the messenger to throttle on one OSD, causing CPU to spike above 300% and cause slow operations across unrelated PGs. We trace the root cause to the osd_client_message_cap throttle and its interaction with a known upstream bug Ceph Tracker #62512.
Environment and Background
This was a Ceph Reef v18.2.7 cluster all NVMEs where clients were accessing RADOS directly which means no CephFS/RGW/RBD deployed. This was a cluster with an erasure coded (EC) deployment of 6+2, and 100G NIC deployment.
During this time there was a host in maintenance mode, those OSDs were already down+out and can be considered unrelated for this problem as the health warnings can look misleading.
$ ceph -s
cluster:
id: abc
health: HEALTH_WARN
13 failed cephadm daemon(s)
1 hosts fail cephadm check
failed to probe daemons or devices
1 host is in maintenance mode
2 OSDs or CRUSH {nodes, device-classes} have {NOUP,NODOWN,NOIN,NOOUT} flags set
services:
mon: 5 daemons, quorum a,b,c,d,e(age 44h)
mgr: a.zqnmoz(active, since 7w), standbys: b.kdgqlg, c.dkqshj, d.ltfvqz, e.qyleyf
osd: 1600 osds: 1568 up (since 20m), 1568 in (since 41h)
data:
pools: 3 pools, 16897 pgs
objects: 17.54G objects, 15 PiB
usage: 20 PiB used, 65 PiB / 86 PiB avail
pgs: 16833 active+clean
36 active+clean+scrubbing+deep
28 active+clean+scrubbing
io:
client: 9.1 GiB/s rd, 863 MiB/s wr, 30.30k op/s rd, 1.54k op/s wr
This admin reported "some percentage of object reads are taking orders of magnitude longer than they should, more than 20-30 second" and seeing errors such as "no such file or directory" (ENOENT).
End-users (who were using RADOS directly) reported application-level timeouts and errors. Even objects that no longer existed were experiencing this slowness. For comparison, reads against other objects in the same pool returned reliably in ~0.05s.
For example, this command took between 1 to 20 seconds to respond with an ENOENT.
rados -p test get 2572e62cbe6ec0006f74ac1f6b40a318-617 /dev/null
During this time, the admin was also reporting these RADOS operations coincided to a specific PG: 3.12b.
Some columns were redacted in this output, but we can identify that osd.734 was primary for this specific PG.
ceph pg dump | grep 3.12b
PG_STAT OBJECTS STATE UP UP_PRIMARY ACTING ACTING_PRIMARY
3.12b 6951 active+clean [734,29,487,1406,482,2010,421,1734] 734 [734,29,487,1406,482,2010,421,1734] 734
During the debugging, the team also confirmed that the issue gets 'moved' to another OSD if this osd.734 were to go down.
The admin also attempted to stop osd.734.
Commands that previously took a long time ran as expected, but an identical problem arose on PG 2.3387. When osd.734 was restarted and returned to an UP state, the problem with the objects returned.
The cluster was reporting SLOW_OPS on osd.734:
2026-03-13T07:06:10.571-0700 0 log_channel(cluster) log [WRN] :
Health check failed: 0 slow ops, oldest one blocked for 32 sec,
osd.734 has slow ops (SLOW_OPS)
The SLOW_OPS health warning would go away and was not persistent under 'ceph status'. These were found by looking into the monitor's logs.
What Made osd.734 Special?
The fact that the problem would 'move' to another OSD, leads us to believe this points to an issue with the workload instead of a hardware issue with that specific OSD.
top showed osd.734 consuming ~338% CPU, dramatically more than any other OSD on the host:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
1898280 167 20 0 8628268 6.9g 28416 S 337.8 1.9 194:38.68 ceph-osd <-- osd.734
42538 167 20 0 19.6g 11.2g 22272 S 18.3 3.0 3w+0d ceph-osd
40237 167 20 0 19.8g 10.4g 21504 S 15.9 2.8 3w+1d ceph-osd
37182 167 20 0 19.6g 10.9g 22272 S 13.4 2.9 3w+1d ceph-osd
46551 167 20 0 23.3g 9.6g 23040 S 7.3 2.6 3w+3d ceph-osd
We can do top -c and it will show which pid belonging to which OSD ID.
Per-thread view (top -H) confirmed the CPU was consumed almost entirely by the three Messenger worker threads:
PID USER PR NI VIRT RES SHR S %CPU %MEM TIME+ COMMAND
2027477 167 20 0 19.6g 15.2g 29952 R 97.0 4.1 222:49.04 msgr-worker-1
2027478 167 20 0 19.6g 15.2g 29952 R 95.7 4.1 223:03.48 msgr-worker-2
2027476 167 20 0 19.6g 15.2g 29952 R 90.2 4.1 208:02.53 msgr-worker-0
2028133 167 20 0 19.6g 15.2g 29952 S 21.0 4.1 51:34.03 tp_osd_tp
48511 167 20 0 23.3g 9.8g 23040 S 19.0 2.6 27,02 tp_osd_tp
2028125 167 20 0 19.6g 15.2g 29952 R 18.7 4.1 43:35.56 tp_osd_tp
48519 167 20 0 23.3g 9.8g 23040 S 17.0 2.6 27,05 tp_osd_tp
These msgr-worker threads belonged to our osd.734.
All three msgr-worker threads were pinned at ~95-97%.
A single OSD would usually have multiple threads, 3 dedicated to the Ceph messenger (msgr-worker-x) and tp_osd_tp threads which are responsible for disk IO.
The output of iostat for this OSD didn't seem to give anything unusal.
$ iostat -x
Device r/s rkB/s rrqm/s %rrqm r_await rareq-sz w/s wkB/s wrqm/s %wrqm w_await wareq-sz d/s dkB/s drqm/s %drqm d_await dareq-sz f/s f_await aqu-sz %util
nvme6n1 50.00 816.00 2.00 3.85 0.10 16.32 33.00 400.00 6.00 15.38 0.03 12.12 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.00 0.01 0.50
After going through smartctl, perf top it becomes more evident here that this doesn't look to be a hardware issue on osd.734. Although at this point it wasn't clear what was even happening.
The team increased logging for osd.734, in particular debug_ms=1 to see what the Messenger was doing. Ontop of this, the team used upmaps to manually move PGs one by one off of osd.734 to pinpoint down the issue.
The output of debug_ms=1 for the OSD was captured over the span of 10 seconds multiple times. From there we found that a singular RADOS object (src-12d7b69b29cf2140d40c7a16936da33f-0) was being requested by 107 different clients re-reading the same object ~35,000 times in a 10s window.
In retrospect, slow operations were being reported initially, which means those slow operations were being recorded and can be queried ceph tell osd.734 dump_historic_slow_ops
{
"event": "throttled",
"time": "2026-03-13T15:35:00.338542+0000",
"duration": 13.568615711
}
It seemed that all the slow operations recorded were get delayed because of the throttled event, which also hints it isn't a hardware or a system wide problem.
$ ceph tell osd.734 dump_historic_slow_ops | grep desc
"description": "osd_op(client.2330059945.0:2146931 2.3bebs0 2:d7de3792:::src-08f4369b42091000bf56c84bd6ee2170-0:head [stat] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e1933819)",
"description": "osd_op(client.2330525287.0:53970260 2.f19s0 2:98f2aa40:::src-12d7b69b29cf2140d40c7a16936da33f-0:head [assert-version v19126837,read 4~4194516,stat] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e1933819)",
"description": "osd_op(client.2330430683.0:3561166 2.3bebs0 2:d7dee860:::36d3469b4206f0b66e67b4e9b801dfe2:head [create,writefull 0~1502942] snapc 0=[] ondisk+write+known_if_redirected+supports_pool_eio e1933819)",
"description": "osd_op(client.2330062125.0:94888973 2.f19s0 2:98f2aa40:::src-12d7b69b29cf2140d40c7a16936da33f-0:head [stat] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e1933819)",
"description": "osd_op(client.2330430968.0:145419223 2.f19s0 2:98f2aa40:::src-12d7b69b29cf2140d40c7a16936da33f-0:head [stat] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e1933819)",
"description": "osd_op(client.2330509577.0:515965984 2.f19s0 2:98f2aa40:::src-12d7b69b29cf2140d40c7a16936da33f-0:head [assert-version v19126837,read 4~4194516,stat] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e1933819)",
"description": "osd_op(client.2330071635.0:86513218 2.f19s0 2:98f2aa40:::src-12d7b69b29cf2140d40c7a16936da33f-0:head [assert-version v19126837,read 4~4194516,stat] snapc 0=[] ondisk+read+known_if_redirected+supports_pool_eio e1933819)",
...
...
Since these throttles were getting hit, understanding why they were getting hit and how they are impacting IO is an important step in debugging this issue.
The output of perf dump of an OSD can be useful for figuring out where things are slow and which throttles are being hit. At some point, we reset these counters to get a fresh recording 1.
A perf dump of osd.734 (reset, then collected after 5 minutes) showed the osd_client_message_cap throttle pinned at its maximum:
$ ceph tell osd.734 perf dump
...
..
"throttle-osd_client_messages": {
"val": 254,
"max": 256,
"get_started": 0,
"get": 2358958,
"get_sum": 2358958,
"get_or_fail_fail": 9046931,
"get_or_fail_success": 2358958,
"take": 0,
"take_sum": 0,
"put": 2358704,
"put_sum": 2358704,
"wait": {
"avgcount": 0,
"sum": 0.000000000,
"avgtime": 0.000000000
}
}
...
Some things to note in this perf dump:
val: 254/max: 256— the throttle is essentially full at all times.get_or_fail_fail: 9,046,931— over 9 million attempts to acquire a throttle slot were rejected in 5 minutes.get_or_fail_success: 2,358,958— only ~2.4M requests were admitted in the same period.wait.avgcount: 0— no threads are blocking on the throttle.
The team narrowed it down to this bug described in Ceph Tracker #62512: when osd_client_message_cap is hit, messenger worker threads enter a tight get_or_fail retry loop that consumes 100% of each worker thread's CPU.
We increased osd_client_message_cap incrementally up to 100,000 via ceph config set. We confirmed with debug_throttle=10 that the throttle was no longer being hit. However, the CPU usage remained above 300%, suggesting the messenger threads may have been stuck in a spin state that began during the saturation. A full restart of osd.734 with the higher cap would be needed to test this theory.
What was the bug about?
To understand why this is a bug in the first place, we need to understand how the Async-Messenger works and what epoll_wait() does.
epoll is used to watch many file descriptors at once. The man page describes it as:
monitoring multiple file descriptors to see if I/O is possible on any of them
The call a program actually makes to block on that set is epoll_wait():
waits for events on the epoll(7) instance
In practice, a thread calls epoll_wait() with a timeout and one of three things happens:
- a file descriptor becomes ready and the call returns immediately with the list of ready events,
- the timeout expires and the call returns with zero events,
- the thread sleeps in the kernel until one of the first two occurs 2.
This lets a single thread service hundreds of sockets efficiently instead of dedicating a thread per connection.
Ceph's Async-Messenger uses this pattern. Each msgr-worker thread runs an event loop that calls epoll_wait() to either pick up new socket activity or sleep until the next scheduled timer event fires. At a high level the loop either sleeps or processes messages/events.
The code below is responsible for a single 'tick' in the Messenger's event loop 3. It figures out how long the Messenger needs to sleep (until the next queued time event) before calling epoll_wait(). So we either wake up on an epoll event, or sleep because there is no work to do right now.
timeout_microseconds = 1000
int EventCenter::process_events(){
auto now = clock_type::now();
clock_type::time_point end_time = now + std::chrono::microseconds(timeout_microseconds);
auto it = time_events.begin();
if (it != time_events.end() && end_time >= it->first) {
trigger_time = true;
end_time = it->first;
if (end_time > now) {
timeout_microseconds = std::chrono::duration_cast<std::chrono::microseconds>(end_time - now).count();
} else {
timeout_microseconds = 0;
}
}
..
..
epoll_wait(epfd, events, nevent, /*timeout_ms=*/0);
Two time resolutions in play here nanoseconds (the clock and how we record events), and microseconds (timeout_microseconds). Note that 1000 ns = 1µs.
This line will truncate to 0 if (end_time-now) evaluates to anything smaller than 1 µs such as 999ns.
timeout_microseconds = std::chrono::duration_cast<std::chrono::microseconds>(end_time - now).count();
Going back to epoll_wait()
specifying a timeout equal to zero causes epoll_wait() to return immediately, even if no events are available.
When the next event was already close, say 600 ns away. What we want it to do is sleep, but instead since 600ns gets truncated to 0, we are not sleeping at all 4.
Essentially the Messenger is skipping the sleep part. At this point the Messenger is doing work and 'ticking' but there is actually no work to be done, it could have been 999ns into the future.
This is not a problem if there is only a single event being queued, eventually it will go away and be processed, however if the Messenger is being bombarded with new events it becomes a matter of probability hitting this nanosecond granularity and the wasted CPU cycles adds up like we saw in the original issue.
The fix in the tracker involved setting a floor so it rounds to 1ms, so in events like this we should go to sleep anyways.
if (end_time > now) {
timeout_microseconds = std::chrono::duration_cast<std::chrono::microseconds>(end_time - now).count();
timeout_microseconds = std::max<unsigned>(timeout_microseconds,
cct->_conf->ms_time_events_min_wait_interval);
} else {
timeout_microseconds = 0;
}
Currently this bug is present in all of Reef and Squid. This bug is normally infrequent and low-urgency, but a sufficiently hot read/write pattern against a single object can amplify it into the CPU saturation we saw here. Debugging Ceph issues can be complex but eliminating different layers makes debugging more systematic.
Footnotes
-
ceph tell osd.734 perf reset *↩ -
I omitted that
epoll_wait()can also wake up if it gets interrupted by a signal (EINTR). ↩ -
Source:
EventCenter::process_eventsinsrc/msg/async/Event.cc. ↩ -
Some readers may notice that
epoll_wait()'s lowest timeout resolution is 1 ms (1000 microseconds). There was some code omitted between the timeout calculation and theepoll_wait()call that rounds anything less than 1000 microseconds (besides 0) up to 1000 microseconds. ↩