|
Hi ceph users,
We’ve upgraded to 0.94.4 (all ceph daemons got restarted) – and are in the middle of doing some rebalancing due to crush changes (removing some disks). During the rebalance, I see that some placement groups get stuck in ‘active+clean+replay’ for a long
time (essentially until I restart the OSD they are on). All IO for these PGs gets queued, and clients hang.
ceph health details the blocked ops in it:
4 ops are blocked > 2097.15 sec
1 ops are blocked > 131.072 sec
2 ops are blocked > 2097.15 sec on osd.41
2 ops are blocked > 2097.15 sec on osd.119
1 ops are blocked > 131.072 sec on osd.124
ceph pg dump | grep replay
dumped all in format plain
2.121b 3836
0 0
0 0
15705994377 3006
3006 active+clean+replay
2015-10-22 14:12:01.104564
123840'2258640
125080:1252265 [41,111]
41 [41,111]
41 114515'2258631
2015-10-20 18:44:09.757620
114515'2258631
2015-10-20 18:44:09.757620
2.b4 3799
0 0
0 0
15604827445 3003
3003 active+clean+replay
2015-10-22 13:57:25.490150
119558'2322127
125084:1174759 [119,75]
119 [119,75]
119 114515'2322124
2015-10-20 11:00:51.448239
114515'2322124
2015-10-17 09:22:14.676006
Both osd.41 and OSD.119 are doing this “replay”.
The end of the log of osd.41:
2015-10-22 10:44:35.727000 7f037929b700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.170:6913/121602 pipe(0x3b4d0000 sd=125 :6827 s=2 pgs=618 cs=1 l=0 c=0x374398c0).fault with nothing to send, going to standby
2015-10-22 10:50:25.954404 7f038adae700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.105:6809/141110 pipe(0x3adff000 sd=229 :6827 s=2 pgs=94 cs=3 l=0 c=0x3e9d0940).fault with nothing to send, going to standby
2015-10-22 12:11:28.029214 7f03a0e0d700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.106:6864/102556 pipe(0x40afe000 sd=621 :6827 s=2 pgs=91 cs=3 l=0 c=0x3acf5860).fault with nothing to send, going to standby
2015-10-22 12:45:45.404765 7f038050d700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.102:6837/77957 pipe(0x39cbe000 sd=578 :6827 s=0 pgs=0 cs=0 l=0 c=0x37b3cec0).accept connect_seq 1 vs existing 1 state standby
2015-10-22 12:45:45.405232 7f038050d700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.102:6837/77957 pipe(0x39cbe000 sd=578 :6827 s=0 pgs=0 cs=0 l=0 c=0x37b3cec0).accept connect_seq 2 vs existing 1 state standby
2015-10-22 12:52:49.062752 7f036525c700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.105:6809/141110 pipe(0x3f637000 sd=405 :6827 s=0 pgs=0 cs=0 l=0 c=0x37b3ba20).accept connect_seq 3 vs existing 3 state standby
2015-10-22 12:52:49.063169 7f036525c700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.105:6809/141110 pipe(0x3f637000 sd=405 :6827 s=0 pgs=0 cs=0 l=0 c=0x37b3ba20).accept connect_seq 4 vs existing 3 state standby
2015-10-22 13:02:16.573546 7f038050d700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.102:6837/77957 pipe(0x39cbe000 sd=578 :6827 s=2 pgs=110 cs=3 l=0 c=0x37b92000).fault with nothing to send, going to standby
2015-10-22 13:07:58.667432 7f036525c700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.105:6809/141110 pipe(0x3f637000 sd=405 :6827 s=2 pgs=146 cs=5 l=0 c=0x3e9d0940).fault with nothing to send, going to standby
2015-10-22 13:25:35.020722 7f038191a700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.111:6841/71447 pipe(0x3e78e000 sd=205 :6827 s=2 pgs=82 cs=3 l=0 c=0x36bf5860).fault with nothing to send, going to standby
2015-10-22 13:45:48.610068 7f0361620700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.105:6841/99063 pipe(0x3e43b000 sd=539 :6827 s=0 pgs=0 cs=0 l=0 c=0x373e11e0).accept we reset (peer sent cseq 1), sending RESETSESSION
2015-10-22 13:45:48.880698 7f0361620700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.105:6841/99063 pipe(0x3e43b000 sd=539 :6827 s=2 pgs=199 cs=1 l=0 c=0x373e11e0).reader missed message? skipped from seq 0 to 825623574
2015-10-22 14:11:32.967937 7f035d9e4700 0 -- 10.4.36.105:6827/98624 >> 10.4.36.105:6802/98037 pipe(0x3ce82000 sd=63 :43711 s=2 pgs=144 cs=3 l=0 c=0x3bf8c100).fault with nothing to send, going to standby
2015-10-22 14:12:35.338635 7f03afffb700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 30.079053 secs
2015-10-22 14:12:35.338875 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 30.079053 seconds old, received at 2015-10-22 14:12:05.259156: osd_op(client.734338.0:50618164 100000b8f73.000003ef [read 0~65536] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:12:35.339050 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 30.063995 seconds old, received at 2015-10-22 14:12:05.274213: osd_op(client.734338.0:50618166 100000b8f73.000003ef [read 65536~131072] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:13:11.817243 7f03afffb700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 66.557970 secs
2015-10-22 14:13:11.817408 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 66.557970 seconds old, received at 2015-10-22 14:12:05.259156: osd_op(client.734338.0:50618164 100000b8f73.000003ef [read 0~65536] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:13:11.817459 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 66.542913 seconds old, received at 2015-10-22 14:12:05.274213: osd_op(client.734338.0:50618166 100000b8f73.000003ef [read 65536~131072] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:14:07.789899 7f03afffb700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 122.530339 secs
2015-10-22 14:14:07.790050 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 122.530339 seconds old, received at 2015-10-22 14:12:05.259156: osd_op(client.734338.0:50618164 100000b8f73.000003ef [read 0~65536] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:14:07.790234 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 122.515282 seconds old, received at 2015-10-22 14:12:05.274213: osd_op(client.734338.0:50618166 100000b8f73.000003ef [read 65536~131072] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:16:08.916570 7f03afffb700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 243.657192 secs
2015-10-22 14:16:08.916766 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 243.657192 seconds old, received at 2015-10-22 14:12:05.259156: osd_op(client.734338.0:50618164 100000b8f73.000003ef [read 0~65536] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:16:08.916789 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 243.642134 seconds old, received at 2015-10-22 14:12:05.274213: osd_op(client.734338.0:50618166 100000b8f73.000003ef [read 65536~131072] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:20:06.142134 7f03afffb700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 480.882700 secs
2015-10-22 14:20:06.142151 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 480.882700 seconds old, received at 2015-10-22 14:12:05.259156: osd_op(client.734338.0:50618164 100000b8f73.000003ef [read 0~65536] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:20:06.142410 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 480.867642 seconds old, received at 2015-10-22 14:12:05.274213: osd_op(client.734338.0:50618166 100000b8f73.000003ef [read 65536~131072] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:28:05.979668 7f03afffb700 0 log_channel(cluster) log [WRN] : 2 slow requests, 2 included below; oldest blocked for > 960.720279 secs
2015-10-22 14:28:05.979684 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 960.720279 seconds old, received at 2015-10-22 14:12:05.259156: osd_op(client.734338.0:50618164 100000b8f73.000003ef [read 0~65536] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
2015-10-22 14:28:05.979720 7f03afffb700 0 log_channel(cluster) log [WRN] : slow request 960.705221 seconds old, received at 2015-10-22 14:12:05.274213: osd_op(client.734338.0:50618166 100000b8f73.000003ef [read 65536~131072] 2.338a921b ack+read+known_if_redirected
e124995) currently waiting for replay end
The process seems to be pretty busy (using about 20% of a CPU core or so) - I.e. Definitely not locked up.
When I restart it, the problem seems to resolve itself. However, the shutdown of the OSD takes a long time (half an hour or more). During this time the osd is spewing megabytes of messages like
2015-10-22 14:40:52.225902 7f03a83cc700 10 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/6d49ead4/10000022ccf.000036f0/head//2 = 0
2015-10-22 14:40:52.225919 7f03a83cc700 15 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/5959ead4/10000147a83.00000807/head//2
2015-10-22 14:40:52.243392 7f03a83cc700 20 filestore(/var/lib/ceph/osd/ceph-41) lfn_unlink: clearing omap on 5959ead4/10000147a83.00000807/head//2 in cid 2.ad4_head
2015-10-22 14:40:52.252792 7f03a83cc700 10 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/5959ead4/10000147a83.00000807/head//2 = 0
2015-10-22 14:40:52.252809 7f03a83cc700 15 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/ff59ead4/10000022e89.0000af9c/head//2
2015-10-22 14:40:52.252897 7f03a83cc700 20 filestore(/var/lib/ceph/osd/ceph-41) lfn_unlink: clearing omap on ff59ead4/10000022e89.0000af9c/head//2 in cid 2.ad4_head
2015-10-22 14:40:52.253132 7f03a83cc700 10 filestore oid: ff59ead4/10000022e89.0000af9c/head//2 not skipping op, *spos 11788505.0.14
2015-10-22 14:40:52.253142 7f03a83cc700 10 filestore > header.spos 0.0.0
2015-10-22 14:40:52.253145 7f03a83cc700 20 filestore remove_map_header: removing 1604853 oid ff59ead4/10000022e89.0000af9c/head//2
2015-10-22 14:40:52.253163 7f03a83cc700 20 filestore clear_header: clearing seq 1604853
2015-10-22 14:40:52.253828 7f03a83cc700 10 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/ff59ead4/10000022e89.0000af9c/head//2 = 0
2015-10-22 14:40:52.253847 7f03a83cc700 15 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/f379ead4/100000b1bc9.00000146/head//2
2015-10-22 14:40:52.253948 7f03a83cc700 20 filestore(/var/lib/ceph/osd/ceph-41) lfn_unlink: clearing omap on f379ead4/100000b1bc9.00000146/head//2 in cid 2.ad4_head
2015-10-22 14:40:52.254195 7f03a83cc700 10 filestore oid: f379ead4/100000b1bc9.00000146/head//2 not skipping op, *spos 11788505.0.15
2015-10-22 14:40:52.254206 7f03a83cc700 10 filestore > header.spos 0.0.0
2015-10-22 14:40:52.254210 7f03a83cc700 20 filestore remove_map_header: removing 1604854 oid f379ead4/100000b1bc9.00000146/head//2
2015-10-22 14:40:52.254229 7f03a83cc700 20 filestore clear_header: clearing seq 1604854
2015-10-22 14:40:52.254953 7f03a83cc700 10 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/f379ead4/100000b1bc9.00000146/head//2 = 0
2015-10-22 14:40:52.254972 7f03a83cc700 15 filestore(/var/lib/ceph/osd/ceph-41) remove 2.ad4_head/7489ead4/10000022af1.00007093/head//2
2015-10-22 14:40:52.255086 7f03a83cc700 20 filestore(/var/lib/ceph/osd/ceph-41) lfn_unlink: clearing omap on 7489ead4/10000022af1.00007093/head//2 in cid 2.ad4_head
2015-10-22 14:40:52.255318 7f03a83cc700 10 filestore oid: 7489ead4/10000022af1.00007093/head//2 not skipping op, *spos 11788505.0.16
Seemingly doing some very large cleanup before shutting down.
Today I’ve had something like a dozen such osd’s out of about a hundred that we have on the cluster. Any ideas what might be going on here? On some of these I’ve waited a few hours, but it doesn’t seem to resolve itself – should I wait more even?
Thanks,
Andras
|
_______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
