Hi,
the problem still exists and I don't know whats the reason and how to
fix it.
I figured out, that only about 20 OSDs was affected. After I did a ceph
daemon osd.<id> compact on this the problem was gone.
I compacted all OSDs in the hope my issue will be fixed with this. But
over the weekend I run into the same issue.
Does anyone have/had the same issue and has a solution for this?
Regards
Manuel
On Mon, 27 Jul 2020 15:59:01 +0200
Manuel Lausch <manuel.lausch(a)1und1.de> wrote:
Hi,
since some days I try to debug a problem with snaptrimming under
nautilus.
I have a cluster with Nautilus (v14.2.10) , 44 Nodes á 24 OSDs á 14 TB
I create every day a snapshot for 7 days.
Every time the old snapshot is deleting I have bad IO performcance
and blocked requests for several seconds until the snaptrim is done.
Settings like snaptrim_sleep and osd_pg_max_concurrent_snap_trims
don't affect this behavior.
In the debug_osd 10/10 log I see the following:
2020-07-27 11:45:49.976 7fd8b8404700 10 osd.411 22457 dequeue_op
0x557886edda20 prio 196 cost 0 latency 0.019545
osd_repop_reply(client.22731418.0:615257 3.636 e22457/22372) v2 pg
pg[3.636( v 22457'100855 (21737'97756,22457'100855]
local-lis/les=22372/22374 n=27762 ec=2842/2839 lis/c 22372/22372
les/c/f 22374/22374/0 22372/22372/22343) [411,36,956,763] r=0
lpr=22372 luod=22457'100854 crt=22457'100855 lcod 22457'100853 mlcod
22457'100853 active+clean+snaptrim_wait trimq=[1d~1]] 2020-07-27
11:45:49.976 7fd8b8404700 10 osd.411 22457 dequeue_op 0x557886edda20
finish 2020-07-27 11:45:49.976 7fd8b8404700 10 osd.411 22457
dequeue_op 0x557886edc2c0 prio 127 cost 0 latency 0.043165
MOSDScrubReserve(2.2645 RELEASE e22457) v1 pg pg[2.2645( empty
local-lis/les=22359/22364 n=0 ec=2403/2403 lis/c 22359/22359 les/c/f
22364/22367/0 22359/22359/22359) [379,411,884,975] r=1 lpr=22359
crt=0'0 active mbc={}] 2020-07-27 11:45:49.976 7fd8b8404700 10
osd.411 22457 dequeue_op 0x557886edc2c0 finish 2020-07-27
11:45:50.039 7fd8b8404700 10 osd.411 pg_epoch: 22457 pg[3.278e( v
22457'99491 (21594'96426,22457'99491] local-lis/les=22359/22362
n=27669 ec=2859/2839 lis/c 22359/22359 les/c/f 22362/22365/0
22359/22359/22343) [411,379,848,924] r=0 lpr=22359 crt=22457'99491
lcod 22457'99489 mlcod 22457'99489 active+clean+snaptrim
trimq=[1d~1]] snap_trimmer posting 2020-07-27 11:45:57.801
7fd8b8404700 10 osd.411 pg_epoch: 22457 pg[3.278e( v 22457'99493
(21594'96426,22457'99493] local-lis/les=22359/22362 n=27669
ec=2859/2839 lis/c 22359/22359 les/c/f 22362/22365/0
22359/22359/22343) [411,379,848,924] r=0 lpr=22359 luod=22457'99491
crt=22457'99493 lcod 22457'99489 mlcod 22457'99489
active+clean+snaptrim trimq=[1d~1]] snap_trimmer complete 2020-07-27
11:45:57.801 7fd8b8404700 10 osd.411 22457 dequeue_op 0x557880ac3760
prio 127 cost 663 latency 7.761823 osd_repop(osd.217.0:3025 3.1ca5
e22457/22378) v2 pg pg[3.1ca5( v 22457'100370
(21716'97357,22457'100370] local-lis/les=22378/22379 n=27532
ec=2855/2839 lis/c 22378/22378 les/c/f 22379/22379/0
22378/22378/22378) [217,411,551,1055] r=1 lpr=22378 luod=0'0
lua=22294'100006 crt=22457'100370 lcod 22457'100369 active mbc={}]
2020-07-27 11:45:57.801 7fd8b8404700 10 osd.411 22457 dequeue_op
0x557880ac3760 finish 2020-07-27 11:45:57.801 7fd8b8404700 10 osd.411
22457 dequeue_op 0x5578813e1e40 prio 127 cost 0 latency 7.494296
MOSDScrubReserve(2.37e2 REQUEST e22457) v1 pg pg[2.37e2( empty
local-lis/les=22355/22356 n=0 ec=2412/2412 lis/c 22355/22355 les/c/f
22356/22356/0 22355/22355/22355) [245,411,834,768] r=1 lpr=22355
crt=0'0 active mbc={}] 2020-07-27 11:45:57.801 7fd8b8404700 10
osd.411 22457 dequeue_op 0x5578813e1e40 finish
the dequeueing of ops works without pauses until the „snap_trimmer
posting“ and „snap_trimmer complete“ loglines. This task takes in
this example about 7 Seconds. The following operations which are
dequeued have now a latency of about this time.
I tried to drill down this in the code. (Developers are asked here)
It seems, that the PG will be locked for every operation.
The snap_trimmer posting and complete message comes from
„osd/PrimaryLogPG.cc“ on line 4700. This indicates me, that the
process of deleting a snapshot object will sometimes take some time.
After further poking around. I see in „osd/SnapMapper.cc“ the method
„SnapMapper::get_next_objects_to_trim“ which takes several seconds to
get finished. I followed this further to the „common/map_cacher.hpp“
to the line 94: „int r = driver->get_next(key, &store);“ From there I
lost the path.
The slowness is not on all OSDs at the same time. Somteime, this few
OSDs are affected, sometimes some others. Restart of an OSD does not
help.
With luminous and filestore, snapshot deletion was not an issue at
all. With nautilus and bluestore this is not acceptable for my
usecase.
I don‘t know so far, if this is a bluestore specific problem or some
general issue. I wonder a bit why there are no other who have this
problem.
Regards
Manuel
_______________________________________________
ceph-users mailing list -- ceph-users(a)ceph.io
To unsubscribe send an email to ceph-users-leave(a)ceph.io