[ceph-users] Re: slow ops at restarting OSDs (octopus)

Hi, yeah. I wasn't aware, that I have set "osd op complaint time" to 5 seconds. AFAIK the default is 32. So I get slow ops already after 5 instead of 32 seconds. Thats why I think no one before have noticed this before. My application which uses the cluster will throw timeouts after 6 seconds, thats why we set this down. For clarification, with Nautilus, restarting OSDs worked just fine. The problems started while upgradeing to Ocotopus. Here is some OSD debug output from one OSD while stopping some other. (debug_osd 10/10, grepped for laggy and waiting) # cat /var/log/ceph/ceph-osd.313.log | egrep '(laggy|waiting)' 2021-06-15T16:13:51.605+0200 7fa825434700 10 osd.313 pg_epoch: 43919 pg[2.47b6( v 43901'122473 (39559'119595,43901'122473] local-lis/les=43918/43919 n=15195 ec=34033/13925 lis/c=43335/43335 les/c/f=43336/43336/0 sis=43918 pruub=12.087973374s) [313,761,693] r=0 lpr=43918 pi=[43335,43918)/1 crt=43901'122473 lcod 43894'122471 mlcod 0'0 active+undersized+degraded pruub 4840.521138536s@395 mbc={} trimq=[a4~1] ps=[a2~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4840.521138536s > mnow 4828.443041141s 2021-06-15T16:13:51.620+0200 7fa824c33700 10 osd.313 pg_epoch: 43919 pg[2.1aee( v 43913'115951 (39517'112986,43913'115951] local-lis/les=43918/43919 n=15215 ec=13938/13925 lis/c=43243/43243 les/c/f=43244/43244/0 sis=43918 pruub=11.520263431s) [313,671,763] r=0 lpr=43918 pi=[43243,43918)/1 crt=43913'115951 lcod 43911'115949 mlcod 0'0 active+undersized+degraded pruub 4839.953296047s@367 mbc={} trimq=[a4~1] ps=[a2~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4839.953296047s > mnow 4828.458182468s 2021-06-15T16:13:51.621+0200 7fa825434700 10 osd.313 pg_epoch: 43919 pg[2.5aee( v 43850'116365 (39537'113382,43850'116365] local-lis/les=43918/43919 n=14880 ec=35934/13925 lis/c=43243/43243 les/c/f=43244/43244/0 sis=43918 pruub=11.676727555s) [313,671,763] r=0 lpr=43918 pi=[43243,43918)/1 crt=43850'116365 lcod 43850'116363 mlcod 0'0 active+undersized+degraded pruub 4840.106063793s@367 mbc={} ps=[a2~1,a4~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4840.106063793s > mnow 4828.459634014s 2021-06-15T16:13:51.626+0200 7fa825434700 10 osd.313 pg_epoch: 43919 pg[2.39dd( v 43915'116280 (39489'113285,43915'116280] local-lis/les=43918/43919 n=14951 ec=13954/13925 lis/c=43331/43331 les/c/f=43332/43332/0 sis=43918 pruub=7.720345059s) [313,1107,657] r=0 lpr=43918 pi=[43331,43918)/1 crt=43915'116280 lcod 43875'116278 mlcod 0'0 active+undersized+degraded pruub 4836.150186323s@419 mbc={} ps=[a2~1,a4~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4836.150186323s > mnow 4828.463817104s 2021-06-15T16:13:51.626+0200 7fa825c35700 10 osd.313 pg_epoch: 43919 pg[2.79dd( v 43911'116563 (39565'113592,43911'116563] local-lis/les=43918/43919 n=15008 ec=35977/13925 lis/c=43331/43331 les/c/f=43332/43332/0 sis=43918 pruub=7.874664992s) [313,1107,657] r=0 lpr=43918 pi=[43331,43918)/1 crt=43911'116563 lcod 43901'116562 mlcod 0'0 active+undersized+degraded pruub 4836.305711908s@419 mbc={} ps=[a2~1,a4~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4836.305711908s > mnow 4828.464542182s 2021-06-15T16:13:51.627+0200 7fa825c35700 10 osd.313 pg_epoch: 43919 pg[2.79dd( v 43911'116563 (39565'113592,43911'116563] local-lis/les=43918/43919 n=15008 ec=35977/13925 lis/c=43918/43331 les/c/f=43919/43332/0 sis=43918 pruub=7.840968898s) [313,1107,657] r=0 lpr=43918 pi=[43331,43918)/1 crt=43911'116563 lcod 43901'116562 mlcod 0'0 active+undersized+degraded+wait pruub 4836.305711908s@419 mbc={} ps=[a2~1,a4~1]] check_laggy PG is WAIT state 2021-06-15T16:13:51.627+0200 7fa825c35700 10 osd.313 pg_epoch: 43919 pg[2.79dd( v 43911'116563 (39565'113592,43911'116563] local-lis/les=43918/43919 n=15008 ec=35977/13925 lis/c=43918/43331 les/c/f=43919/43332/0 sis=43918 pruub=7.840968898s) [313,1107,657] r=0 lpr=43918 pi=[43331,43918)/1 crt=43911'116563 lcod 43901'116562 mlcod 0'0 active+undersized+degraded+wait pruub 4836.305711908s@419 mbc={} ps=[a2~1,a4~1]] check_laggy not readable 2021-06-15T16:13:51.632+0200 7fa824c33700 10 osd.313 pg_epoch: 43919 pg[2.7b6( v 43915'120583 (39610'117714,43915'120583] local-lis/les=43918/43919 n=15292 ec=13928/13925 lis/c=43285/43285 les/c/f=43286/43286/0 sis=43918 pruub=11.740174435s) [313,761,686] r=0 lpr=43918 pi=[43285,43918)/1 crt=43915'120583 lcod 43911'120581 mlcod 0'0 active+undersized+degraded pruub 4840.170557038s@395 mbc={} trimq=[a4~1] ps=[a2~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4840.170557038s > mnow 4828.470484105s 2021-06-15T16:13:51.638+0200 7fa825434700 10 osd.313 pg_epoch: 43919 pg[2.1a61( v 43901'117636 (39730'114897,43901'117636] local-lis/les=43918/43919 n=15068 ec=13938/13925 lis/c=43356/43356 les/c/f=43357/43357/0 sis=43918 pruub=12.126607104s) [313,1116,951] r=0 lpr=43918 pi=[43356,43918)/1 crt=43901'117636 lcod 43881'117635 mlcod 0'0 active+undersized+degraded pruub 4840.556990188s@269 mbc={} trimq=[a4~1] ps=[a2~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4840.556990188s > mnow 4828.476309716s 2021-06-15T16:13:51.638+0200 7fa825c35700 10 osd.313 pg_epoch: 43919 pg[2.5a61( v 43911'114881 (39797'112139,43911'114881] local-lis/les=43918/43919 n=15046 ec=35934/13925 lis/c=43356/43356 les/c/f=43357/43357/0 sis=43918 pruub=11.819966361s) [313,1116,951] r=0 lpr=43918 pi=[43356,43918)/1 crt=43911'114881 lcod 43911'114879 mlcod 0'0 active+undersized+degraded pruub 4840.250617987s@269 mbc={} ps=[a2~1,a4~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4840.250617987s > mnow 4828.476475169s 2021-06-15T16:13:51.646+0200 7fa826c37700 10 osd.313 pg_epoch: 43919 pg[2.7dfa( v 43894'121976 (39366'119005,43894'121976] local-lis/les=43918/43919 n=15008 ec=35982/13925 lis/c=43227/43227 les/c/f=43228/43228/0 sis=43918 pruub=10.205329712s) [313,868,699] r=0 lpr=43918 pi=[43227,43918)/1 crt=43894'121976 lcod 43894'121974 mlcod 0'0 active+undersized+degraded pruub 4838.635614602s@367 mbc={} ps=[a2~1,a4~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4838.635614602s > mnow 4828.484055710s 2021-06-15T16:13:51.648+0200 7fa826436700 10 osd.313 pg_epoch: 43919 pg[2.3dfa( v 43915'121818 (39519'118828,43915'121818] local-lis/les=43918/43919 n=15079 ec=13956/13925 lis/c=43227/43227 les/c/f=43228/43228/0 sis=43918 pruub=10.158707684s) [313,868,699] r=0 lpr=43918 pi=[43227,43918)/1 crt=43915'121818 lcod 43894'121816 mlcod 0'0 active+undersized+degraded pruub 4838.588209355s@367 mbc={} trimq=[a4~1] ps=[a2~1]] state<Started/Primary/Active>: waiting for prior_readable_until_ub 4838.588209355s > mnow 4828.486504603s 2021-06-15T16:14:02.617+0200 7fa825434700 10 osd.313 pg_epoch: 43919 pg[2.1a61( v 43901'117636 (39730'114897,43901'117636] local-lis/les=43918/43919 n=15068 ec=13938/13925 lis/c=43918/43356 les/c/f=43919/43357/0 sis=43918 pruub=12.080355303s) [313,1116,951] r=0 lpr=43918 pi=[43356,43918)/1 crt=43901'117636 lcod 43881'117635 mlcod 0'0 active+undersized+degraded+wait pruub 4840.556990188s@269 mbc={} trimq=[a4~1] ps=[a2~1]] check_laggy PG is WAIT state 2021-06-15T16:14:02.618+0200 7fa825434700 10 osd.313 pg_epoch: 43919 pg[2.1a61( v 43901'117636 (39730'114897,43901'117636] local-lis/les=43918/43919 n=15068 ec=13938/13925 lis/c=43918/43356 les/c/f=43919/43357/0 sis=43918 pruub=12.080355303s) [313,1116,951] r=0 lpr=43918 pi=[43356,43918)/1 crt=43901'117636 lcod 43881'117635 mlcod 0'0 active+undersized+degraded+wait pruub 4840.556990188s@269 mbc={} trimq=[a4~1] ps=[a2~1]] check_laggy not readable On Fri, 11 Jun 2021 12:11:24 +0200 Peter Lieven &lt;pl(a)kamp.de&gt; wrote: