9 Jan
2020
9 Jan
'20
7:03 p.m.
Hi All,
I am observing strange behaviour on one OSD, which is dedicated for RGW
index (pool: default.rgw.buckets.index).
My ceph is: ceph version 14.2.4 (75f4de193b3ea58512f204623e6c5a16e6c1e1ba)
nautilus (stable)
In log files are many messages like below:
2020-01-08 10:37:53.054 7f1fa22dd700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency slow operation observed
for next, latency = 22.4641s
...
2020-01-08 14:57:06.987 7f1fa22dd700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency_fn slow operation observed
for upper_bound, latency = 28.9336s, after = �0_ omap_iterator(cid =
230.2c_head, oid =
#230:36f53ff9:::.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31:head#)
2020-01-08 15:17:39.972 7f1fa22dd700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency_fn slow operation observed
for upper_bound, latency = 23.9168s, after = �0_ omap_iterator(cid =
230.2c_head, oid =
#230:36f53ff9:::.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31:head#)
2020-01-08 15:37:44.221 7f1fa62e5700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency_fn slow operation observed
for upper_bound, latency = 25.8316s, after = �0_ omap_iterator(cid =
230.2c_head, oid =
#230:36f53ff9:::.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31:head#)
2020-01-08 15:58:12.279 7f1fa62e5700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency_fn slow operation observed
for upper_bound, latency = 27.8207s, after = �0_ omap_iterator(cid =
230.2c_head, oid =
#230:36f53ff9:::.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31:head#)
I discovered that these times are associated with GC bilogs (it runs every
30 minutes).
# /etc/ceph/ceph.conf
rgw sync log trim interval = 1200
ID of bucket bucket_1: 12307ed8-2342-4293-9f14-12234220a234.13221775.224244
Shard nr. 31 of bucket (bucket_1) index:
.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31
[root@mon-1 ~]# ceph osd map default.rgw.buckets.index
.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31
osdmap e23417 pool 'default.rgw.buckets.index' (230) object
'.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31' -> pg
230.9ffcaf6c (230.2c) -> up ([62,56,60], p62) acting ([62,56,60], p62)
OSD: 62,56,60
Problematic OSD: 62
Problematic PG: 230.2c
digging deeper..
I checked that when I run the command:
[root@mon-1 ~]# radosgw-admin bilog list --bucket bucket_1
[]
Even when there are no bilogs, there are the same symptoms:
1) In logs:
2020-01-08 16:31:24.728 7f1fa22dd700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency_fn slow operation observed
for upper_bound, latency = 28.653s, after = �0_ omap_iterator(cid =
230.2c_head, oid =
#230:36f53ff9:::.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31:head#)
2) Any other radosgw-admin commands are very slow while other process is
iterating through bilogs (of this bucket).
[dc-2 root@mon-1 ~]# time radosgw-admin bucket stats --bucket=bucket234
...
real 0m25.641s
user 0m0.148s
sys 0m0.075s
When i try to run deep scrub on this pg 230.2c, in logs appears:
[root@mon-1 ~]# ceph pg deep-scrub 230.2c
2020-01-08 16:38:32.551 7f1fc50f0700 1 heartbeat_map is_healthy
'OSD::osd_op_tp thread 0x7f1fa22dd700' had timed out after 15
...
2020-01-08 16:38:46.735 7f1fc60f2700 1 heartbeat_map is_healthy
'OSD::osd_op_tp thread 0x7f1fa62e5700' had timed out after 15
2020-01-08 16:38:46.735 7f1fc60f2700 1 heartbeat_map is_healthy
'OSD::osd_op_tp thread 0x7f1fa22dd700' had timed out after 15
2020-01-08 16:38:46.735 7f1fc60f2700 1 heartbeat_map is_healthy
'OSD::osd_op_tp thread 0x7f1fa62e5700' had timed out after 15
2020-01-08 16:38:46.911 7f1fa22dd700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency_fn slow operation observed
for upper_bound, latency = 29.8655s, after = <80>0_ omap_iterator(cid =
230.2c_head, oid =
#230:36f53ff9:::.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31:head#)
2020-01-08 16:38:46.911 7f1fa22dd700 1 heartbeat_map reset_timeout
'OSD::osd_op_tp thread 0x7f1fa22dd700' had timed out after 15
2020-01-08 16:38:46.911 7f1fa62e5700 1 heartbeat_map reset_timeout
'OSD::osd_op_tp thread 0x7f1fa62e5700' had timed out after 15
2020-01-08 10:37:53.054 7f1fa22dd700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency slow operation observed
for next, latency = 22.4641s
When i try to iterate over listomapkeys for:
.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31
[root@mon-1 ~]# rados -p default.rgw.buckets.index listomapkeys
.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31
In logs i observe:
2020-01-09 11:08:58.847 7f1fa62e5700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency slow operation observed
for next, latency = 24.1949s
The same for listomapvals
[root@mon-1 ~]# rados -p default.rgw.buckets.index listomapvals
.dir.12307ed8-2342-4293-9f14-12234220a234.13221775.224244.31
2020-01-09 11:11:36.508 7f1fa62e5700 0
bluestore(/var/lib/ceph/osd/ceph-62) log_latency slow operation observed
for next, latency = 28.2137s
I tried to purge and recreate this OSD, also I trimmed bilogs for this
bucket (radosgw-admin bilog trim --bucket bucket_1), but this didn't help.
I suspect that any operations on PG: 230.2c on OSD: 62 can causing slow
operations on my cluster.
I have no idea how to debug/resolve this problem. Any help/hint is
appreciated!
Thanks,
Piotr