[ceph-users] MDS hangs in "heartbeat_map" deadlock

[Stefan Kooman]

Dear list,

Today we hit our first Ceph MDS issue. Out of the blue the active MDS
stopped working:

mon.mon1 [WRN] daemon mds.mds1 is not responding, replacing it as rank 0 with standby
daemon mds.mds2.

Logging of ceph-mds1:

2018-10-04 10:50:08.524745 7fdd516bf700 1 mds.mds1 asok_command: status (starting...)
2018-10-04 10:50:08.524782 7fdd516bf700 1 mds.mds1 asok_command: status (complete)

^^ one of our monitoring health checks performing a "ceph daemon mds.mds1 version", business as usual.

2018-10-04 10:52:36.712525 7fdd51ec0700 1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2018-10-04 10:52:36.747577 7fdd4deb8700 1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2018-10-04 10:52:36.747584 7fdd4deb8700 1 mds.beacon.mds1 _send skipping beacon, heartbeat map not healthy

^^ the unresponsive mds1 consumes 100% CPU and keeps on logging above heatbeat_map messages.

In the meantime ceph-mds2 has transitioned from "standby-replay" to "active":

mon.mon1 [INF] daemon mds.mds2 is now active in filesystem BITED-153874-cephfs as rank 0

Logging:

replays, final replay as standby, reopen log

2018-10-04 10:52:53.268470 7fdb231d9700 1 mds.0.141 reconnect_done
2018-10-04 10:52:53.759844 7fdb231d9700 1 mds.mds2 Updating MDS map to version 143 from mon.3
2018-10-04 10:52:53.759859 7fdb231d9700 1 mds.0.141 handle_mds_map i am now mds.0.141
2018-10-04 10:52:53.759862 7fdb231d9700 1 mds.0.141 handle_mds_map state change up:reconnect --> up:rejoin
2018-10-04 10:52:53.759868 7fdb231d9700 1 mds.0.141 rejoin_start
2018-10-04 10:52:53.759970 7fdb231d9700 1 mds.0.141 rejoin_joint_start
2018-10-04 10:52:53.760970 7fdb1d1cd700 0 mds.0.cache failed to open ino 0x10000cd95e9 err -5/0
2018-10-04 10:52:54.126658 7fdb1d1cd700 1 mds.0.141 rejoin_done
2018-10-04 10:52:54.770457 7fdb231d9700 1 mds.mds2 Updating MDS map to version 144 from mon.3
2018-10-04 10:52:54.770484 7fdb231d9700 1 mds.0.141 handle_mds_map i am now mds.0.141
2018-10-04 10:52:54.770487 7fdb231d9700 1 mds.0.141 handle_mds_map state change up:rejoin --> up:clientreplay
2018-10-04 10:52:54.770494 7fdb231d9700 1 mds.0.141 recovery_done -- successful recovery!
2018-10-04 10:52:54.770617 7fdb231d9700 1 mds.0.141 clientreplay_start
2018-10-04 10:52:54.882995 7fdb1d1cd700 1 mds.0.141 clientreplay_done
2018-10-04 10:52:55.778598 7fdb231d9700 1 mds.mds2 Updating MDS map to version 145 from mon.3
2018-10-04 10:52:55.778622 7fdb231d9700 1 mds.0.141 handle_mds_map i am now mds.0.141
2018-10-04 10:52:55.778628 7fdb231d9700 1 mds.0.141 handle_mds_map state change up:clientreplay --> up:active
2018-10-04 10:52:55.778638 7fdb231d9700 1 mds.0.141 active_start
2018-10-04 10:52:55.805206 7fdb231d9700 1 mds.0.141 cluster recovered.

And then it _also_ starts to log hearbeat_map messages (and consuming 100% CPU):

en dan deze meldingen die zichzelf blijven herhalen bij 100% cpu
2018-10-04 10:53:41.550793 7fdb241db700 1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2018-10-04 10:53:42.884018 7fdb201d3700 1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2018-10-04 10:53:42.884024 7fdb201d3700 1 mds.beacon.mds2 _send skipping beacon, heartbeat map not healthy

At that point in time there is one active MDS according to ceph, but in reality it's
not functioning correctly (not serving clients at least).

... we stopped both daemons. Restarted one ... recovery ...
works for half a minute ... then starts logging heartbeat_map messages.
Restart again ... works for a little while ... starts logging
heartbeat_map messages again. We restart the mds with debug_mds=20 ....
it keeps working fine. The other mds gets restarted and keeps on
working. We do a couple of failover tests .... works flawlessly
(failover in < 1 second, clients reconnect instantly).

A couple of hours later we hit the same issue. We restarted with
debug_mds=20 and debug_journaler=20 on the standby-replay node. Eight
hours later (an hour ago) we hit the same issue. We captured ~ 4.7 GB of
logging.... I skipped to the end of the log file just before the
"hearbeat_map" messages start:

2018-10-04 23:23:53.144644 7f415ebf4700 20 mds.0.locker client.17079146 pending pAsLsXsFscr allowed pAsLsXsFscr wanted pFscr
2018-10-04 23:23:53.144645 7f415ebf4700 10 mds.0.locker eval done
2018-10-04 23:23:55.088542 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5021
2018-10-04 23:23:59.088602 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5022
2018-10-04 23:24:03.088688 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5023
2018-10-04 23:24:07.088775 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5024
2018-10-04 23:24:11.088867 7f415bbee700 1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2018-10-04 23:24:11.088871 7f415bbee700 1 mds.beacon.mds2 _send skipping beacon, heartbeat map not healthy

As far as I can see just normal behaviour.

The big question is: what is happening when the mds start logging the hearbeat_map messages?
Why does it log "heartbeat_map is_healthy", just to log .000004 seconds later it's not healthy?

Ceph version: 12.2.8 on all nodes (mon, osd, mds)
mds: one active / one standby-replay

The system was not under any kind of resource pressure: plenty of CPU, RAM
available. Metrics all look normal up to the moment things go into a deadlock
(so it seems).

Thanks for any hints / clue.

Gr. Stefan

[Gregory Farnum]

Post by Stefan Kooman
Dear list,
Today we hit our first Ceph MDS issue. Out of the blue the active MDS
mon.mon1 [WRN] daemon mds.mds1 is not responding, replacing it as rank 0 with standby
daemon mds.mds2.
2018-10-04 10:50:08.524745 7fdd516bf700 1 mds.mds1 asok_command: status (starting...)
2018-10-04 10:50:08.524782 7fdd516bf700 1 mds.mds1 asok_command: status (complete)
^^ one of our monitoring health checks performing a "ceph daemon mds.mds1
version", business as usual.
2018-10-04 10:52:36.712525 7fdd51ec0700 1 heartbeat_map is_healthy
'MDSRank' had timed out after 15
2018-10-04 10:52:36.747577 7fdd4deb8700 1 heartbeat_map is_healthy
'MDSRank' had timed out after 15
2018-10-04 10:52:36.747584 7fdd4deb8700 1 mds.beacon.mds1 _send skipping
beacon, heartbeat map not healthy
^^ the unresponsive mds1 consumes 100% CPU and keeps on logging above
heatbeat_map messages.
mon.mon1 [INF] daemon mds.mds2 is now active in filesystem
BITED-153874-cephfs as rank 0
replays, final replay as standby, reopen log
2018-10-04 10:52:53.268470 7fdb231d9700 1 mds.0.141 reconnect_done
2018-10-04 10:52:53.759844 7fdb231d9700 1 mds.mds2 Updating MDS map to
version 143 from mon.3
2018-10-04 10:52:53.759859 7fdb231d9700 1 mds.0.141 handle_mds_map i am now mds.0.141
2018-10-04 10:52:53.759862 7fdb231d9700 1 mds.0.141 handle_mds_map state
change up:reconnect --> up:rejoin
2018-10-04 10:52:53.759868 7fdb231d9700 1 mds.0.141 rejoin_start
2018-10-04 10:52:53.759970 7fdb231d9700 1 mds.0.141 rejoin_joint_start
2018-10-04 10:52:53.760970 7fdb1d1cd700 0 mds.0.cache failed to open ino
0x10000cd95e9 err -5/0
2018-10-04 10:52:54.126658 7fdb1d1cd700 1 mds.0.141 rejoin_done
2018-10-04 10:52:54.770457 7fdb231d9700 1 mds.mds2 Updating MDS map to
version 144 from mon.3
2018-10-04 10:52:54.770484 7fdb231d9700 1 mds.0.141 handle_mds_map i am now mds.0.141
2018-10-04 10:52:54.770487 7fdb231d9700 1 mds.0.141 handle_mds_map state
change up:rejoin --> up:clientreplay
2018-10-04 10:52:54.770494 7fdb231d9700 1 mds.0.141 recovery_done -- successful recovery!
2018-10-04 10:52:54.770617 7fdb231d9700 1 mds.0.141 clientreplay_start
2018-10-04 10:52:54.882995 7fdb1d1cd700 1 mds.0.141 clientreplay_done
2018-10-04 10:52:55.778598 7fdb231d9700 1 mds.mds2 Updating MDS map to
version 145 from mon.3
2018-10-04 10:52:55.778622 7fdb231d9700 1 mds.0.141 handle_mds_map i am now mds.0.141
2018-10-04 10:52:55.778628 7fdb231d9700 1 mds.0.141 handle_mds_map state
change up:clientreplay --> up:active
2018-10-04 10:52:55.778638 7fdb231d9700 1 mds.0.141 active_start
2018-10-04 10:52:55.805206 7fdb231d9700 1 mds.0.141 cluster recovered.
en dan deze meldingen die zichzelf blijven herhalen bij 100% cpu
2018-10-04 10:53:41.550793 7fdb241db700 1 heartbeat_map is_healthy
'MDSRank' had timed out after 15
2018-10-04 10:53:42.884018 7fdb201d3700 1 heartbeat_map is_healthy
'MDSRank' had timed out after 15
2018-10-04 10:53:42.884024 7fdb201d3700 1 mds.beacon.mds2 _send skipping
beacon, heartbeat map not healthy
At that point in time there is one active MDS according to ceph, but in reality it's
not functioning correctly (not serving clients at least).
... we stopped both daemons. Restarted one ... recovery ...
works for half a minute ... then starts logging heartbeat_map messages.
Restart again ... works for a little while ... starts logging
heartbeat_map messages again. We restart the mds with debug_mds=20 ....
it keeps working fine. The other mds gets restarted and keeps on
working. We do a couple of failover tests .... works flawlessly
(failover in < 1 second, clients reconnect instantly).
A couple of hours later we hit the same issue. We restarted with
debug_mds=20 and debug_journaler=20 on the standby-replay node. Eight
hours later (an hour ago) we hit the same issue. We captured ~ 4.7 GB of
logging.... I skipped to the end of the log file just before the
2018-10-04 23:23:53.144644 7f415ebf4700 20 mds.0.locker client.17079146
pending pAsLsXsFscr allowed pAsLsXsFscr wanted pFscr
2018-10-04 23:23:53.144645 7f415ebf4700 10 mds.0.locker eval done
2018-10-04 23:23:55.088542 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5021
2018-10-04 23:23:59.088602 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5022
2018-10-04 23:24:03.088688 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5023
2018-10-04 23:24:07.088775 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5024
2018-10-04 23:24:11.088867 7f415bbee700 1 heartbeat_map is_healthy
'MDSRank' had timed out after 15
2018-10-04 23:24:11.088871 7f415bbee700 1 mds.beacon.mds2 _send skipping
beacon, heartbeat map not healthy
As far as I can see just normal behaviour.
The big question is: what is happening when the mds start logging the
hearbeat_map messages?
Why does it log "heartbeat_map is_healthy", just to log .000004 seconds
later it's not healthy?

Ah, there's a misunderstanding here — the output isn't terribly clear.
"is_healthy" is the name of a *function* in the source code. The line

heartbeat_map is_healthy 'MDSRank' had timed out after 15

is telling you that the heartbeat_map's is_healthy function is running, and
it finds that "'MDSRank' had timed out after 15 [seconds]". So the thread
MDSRank is *not* healthy, it didn't check in for 15 seconds! Therefore the
MDS beacon code decides not to send a beacon, because it thinks the MDS
might be stuck.

From what you've described here, it's most likely that the MDS is trying to
read something out of RADOS which is taking a long time, and which we
didn't expect to cause a slow down. You can check via the admin socket to
see if there are outstanding Objecter requests or ops_in_flight to get a
clue.
-Greg

Post by Stefan Kooman
Ceph version: 12.2.8 on all nodes (mon, osd, mds)
mds: one active / one standby-replay
The system was not under any kind of resource pressure: plenty of CPU, RAM
available. Metrics all look normal up to the moment things go into a deadlock
(so it seems).
Thanks for any hints / clue.
Gr. Stefan
--
| BIT BV http://www.bit.nl/ Kamer van Koophandel 09090351
| GPG: 0xD14839C6 [phone]
_______________________________________________
ceph-users mailing list
http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com

[Stefan Kooman]

Ah, there's a misunderstanding here — the output isn't terribly clear.
"is_healthy" is the name of a *function* in the source code. The line
heartbeat_map is_healthy 'MDSRank' had timed out after 15
is telling you that the heartbeat_map's is_healthy function is running, and
it finds that "'MDSRank' had timed out after 15 [seconds]". So the thread
MDSRank is *not* healthy, it didn't check in for 15 seconds! Therefore the
MDS beacon code decides not to send a beacon, because it thinks the MDS
might be stuck.

Thanks for the explanation.

From what you've described here, it's most likely that the MDS is trying to
read something out of RADOS which is taking a long time, and which we
didn't expect to cause a slow down. You can check via the admin socket to
see if there are outstanding Objecter requests or ops_in_flight to get a
clue.

Hmm, I avoided that because of this issue [1]. Killing the MDS while
debugging why it's hanging is defeating the purpose ;-).

I might check for "Objecter requests".

Thanks!

Gr. Stefan

[1]: http://tracker.ceph.com/issues/26894

[Stefan Kooman]

Post by Gregory Farnum
From what you've described here, it's most likely that the MDS is trying to
read something out of RADOS which is taking a long time, and which we
didn't expect to cause a slow down. You can check via the admin socket to
see if there are outstanding Objecter requests or ops_in_flight to get a
clue.

I double checked the load of the OSDs, MONs, MDSs, but that's all
normal. I would expect "slow requests" first, before hitting a timeout of
some sort.
What would cause a MDS spinning and consuming 100% CPU if a request would
be slow?

Thanks,

Stefan

[Patrick Donnelly]

Post by Stefan Kooman
A couple of hours later we hit the same issue. We restarted with
debug_mds=20 and debug_journaler=20 on the standby-replay node. Eight
hours later (an hour ago) we hit the same issue. We captured ~ 4.7 GB of
logging.... I skipped to the end of the log file just before the
2018-10-04 23:23:53.144644 7f415ebf4700 20 mds.0.locker client.17079146 pending pAsLsXsFscr allowed pAsLsXsFscr wanted pFscr
2018-10-04 23:23:53.144645 7f415ebf4700 10 mds.0.locker eval done
2018-10-04 23:23:55.088542 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5021
2018-10-04 23:23:59.088602 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5022
2018-10-04 23:24:03.088688 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5023
2018-10-04 23:24:07.088775 7f415bbee700 10 mds.beacon.mds2 _send up:active seq 5024
2018-10-04 23:24:11.088867 7f415bbee700 1 heartbeat_map is_healthy 'MDSRank' had timed out after 15
2018-10-04 23:24:11.088871 7f415bbee700 1 mds.beacon.mds2 _send skipping beacon, heartbeat map not healthy
As far as I can see just normal behaviour.
The big question is: what is happening when the mds start logging the hearbeat_map messages?
Why does it log "heartbeat_map is_healthy", just to log .000004 seconds later it's not healthy?
Ceph version: 12.2.8 on all nodes (mon, osd, mds)
mds: one active / one standby-replay
The system was not under any kind of resource pressure: plenty of CPU, RAM
available. Metrics all look normal up to the moment things go into a deadlock
(so it seems).

Thanks for the detailed notes. It looks like the MDS is stuck
somewhere it's not even outputting any log messages. If possible, it'd
be helpful to get a coredump (e.g. by sending SIGQUIT to the MDS) or,
if you're comfortable with gdb, a backtrace of any threads that look
suspicious (e.g. not waiting on a futex) including `info threads`.

[Stefan Kooman]

Post by Patrick Donnelly
Thanks for the detailed notes. It looks like the MDS is stuck
somewhere it's not even outputting any log messages. If possible, it'd
be helpful to get a coredump (e.g. by sending SIGQUIT to the MDS) or,
if you're comfortable with gdb, a backtrace of any threads that look
suspicious (e.g. not waiting on a futex) including `info threads`.

It took a while before the same issue reappeared again ... but we
managed to catch gdb backtraces and strace output. See below pastebin
links. Note: we had difficulty getting the MDSs working again, so we had
to restart them a couple of times, capturing debug output as much as we
can. Hopefully you can squeeze some useful information out of this data.

MDS1:
https://8n1.org/13869/bc3b - Some few minutes after it first started
acting up
https://8n1.org/13870/caf4 - Probably made when I tried to stop the
process and it took too long (process already received SIGKILL)
https://8n1.org/13871/2f22 - After restarting the same issue returned
https://8n1.org/13872/2246 - After restarting the same issue returned

MDS2:
https://8n1.org/13873/f861 - After it went craycray when it became
active
https://8n1.org/13874/c567 - After restarting the same issue returned
https://8n1.org/13875/133a - After restarting the same issue returned

STRACES:
MDS1: https://8n1.org/mds1-strace.zip
MDS2: https://8n1.org/mds2-strace.zip

Gr. Stefan

[Stefan Kooman]

Post by Patrick Donnelly
Thanks for the detailed notes. It looks like the MDS is stuck
somewhere it's not even outputting any log messages. If possible, it'd
be helpful to get a coredump (e.g. by sending SIGQUIT to the MDS) or,
if you're comfortable with gdb, a backtrace of any threads that look
suspicious (e.g. not waiting on a futex) including `info threads`.

Today the issue reappeared (after being absent for ~ 3 weeks). This time
the standby MDS could take over and would not get into a deadlock
itself. We made gdb traces again, which you can find over here:

https://8n1.org/14011/d444

Would be great if someone could figure out whats causing this issue.

Thanks,

Stefan