Hi, I believe I've stumbled on a bug in Ceph, and I'm currently trying to figure out if this is a new bug, some behaviour caused by our cluster being in the midst of a hammer(0.94.6)->jewel(10.2.2) upgrade, or other factors. The state of the cluster at the time of the incident: - All monitor nodes are running 10.2.2. - One OSD-server (4 osds) is up with 10.2.2 and with all pg's in active+clean. - One OSD-server (4 osds) is up with 10.2.2 and undergoing backfills (however: nobackfill was set, as we try to keep backfills running during night time). We have 4 OSD-servers with 4 osds each with 0.94.6. We have 3 OSD-servers with 2 osds each with 0.94.6. We experienced something that heavily affected our RGW-users. Some requests interfacing with 0.94.6 nodes were slow. During a 10 minute window, our RGW-nodes ran out of available workers and ceased to respond. Some nodes logged some lines like these (only 0.94.6 nodes): 2016-06-21 09:51:08.053886 7f54610d8700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 74.368036 secs 2016-06-21 09:51:08.053951 7f54610d8700 0 log_channel(cluster) log [WRN] : slow request 30.056333 seconds old, received at 2016-06-21 09:50:37.997327: osd_op(client.9433496.0:1089298249 somergwuser.buckets [call user.set_buckets_info] 12.da8df901 ondisk+write+known_if_redirected e9906) currently waiting for rw locks Some nodes logged some lines like these (there were some, but not 100% overlap between osds that logged these and the beforementioned lines - only 0.94.6 nodes): 2016-06-21 09:51:48.677474 7f8cb6628700 0 log_channel(cluster) log [WRN] : 2 slow requests, 1 included below; oldest blocked for > 42.033650 secs 2016-06-21 09:51:48.677565 7f8cb6628700 0 log_channel(cluster) log [WRN] : slow request 30.371173 seconds old, received at 2016-06-21 09:51:18.305770: osd_op(client.9525441.0:764274789 gc.1164 [call lock.lock] 7.7b4f1779 ondisk+write+known_if_redirected e9906) currently waiting for subops from 40,50 All of the osds that logged these lines, were waiting for subops from osd.50 Investigating what's going on this osd during that window: 2016-06-21 09:48:22.064630 7f1cbb41d700 0 log_channel(cluster) log [INF] : 5.b5 deep-scrub starts 2016-06-21 09:59:56.640012 7f1c90163700 0 -- 10.21.9.22:6800/2003521 >> 10.20.9.21:6805/7755 pipe(0x1e47a000 sd=298 :39448 s=2 pgs=23 cs=1 l=0 c=0x1033ba20).fault with nothing to send, going to standby 2016-06-21 09:59:56.997763 7f1c700f8700 0 -- 10.21.9.22:6808/3521 >> 10.21.9.12:0/1028533 pipe(0x1f30f000 sd=87 :6808 s=0 pgs=0 cs=0 l=1 c=0x743c840).accept replacing existing (lossy) channel (new one lossy=1) 2016-06-21 10:00:39.938700 7f1cd9828700 0 log_channel(cluster) log [WRN] : 33 slow requests, 33 included below; oldest blocked for > 727.862759 secs 2016-06-21 10:00:39.938708 7f1cd9828700 0 log_channel(cluster) log [WRN] : slow request 670.918857 seconds old, received at 2016-06-21 09:49:29.019653: osd_op(client.9403437.0:1209613500 TZ1A91MYDE1LO63AQCM3 [getxattrs,stat] 9.442585e6 ack+read+known_if_redirected e9906) currently no flag points reached 2016-06-21 10:00:39.938800 7f1cd9828700 0 log_channel(cluster) log [WRN] : slow request 689.815851 seconds old, received at 2016-06-21 09:49:10.122660: osd_op(client.9403437.0:1209611533 TZ1A91MYDE1LO63AQCM3 [getxattrs,stat] 9.442585e6 ack+read+known_if_redirected e9906) currently no flag points reached 2016-06-21 10:00:39.938807 7f1cd9828700 0 log_channel(cluster) log [WRN] : slow request 670.895353 seconds old, received at 2016-06-21 09:49:29.043158: osd_op(client.9403437.0:1209613505 prod.arkham [call version.read,getxattrs,stat] 2.4da23de6 ack+read+known_if_redirected e9906) currently no flag points reached 2016-06-21 10:00:39.938810 7f1cd9828700 0 log_channel(cluster) log [WRN] : slow request 688.612303 seconds old, received at 2016-06-21 09:49:11.326207: osd_op(client.20712623.0:137251515 TZ1A91MYDE1LO63AQCM3 [getxattrs,stat] 9.442585e6 ack+read+known_if_redirected e9906) currently no flag points reached 2016-06-21 10:00:39.938813 7f1cd9828700 0 log_channel(cluster) log [WRN] : slow request 658.605163 seconds old, received at 2016-06-21 09:49:41.333348: osd_op(client.20712623.0:137254412 TZ1A91MYDE1LO63AQCM3 [getxattrs,stat] 9.442585e6 ack+read+known_if_redirected e9906) currently no flag points reached 2016-06-21 10:00:39.960300 7f1cbb41d700 0 log_channel(cluster) log [INF] : 5.b5 deep-scrub ok Looking at the contents of 5.b5 (which is in our .rgw.buckets.index pool, if relevant) and it's almost empty (12KB of files on the disk) I find it unlikely for a scrubbing to take that long. Which is why I suspect we've ran into a bug. With the information I've provided here, can anyone shed some light on what this may be, and if it's a bug that is not fixed in HEAD; What information would be useful to include in a bug report? Regards -- Trygve Vea _______________________________________________ ceph-users mailing list ceph-users@xxxxxxxxxxxxxx http://lists.ceph.com/listinfo.cgi/ceph-users-ceph.com
 |