On Fri, Apr 9, 2021 at 11:50 PM Robert LeBlanc <robert(a)leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 2:04 PM Dan van der Ster <dan(a)vanderster.com> wrote:
On Fri, Apr 9, 2021 at 9:37 PM Dan van der Ster <dan(a)vanderster.com> wrote:
On Fri, Apr 9, 2021 at 8:39 PM Robert LeBlanc <robert(a)leblancnet.us> wrote:
On Fri, Apr 9, 2021 at 11:49 AM Dan van der Ster <dan(a)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(a)0(leader).osd e1987355 check_osdmap_sub
0x55e2e2133de0 next 1170448 (onetime)
2021-04-09 17:07:27.238 7f9fc83e4700 5
mon.sun-storemon01(a)0(leader).osd e1987355 send_incremental
[1170448..1987355] to client.131831153
2021-04-09 17:07:28.590 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 0
[1~3]
2021-04-09 17:07:29.898 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 5 []
2021-04-09 17:07:31.258 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 6 []
2021-04-09 17:07:32.562 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 20
[]
2021-04-09 17:07:33.866 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 21
[]
2021-04-09 17:07:35.162 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 22
[]
2021-04-09 17:07:36.470 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 23
[]
2021-04-09 17:07:37.778 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 24
[]
2021-04-09 17:07:39.090 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 25
[]
2021-04-09 17:07:40.398 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 26
[]
2021-04-09 17:07:41.706 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 27
[]
2021-04-09 17:07:43.006 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 28
[]
2021-04-09 17:07:44.322 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 29
[]
2021-04-09 17:07:45.630 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 30
[]
2021-04-09 17:07:46.938 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 31
[]
2021-04-09 17:07:48.246 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 32
[]
2021-04-09 17:07:49.562 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 34
[]
2021-04-09 17:07:50.862 7f9fc83e4700 10
mon.sun-storemon01(a)0(leader).osd e1987355 get_removed_snaps_range 35
[]
2021-04-09 17:07:50.862 7f9fc83e4700 20
mon.sun-storemon01(a)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(a)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