27 Jul
2020
27 Jul
'20
4:59 p.m.
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