8 Apr
2021
8 Apr
'21
8:52 p.m.
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.
I did a `perf top` on the node to see what's taking all the time and it
appears to be in the rocksdb code path. I've set `mon_compact_on_start =
true` in the ceph.conf but that does not appear to help. The
`/var/lib/ceph/mon/` directory is 311MB which is down from 3.0 GB while the
backfills were going on. I've tried adding a second monitor, but it goes
back to the constant elections. I tried restarting all the services without
luck. I also pulled the monitor from the network work and tried restarting
the mon service isolated (this helped a couple of weeks ago when `ceph -s`
would cause 100% CPU and lock up the service much worse than this) and
didn't see the high CPU load. So I'm guessing it's triggered from some
external source.
I'm happy to provide more info, just let me know what would be helpful.
Thank you,
Robert LeBlanc
[image: image.png]
----------------
Robert LeBlanc
PGP Fingerprint 79A2 9CA4 6CC4 45DD A904 C70E E654 3BB2 FA62 B9F1
8 Apr
8 Apr
9:54 p.m.
On Thu, Apr 8, 2021 at 10:22 AM Robert LeBlanc <robert(a)leblancnet.us> 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.
I did a `perf top` on the node to see what's taking all the time and it appears to be
in the rocksdb code path. I've set `mon_compact_on_start = true` in the ceph.conf but
that does not appear to help. The `/var/lib/ceph/mon/` directory is 311MB which is down
from 3.0 GB while the backfills were going on. I've tried adding a second monitor, but
it goes back to the constant elections. I tried restarting all the services without luck.
I also pulled the monitor from the network work and tried restarting the mon service
isolated (this helped a couple of weeks ago when `ceph -s` would cause 100% CPU and lock
up the service much worse than this) and didn't see the high CPU load. So I'm
guessing it's triggered from some external source.
I'm happy to provide more info, just let me know what would be helpful.
Sent this to the dev list, but forgot it needed to be plain text. Here
is text output of the `perf top` taken a bit later, so not exactly the
same as the screenshot earlier.
Samples: 20M of event 'cycles', 4000 Hz, Event count (approx.):
61966526527 lost: 0/0 drop: 0/0
Overhead Shared Object Symbol
11.52% ceph-mon [.]
rocksdb::MemTable::KeyComparator::operator()
6.80% ceph-mon [.]
rocksdb::MemTable::KeyComparator::operator()
4.75% ceph-mon [.]
rocksdb::InlineSkipList<rocksdb::MemTableRep::KeyComparator
const&>::FindGreaterOrEqual
2.89% libc-2.27.so [.] vfprintf
2.54% libtcmalloc.so.4.3.0 [.] tc_deletearray_nothrow
2.31% ceph-mon [.] TLS init
function for rocksdb::perf_context
2.14% ceph-mon [.] rocksdb::DBImpl::GetImpl
1.53% libc-2.27.so [.] 0x000000000018acf8
1.44% libc-2.27.so [.] _IO_default_xsputn
1.34% ceph-mon [.] memcmp@plt
1.32% libtcmalloc.so.4.3.0 [.] tc_malloc
1.28% ceph-mon [.] rocksdb::Version::Get
1.27% libc-2.27.so [.] 0x000000000018abf4
1.17% ceph-mon [.] RocksDBStore::get
1.08% ceph-mon [.] 0x0000000000639a33
1.04% ceph-mon [.] 0x0000000000639a0e
0.89% ceph-mon [.] 0x0000000000639a46
0.86% ceph-mon [.] rocksdb::TableCache::Get
0.72% libc-2.27.so [.] 0x000000000018abfe
0.68% libceph-common.so.0 [.] ceph_str_hash_rjenkins
0.66% ceph-mon [.] rocksdb::Hash
0.63% ceph-mon [.] rocksdb::MemTable::Get
0.62% ceph-mon [.] 0x00000000006399ff
0.57% libc-2.27.so [.] 0x000000000018abf0
0.57% ceph-mon [.]
rocksdb::GetContext::GetContext
0.57% ceph-mon [.]
rocksdb::BlockBasedTable::Get
0.57% ceph-mon [.]
rocksdb::BlockBasedTable::GetFilter
0.55% [vdso] [.] __vdso_clock_gettime
0.54% ceph-mon [.] 0x00000000005afa17
0.53% ceph-mgr [.]
std::_Rb_tree<pg_t, pg_t, std::_Identity<pg_t>, std::less<pg_t>,
std::allocator<pg_t> >::equal_range
0.51% libceph-common.so.0 [.] PerfCounters::tinc
0.50% ceph-mon [.]
OSDMonitor::make_snap_epoch_key[abi:cxx11]
10:19 p.m.
On Thu, Apr 8, 2021 at 11:24 AM Robert LeBlanc <robert(a)leblancnet.us> wrote:
On Thu, Apr 8, 2021 at 10:22 AM Robert LeBlanc <robert(a)leblancnet.us> wrote:
Okay, I think I sent it to the old dev list. Trying again.
Thank you,
Robert LeBlanc
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.
I did a `perf top` on the node to see what's taking all the time and it appears to be
in the rocksdb code path. I've set `mon_compact_on_start = true` in the ceph.conf but
that does not appear to help. The `/var/lib/ceph/mon/` directory is 311MB which is down
from 3.0 GB while the backfills were going on. I've tried adding a second monitor, but
it goes back to the constant elections. I tried restarting all the services without luck.
I also pulled the monitor from the network work and tried restarting the mon service
isolated (this helped a couple of weeks ago when `ceph -s` would cause 100% CPU and lock
up the service much worse than this) and didn't see the high CPU load. So I'm
guessing it's triggered from some external source.
I'm happy to provide more info, just let me know what would be helpful.
Sent this to the dev list, but forgot it needed to be plain text. Here
is text output of the `perf top` taken a bit later, so not exactly the
same as the screenshot earlier.
Samples: 20M of event 'cycles', 4000 Hz, Event count (approx.):
61966526527 lost: 0/0 drop: 0/0
Overhead Shared Object Symbol
11.52% ceph-mon [.]
rocksdb::MemTable::KeyComparator::operator()
6.80% ceph-mon [.]
rocksdb::MemTable::KeyComparator::operator()
4.75% ceph-mon [.]
rocksdb::InlineSkipList<rocksdb::MemTableRep::KeyComparator
const&>::FindGreaterOrEqual
2.89% libc-2.27.so [.] vfprintf
2.54% libtcmalloc.so.4.3.0 [.] tc_deletearray_nothrow
2.31% ceph-mon [.] TLS init
function for rocksdb::perf_context
2.14% ceph-mon [.] rocksdb::DBImpl::GetImpl
1.53% libc-2.27.so [.] 0x000000000018acf8
1.44% libc-2.27.so [.] _IO_default_xsputn
1.34% ceph-mon [.] memcmp@plt
1.32% libtcmalloc.so.4.3.0 [.] tc_malloc
1.28% ceph-mon [.] rocksdb::Version::Get
1.27% libc-2.27.so [.] 0x000000000018abf4
1.17% ceph-mon [.] RocksDBStore::get
1.08% ceph-mon [.] 0x0000000000639a33
1.04% ceph-mon [.] 0x0000000000639a0e
0.89% ceph-mon [.] 0x0000000000639a46
0.86% ceph-mon [.] rocksdb::TableCache::Get
0.72% libc-2.27.so [.] 0x000000000018abfe
0.68% libceph-common.so.0 [.] ceph_str_hash_rjenkins
0.66% ceph-mon [.] rocksdb::Hash
0.63% ceph-mon [.] rocksdb::MemTable::Get
0.62% ceph-mon [.] 0x00000000006399ff
0.57% libc-2.27.so [.] 0x000000000018abf0
0.57% ceph-mon [.]
rocksdb::GetContext::GetContext
0.57% ceph-mon [.]
rocksdb::BlockBasedTable::Get
0.57% ceph-mon [.]
rocksdb::BlockBasedTable::GetFilter
0.55% [vdso] [.] __vdso_clock_gettime
0.54% ceph-mon [.] 0x00000000005afa17
0.53% ceph-mgr [.]
std::_Rb_tree<pg_t, pg_t, std::_Identity<pg_t>, std::less<pg_t>,
std::allocator<pg_t> >::equal_range
0.51% libceph-common.so.0 [.] PerfCounters::tinc
0.50% ceph-mon [.]
OSDMonitor::make_snap_epoch_key[abi:cxx11] 
11:41 p.m.
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
9 Apr
9 Apr
12:56 a.m.
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(a)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
1134
days inactive
1134
days old
4 comments
2 participants
participants (2)
-
Robert LeBlanc -
Stefan Kooman