osds dropping out of the cluster w/ "OSD::osd_op_tp thread … had timed out"
hi there, we are seeing osd occasionally getting kicked out of our cluster, after having been marked down by other osds. most of the time, the affected osd rejoins the cluster after about ~5 minutes, but sometimes this takes much longer. during that time, the osd seems to run just fine. this happens more often that we'd like it to … is "OSD::osd_op_tp thread … had timed out" a real error condition or just a warning about certain operations on the osd taking a long time? i already set osd_op_thread_timeout to 120 (was 60 before, default should be 15 according to the docs), but apparently that doesn't make any difference. are there any other settings that prevent this kind of behaviour? mon_osd_report_timeout maybe, as in frank schilder's case? the cluster runs nautilus 14.2.7, osds are backed by spinning platters with their rocksdb and wals on nvmes. in general, there seems to be the following pattern: - it happens under moderate to heavy load, eg. while creating pools with a lot of pgs - the affected osd logs a lot of: "heartbeat_map is_healthy 'OSD::osd_op_tp thread ${thread-id}' had timed out after 60" … and finally something along the lines of: May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.211 7fb25cc80700 0 bluestore(/var/lib/ceph/osd/ceph-293) log_latency_fn slow operation observed for _collection_list, latency = 96.337s, lat = 96s cid =2.0s2_head start GHMAX end GHMAX max 30 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.219 7fb25cc80700 1 heartbeat_map clear_timeout 'OSD::osd_op_tp thread 0x7fb25cc80700' had timed out after 60 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: osd.293 osd.293 2 : Monitor daemon marked osd.293 down, but it is still running May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) log [WRN] : Monitor daemon marked osd.293 down, but it is still running May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) do_log log to syslog May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) log [DBG] : map e646639 wrongly marked me down at e646638 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) do_log log to syslog May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.371 7fb272cac700 -1 osd.293 646639 set_numa_affinity unable to identify public interface 'br-bond0' numa node: (2) No such file or directory May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.371 7fb272cac700 -1 osd.293 646639 set_numa_affinity unable to identify public interface 'br-bond0' numa node: (2) No such file or directory - meanwhile on the mon: 2020-05-18 21:12:16.440 7f08f7933700 0 mon.ceph-mon-01@0(leader) e4 handle_command mon_command({"prefix": "status"} v 0) v1 entity='client.admin' cmd=[{"prefix": "status"}]: dispatch 2020-05-18 21:12:18.436 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.101 2020-05-18 21:12:18.848 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.533 [… lots of these from various osds] 2020-05-18 21:12:24.992 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.421 2020-05-18 21:12:26.124 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.504 2020-05-18 21:12:26.132 7f08f7933700 0 log_channel(cluster) log [INF] : osd.293 failed (root=tuberlin,datacenter=barz,host=ceph-osd-05) (16 reporters from different host after 27.137527 >= grace 26.361774) 2020-05-18 21:12:26.236 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: 1 osds down (OSD_DOWN) 2020-05-18 21:12:26.280 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646638: 604 total, 603 up, 604 in 2020-05-18 21:12:27.336 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646639: 604 total, 603 up, 604 in 2020-05-18 21:12:28.248 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: Reduced data availability: 17 pgs peering (PG_AVAILABILITY) 2020-05-18 21:12:29.392 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: Degraded data redundancy: 80091/181232010 objects degraded (0.044%), 18 pgs degraded (PG_DEGRADED) 2020-05-18 21:12:33.927 7f08fa138700 0 log_channel(cluster) log [INF] : Health check cleared: PG_AVAILABILITY (was: Reduced data availability: 1 pg inactive, 22 pgs peering) 2020-05-18 21:12:35.095 7f08fa138700 0 log_channel(cluster) log [INF] : Health check cleared: OSD_DOWN (was: 1 osds down) 2020-05-18 21:12:35.119 7f08f6130700 0 log_channel(cluster) log [INF] : osd.293 [v2:172.28.9.26:6936/2356578,v1:172.28.9.26:6937/2356578] boot 2020-05-18 21:12:35.119 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646640: 604 total, 604 up, 604 in 2020-05-18 21:12:36.175 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646641: 604 total, 604 up, 604 in i can happily provide more detailed logs, if that helps. thank you very much & with kind regards, thoralf.
Hi Thoralf, given the following indication from your logs: May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.211 7fb25cc80700 0 bluestore(/var/lib/ceph/osd/ceph-293) log_latency_fn slow operation observed for _collection_list, latency = 96.337s, lat = 96s cid =2.0s2_head start GHMAX end GHMAX max 30 I presume that your OSDs suffer from slow RocksDB access, collection_listing operation is a culprit in this case - 30 items listing takes 96seconds to complete. From my experience such issues tend to happen after massive DB data removals (e.g. pool removal(s)) often backed by RGW usage which is "DB access greedy". DB data fragmentation is presumably the root cause for the resulting slowdown. BlueFS spillover to main HDD device if any to be eliminated too. To temporary workaround the issue you might want to do manual RocksDB compaction - it's known to be helpful in such cases. But the positive effect doesn't last forever - DB might go into degraded state again. Some questions about your cases: - What kind of payload do you have - RGW or something else? - Have you done massive removals recently? - How large are main and DB disks for suffering OSDs? How much is their current utilization? - Do you see multiple "slow operation observed" patterns in OSD logs? Are they all about _collection_list function? Thanks, Igor On 5/19/2020 12:07 PM, thoralf schulze wrote:
hi there,
we are seeing osd occasionally getting kicked out of our cluster, after having been marked down by other osds. most of the time, the affected osd rejoins the cluster after about ~5 minutes, but sometimes this takes much longer. during that time, the osd seems to run just fine.
this happens more often that we'd like it to … is "OSD::osd_op_tp thread … had timed out" a real error condition or just a warning about certain operations on the osd taking a long time? i already set osd_op_thread_timeout to 120 (was 60 before, default should be 15 according to the docs), but apparently that doesn't make any difference.
are there any other settings that prevent this kind of behaviour? mon_osd_report_timeout maybe, as in frank schilder's case?
the cluster runs nautilus 14.2.7, osds are backed by spinning platters with their rocksdb and wals on nvmes. in general, there seems to be the following pattern:
- it happens under moderate to heavy load, eg. while creating pools with a lot of pgs - the affected osd logs a lot of: "heartbeat_map is_healthy 'OSD::osd_op_tp thread ${thread-id}' had timed out after 60" … and finally something along the lines of: May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.211 7fb25cc80700 0 bluestore(/var/lib/ceph/osd/ceph-293) log_latency_fn slow operation observed for _collection_list, latency = 96.337s, lat = 96s cid =2.0s2_head start GHMAX end GHMAX max 30 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.219 7fb25cc80700 1 heartbeat_map clear_timeout 'OSD::osd_op_tp thread 0x7fb25cc80700' had timed out after 60 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: osd.293 osd.293 2 : Monitor daemon marked osd.293 down, but it is still running May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) log [WRN] : Monitor daemon marked osd.293 down, but it is still running May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) do_log log to syslog May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) log [DBG] : map e646639 wrongly marked me down at e646638 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) do_log log to syslog May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.371 7fb272cac700 -1 osd.293 646639 set_numa_affinity unable to identify public interface 'br-bond0' numa node: (2) No such file or directory May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.371 7fb272cac700 -1 osd.293 646639 set_numa_affinity unable to identify public interface 'br-bond0' numa node: (2) No such file or directory
- meanwhile on the mon: 2020-05-18 21:12:16.440 7f08f7933700 0 mon.ceph-mon-01@0(leader) e4 handle_command mon_command({"prefix": "status"} v 0) v1 entity='client.admin' cmd=[{"prefix": "status"}]: dispatch 2020-05-18 21:12:18.436 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.101 2020-05-18 21:12:18.848 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.533 [… lots of these from various osds] 2020-05-18 21:12:24.992 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.421 2020-05-18 21:12:26.124 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.504 2020-05-18 21:12:26.132 7f08f7933700 0 log_channel(cluster) log [INF] : osd.293 failed (root=tuberlin,datacenter=barz,host=ceph-osd-05) (16 reporters from different host after 27.137527 >= grace 26.361774) 2020-05-18 21:12:26.236 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: 1 osds down (OSD_DOWN) 2020-05-18 21:12:26.280 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646638: 604 total, 603 up, 604 in 2020-05-18 21:12:27.336 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646639: 604 total, 603 up, 604 in 2020-05-18 21:12:28.248 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: Reduced data availability: 17 pgs peering (PG_AVAILABILITY) 2020-05-18 21:12:29.392 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: Degraded data redundancy: 80091/181232010 objects degraded (0.044%), 18 pgs degraded (PG_DEGRADED) 2020-05-18 21:12:33.927 7f08fa138700 0 log_channel(cluster) log [INF] : Health check cleared: PG_AVAILABILITY (was: Reduced data availability: 1 pg inactive, 22 pgs peering) 2020-05-18 21:12:35.095 7f08fa138700 0 log_channel(cluster) log [INF] : Health check cleared: OSD_DOWN (was: 1 osds down) 2020-05-18 21:12:35.119 7f08f6130700 0 log_channel(cluster) log [INF] : osd.293 [v2:172.28.9.26:6936/2356578,v1:172.28.9.26:6937/2356578] boot 2020-05-18 21:12:35.119 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646640: 604 total, 604 up, 604 in 2020-05-18 21:12:36.175 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646641: 604 total, 604 up, 604 in
i can happily provide more detailed logs, if that helps.
thank you very much & with kind regards, thoralf.
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
On Tue, May 19, 2020 at 2:06 PM Igor Fedotov <ifedotov@suse.de> wrote:
Hi Thoralf,
given the following indication from your logs:
May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.211 7fb25cc80700 0 bluestore(/var/lib/ceph/osd/ceph-293) log_latency_fn slow operation observed for _collection_list, latency = 96.337s, lat = 96s cid =2.0s2_head start GHMAX end GHMAX max 30
I presume that your OSDs suffer from slow RocksDB access, collection_listing operation is a culprit in this case - 30 items listing takes 96seconds to complete. From my experience such issues tend to happen after massive DB data removals (e.g. pool removal(s)) often backed by RGW usage which is "DB access greedy".
+1, also my experience: this happens when running large RGW setups. Usually the solution is making sure that 1) all metadata really goes to SSD 2) there is no spillover 3) if necessary add more OSDs; common problem is having very few dedicated OSDs for the index pool; running the index on all OSDs (and having a fast DB device for every disk) is better. But sounds like you already have that Paul
DB data fragmentation is presumably the root cause for the resulting slowdown. BlueFS spillover to main HDD device if any to be eliminated too. To temporary workaround the issue you might want to do manual RocksDB compaction - it's known to be helpful in such cases. But the positive effect doesn't last forever - DB might go into degraded state again.
Some questions about your cases: - What kind of payload do you have - RGW or something else? - Have you done massive removals recently? - How large are main and DB disks for suffering OSDs? How much is their current utilization? - Do you see multiple "slow operation observed" patterns in OSD logs? Are they all about _collection_list function?
Thanks, Igor On 5/19/2020 12:07 PM, thoralf schulze wrote:
hi there,
we are seeing osd occasionally getting kicked out of our cluster, after having been marked down by other osds. most of the time, the affected osd rejoins the cluster after about ~5 minutes, but sometimes this takes much longer. during that time, the osd seems to run just fine.
this happens more often that we'd like it to … is "OSD::osd_op_tp thread … had timed out" a real error condition or just a warning about certain operations on the osd taking a long time? i already set osd_op_thread_timeout to 120 (was 60 before, default should be 15 according to the docs), but apparently that doesn't make any difference.
are there any other settings that prevent this kind of behaviour? mon_osd_report_timeout maybe, as in frank schilder's case?
the cluster runs nautilus 14.2.7, osds are backed by spinning platters with their rocksdb and wals on nvmes. in general, there seems to be the following pattern:
- it happens under moderate to heavy load, eg. while creating pools with a lot of pgs - the affected osd logs a lot of: "heartbeat_map is_healthy 'OSD::osd_op_tp thread ${thread-id}' had timed out after 60" … and finally something along the lines of: May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.211 7fb25cc80700 0 bluestore(/var/lib/ceph/osd/ceph-293) log_latency_fn slow operation observed for _collection_list, latency = 96.337s, lat = 96s cid =2.0s2_head start GHMAX end GHMAX max 30 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.219 7fb25cc80700 1 heartbeat_map clear_timeout 'OSD::osd_op_tp thread 0x7fb25cc80700' had timed out after 60 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: osd.293 osd.293 2 : Monitor daemon marked osd.293 down, but it is still running May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) log [WRN] : Monitor daemon marked osd.293 down, but it is still running May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) do_log log to syslog May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) log [DBG] : map e646639 wrongly marked me down at e646638 May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.315 7fb267c96700 0 log_channel(cluster) do_log log to syslog May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.371 7fb272cac700 -1 osd.293 646639 set_numa_affinity unable to identify public interface 'br-bond0' numa node: (2) No such file or directory May 18 21:12:34 ceph-osd-05 ceph-osd[2356578]: 2020-05-18 21:12:34.371 7fb272cac700 -1 osd.293 646639 set_numa_affinity unable to identify public interface 'br-bond0' numa node: (2) No such file or directory
- meanwhile on the mon: 2020-05-18 21:12:16.440 7f08f7933700 0 mon.ceph-mon-01@0(leader) e4 handle_command mon_command({"prefix": "status"} v 0) v1 entity='client.admin' cmd=[{"prefix": "status"}]: dispatch 2020-05-18 21:12:18.436 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.101 2020-05-18 21:12:18.848 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.533 [… lots of these from various osds] 2020-05-18 21:12:24.992 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.421 2020-05-18 21:12:26.124 7f08f7933700 0 log_channel(cluster) log [DBG] : osd.293 reported failed by osd.504 2020-05-18 21:12:26.132 7f08f7933700 0 log_channel(cluster) log [INF] : osd.293 failed (root=tuberlin,datacenter=barz,host=ceph-osd-05) (16 reporters from different host after 27.137527 >= grace 26.361774) 2020-05-18 21:12:26.236 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: 1 osds down (OSD_DOWN) 2020-05-18 21:12:26.280 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646638: 604 total, 603 up, 604 in 2020-05-18 21:12:27.336 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646639: 604 total, 603 up, 604 in 2020-05-18 21:12:28.248 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: Reduced data availability: 17 pgs peering (PG_AVAILABILITY) 2020-05-18 21:12:29.392 7f08fa138700 0 log_channel(cluster) log [WRN] : Health check failed: Degraded data redundancy: 80091/181232010 objects degraded (0.044%), 18 pgs degraded (PG_DEGRADED) 2020-05-18 21:12:33.927 7f08fa138700 0 log_channel(cluster) log [INF] : Health check cleared: PG_AVAILABILITY (was: Reduced data availability: 1 pg inactive, 22 pgs peering) 2020-05-18 21:12:35.095 7f08fa138700 0 log_channel(cluster) log [INF] : Health check cleared: OSD_DOWN (was: 1 osds down) 2020-05-18 21:12:35.119 7f08f6130700 0 log_channel(cluster) log [INF] : osd.293 [v2:172.28.9.26:6936/2356578,v1:172.28.9.26:6937/2356578] boot 2020-05-18 21:12:35.119 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646640: 604 total, 604 up, 604 in 2020-05-18 21:12:36.175 7f08f6130700 0 log_channel(cluster) log [DBG] : osdmap e646641: 604 total, 604 up, 604 in
i can happily provide more detailed logs, if that helps.
thank you very much & with kind regards, thoralf.
_______________________________________________ ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
ceph-users mailing list -- ceph-users@ceph.io To unsubscribe send an email to ceph-users-leave@ceph.io
hi igor, hi paul - thank you for your answers. On 5/19/20 2:05 PM, Igor Fedotov wrote:
I presume that your OSDs suffer from slow RocksDB access, collection_listing operation is a culprit in this case - 30 items listing takes 96seconds to complete. From my experience such issues tend to happen after massive DB data removals (e.g. pool removal(s)) often backed by RGW usage which is "DB access greedy". DB data fragmentation is presumably the root cause for the resulting slowdown. BlueFS spillover to main HDD device if any to be eliminated too. To temporary workaround the issue you might want to do manual RocksDB compaction - it's known to be helpful in such cases. But the positive effect doesn't last forever - DB might go into degraded state again.
so i'll try to compact the rockdbs and report back … we didn't see any spillovers yet, but indeed created a few large test pools with many pgs and removed these afterwards. also, the affected pools had a significant number of osds added to them recently. apart from this, the pools are mainly being used for cephfs, with some rather small rgw pools for openstack on top. On 5/19/20 2:13 PM, Paul Emmerich wrote:
3) if necessary add more OSDs; common problem is having very few dedicated OSDs for the index pool; running the index on all OSDs (and having a fast DB device for every disk) is better. But sounds like you already have that
nope, unfortunately not. default.rgw.buckets.index is an replicated pool on hdds with only 4 pgs, i'll see if i can change that. back to igors questions:
Some questions about your cases: - What kind of payload do you have - RGW or something else? mostly cephfs. the most active pools in terms of i/o are the openstack rgw ones, though.
- Have you done massive removals recently? yes, see above
- How large are main and DB disks for suffering OSDs? How much is their current utilization? for osd.293, for which i've sent the log: main: 2tb hdd (5% used), db: 14gb partition on a 180gb nvme (~400mb used) … i'll attach a perf dump for this osd.
- Do you see multiple "slow operation observed" patterns in OSD logs? yes, although they do not necessarily correlate with osd down events.
Are they all about _collection_list function? no, there are also submit_transact and _txc_committed_kv, with about the same frequency as collection_list.
thank you very much for your analysis & with kind regards, thoralf.
On Tue, May 19, 2020 at 3:11 PM thoralf schulze <t.schulze@tu-berlin.de> wrote:
On 5/19/20 2:13 PM, Paul Emmerich wrote:
3) if necessary add more OSDs; common problem is having very few dedicated OSDs for the index pool; running the index on all OSDs (and having a fast DB device for every disk) is better. But sounds like you already have that
nope, unfortunately not. default.rgw.buckets.index is an replicated pool on hdds with only 4 pgs, i'll see if i can change that.
these PGs should be distributed across all OSDs; in general it's a good idea to have at least as many PGs as you have OSDs of the target type for that pool (technically a third would be enough to target one PG per OSD, because of x3 replication) Paul
back to igors questions:
Some questions about your cases: - What kind of payload do you have - RGW or something else? mostly cephfs. the most active pools in terms of i/o are the openstack rgw ones, though.
- Have you done massive removals recently? yes, see above
- How large are main and DB disks for suffering OSDs? How much is their current utilization? for osd.293, for which i've sent the log: main: 2tb hdd (5% used), db: 14gb partition on a 180gb nvme (~400mb used) … i'll attach a perf dump for this osd.
- Do you see multiple "slow operation observed" patterns in OSD logs? yes, although they do not necessarily correlate with osd down events.
Are they all about _collection_list function? no, there are also submit_transact and _txc_committed_kv, with about the same frequency as collection_list.
thank you very much for your analysis & with kind regards, thoralf.
Thoralf, from your perf counter's dump: "db_total_bytes": 15032377344, "db_used_bytes": 411033600, "wal_total_bytes": 0, "wal_used_bytes": 0, "slow_total_bytes": 94737203200, "slow_used_bytes": 10714480640, slow_used_bytes is non-zero hence you have a spillover. Additionally your DB volume size selection isn't perfect. For optimal space usage RocksDB/BlueFS require DB volume sizes to aligned with the following sequence (a bit simplified view): 3-6GB, 30-60GB, 300+GB. This has been discussed in this mailing list multiple times. Using DB volume size (15 GB in you case) out of these ranges cause wasting of space from one side and early spillovers from another. Hence this worths adjusting in long term too. Thanks, Igor On 5/19/2020 4:11 PM, thoralf schulze wrote:
hi igor, hi paul -
thank you for your answers.
I presume that your OSDs suffer from slow RocksDB access, collection_listing operation is a culprit in this case - 30 items listing takes 96seconds to complete. From my experience such issues tend to happen after massive DB data removals (e.g. pool removal(s)) often backed by RGW usage which is "DB access greedy". DB data fragmentation is presumably the root cause for the resulting slowdown. BlueFS spillover to main HDD device if any to be eliminated too. To temporary workaround the issue you might want to do manual RocksDB compaction - it's known to be helpful in such cases. But the positive effect doesn't last forever - DB might go into degraded state again. so i'll try to compact the rockdbs and report back … we didn't see any spillovers yet, but indeed created a few large test pools with many pgs and removed these afterwards. also, the affected pools had a significant number of osds added to them recently. apart from this, the pools are
On 5/19/20 2:05 PM, Igor Fedotov wrote: mainly being used for cephfs, with some rather small rgw pools for openstack on top.
On 5/19/20 2:13 PM, Paul Emmerich wrote:
3) if necessary add more OSDs; common problem is having very few dedicated OSDs for the index pool; running the index on all OSDs (and having a fast DB device for every disk) is better. But sounds like you already have that nope, unfortunately not. default.rgw.buckets.index is an replicated pool on hdds with only 4 pgs, i'll see if i can change that.
back to igors questions:
Some questions about your cases: - What kind of payload do you have - RGW or something else? mostly cephfs. the most active pools in terms of i/o are the openstack rgw ones, though.
- Have you done massive removals recently? yes, see above
- How large are main and DB disks for suffering OSDs? How much is their current utilization? for osd.293, for which i've sent the log: main: 2tb hdd (5% used), db: 14gb partition on a 180gb nvme (~400mb used) … i'll attach a perf dump for this osd.
- Do you see multiple "slow operation observed" patterns in OSD logs? yes, although they do not necessarily correlate with osd down events.
Are they all about _collection_list function? no, there are also submit_transact and _txc_committed_kv, with about the same frequency as collection_list.
thank you very much for your analysis & with kind regards, thoralf.
hi igor - On 5/19/20 3:23 PM, Igor Fedotov wrote:
slow_used_bytes is non-zero hence you have a spillover.
you are absolutely right, we do have spillovers on a large number of osds. ceph tell osd.* compact is running right now.
Additionally your DB volume size selection isn't perfect. For optimal space usage RocksDB/BlueFS require DB volume sizes to aligned with the following sequence (a bit simplified view):
3-6GB, 30-60GB, 300+GB. This has been discussed in this mailing list multiple times.
Using DB volume size (15 GB in you case) out of these ranges cause wasting of space from one side and early spillovers from another.
Hence this worths adjusting in long term too.
yes, adding additional nvmes to the cluster is on our to do-list. thank you, thoralf.
hi there - On 5/19/20 3:11 PM, thoralf schulze wrote:
[…] and report back …
i tried to reproduce the issue with osds each using 37gb of ssd storage for db and wal. everything went fine - so yes, spillovers are to be avoided. thank you very much & with kind regards, thoralf.
participants (3)
-
Igor Fedotov
-
Paul Emmerich
-
thoralf schulze