Ceph » bluestore

Saw this on 8 more osds over the weekend.

11 more osds started doing this over the holiday weekend.

Igor/Adam - "But the behavior stops immediately on restart. So feels like some thread in the osd is doing something unusual until restarted." this is pretty important information. How come a restart is helping? Maybe in restart we compact?

Kevin - are these osds have a heavy delete workload?

These run away osds are not on the heavy delete workload cluster. Its a relatively lightly loaded cluster. though I can't say it doesn't experience slight moments of busyness. I haven't kept that close an eye on it. Not sure I could tell.

Is there a way to get a thread dump or something the next time we get a runaway one that might help shed light on the issue?

Another 10 are doing it now.

We ended up slowly reformatting all of our osts and re-adding them. Things settled out to a fragmentation score of < .20.

I checked today and several ost's have been slowly but steadily been rising over the last 3 weeks of data I have. So, looks like it may still be a problem, even with freshly formatted osds.

If I strace a run away osd, it shows up with 59 threads. If I do it to one that is not run away, it shows up with 59 threads. So, no extra thread....

Vikhyat Umrao wrote:

Igor/Adam - "But the behavior stops immediately on restart. So feels like some thread in the osd is doing something unusual until restarted." this is pretty important information. How come a restart is helping? Maybe in restart we compact?

One potential explanation can be pretty trivial: allocator keeps tracking a sort of history(hints) where to start the next allocation from based on the previous allocation result(s). On restart this history is reset and allocations start over. Just a hypothesis...

At the first step I'd like to see allocation stats probes from OSD logs. Here is an example:

2023-01-20T16:28:41.464+0300 7fab001a66c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) allocation stats probe 0: cnt: 1411 frags: 1411 size: 463032320
2023-01-20T16:28:41.464+0300 7fab001a66c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) probe -1: 0, 0, 0
2023-01-20T16:28:41.464+0300 7fab001a66c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) probe -2: 0, 0, 0
2023-01-20T16:28:41.464+0300 7fab001a66c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) probe -4: 0, 0, 0
2023-01-20T16:28:41.464+0300 7fab001a66c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) probe -8: 0, 0, 0
2023-01-20T16:28:41.464+0300 7fab001a66c0 0 bluestore(/home/if/ceph.2/build/dev/osd0) probe -16: 0, 0, 0

This shows amount of allocation requests (=cnt), amount of returned fragments(frags) and total allocated size for the last day, day before and 2/4/8/16 days before.

It's reset on OSD restart. Having a bunch of such probes we'll hopefully see how large is the difference (in terms of fragmentation) between allocations between and after restart. As well as how things are becoming worse over time without restart...

So please run through existing OSD logs and collect these allocation probes along with information about OSD restarts, relevant OSD log line looks like (actual version might vary):
2023-01-19T16:28:36.273+0300 7fab0fa05500 0 ceph version Development (no_version) reef (dev), process ceph-osd, pid 22499

Here's osd4 that was still running away this morning. I just restarted it. Here's the right before metrics. Will get more soon.
[root@rcs3 ~]# journalctl -u ceph-b15015c8-af07-4973-b35d-28c3bfd2af22@osd.4.service | grep probe
Jan 22 17:40:46 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^2099039: debug 2023-01-23T01:40:46.765+0000 7fe1350e5700 0 bluestore(/var/lib/ceph/osd/ceph-4) allocation stats probe 25: cnt: 42495 frags: 42495 size: 45438136320
Jan 22 17:40:46 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^2099039: debug 2023-01-23T01:40:46.765+0000 7fe1350e5700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -1: 42484, 42484, 44923281408
Jan 22 17:40:46 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^2099039: debug 2023-01-23T01:40:46.765+0000 7fe1350e5700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -3: 47025, 47025, 51463442432
Jan 22 17:40:46 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^2099039: debug 2023-01-23T01:40:46.765+0000 7fe1350e5700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -5: 51034, 51034, 54404734976
Jan 22 17:40:46 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^2099039: debug 2023-01-23T01:40:46.765+0000 7fe1350e5700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -9: 48928, 48928, 51115958272
Jan 22 17:40:46 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^2099039: debug 2023-01-23T01:40:46.765+0000 7fe1350e5700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -25: 543961, 543961, 1790549340160

After restart:
[root@rcs3 ~]# journalctl -u ceph-b15015c8-af07-4973-b35d-28c3bfd2af22@osd.4.service | grep probe
Jan 24 08:57:33 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^1524224: debug 2023-01-24T16:57:33.217+0000 7f1c9fb26700 0 bluestore(/var/lib/ceph/osd/ceph-4) allocation stats probe 0: cnt: 44417 frags: 44417 size: 52236275712
Jan 24 08:57:33 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^1524224: debug 2023-01-24T16:57:33.217+0000 7f1c9fb26700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -1: 0, 0, 0
Jan 24 08:57:33 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^1524224: debug 2023-01-24T16:57:33.217+0000 7f1c9fb26700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -2: 0, 0, 0
Jan 24 08:57:33 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^1524224: debug 2023-01-24T16:57:33.217+0000 7f1c9fb26700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -4: 0, 0, 0
Jan 24 08:57:33 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^1524224: debug 2023-01-24T16:57:33.217+0000 7f1c9fb26700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -8: 0, 0, 0
Jan 24 08:57:33 rcs3.cloud.pnnl.gov ceph-b15015c8-af07-4973-b35d-28c3bfd2af22-osd-4^1524224: debug 2023-01-24T16:57:33.217+0000 7f1c9fb26700 0 bluestore(/var/lib/ceph/osd/ceph-4) probe -16: 0, 0, 0

Hi Kevin,

I have two questions:
1) Is rising fragmentation score related to change of free space?
If no other method is available, free space can be read by admin socket command "bluestore bluefs device info".
2) Might it be possible to collect few snapshots of "bluestore allocator dump block" from osd.3 or osd.4
(the hosts that showed increasing fragmentation that reversed trend after restart).

The overall inquiry I am targeting is to find out whether fragmentation calculation algorithm is too sensitive in some contexts.
It is possible that the algorithm behaves in following way:
a) 10MB free / 1KB data / 490MB free = fragmentation 0.08
b) 250MB free / 1KB data / 250MB free = fragmentation 0.14

Regards,
Adam

https://github.com/ceph/ceph/pull/49885

The patch implies that the calculation may be wrong? But why would behavior change on restart?

Thanks,
Kevin

Igor Fedotov wrote:

One potential explanation can be pretty trivial: allocator keeps tracking a sort of history(hints) where to start the next allocation from based on the previous allocation result(s). On restart this history is reset and allocations start over. Just a hypothesis...

Kevin Fox wrote:

The patch implies that the calculation may be wrong? But why would behavior change on restart?

Thanks,
Kevin

The calculation was wrong in the sense that 100% fragmentation was unachievable (part 1 of PR)
I believed Igor's hypothesis so much that I decided to numb a bit fragmentation calculation algorithm (part 2 or PR).

To prove it I need "bluestore allocator dump"s.

Just looking at lengths, there are lots of pretty small ones?:
[kfox@zathras tmp]$ jq '.extents[].length' osd.3 | sort | uniq -c | sort -k 1 -n | tail -n 4
3458 "0x20000"
4410 "0x70000"
9544 "0x1000"
55281 "0x10000"
[kfox@zathras tmp]$ jq '.extents[].length' osd.4 | sort | uniq -c | sort -k 1 -n | tail -n 4
2619 "0x20000"
4237 "0x70000"
11238 "0x1000"
44461 "0x10000"

We got some monitoring on a 3rd cluster. we're seeing it there too, though slower then the other cluster.

I was seeing a fairly constant increase of ~0.000172 per hour to the fragmentation scores of a bunch of osds on it. It was upgraded from nautilus->octopus->pacific somewhere around end of October or early November I think. The scores were less then .20 then. Now there are some scores up just shy of .60. I restarted one a few days ago and its score has started decreasing a little bit rather then the constant increase.

Anything else I can provide to help debug this?

@Kevin H:

What BlueStore allocator did you use in Nautilus / Octopus? Did you use the defaults there (which should have been bitmap)? If nothing explicitly configured otherwise I guess you did. Did you set the minimum allocation size to 4K when you created the OSDs (in Nautilus)? So these parameters:

bluestore_min_alloc_size_ssd = 4096
bluestore_min_alloc_size_hdd = 4096

Or did you use the default settings by Nautilus (16K / 64K for SSD / HDD resp.)

Used all defaults for nautilus. Haven't ever specified any of those flags.

Kevin Fox wrote:

Used all defaults for nautilus. Haven't ever specified any of those flags.

OK. Then you might have different allocation sizes for different OSDs: OSDs created in Nautilus 16/64K and OSDs created in Pacific 4K. Do you also have this issue on the newly created OSDs?

Stefan Kooman wrote:

OK. Then you might have different allocation sizes for different OSDs: OSDs created in Nautilus 16/64K and OSDs created in Pacific 4K. Do you also have this issue on the newly created OSDs?

Was that this? https://github.com/ceph/ceph/pull/49884 I don't see it backported to a released Pacific though. Would we have to get to Quincy before reformatting to fix it?

Kevin Fox wrote:

Stefan Kooman wrote:

OK. Then you might have different allocation sizes for different OSDs: OSDs created in Nautilus 16/64K and OSDs created in Pacific 4K. Do you also have this issue on the newly created OSDs?

Was that this? https://github.com/ceph/ceph/pull/49884 I don't see it backported to a released Pacific though.

No, this one enables 4K unit support for BlueFS and it hasn't been backported to Pacific yet.

But I was talking about 4K unit support for user/main data. Here it is:https://github.com/ceph/ceph/pull/34588

Would we have to get to Quincy before reformatting to fix it?

No, Pacific is enough to be able to reformat to get 4K main data allocation units.

Ok, cool. Thanks for the info.

Would we want to reformat at Quincy to get the BlueFS 4k support too, or does that automatically kick in as needed?

Trying to decide what is more critical. Reformatting the osds now in Pacific, or upgrading first before reformatting.

Kevin Fox wrote:

Ok, cool. Thanks for the info.

Would we want to reformat at Quincy to get the BlueFS 4k support too, or does that automatically kick in as needed?

No need to reformat to 4K BlueFS in Quincy. It will kick in automatically. Just one thing to mention - this is irreversible step - no downgrade is allowed when it's enabled.

Igor Fedotov wrote:

No need to reformat to 4K BlueFS in Quincy. It will kick in automatically. Just one thing to mention - this is irreversible step - no downgrade is allowed when it's enabled.

Ok. Thank you! :)