On Thu, Oct 22, 2015 at 3:58 PM, Andras Pataki <apataki@xxxxxxxxxxxxxxxxxxxx> wrote: > 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? Have you learned anything else about this? Replay should definitely not be taking that long. :( Do I correctly assume you're using CephFS on top of this pool? -Greg _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
 |