Re: Nautilus 14.2.19 mon 100% CPU
Good thought. The storage for the monitor data is a RAID-0 over three NVMe devices. Watching iostat, they are completely idle, maybe 0.8% to 1.4% for a second every minute or so. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Thu, Apr 8, 2021 at 7:48 PM Zizon Qiu <zzdtsv@gmail.com> wrote:
Will it be related to some kind of disk issue of that mon located in,which may casually slow down IO and further the rocksdb?
On Fri, Apr 9, 2021 at 4:29 AM Robert LeBlanc <robert@leblancnet.us> wrote:
I found this thread that matches a lot of what I'm seeing. I see the ms_dispatch thread going to 100%, but I'm at a single MON, the recovery is done and the rocksdb MON database is ~300MB. I've tried all the settings mentioned in that thread with no noticeable improvement. I was hoping that once the recovery was done (backfills to reformatted OSDs) that it would clear up, but not yet. So any other ideas would be really helpful. Our MDS is functioning, but stalls a lot because the mons miss heartbeats.
mon_compact_on_start = true rocksdb_cache_size = 1342177280 mon_lease = 30 mon_osd_cache_size = 200000 mon_sync_max_payload_size = 4096
---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Thu, Apr 8, 2021 at 1:11 PM Stefan Kooman <stefan@bit.nl> wrote:
On 4/8/21 6:22 PM, Robert LeBlanc wrote:
I upgraded our Luminous cluster to Nautilus a couple of weeks ago and converted the last batch of FileStore OSDs to BlueStore about 36 hours ago. Yesterday our monitor cluster went nuts and started constantly calling elections because monitor nodes were at 100% and wouldn't respond to heartbeats. I reduced the monitor cluster to one to prevent the constant elections and that let the system limp along until the backfills finished. There are large amounts of time where ceph commands hang with the CPU is at 100%, when the CPU drops I see a lot of work getting done in the monitor logs which stops as soon as the CPU is at 100% again.
Try reducing mon_sync_max_payload_size=4096. I have seen Frank Schilder advise this several times because of monitor issues. Also recently for a cluster that got upgraded from Luminous -> Mimic -> Nautilus.
Worth a shot.
Otherwise I'll try to look in depth and see if I can come up with something smart (for now I need to go catch some sleep).
Gr. Stefan
I'm attempting to deep scrub all the PGs to see if that helps clear up some accounting issues, but that's going to take a really long time on 2PB of data. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Thu, Apr 8, 2021 at 9:48 PM Robert LeBlanc <robert@leblancnet.us> wrote:
Good thought. The storage for the monitor data is a RAID-0 over three NVMe devices. Watching iostat, they are completely idle, maybe 0.8% to 1.4% for a second every minute or so. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Thu, Apr 8, 2021 at 7:48 PM Zizon Qiu <zzdtsv@gmail.com> wrote:
Will it be related to some kind of disk issue of that mon located in,which may casually slow down IO and further the rocksdb?
On Fri, Apr 9, 2021 at 4:29 AM Robert LeBlanc <robert@leblancnet.us> wrote:
I found this thread that matches a lot of what I'm seeing. I see the ms_dispatch thread going to 100%, but I'm at a single MON, the recovery is done and the rocksdb MON database is ~300MB. I've tried all the settings mentioned in that thread with no noticeable improvement. I was hoping that once the recovery was done (backfills to reformatted OSDs) that it would clear up, but not yet. So any other ideas would be really helpful. Our MDS is functioning, but stalls a lot because the mons miss heartbeats.
mon_compact_on_start = true rocksdb_cache_size = 1342177280 mon_lease = 30 mon_osd_cache_size = 200000 mon_sync_max_payload_size = 4096
---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Thu, Apr 8, 2021 at 1:11 PM Stefan Kooman <stefan@bit.nl> wrote:
On 4/8/21 6:22 PM, Robert LeBlanc wrote:
I upgraded our Luminous cluster to Nautilus a couple of weeks ago and converted the last batch of FileStore OSDs to BlueStore about 36 hours ago. Yesterday our monitor cluster went nuts and started constantly calling elections because monitor nodes were at 100% and wouldn't respond to heartbeats. I reduced the monitor cluster to one to prevent the constant elections and that let the system limp along until the backfills finished. There are large amounts of time where ceph commands hang with the CPU is at 100%, when the CPU drops I see a lot of work getting done in the monitor logs which stops as soon as the CPU is at 100% again.
Try reducing mon_sync_max_payload_size=4096. I have seen Frank Schilder advise this several times because of monitor issues. Also recently for a cluster that got upgraded from Luminous -> Mimic -> Nautilus.
Worth a shot.
Otherwise I'll try to look in depth and see if I can come up with something smart (for now I need to go catch some sleep).
Gr. Stefan
On 4/9/21 3:40 PM, Robert LeBlanc wrote:
I'm attempting to deep scrub all the PGs to see if that helps clear up some accounting issues, but that's going to take a really long time on 2PB of data.
Are you running with 1 mon now? Have you tried adding mons from scratch? So with a fresh database? And then maybe after they have joined, kill the donor mon and start from scratch. You have for sure not missed a step during the upgrade (just checking mode), i.e. ceph osd require-osd-release nautilus. Gr. Stefan
On Fri, Apr 9, 2021 at 9:25 AM Stefan Kooman <stefan@bit.nl> wrote:
Are you running with 1 mon now? Have you tried adding mons from scratch? So with a fresh database? And then maybe after they have joined, kill the donor mon and start from scratch.
You have for sure not missed a step during the upgrade (just checking mode), i.e. ceph osd require-osd-release nautilus.
I have tried adding one of the other monitors by removing the data directory and starting from scratch, but it would go back to the monitor elections and I didn't feel comfortable that it's up to sync to fail over to it so I took it back out. I have run `ceph osd-require-osd-release nautilus` after the upgrade of all the OSDs. I'll go back and double check all the steps, but I think I got them all. Thank you, Robert LeBlanc
The only step not yet taken was to move to straw2. That was the last step we were going to do next. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1 On Fri, Apr 9, 2021 at 10:41 AM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 9:25 AM Stefan Kooman <stefan@bit.nl> wrote:
Are you running with 1 mon now? Have you tried adding mons from scratch? So with a fresh database? And then maybe after they have joined, kill the donor mon and start from scratch.
You have for sure not missed a step during the upgrade (just checking mode), i.e. ceph osd require-osd-release nautilus.
I have tried adding one of the other monitors by removing the data directory and starting from scratch, but it would go back to the monitor elections and I didn't feel comfortable that it's up to sync to fail over to it so I took it back out. I have run `ceph osd-require-osd-release nautilus` after the upgrade of all the OSDs. I'll go back and double check all the steps, but I think I got them all.
Thank you, Robert LeBlanc
Hi Robert, Have you checked a log with debug_mon=20 yet to try to see what it's doing? .. Dan On Fri, Apr 9, 2021, 7:02 PM Robert LeBlanc <robert@leblancnet.us> wrote:
The only step not yet taken was to move to straw2. That was the last step we were going to do next. ---------------- Robert LeBlanc PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
On Fri, Apr 9, 2021 at 10:41 AM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 9:25 AM Stefan Kooman <stefan@bit.nl> wrote:
Are you running with 1 mon now? Have you tried adding mons from
scratch?
So with a fresh database? And then maybe after they have joined, kill the donor mon and start from scratch.
You have for sure not missed a step during the upgrade (just checking mode), i.e. ceph osd require-osd-release nautilus.
I have tried adding one of the other monitors by removing the data directory and starting from scratch, but it would go back to the monitor elections and I didn't feel comfortable that it's up to sync to fail over to it so I took it back out. I have run `ceph osd-require-osd-release nautilus` after the upgrade of all the OSDs. I'll go back and double check all the steps, but I think I got them all.
Thank you, Robert LeBlanc
On Fri, Apr 9, 2021 at 11:05 AM Dan van der Ster <dan@vanderster.com> wrote:
Hi Robert,
Have you checked a log with debug_mon=20 yet to try to see what it's doing?
I've posted the logs with debug_mon=20 for a period during high CPU here https://owncloud.leblancnet.us/owncloud/index.php/s/OtHsBAYN9r5eSbU You can look near the end of the log for the verbose logging. I'm not sure what to look for in there, nothing sticks out to me. I did disable cephx in the config file to see if that would help, but we still have the 100% CPU. Thank you, Robert LeBlanc
On Fri, Apr 9, 2021 at 7:24 PM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 11:05 AM Dan van der Ster <dan@vanderster.com> wrote:
Hi Robert,
Have you checked a log with debug_mon=20 yet to try to see what it's doing?
I've posted the logs with debug_mon=20 for a period during high CPU here https://owncloud.leblancnet.us/owncloud/index.php/s/OtHsBAYN9r5eSbU
You can look near the end of the log for the verbose logging. I'm not sure what to look for in there, nothing sticks out to me. I did disable cephx in the config file to see if that would help, but we still have the 100% CPU.
Thanks. I didn't see anything ultra obvious to me. But I did notice the nearfull warnings so I wonder if this cluster is churning through osdmaps? Did you see a large increase in inbound or outbound network traffic on this mon following the upgrade? Totally speculating here, but maybe there is an issue where you have some old clients, which can't decode an incremental osdmap from a nautilus mon, so the single mon is busy serving up these maps to the clients. Does the mon load decrease if you stop the osdmap churn?, e.g. by setting norebalance if that is indeed ongoing. Could you also share debug_ms = 1 for a minute of busy cpu mon? -- dan
Thank you, Robert LeBlanc
On Fri, Apr 9, 2021 at 11:49 AM Dan van der Ster <dan@vanderster.com> wrote:
Thanks. I didn't see anything ultra obvious to me.
But I did notice the nearfull warnings so I wonder if this cluster is churning through osdmaps? Did you see a large increase in inbound or outbound network traffic on this mon following the upgrade? Totally speculating here, but maybe there is an issue where you have some old clients, which can't decode an incremental osdmap from a nautilus mon, so the single mon is busy serving up these maps to the clients.
Does the mon load decrease if you stop the osdmap churn?, e.g. by setting norebalance if that is indeed ongoing.
Could you also share debug_ms = 1 for a minute of busy cpu mon?
Here are the new logs with the debug_ms=1 for a bit. https://owncloud.leblancnet.us/owncloud/index.php/s/1hvtJo3s2oLPpWn We do have nearfill, but there are no backfills going on (we don't have any auto balancing, we only use a tool that we wrote and only do it periodically). All PGs are currently active+clean. It appears that some osdmaps are still being trimmed on OSDs, but I'm not sure how to validate that. Our system is always under heavy load so there is always a lot of new data and deletions. We did have our monitor cluster freeze up after the upgrade. It was completely locked up when `ceph -s` command would run. It would not recover on it's own. We reduced the mon cluster to a single node then and we had to take the monitor node off the network. Then we started and stopped the monitor a few times and could run `ceph -s` commands without the 100% CPU. We then put it back on the network and it was fine. We added the remaining monitor nodes after deleting the data directory (fresh install) and it was fine until the last batch of OSDs were converted to BlueStore. The CPU for the entire upgrade is here https://owncloud.leblancnet.us/owncloud/index.php/s/Jku5z575PdE3AOr and the upgrade started just before 3/25. Some of that is due to the mgr. We do have some very old clients (Ubuntu 14.04) that we can't easily upgrade that use CephFS (we can probably upgrade to FUSE on these nodes, but it will take a long time). A good portion of our clients are Ubuntu 18.04 with a 5.3 kernel. I did set up a for loop to deep scrub all the PGs in case it needed to update some internal data structures as indicated from the `ceph pg ls` command. ``` * NOTE: Omap statistics are gathered during deep scrub and may be inaccurate soon afterwards depending on utilisation. See http://docs.ceph.com/docs/master/dev/placement-group/#omap-statistics for further details. ``` Which I thought may help get `ceph df` working properly so we know how much storage is actually being used. We do have crons running to get metrics into graphite and some of them do ceph commands, others are creating/writing/reading/deleting files to get some file system performance metrics but none doing scrubs, rebalance, etc. Thank you, Robert LeBlanc
On Fri, Apr 9, 2021 at 8:39 PM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 11:49 AM Dan van der Ster <dan@vanderster.com> wrote:
Thanks. I didn't see anything ultra obvious to me.
But I did notice the nearfull warnings so I wonder if this cluster is churning through osdmaps? Did you see a large increase in inbound or outbound network traffic on this mon following the upgrade? Totally speculating here, but maybe there is an issue where you have some old clients, which can't decode an incremental osdmap from a nautilus mon, so the single mon is busy serving up these maps to the clients.
Does the mon load decrease if you stop the osdmap churn?, e.g. by setting norebalance if that is indeed ongoing.
Could you also share debug_ms = 1 for a minute of busy cpu mon?
Here are the new logs with the debug_ms=1 for a bit. https://owncloud.leblancnet.us/owncloud/index.php/s/1hvtJo3s2oLPpWn
Something strange in this is there is one hammer client that is asking for nearly a million incremental osdmaps, seemingly every 30s: client.131831153 at 172.16.212.55 is asking for incrementals from 1170448..1987355 (see [1]) Can you try to evict/kill/block that client and see if your mon load drops? -- dan [1] -43> 2021-04-09 13:12:37.032 7f50de246700 5 mon.sun-storemon01@0(leader).osd e1987341 send_incremental [1170448..1987341] to client.131831153 2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader) e45 handle_subscribe mon_subscribe({mdsmap=3914079+,monmap=0+,osdmap=1170448}) 2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 check_osdmap_sub 0x55e2e2133de0 next 1170448 (onetime) 2021-04-09 17:07:27.238 7f9fc83e4700 5 mon.sun-storemon01@0(leader).osd e1987355 send_incremental [1170448..1987355] to client.131831153 2021-04-09 17:07:50.910 7f9fc83e4700 5 mon.sun-storemon01@0(leader) e45 dispatch_op client.131831153 v1:172.16.212.55:0/527701465 is not authenticated, dropping mon_subscribe({mdsmap=3914079+,monmap=0+,osdmap=1170448}) 2021-04-09 18:14:47.295 7f9fc83e4700 1 -- [v2:10.65.7.203:3300/0,v1:10.65.7.203:6789/0] <== client.131831153 v1:172.16.212.55:0/527701465 3 ==== mon_subscribe({mdsmap=3914127+,monmap=0+,osdmap=1170448}) ==== 85+0+0 (unknown 1413914345 0 0) 0x55e2dbc52c00 con 0x55e2e1cf5680 2021-04-09 18:15:17.006 7f9fc83e4700 1 -- [v2:10.65.7.203:3300/0,v1:10.65.7.203:6789/0] <== client.131831153 v1:172.16.212.55:0/527701465 2 ==== mon_subscribe({mdsmap=3914127+,monmap=0+,osdmap=1170448}) ==== 85+0+0 (unknown 1413914345 0 0) 0x55e2da565200 con 0x55e2df00a880 2021-04-09 18:15:17.278 7f9fc83e4700 1 -- [v2:10.65.7.203:3300/0,v1:10.65.7.203:6789/0] <== client.131831153 v1:172.16.212.55:0/527701465 3 ==== mon_subscribe({mdsmap=3914127+,monmap=0+,osdmap=1170448}) ==== 85+0+0 (unknown 1413914345 0 0) 0x55e2de443000 con 0x55e2ee3d8400
On Fri, Apr 9, 2021 at 9:37 PM Dan van der Ster <dan@vanderster.com> wrote:
On Fri, Apr 9, 2021 at 8:39 PM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 11:49 AM Dan van der Ster <dan@vanderster.com> wrote:
Thanks. I didn't see anything ultra obvious to me.
But I did notice the nearfull warnings so I wonder if this cluster is churning through osdmaps? Did you see a large increase in inbound or outbound network traffic on this mon following the upgrade? Totally speculating here, but maybe there is an issue where you have some old clients, which can't decode an incremental osdmap from a nautilus mon, so the single mon is busy serving up these maps to the clients.
Does the mon load decrease if you stop the osdmap churn?, e.g. by setting norebalance if that is indeed ongoing.
Could you also share debug_ms = 1 for a minute of busy cpu mon?
Here are the new logs with the debug_ms=1 for a bit. https://owncloud.leblancnet.us/owncloud/index.php/s/1hvtJo3s2oLPpWn
Something strange in this is there is one hammer client that is asking for nearly a million incremental osdmaps, seemingly every 30s:
client.131831153 at 172.16.212.55 is asking for incrementals from 1170448..1987355 (see [1])
Can you try to evict/kill/block that client and see if your mon load drops?
Before you respond, just noting here ftr that i think there's a possible issue with OSDMonitor::get_removed_snaps_range and clients like this. https://github.com/ceph/ceph/blob/v14.2.19/src/mon/OSDMonitor.cc#L4193 Called by send_incremental: https://github.com/ceph/ceph/blob/v14.2.19/src/mon/OSDMonitor.cc#L4152 When building the incremental it will search the mon's rocksdb for removed snaps across those ~million missing maps. That feature seems removed from octopus onward. -- dan
On Fri, Apr 9, 2021 at 2:04 PM Dan van der Ster <dan@vanderster.com> wrote:
On Fri, Apr 9, 2021 at 9:37 PM Dan van der Ster <dan@vanderster.com> wrote:
On Fri, Apr 9, 2021 at 8:39 PM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 11:49 AM Dan van der Ster <dan@vanderster.com> wrote:
Thanks. I didn't see anything ultra obvious to me.
But I did notice the nearfull warnings so I wonder if this cluster is churning through osdmaps? Did you see a large increase in inbound or outbound network traffic on this mon following the upgrade? Totally speculating here, but maybe there is an issue where you have some old clients, which can't decode an incremental osdmap from a nautilus mon, so the single mon is busy serving up these maps to the clients.
Does the mon load decrease if you stop the osdmap churn?, e.g. by setting norebalance if that is indeed ongoing.
Could you also share debug_ms = 1 for a minute of busy cpu mon?
Here are the new logs with the debug_ms=1 for a bit. https://owncloud.leblancnet.us/owncloud/index.php/s/1hvtJo3s2oLPpWn
Something strange in this is there is one hammer client that is asking for nearly a million incremental osdmaps, seemingly every 30s:
client.131831153 at 172.16.212.55 is asking for incrementals from 1170448..1987355 (see [1])
Can you try to evict/kill/block that client and see if your mon load drops?
Before you respond, just noting here ftr that i think there's a possible issue with OSDMonitor::get_removed_snaps_range and clients like this.
https://github.com/ceph/ceph/blob/v14.2.19/src/mon/OSDMonitor.cc#L4193
Called by send_incremental:
https://github.com/ceph/ceph/blob/v14.2.19/src/mon/OSDMonitor.cc#L4152
When building the incremental it will search the mon's rocksdb for removed snaps across those ~million missing maps.
That feature seems removed from octopus onward.
I evicted that client and CPU hasn't gone down significantly. There may be other clients also causing the issue. Was it the `osdmap=1170448` part of the line that says how many OSDmaps it's trying to get? I can look for others in the logs and evict them as well. Maybe if that code path isn't needed in Nautilus it can be removed in the next point release? Thank you, Robert LeBlanc
On Fri, Apr 9, 2021 at 11:50 PM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 2:04 PM Dan van der Ster <dan@vanderster.com> wrote:
On Fri, Apr 9, 2021 at 9:37 PM Dan van der Ster <dan@vanderster.com> wrote:
On Fri, Apr 9, 2021 at 8:39 PM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 11:49 AM Dan van der Ster <dan@vanderster.com> wrote:
Thanks. I didn't see anything ultra obvious to me.
But I did notice the nearfull warnings so I wonder if this cluster is churning through osdmaps? Did you see a large increase in inbound or outbound network traffic on this mon following the upgrade? Totally speculating here, but maybe there is an issue where you have some old clients, which can't decode an incremental osdmap from a nautilus mon, so the single mon is busy serving up these maps to the clients.
Does the mon load decrease if you stop the osdmap churn?, e.g. by setting norebalance if that is indeed ongoing.
Could you also share debug_ms = 1 for a minute of busy cpu mon?
Here are the new logs with the debug_ms=1 for a bit. https://owncloud.leblancnet.us/owncloud/index.php/s/1hvtJo3s2oLPpWn
Something strange in this is there is one hammer client that is asking for nearly a million incremental osdmaps, seemingly every 30s:
client.131831153 at 172.16.212.55 is asking for incrementals from 1170448..1987355 (see [1])
Can you try to evict/kill/block that client and see if your mon load drops?
Before you respond, just noting here ftr that i think there's a possible issue with OSDMonitor::get_removed_snaps_range and clients like this.
https://github.com/ceph/ceph/blob/v14.2.19/src/mon/OSDMonitor.cc#L4193
Called by send_incremental:
https://github.com/ceph/ceph/blob/v14.2.19/src/mon/OSDMonitor.cc#L4152
When building the incremental it will search the mon's rocksdb for removed snaps across those ~million missing maps.
That feature seems removed from octopus onward.
I evicted that client and CPU hasn't gone down significantly. There may be other clients also causing the issue. Was it the `osdmap=1170448` part of the line that says how many OSDmaps it's trying to get? I can look for others in the logs and evict them as well.
Here's what you should look for, with debug_mon=10. It shows clearly that it takes the mon 23 seconds to run through get_removed_snaps_range. So if this is happening every 30s, it explains at least part of why this mon is busy. 2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader) e45 handle_subscribe mon_subscribe({mdsmap=3914079+,monmap=0+,osdmap=1170448}) 2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 check_osdmap_sub 0x55e2e2133de0 next 1170448 (onetime) 2021-04-09 17:07:27.238 7f9fc83e4700 5 mon.sun-storemon01@0(leader).osd e1987355 send_incremental [1170448..1987355] to client.131831153 2021-04-09 17:07:28.590 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 0 [1~3] 2021-04-09 17:07:29.898 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 5 [] 2021-04-09 17:07:31.258 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 6 [] 2021-04-09 17:07:32.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 20 [] 2021-04-09 17:07:33.866 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 21 [] 2021-04-09 17:07:35.162 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 22 [] 2021-04-09 17:07:36.470 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 23 [] 2021-04-09 17:07:37.778 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 24 [] 2021-04-09 17:07:39.090 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 25 [] 2021-04-09 17:07:40.398 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 26 [] 2021-04-09 17:07:41.706 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 27 [] 2021-04-09 17:07:43.006 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 28 [] 2021-04-09 17:07:44.322 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 29 [] 2021-04-09 17:07:45.630 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 30 [] 2021-04-09 17:07:46.938 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 31 [] 2021-04-09 17:07:48.246 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 32 [] 2021-04-09 17:07:49.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 34 [] 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 35 [] 2021-04-09 17:07:50.862 7f9fc83e4700 20 mon.sun-storemon01@0(leader).osd e1987355 send_incremental starting with base full 1986745 664086 bytes 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 build_incremental [1986746..1986785] with features 107b84a842aca So have a look for that client again or other similar traces.
Maybe if that code path isn't needed in Nautilus it can be removed in the next point release?
I think there were other major changes in this area that might make such a backport difficult. And we should expect nautilus to be nearing its end... -- dan
Thank you, Robert LeBlanc
On Fri, Apr 9, 2021 at 4:04 PM Dan van der Ster <dan@vanderster.com> wrote:
Here's what you should look for, with debug_mon=10. It shows clearly that it takes the mon 23 seconds to run through get_removed_snaps_range. So if this is happening every 30s, it explains at least part of why this mon is busy.
2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader) e45 handle_subscribe mon_subscribe({mdsmap=3914079+,monmap=0+,osdmap=1170448}) 2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 check_osdmap_sub 0x55e2e2133de0 next 1170448 (onetime) 2021-04-09 17:07:27.238 7f9fc83e4700 5 mon.sun-storemon01@0(leader).osd e1987355 send_incremental [1170448..1987355] to client.131831153 2021-04-09 17:07:28.590 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 0 [1~3] 2021-04-09 17:07:29.898 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 5 [] 2021-04-09 17:07:31.258 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 6 [] 2021-04-09 17:07:32.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 20 [] 2021-04-09 17:07:33.866 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 21 [] 2021-04-09 17:07:35.162 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 22 [] 2021-04-09 17:07:36.470 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 23 [] 2021-04-09 17:07:37.778 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 24 [] 2021-04-09 17:07:39.090 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 25 [] 2021-04-09 17:07:40.398 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 26 [] 2021-04-09 17:07:41.706 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 27 [] 2021-04-09 17:07:43.006 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 28 [] 2021-04-09 17:07:44.322 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 29 [] 2021-04-09 17:07:45.630 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 30 [] 2021-04-09 17:07:46.938 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 31 [] 2021-04-09 17:07:48.246 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 32 [] 2021-04-09 17:07:49.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 34 [] 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 35 [] 2021-04-09 17:07:50.862 7f9fc83e4700 20 mon.sun-storemon01@0(leader).osd e1987355 send_incremental starting with base full 1986745 664086 bytes 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 build_incremental [1986746..1986785] with features 107b84a842aca
So have a look for that client again or other similar traces.
So, even though I blacklisted the client and we remounted the file system on it, it wasn't enough for it to keep performing the same bad requests. We found another node that had two sessions to the same mount point. We rebooted both nodes and the CPU is now back at a reasonable 4-6% and the cluster is running at full performance again. I've added in back both MONs to have all 3 mons in the system and there are no more elections. Thank you for helping us track down the bad clients out of over 2,000 clients.
Maybe if that code path isn't needed in Nautilus it can be removed in the next point release?
I think there were other major changes in this area that might make such a backport difficult. And we should expect nautilus to be nearing its end...
But ... we just got to Nautilus... :) Thank you, Robert LeBlanc
PSA. https://docs.ceph.com/en/latest/releases/general/#lifetime-of-stable-release... https://docs.ceph.com/en/latest/releases/#ceph-releases-index On Sat, Apr 10, 2021 at 10:11 AM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 4:04 PM Dan van der Ster <dan@vanderster.com> wrote:
Here's what you should look for, with debug_mon=10. It shows clearly that it takes the mon 23 seconds to run through get_removed_snaps_range. So if this is happening every 30s, it explains at least part of why this mon is busy.
2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader) e45 handle_subscribe mon_subscribe({mdsmap=3914079+,monmap=0+,osdmap=1170448}) 2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 check_osdmap_sub 0x55e2e2133de0 next 1170448 (onetime) 2021-04-09 17:07:27.238 7f9fc83e4700 5 mon.sun-storemon01@0(leader).osd e1987355 send_incremental [1170448..1987355] to client.131831153 2021-04-09 17:07:28.590 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 0 [1~3] 2021-04-09 17:07:29.898 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 5 [] 2021-04-09 17:07:31.258 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 6 [] 2021-04-09 17:07:32.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 20 [] 2021-04-09 17:07:33.866 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 21 [] 2021-04-09 17:07:35.162 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 22 [] 2021-04-09 17:07:36.470 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 23 [] 2021-04-09 17:07:37.778 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 24 [] 2021-04-09 17:07:39.090 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 25 [] 2021-04-09 17:07:40.398 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 26 [] 2021-04-09 17:07:41.706 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 27 [] 2021-04-09 17:07:43.006 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 28 [] 2021-04-09 17:07:44.322 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 29 [] 2021-04-09 17:07:45.630 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 30 [] 2021-04-09 17:07:46.938 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 31 [] 2021-04-09 17:07:48.246 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 32 [] 2021-04-09 17:07:49.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 34 [] 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 35 [] 2021-04-09 17:07:50.862 7f9fc83e4700 20 mon.sun-storemon01@0(leader).osd e1987355 send_incremental starting with base full 1986745 664086 bytes 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 build_incremental [1986746..1986785] with features 107b84a842aca
So have a look for that client again or other similar traces.
So, even though I blacklisted the client and we remounted the file system on it, it wasn't enough for it to keep performing the same bad requests. We found another node that had two sessions to the same mount point. We rebooted both nodes and the CPU is now back at a reasonable 4-6% and the cluster is running at full performance again. I've added in back both MONs to have all 3 mons in the system and there are no more elections. Thank you for helping us track down the bad clients out of over 2,000 clients.
Maybe if that code path isn't needed in Nautilus it can be removed in the next point release?
I think there were other major changes in this area that might make such a backport difficult. And we should expect nautilus to be nearing its end...
But ... we just got to Nautilus... :)
Thank you, Robert LeBlanc _______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
-- Cheers, Brad
On Sun, Apr 11, 2021 at 4:19 PM Brad Hubbard <bhubbard@redhat.com> wrote:
PSA.
https://docs.ceph.com/en/latest/releases/general/#lifetime-of-stable-release...
https://docs.ceph.com/en/latest/releases/#ceph-releases-index
I'm very well aware that we are living on the dying edge (well, past dead), but a good chunk of machines are Ubuntu 14.04 not by choice. Getting this upgrade done was sorely needed, but very risky at the same time. Thanks, Robert LeBlanc
On Mon, Apr 12, 2021 at 11:35 AM Robert LeBlanc <robert@leblancnet.us> wrote:
On Sun, Apr 11, 2021 at 4:19 PM Brad Hubbard <bhubbard@redhat.com> wrote:
PSA.
https://docs.ceph.com/en/latest/releases/general/#lifetime-of-stable-release...
https://docs.ceph.com/en/latest/releases/#ceph-releases-index
I'm very well aware that we are living on the dying edge (well, past dead), but a good chunk of machines are Ubuntu 14.04 not by choice. Getting this upgrade done was sorely needed, but very risky at the same time.
Sure Robert, I understand the realities of maintaining large installations which may have many reasons holding them back from upgrading any of the interdependent software they run. The other side of the page however is that we can not support releases indefinitely as each additional supported release places a huge burden on limited dev, support, and QA resources. We try to strike a balance but it's not "one size fits all" unfortunately. -- Cheers, Brad
On Mon, Apr 12, 2021 at 3:41 PM Brad Hubbard <bhubbard@redhat.com> wrote:
Sure Robert,
I understand the realities of maintaining large installations which may have many reasons holding them back from upgrading any of the interdependent software they run. The other side of the page however is that we can not support releases indefinitely as each additional supported release places a huge burden on limited dev, support, and QA resources. We try to strike a balance but it's not "one size fits all" unfortunately.
I do appreciate the considerable effort that allows for such massive backwards compatibility, so I want to make sure I'm not coming off ungrateful or anything like that. I know it takes a lot of effort to maintain software for such old systems. We are spending far too much time maintaining old machines, so we understand. At least there is the FUSE client from Luminous that we can deploy on 14.04, still better than the Jewel or Hammer compatibility of the kernel from 14.04. Life and safety systems are alway so difficult to make changes to. Do you think it would be possible to build Nautilus FUSE or newer on 14.04, or do you think the toolchain has evolved too much since then? Thanks, Robert LeBlanc
On Tue, Apr 13, 2021 at 8:40 AM Robert LeBlanc <robert@leblancnet.us> wrote:
Do you think it would be possible to build Nautilus FUSE or newer on 14.04, or do you think the toolchain has evolved too much since then?
An interesting question. # cat /etc/os-release NAME="Ubuntu" VERSION="14.04.6 LTS, Trusty Tahr" ID=ubuntu ID_LIKE=debian PRETTY_NAME="Ubuntu 14.04.6 LTS" VERSION_ID="14.04" HOME_URL="http://www.ubuntu.com/" SUPPORT_URL="http://help.ubuntu.com/" BUG_REPORT_URL="http://bugs.launchpad.net/ubuntu/" Had to tell cmake not to look for lz4 because the version on Trusty is too old. # ./do_cmake.sh -DWITH_LZ4=off # cd build/ # make -j8 ceph-fuse # make -j8 rbd-fuse # ./bin/rbd-fuse --version ceph version 14.2.19-83-g53aefaa (53aefaa1443c3a9bbd4e6448aa69e3d88b58cd51) nautilus (stable) # ./bin/ceph-fuse --version ceph version 14.2.19-83-g53aefaa (53aefaa1443c3a9bbd4e6448aa69e3d88b58cd51) nautilus (stable) I don't think Octopus would build on 14.04. -- Cheers, Brad
On Sat, Apr 10, 2021 at 2:10 AM Robert LeBlanc <robert@leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 4:04 PM Dan van der Ster <dan@vanderster.com> wrote:
Here's what you should look for, with debug_mon=10. It shows clearly that it takes the mon 23 seconds to run through get_removed_snaps_range. So if this is happening every 30s, it explains at least part of why this mon is busy.
2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader) e45 handle_subscribe mon_subscribe({mdsmap=3914079+,monmap=0+,osdmap=1170448}) 2021-04-09 17:07:27.238 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 check_osdmap_sub 0x55e2e2133de0 next 1170448 (onetime) 2021-04-09 17:07:27.238 7f9fc83e4700 5 mon.sun-storemon01@0(leader).osd e1987355 send_incremental [1170448..1987355] to client.131831153 2021-04-09 17:07:28.590 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 0 [1~3] 2021-04-09 17:07:29.898 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 5 [] 2021-04-09 17:07:31.258 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 6 [] 2021-04-09 17:07:32.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 20 [] 2021-04-09 17:07:33.866 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 21 [] 2021-04-09 17:07:35.162 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 22 [] 2021-04-09 17:07:36.470 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 23 [] 2021-04-09 17:07:37.778 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 24 [] 2021-04-09 17:07:39.090 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 25 [] 2021-04-09 17:07:40.398 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 26 [] 2021-04-09 17:07:41.706 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 27 [] 2021-04-09 17:07:43.006 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 28 [] 2021-04-09 17:07:44.322 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 29 [] 2021-04-09 17:07:45.630 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 30 [] 2021-04-09 17:07:46.938 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 31 [] 2021-04-09 17:07:48.246 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 32 [] 2021-04-09 17:07:49.562 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 34 [] 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 get_removed_snaps_range 35 [] 2021-04-09 17:07:50.862 7f9fc83e4700 20 mon.sun-storemon01@0(leader).osd e1987355 send_incremental starting with base full 1986745 664086 bytes 2021-04-09 17:07:50.862 7f9fc83e4700 10 mon.sun-storemon01@0(leader).osd e1987355 build_incremental [1986746..1986785] with features 107b84a842aca
So have a look for that client again or other similar traces.
So, even though I blacklisted the client and we remounted the file system on it, it wasn't enough for it to keep performing the same bad requests. We found another node that had two sessions to the same mount point. We rebooted both nodes and the CPU is now back at a reasonable 4-6% and the cluster is running at full performance again. I've added in back both MONs to have all 3 mons in the system and there are no more elections. Thank you for helping us track down the bad clients out of over 2,000 clients.
Maybe if that code path isn't needed in Nautilus it can be removed in the next point release?
I think there were other major changes in this area that might make such a backport difficult. And we should expect nautilus to be nearing its end...
But ... we just got to Nautilus... :)
Ouch, we just suffered this or a similar issue on our big prod block storage cluster running 14.2.19. But in our case it wasn't related to an old client -- rather we had 100% mon cpu and election storms but also huge tcmallocs all following the recreation of a couple OSDs. We wrote the details here: https://tracker.ceph.com/issues/50587 -- Dan
participants (4)
-
Brad Hubbard
-
Dan van der Ster
-
Robert LeBlanc
-
Stefan Kooman