Ceph

Dan van der Ster wrote:

I also noticed that before the snap trimmer starts, purge_snaps is [] for 5.318. Is that normal, or should (the complete) purge_snaps normally be copied along to the new OSD? Certainly if it had been, the small incremental (if at all) trim would have completed very quickly. If on the contrary the missed purged_snaps update is only happening rarely, then that might explain why we don't see these slow requests after every backfill of a pool 5 PG completes.

I think this is exactly the problem... purged_snaps shouldn't start out empty. That's why it is uselessing scanning for all 7000 deleted snaps.

Trying to reproduce this ....

wip-9487
wip-9487-dumpling for backport

I had some comments on that pull request.

Hi Sage and Sam,
I've just tried wip-9113-9487-dumpling on our test cluster. (Using this build: http://gitbuilder.ceph.com/ceph-rpm-centos6_5-x86_64-basic/ref/wip-9113-9487-dumpling/x86_64/)

osd.76: running {"version":"0.67.11-4-g496e561"}

This commit:

ReplicatedPG: don't move on to the next snap immediately

seems to work. I see a sleep between each trim operation now.

But this fix:

osd: initialize purged_snap on backfill start; restart backfill if change

doesn't seem to work here. I still see

2014-11-04 11:11:50.037102 7f84cc75f700  5 osd.76 pg_epoch: 18200 pg[35.0( empty local-les=0 n=0 ec=18036 les/c 18151/18151 18188/18188/18188) [76,71,298] r=0 lpr=18188 pi=18148-18187/2 mlcod 0'0 inactive] enter Star
ted/Primary/Active
2014-11-04 11:11:50.037123 7f84cc75f700 10 osd.76 pg_epoch: 18200 pg[35.0( empty local-les=0 n=0 ec=18036 les/c 18151/18151 18188/18188/18188) [76,71,298] r=0 lpr=18188 pi=18148-18187/2 mlcod 0'0 inactive] state<Star
ted/Primary/Active>: In Active, about to call activate
2014-11-04 11:11:50.037138 7f84cc75f700 10 osd.76 pg_epoch: 18200 pg[35.0( empty local-les=18200 n=0 ec=18036 les/c 18151/18151 18188/18188/18188) [76,71,298] r=0 lpr=18188 pi=18148-18187/2 mlcod 0'0 active] check_lo
cal
2014-11-04 11:11:50.037152 7f84cc75f700 10 osd.76 pg_epoch: 18200 pg[35.0( empty local-les=18200 n=0 ec=18036 les/c 18151/18151 18188/18188/18188) [76,71,298] r=0 lpr=18188 pi=18148-18187/2 mlcod 0'0 active snaptrimq=[1~6e]] activate - snap_trimq [1~6e]

...

2014-11-04 11:11:50.037152 7f84cc75f700 10 osd.76 pg_epoch: 18200 pg[35.0( empty local-les=18200 n=0 ec=18036 les/c 18151/18151 18188/18188/18188) [76,71,298] r=0 lpr=18188 pi=18148-18187/2 mlcod 0'0 active snaptrimq=[1~6e]] activate - snap_trimq [1~6e]
2014-11-04 11:12:01.181457 7f84c955a700 10 osd.76 pg_epoch: 18206 pg[35.0( empty local-les=18200 n=0 ec=18036 les/c 18200/18206 18188/18188/18188) [76,71,298] r=0 lpr=18188 mlcod 0'0 active+clean snaptrimq=[2~6d]] SnapTrimmer state<Trimming/WaitingOnReplicas>: purged_snaps now [1~1], snap_trimq now [2~6d]
2014-11-04 11:12:01.370462 7f84c955a700 10 osd.76 pg_epoch: 18206 pg[35.0( empty local-les=18200 n=0 ec=18036 les/c 18200/18206 18188/18188/18188) [76,71,298] r=0 lpr=18188 mlcod 0'0 active+clean snaptrimq=[3~6c]] SnapTrimmer state<Trimming/WaitingOnReplicas>: purged_snaps now [1~2], snap_trimq now [3~6c]
2014-11-04 11:12:01.508636 7f84c955a700 10 osd.76 pg_epoch: 18206 pg[35.0( empty local-les=18200 n=0 ec=18036 les/c 18200/18206 18188/18188/18188) [76,71,298] r=0 lpr=18188 mlcod 0'0 active+clean snaptrimq=[4~6b]] SnapTrimmer state<Trimming/WaitingOnReplicas>: purged_snaps now [1~3], snap_trimq now [4~6b]
...

A full log is attached (of OSD 76, who is getting PG 35.0 which has a few trimmed snaps inside).

(This is strange because the older branch wip-9487-dumpling does fix the purged_snaps initialization problem -- we're still running that branch elsewhere -- and the relevant commit hasn't changed much since then).

Well the PG isn't empty -- I've been writing a bunch of data to it using rados bench. Basically, I'm having trouble getting a new test pool to enter backfilling at all. But maybe thats a different issue.

Anyway, I have other older pools that are entering backfilling and have a few purged_snaps. But alas I still have re-trimming of already purged snaps with 0.67.11-4-g496e561. I've attached a log for osd.90 -- PG's 3.2e7 and 3.7e are affected, e.g.

2014-11-17 11:54:38.981159 7f0cc119e700 10 osd.90 pg_epoch: 19542 pg[3.2e7( v 19531'36796 (18972'33790,19531'36796] local-les=19542 n=0 ec=256 les/c 19542/19542 19522/19541/19532) [90,7,99] r=0 lpr=19541 lcod 19531'36795 mlcod 0'0 active+clean snaptrimq=[1~14]] SnapTrimmer state<Trimming/WaitingOnReplicas>: WaitingOnReplicas: adding snap 1 to purged_snaps
2014-11-17 11:54:38.981177 7f0cc119e700 10 osd.90 pg_epoch: 19542 pg[3.2e7( v 19531'36796 (18972'33790,19531'36796] local-les=19542 n=0 ec=256 les/c 19542/19542 19522/19541/19532) [90,7,99] r=0 lpr=19541 lcod 19531'36795 mlcod 0'0 active+clean snaptrimq=[2~13]] SnapTrimmer state<Trimming/WaitingOnReplicas>: purged_snaps now [1~1], snap_trimq now [2~13]
2014-11-17 11:54:39.084524 7f0cc079d700 10 osd.90 pg_epoch: 19542 pg[3.2e7( v 19531'36796 (18972'33790,19531'36796] local-les=19542 n=0 ec=256 les/c 19542/19542 19522/19541/19532) [90,7,99] r=0 lpr=19541 lcod 19531'36795 mlcod 0'0 active+clean snaptrimq=[2~13]] SnapTrimmer state<Trimming/WaitingOnReplicas>: WaitingOnReplicas: adding snap 2 to purged_snaps
2014-11-17 11:54:39.084542 7f0cc079d700 10 osd.90 pg_epoch: 19542 pg[3.2e7( v 19531'36796 (18972'33790,19531'36796] local-les=19542 n=0 ec=256 les/c 19542/19542 19522/19541/19532) [90,7,99] r=0 lpr=19541 lcod 19531'36795 mlcod 0'0 active+clean snaptrimq=[3~12]] SnapTrimmer state<Trimming/WaitingOnReplicas>: purged_snaps now [1~2], snap_trimq now [3~12]
2014-11-17 11:54:39.189007 7f0cc119e700 10 osd.90 pg_epoch: 19542 pg[3.2e7( v 19531'36796 (18972'33790,19531'36796] local-les=19542 n=0 ec=256 les/c 19542/19542 19522/19541/19532) [90,7,99] r=0 lpr=19541 lcod 19531'36795 mlcod 0'0 active+clean snaptrimq=[3~12]] SnapTrimmer state<Trimming/WaitingOnReplicas>: WaitingOnReplicas: adding snap 3 to purged_snaps
2014-11-17 11:54:39.189121 7f0cc119e700 10 osd.90 pg_epoch: 19542 pg[3.2e7( v 19531'36796 (18972'33790,19531'36796] local-les=19542 n=0 ec=256 les/c 19542/19542 19522/19541/19532) [90,7,99] r=0 lpr=19541 lcod 19531'36795 mlcod 0'0 active+clean snaptrimq=[4~11]] SnapTrimmer state<Trimming/WaitingOnReplicas>: purged_snaps now [1~3], snap_trimq now [4~11]
...

The full log is attached. Is this yet another case?

Today I restarted every mon and osd on the test cluster (again) and confirmed it is all running 0.67.11-4-g496e561. Now I cannot reproduce the issue anymore!! Great, but strange! (I still have a few PGs with the "annoying special case for snaps purged on an empty pg" issue, but the other issue I was reporting is no longer there).

This is very strange... I am sure that the OSDs have been running 0.67.11-4-g496e561 since Nov 4 -- I have the startup logs to prove it (attached). Perhaps there is something about this patch that implies that OSDs need to be restarted twice for it to fully work??

Anyway, from my side this looks good now to merge to dumpling (and firefly). I will definitely pay close attention when we are running this in production.

oops, still need firefly