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