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 <pl@xxxxxxx> wrote:
> Am 11.06.21 um 11:48 schrieb Dan van der Ster:
> > On Fri, Jun 11, 2021 at 11:08 AM Peter Lieven <pl@xxxxxxx> wrote:
> >> Am 10.06.21 um 17:45 schrieb Manuel Lausch:
> >> I wonder if I faced the same issue. The issue I had occured when
> >> OSDs came back up and peering started.
> >>
> >> My cluster was a fresh octopus install so I think the min osd
> >> release was set to octopus.
> >>
> >>
> >> Is it in general safe to stay with this switch at nautilus and run
> >> octopus to run a maintained release?
> > I would guess not -- one should follow the upgrade instructions as
> > documented. (I was merely confirming that Manuel had indeed followed
> > that procedure).
> >
> > IMHO this issue, as described by Manuel, is not understood.
> >
> > Manuel could you create a tracker and upload any relevant logs from
> > when the slow requests began?
>
>
> I would be interested if the time is also spent in "waiting for
> readable" state.
>
> To check this I reduced the slow ops timeout to 1 second and then
> fetched the info about the
>
> slow ops from the osd daemons that were affected.
>
> Manuel, can you check this as well?
>
>
> Thanks,
>
> Peter
>
>
>
_______________________________________________
ceph-users mailing list -- ceph-users@xxxxxxx
To unsubscribe send an email to ceph-users-leave@xxxxxxx
