help me understand "slow heartbeats" warnings
I see this at times, 2026-10-15T06:33:57.184296+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 3038.405ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:33:57.184319+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 3038.335ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:07.332951+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 2981.937ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:07.332975+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 2982.992ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:35.591255+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 2038.587ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:35.591280+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 2039.430ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:50.182523+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 1284.844ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:50.182545+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 1284.781ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:59.363750+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 1228.156ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:59.363774+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 1228.295ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:35:07.363735+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 1220.582ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:35:07.363771+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 1220.705ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:35:21.546156+0000 mon.mon-1 [INF] Health check cleared: OSD_SLOW_PING_TIME_BACK (was: Slow OSD heartbeats on back (longest 1220.582ms)) 2026-10-15T06:35:21.546210+0000 mon.mon-1 [INF] Health check cleared: OSD_SLOW_PING_TIME_FRONT (was: Slow OSD heartbeats on front (longest 1220.705ms) These lines are 10-15-20 seconds apart, and in that time span, the "longest" is lowering by .. a few hundred milliseconds. So over the course of two minutes something has gone from 3000 ms to under 1000. Now if this was a queue then it seems weird that it did not sink slower, assuming that the involved parts are working off items on the queue for minutes. If they were NOT working off the queue, one would assume it would grow by one second per second, like when you get 1 ops are blocked > 3276 sec on osd.21 and nothing is improving the situation, then that delay does grow by the second, totally reasonable. But the slow ops feels like a mystery to me, how it can be so specific in milliseconds while often working itself downwards so slowly that it takes literal minutes to get down below the warning limit. So what does this "Slow OSD heartbeats" actually measure at the time of these log lines? I often get them during expansion of the cluster or rolling OSD restarts, so its not necessarily even a strict error condition either. -- May the most significant bit of your life be positive.
Yes, OSDs heartbeat their peers to make sure each connection is still working and each peer is responsive. The heartbeat can get blocked by other work if it takes long enough, but it skips most queues IIRC. So this log message is saying an osd pinged a peer and didn’t get the response back for 3 seconds. That’s quite a long time! -Greg On Thu, Oct 15, 2026 at 2:30 AM Janne Johansson <ceph-users@ceph.io> wrote:
I see this at times,
2026-10-15T06:33:57.184296+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 3038.405ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:33:57.184319+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 3038.335ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:07.332951+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 2981.937ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:07.332975+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 2982.992ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:35.591255+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 2038.587ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:35.591280+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 2039.430ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:50.182523+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 1284.844ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:50.182545+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 1284.781ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:34:59.363750+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 1228.156ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:34:59.363774+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 1228.295ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:35:07.363735+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on back (longest 1220.582ms) (OSD_SLOW_PING_TIME_BACK) 2026-10-15T06:35:07.363771+0000 mon.mon-1 [WRN] Health check update: Slow OSD heartbeats on front (longest 1220.705ms) (OSD_SLOW_PING_TIME_FRONT) 2026-10-15T06:35:21.546156+0000 mon.mon-1 [INF] Health check cleared: OSD_SLOW_PING_TIME_BACK (was: Slow OSD heartbeats on back (longest 1220.582ms)) 2026-10-15T06:35:21.546210+0000 mon.mon-1 [INF] Health check cleared: OSD_SLOW_PING_TIME_FRONT (was: Slow OSD heartbeats on front (longest 1220.705ms)
These lines are 10-15-20 seconds apart, and in that time span, the "longest" is lowering by .. a few hundred milliseconds. So over the course of two minutes something has gone from 3000 ms to under 1000. Now if this was a queue then it seems weird that it did not sink slower, assuming that the involved parts are working off items on the queue for minutes. If they were NOT working off the queue, one would assume it would grow by one second per second, like when you get
1 ops are blocked > 3276 sec on osd.21 and nothing is improving the situation, then that delay does grow by the second, totally reasonable. But the slow ops feels like a mystery to me, how it can be so specific in milliseconds while often working itself downwards so slowly that it takes literal minutes to get down below the warning limit.
So what does this "Slow OSD heartbeats" actually measure at the time of these log lines? I often get them during expansion of the cluster or rolling OSD restarts, so its not necessarily even a strict error condition either.
-- May the most significant bit of your life be positive. _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
Den tors 15 okt. 2026 kl 19:25 skrev Gregory Farnum <gfarnum@redhat.com>:
Yes, OSDs heartbeat their peers to make sure each connection is still working and each peer is responsive. The heartbeat can get blocked by other work if it takes long enough, but it skips most queues IIRC.
So this log message is saying an osd pinged a peer and didn’t get the response back for 3 seconds. That’s quite a long time!
That is not the mystery, the mystery is how 2 minutes later, the situation has only improved so that it now takes 1.9 seconds to make that same ping. How can this "delay" either not grow by one second per second (because it is low prio compared to something else and not being done at all) but also not improve more than 0.1s every 15 seconds of wall time?
These lines are 10-15-20 seconds apart, and in that time span, the
"longest" is lowering by .. a few hundred milliseconds. So over the course of two minutes something has gone from 3000 ms to under 1000. Now if this was a queue then it seems weird that it did not sink slower, assuming that the involved parts are working off items on the queue for minutes. If they were NOT working off the queue, one would assume it would grow by one second per second, like when you get
1 ops are blocked > 3276 sec on osd.21 and nothing is improving the situation, then that delay does grow by the second, totally reasonable. But the slow ops feels like a mystery to me, how it can be so specific in milliseconds while often working itself downwards so slowly that it takes literal minutes to get down below the warning limit.
So what does this "Slow OSD heartbeats" actually measure at the time of these log lines? I often get them during expansion of the cluster or rolling OSD restarts, so its not necessarily even a strict error condition either.
-- May the most significant bit of your life be positive.
Heartbeating is a continuous process — it issues a new ping every 5 or 15 seconds or something. So apparently whatever queue is blocking it (switch, kernel queue, something in Ceph code) is getting a bit shorter over that duration. If you have durable and persistent issues with ping latency, the slow change is not surprising. (Note too that this is aggregating the worst reports from OSDs. If you look at the health detail you may see the source switching around. Or maybe it’s one particular NIC causing trouble and it’s always the same one.) On Thu, Oct 15, 2026 at 11:16 AM Janne Johansson <icepic.dz@gmail.com> wrote:
Den tors 15 okt. 2026 kl 19:25 skrev Gregory Farnum <gfarnum@redhat.com>:
Yes, OSDs heartbeat their peers to make sure each connection is still working and each peer is responsive. The heartbeat can get blocked by other work if it takes long enough, but it skips most queues IIRC.
So this log message is saying an osd pinged a peer and didn’t get the response back for 3 seconds. That’s quite a long time!
That is not the mystery, the mystery is how 2 minutes later, the situation has only improved so that it now takes 1.9 seconds to make that same ping. How can this "delay" either not grow by one second per second (because it is low prio compared to something else and not being done at all) but also not improve more than 0.1s every 15 seconds of wall time?
These lines are 10-15-20 seconds apart, and in that time span, the
"longest" is lowering by .. a few hundred milliseconds. So over the course of two minutes something has gone from 3000 ms to under 1000. Now if this was a queue then it seems weird that it did not sink slower, assuming that the involved parts are working off items on the queue for minutes. If they were NOT working off the queue, one would assume it would grow by one second per second, like when you get
1 ops are blocked > 3276 sec on osd.21 and nothing is improving the situation, then that delay does grow by the second, totally reasonable. But the slow ops feels like a mystery to me, how it can be so specific in milliseconds while often working itself downwards so slowly that it takes literal minutes to get down below the warning limit.
So what does this "Slow OSD heartbeats" actually measure at the time of these log lines? I often get them during expansion of the cluster or rolling OSD restarts, so its not necessarily even a strict error condition either.
-- May the most significant bit of your life be positive.
Den tors 15 okt. 2026 kl 20:48 skrev Gregory Farnum <gfarnum@redhat.com>:
Heartbeating is a continuous process — it issues a new ping every 5 or 15 seconds or something. So apparently whatever queue is blocking it (switch, kernel queue, something in Ceph code) is getting a bit shorter over that duration. If you have durable and persistent issues with ping latency, the slow change is not surprising. (Note too that this is aggregating the worst reports from OSDs. If you look at the health detail you may see the source switching around. Or maybe it’s one particular NIC causing trouble and it’s always the same one.)
It is dual 25GE, and its not filled to the brim, so its not something that makes packets take 3 seconds to arrive in between. My point (if I can make some kind of analogy) is that if some student has a bad morning, it is totally reasonable that they can be a few minutes late for first class, but it would be weird if that same reason made them a few minutes late for next class and next again just a bit less late until lunch when the student finally catches up with the schedule and then makes it on time for the rest of the day. Again, I am not confused about if it would rise continuously, so in my possibly poor analogy, if the student doesn't arrive at all, then the teacher would count minutes late that would go up by one minute per minute and at the end of the class note that it was a no-show. The next teacher would start recording lateness again rising at one minute per minute passed. What I am confused about is how it can both be late in the same kind of timespan with 15 seconds in between, for minutes at a time, and most always working its way slowly downward. In my mental picture it doesn't seem to be prioritized and also not de-prioritized work either since both of those would should up differently in terms of what to say about something 3000 ms late 15 seconds ago from "now its only 2900 ms late". It could logically work out, if it is some kind of long time average for which we are seeing a decaying average of something that happened a long time ago, which makes it somewhat meaningless to keep as a warning for something that actually recovered long ago. I'd rather see it show me the current ping response time. -- May the most significant bit of your life be positive.
participants (2)
-
Gregory Farnum
-
Janne Johansson