I have a cluster that is performing *very* poorly. It has 12 physical servers and 72 400GB SATA Intel DC mixed-use SSD OSDs (S3700's & S3710's). All servers have bonded 10GB NICs for 20Gbps aggregate networking to a dedicated switch. At least one CPU core and 8GB RAM per OSD. No SMART errors. All SSDs have media wearout indicators >90% remaining. The cluster is Quincy 17.2.6 under cephadm. (It was recently upgraded from Octopus.) Its primary use is serving RBD VM block devices for Proxmox, but it is a standalone cluster. (The RBD bench above was run from one of the mon servers, so Proxmox is not at all involved here.) The rados bench for this is... problematic: gridfury@f13:~$ rados bench -p docker 60 write --no-cleanup hints = 1 Maintaining 16 concurrent writes of 4194304 bytes to objects of size 4194304 for up to 60 seconds or 0 objects Object prefix: benchmark_data_f13_857310 sec Cur ops started finished avg MB/s cur MB/s last lat(s) avg lat(s) 0 0 0 0 0 0 - 0 1 16 220 204 815.924 816 0.0339855 0.0617994 2 16 252 236 471.942 128 0.0360448 0.0584063 3 16 431 415 553.261 716 0.0544013 0.11399 4 16 533 517 516.93 408 0.0536192 0.103342 5 16 553 537 429.541 80 0.0465437 0.120551 6 16 675 659 439.271 488 0.0390309 0.13919 7 16 704 688 393.087 116 0.0344105 0.134758 8 16 935 919 459.433 924 0.0443338 0.138301 9 16 1167 1151 511.48 928 0.0407041 0.124401 10 16 1219 1203 481.129 208 0.0408885 0.121026 11 16 1219 1203 437.389 0 - 0.121026 12 16 1333 1317 438.934 228 0.0436965 0.141108 13 16 1333 1317 405.169 0 - 0.141108 14 16 1333 1317 376.228 0 - 0.141108 15 16 1333 1317 351.146 0 - 0.141108 16 16 1333 1317 329.199 0 - 0.141108 17 16 1383 1367 321.597 40 0.0738412 0.198283 18 16 1621 1605 356.612 952 0.0396665 0.179042 19 16 1880 1864 392.361 1036 0.0349097 0.162829 2023-08-14T01:27:04.758111+0000 min lat: 0.0238844 max lat: 5.29731 avg lat: 0.152446 sec Cur ops started finished avg MB/s cur MB/s last lat(s) avg lat(s) 20 16 2111 2095 418.936 924 0.0581478 0.152446 21 16 2352 2336 444.881 964 0.0639009 0.143467 22 16 2592 2576 468.288 960 0.0921614 0.136478 23 16 2828 2812 488.965 944 0.0587983 0.130606 24 16 3050 3034 505.586 888 0.106586 0.126353 25 16 3167 3151 504.08 468 0.0606541 0.126778 26 16 3408 3392 521.763 964 0.0356258 0.12252 27 16 3644 3628 537.395 944 0.045652 0.118972 28 16 3844 3828 546.769 800 0.0328637 0.116728 29 16 3870 3854 531.501 104 0.0418716 0.11621 30 16 3870 3854 513.784 0 - 0.11621 31 16 3870 3854 497.21 0 - 0.11621 32 16 3870 3854 481.673 0 - 0.11621 33 16 3870 3854 467.076 0 - 0.11621 34 16 3870 3854 453.339 0 - 0.11621 35 16 3870 3854 440.386 0 - 0.11621 36 16 3870 3854 428.152 0 - 0.11621 37 16 3870 3854 416.581 0 - 0.11621 38 16 3870 3854 405.618 0 - 0.11621 39 16 3870 3854 395.218 0 - 0.11621 2023-08-14T01:27:24.761559+0000 min lat: 0.0238844 max lat: 5.29731 avg lat: 0.11621 sec Cur ops started finished avg MB/s cur MB/s last lat(s) avg lat(s) 40 16 3870 3854 385.337 0 - 0.11621 41 16 3870 3854 375.938 0 - 0.11621 42 16 3870 3854 366.987 0 - 0.11621 43 16 3870 3854 358.452 0 - 0.11621 44 16 3870 3854 350.306 0 - 0.11621 45 16 3870 3854 342.521 0 - 0.11621 46 16 3870 3854 335.075 0 - 0.11621 47 16 3870 3854 327.946 0 - 0.11621 48 16 3870 3854 321.114 0 - 0.11621 49 16 3870 3854 314.56 0 - 0.11621 50 16 3870 3854 308.269 0 - 0.11621 51 16 3870 3854 302.224 0 - 0.11621 52 16 3870 3854 296.412 0 - 0.11621 53 16 3870 3854 290.82 0 - 0.11621 54 16 3870 3854 285.434 0 - 0.11621 55 16 3870 3854 280.244 0 - 0.11621 56 16 3870 3854 275.24 0 - 0.11621 57 16 3870 3854 270.411 0 - 0.11621 58 16 3870 3854 265.749 0 - 0.11621 59 16 3870 3854 261.245 0 - 0.11621 2023-08-14T01:27:44.765065+0000 min lat: 0.0238844 max lat: 5.29731 avg lat: 0.11621 sec Cur ops started finished avg MB/s cur MB/s last lat(s) avg lat(s) 60 16 3870 3854 256.89 0 - 0.11621 61 16 3870 3854 252.679 0 - 0.11621 62 16 3870 3854 248.603 0 - 0.11621 63 16 3870 3854 244.657 0 - 0.11621 64 16 3870 3854 240.835 0 - 0.11621 65 16 3870 3854 237.129 0 - 0.11621 Total time run: 65.6256 Total writes made: 3870 Write size: 4194304 Object size: 4194304 Bandwidth (MB/sec): 235.884 Stddev Bandwidth: 375.227 Max bandwidth (MB/sec): 1036 Min bandwidth (MB/sec): 0 Average IOPS: 58 Stddev IOPS: 93.8068 Max IOPS: 259 Min IOPS: 0 Average Latency(s): 0.271253 Stddev Latency(s): 2.43809 Max latency(s): 37.7948 Min latency(s): 0.0238844 58 IOPs average is... less than I might hope for from this hardware. But those long strings of 0's... I feel like 0 IOPS is inarguably too low. At the time I ran this, I had ceph status running and saw +laggy pgs and actually caught a message: 36 slow ops, oldest one blocked for 37 sec, daemons [osd.10,osd.12,osd.13,osd.14,osd.15,osd.17,osd.2,osd.25,osd.28,osd.3]... So I checked a few osd logs; there is nothing during the test, but several have stuff immediately after like this: Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[2.591( v 110828'143791701 (110828'143791003,110828'143791701] local-lis/les=107797/107798 n=826 ec=1/1 lis/c=107797/107797 les/c/f=107798/107798/43927 sis=110829) [2] r=0 lpr=110829 pi=[10779 7,110829)/1 luod=0'0 lua=107760'143777660 crt=110828'143791701 lcod 110828'143791700 mlcod 0'0 active mbc={}] start_peering_interval up [48,2] -> [2], acting [48,2] -> [2], acting_primary 48 -> 2, up_primary 48 -> 2, role 1 -> 0, features acting 454013832 0759226367 upacting 4540138320759226367 Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[2.591( v 110828'143791701 (110828'143791003,110828'143791701] local-lis/les=107797/107798 n=826 ec=1/1 lis/c=107797/107797 les/c/f=107798/107798/43927 sis=110829) [2] r=0 lpr=110829 pi=[10779 7,110829)/1 crt=110828'143791701 lcod 110828'143791700 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[5.b( v 98878'16 (0'0,98878'16] local-lis/les=107797/107798 n=4 ec=98376/98376 lis/c=107797/107797 les/c/f=107798/107798/0 sis=110829) [2,14] r=0 lpr=110829 pi=[107797,110829)/1 crt=98878'16 l cod 0'0 mlcod 0'0 active mbc={}] start_peering_interval up [2,48,14] -> [2,14], acting [2,48,14] -> [2,14], acting_primary 2 -> 2, up_primary 2 -> 2, role 0 -> 0, features acting 4540138320759226367 upacting 4540138320759226367 Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[5.b( v 98878'16 (0'0,98878'16] local-lis/les=107797/107798 n=4 ec=98376/98376 lis/c=107797/107797 les/c/f=107798/107798/0 sis=110829) [2,14] r=0 lpr=110829 pi=[107797,110829)/1 crt=98878'16 l cod 0'0 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[2.30c( v 110828'58472450 (107939'58468576,110828'58472450] local-lis/les=107797/107798 n=840 ec=1/1 lis/c=107797/107797 les/c/f=107798/107800/43927 sis=110829) [2] r=0 lpr=110829 pi=[107797,1 10829)/1 luod=110828'58472444 crt=110828'58472450 lcod 110828'58472443 mlcod 110828'58472443 active mbc={255={}}] start_peering_interval up [2,48] -> [2], acting [2,48] -> [2], acting_primary 2 -> 2, up_primary 2 -> 2, role 0 -> 0, features acting 4540138 320759226367 upacting 4540138320759226367 Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[2.326( v 110828'84969926 (110432'84966024,110828'84969926] local-lis/les=107797/107798 n=831 ec=1/1 lis/c=107797/107797 les/c/f=107798/107798/43927 sis=110829) [2] r=0 lpr=110829 pi=[107797,1 10829)/1 luod=110828'84969917 crt=110828'84969926 lcod 110828'84969916 mlcod 110828'84969916 active mbc={255={}}] start_peering_interval up [2,48] -> [2], acting [2,48] -> [2], acting_primary 2 -> 2, up_primary 2 -> 2, role 0 -> 0, features acting 4540138 320759226367 upacting 4540138320759226367 Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[2.30c( v 110828'58472450 (107939'58468576,110828'58472450] local-lis/les=107797/107798 n=840 ec=1/1 lis/c=107797/107797 les/c/f=107798/107800/43927 sis=110829) [2] r=0 lpr=110829 pi=[107797,1 10829)/1 crt=110828'58472450 lcod 110828'58472443 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary Aug 14 01:27:49 f13 ceph-osd[651856]: osd.2 pg_epoch: 110829 pg[2.326( v 110828'84969926 (110432'84966024,110828'84969926] local-lis/les=107797/107798 n=831 ec=1/1 lis/c=107797/107797 les/c/f=107798/107798/43927 sis=110829) [2] r=0 lpr=110829 pi=[107797,1 10829)/1 crt=110828'84969926 lcod 110828'84969916 mlcod 0'0 unknown mbc={}] state<Start>: transitioning to Primary Aug 14 01:27:57 f13 ceph-osd[651856]: --2- [v2:192.168.2.213:6804/3119259815,v1:192.168.2.213:6805/3119259815] >> [v2:192.168.2.225:6808/1596776081,v1:192.168.2.225:6809/1596776081] conn(0x55c3dc924400 0x55c3b8555b80 crc :-1 s=SESSION_ACCEPTING pgs=167 cs =0 l=0 rev1=1 crypto rx=0 tx=0 comp rx=0 tx=0).handle_reconnect no existing connection exists, reseting client Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[2.591( v 110828'143791701 (110828'143791003,110828'143791701] local-lis/les=110829/110830 n=826 ec=1/1 lis/c=110829/107797 les/c/f=110830/107798/43927 sis=110833 pruub=15.513665199s) [48,2] r =1 lpr=110833 pi=[107797,110833)/1 crt=110828'143791701 lcod 110828'143791700 mlcod 0'0 active pruub 22348.017578125s@ mbc={}] start_peering_interval up [2] -> [48,2], acting [2] -> [48,2], acting_primary 2 -> 48, up_primary 2 -> 48, role 0 -> 1, features acting 4540138320759226367 upacting 4540138320759226367 Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[2.591( v 110828'143791701 (110828'143791003,110828'143791701] local-lis/les=110829/110830 n=826 ec=1/1 lis/c=110829/107797 les/c/f=110830/107798/43927 sis=110833 pruub=15.513574600s) [48,2] r =1 lpr=110833 pi=[107797,110833)/1 crt=110828'143791701 lcod 110828'143791700 mlcod 0'0 unknown NOTIFY pruub 22348.017578125s@ mbc={}] state<Start>: transitioning to Stray Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[5.b( v 98878'16 (0'0,98878'16] local-lis/les=110829/110830 n=4 ec=98376/98376 lis/c=110829/107797 les/c/f=110830/107798/0 sis=110833 pruub=15.519681931s) [2,48,14] r=0 lpr=110833 pi=[107797,1 10833)/1 crt=98878'16 lcod 0'0 mlcod 0'0 active pruub 22348.023437500s@ mbc={}] start_peering_interval up [2,14] -> [2,48,14], acting [2,14] -> [2,48,14], acting_primary 2 -> 2, up_primary 2 -> 2, role 0 -> 0, features acting 4540138320759226367 upacting 4540138320759226367 Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[5.b( v 98878'16 (0'0,98878'16] local-lis/les=110829/110830 n=4 ec=98376/98376 lis/c=110829/107797 les/c/f=110830/107798/0 sis=110833 pruub=15.519681931s) [2,48,14] r=0 lpr=110833 pi=[107797,1 10833)/1 crt=98878'16 lcod 0'0 mlcod 0'0 unknown pruub 22348.023437500s@ mbc={}] state<Start>: transitioning to Primary Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[2.326( v 110828'84969926 (110432'84966024,110828'84969926] local-lis/les=110829/110830 n=831 ec=1/1 lis/c=110829/107797 les/c/f=110830/107798/43927 sis=110833 pruub=15.512885094s) [2,48] r=0 lpr=110833 pi=[107797,110833)/1 crt=110828'84969926 lcod 110828'84969916 mlcod 0'0 active pruub 22348.017578125s@ mbc={}] start_peering_interval up [2] -> [2,48], acting [2] -> [2,48], acting_primary 2 -> 2, up_primary 2 -> 2, role 0 -> 0, features acting 4540138320759226367 upacting 4540138320759226367 Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[2.326( v 110828'84969926 (110432'84966024,110828'84969926] local-lis/les=110829/110830 n=831 ec=1/1 lis/c=110829/107797 les/c/f=110830/107798/43927 sis=110833 pruub=15.512885094s) [2,48] r=0 lpr=110833 pi=[107797,110833)/1 crt=110828'84969926 lcod 110828'84969916 mlcod 0'0 unknown pruub 22348.017578125s@ mbc={}] state<Start>: transitioning to Primary Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[2.30c( v 110828'58472450 (107939'58468576,110828'58472450] local-lis/les=110829/110830 n=840 ec=1/1 lis/c=110829/107797 les/c/f=110830/107800/43927 sis=110833 pruub=15.512117386s) [2,48] r=0 lpr=110833 pi=[107797,110833)/1 crt=110828'58472450 lcod 110828'58472443 mlcod 0'0 active pruub 22348.017578125s@ mbc={}] start_peering_interval up [2] -> [2,48], acting [2] -> [2,48], acting_primary 2 -> 2, up_primary 2 -> 2, role 0 -> 0, features acting 4540138320759226367 upacting 4540138320759226367 Aug 14 01:27:58 f13 ceph-osd[651856]: osd.2 pg_epoch: 110833 pg[2.30c( v 110828'58472450 (107939'58468576,110828'58472450] local-lis/les=110829/110830 n=840 ec=1/1 lis/c=110829/107797 les/c/f=110830/107800/43927 sis=110833 pruub=15.512117386s) [2,48] r=0 lpr=110833 pi=[107797,110833)/1 crt=110828'58472450 lcod 110828'58472443 mlcod 0'0 unknown pruub 22348.017578125s@ mbc={}] state<Start>: transitioning to Primary I also captured iostat -x 5 from several of the OSDs during the test, including one of the ones identified as having blocked IO. It shows 3-15% utilized with 30-200 IOPS (mostly write). r_await average 0.22, w_await average 0.46. Nothing in dmesg or syslog. Is there anything to be done to further investigate or remediate this? This cluster is pretty old and I'm starting to think we should just scrap it as hopeless. But that's a lot of hardware to write off if there's any possible way to fix this. Thanks for any advice!