Ceph » bluestore

Hey Pivert,
is it possible to get OSD startup log more verbose than just output to stderr? Actually I need one with bluefs-debug set to 1. Perhaps you might need to locate it at /var/log/ceph or systemctl, not system log. And please evidently make sure debug-bluefs set to a value higher than 0.

Just realized that I forgot to mention the tar exension for some files which could be confusing.
The files like:
ceph_crash_logs_$HOSTNAME.xz
are tar.xz files.

Log level is already set to 1 by default on PVE for OSDs.

Hi,

Obviously, I've been able to get out of this terrible situation.
Since I'm on lvm (on top of nvme) and I was keeping some 27GB for Ceph DB for extra SSD volume, I was able to extend the underlying volume. This unlocked the situation. I did this on all the nodes (on pve3 I just gave 5GB instead of the 27GB on pve1 and 2, and probably should give the 27GB / 100% free on this node as well):

root@pve2:~# lvextend -l +100%FREE /dev/pve/cephosdnvme
  Size of logical volume pve/cephosdnvme changed from 290,00 GiB (74240 extents) to 317,57 GiB (81298 extents).
  Logical volume pve/cephosdnvme successfully resized.
root@pve2:~# ceph-bluestore-tool --path /var/lib/ceph/osd/ceph-0/ bluefs-bdev-expand
inferring bluefs devices from bluestore path
1 : device size 0x4f64800000 : using 0x4a951a4000(298 GiB)
Expanding DB/WAL...
1 : expanding  from 0x4880000000 to 0x4f64800000
2022-01-17T01:15:41.775+0100 7f5fb6d0f240 -1 bluestore(/var/lib/ceph/osd/ceph-0) _read_bdev_label failed to read from /var/lib/ceph/osd/ceph-0: (21) Is a directory
2022-01-17T01:15:41.775+0100 7f5fb6d0f240 -1 bluestore(/var/lib/ceph/osd/ceph-0) unable to read label for /var/lib/ceph/osd/ceph-0: (21) Is a directory
(failed reverse-i-search)`start': systemctl ^Cart rclonemount.service
(failed reverse-i-search)`restart': view "/var/log/pve/tasks/3/UPID:pve2:000D2FF5:015D1638:61E35D23:vz^Cstore:105:root@pam:" 
root@pve2:~# systemctl start ceph-osd@0.service
root@pve2:~# ceph status
  cluster:
    id:     e7628d51-32b5-4f5c-8eec-1cafb41ead74
    health: HEALTH_WARN
            mon pve3 is low on available space
            1 backfillfull osd(s)
            1 nearfull osd(s)
            Degraded data redundancy: 497581/1492743 objects degraded (33.333%), 82 pgs degraded, 82 pgs undersized
            4 pool(s) backfillfull
            1344 daemons have recently crashed

  services:
    mon: 3 daemons, quorum pve1,pve3,pve2 (age 22h)
    mgr: pve1(active, since 23h), standbys: pve3, pve2
    mds: 1/1 daemons up, 2 standby
    osd: 3 osds: 2 up (since 7m), 2 in (since 7m)

  data:
    volumes: 1/1 healthy
    pools:   4 pools, 82 pgs
    objects: 497.58k objects, 269 GiB
    usage:   540 GiB used, 72 GiB / 613 GiB avail
    pgs:     497581/1492743 objects degraded (33.333%)
             82 active+undersized+degraded

  io:
    client:   682 B/s rd, 127 KiB/s wr, 0 op/s rd, 15 op/s wr

  progress:
    Global Recovery Event (0s)
      [............................] 

root@pve2:~# ceph status
  cluster:
    id:     e7628d51-32b5-4f5c-8eec-1cafb41ead74
    health: HEALTH_WARN
            mon pve3 is low on available space
            1 backfillfull osd(s)
            2 nearfull osd(s)
            4 pool(s) backfillfull
            1344 daemons have recently crashed

  services:
    mon: 3 daemons, quorum pve1,pve3,pve2 (age 22h)
    mgr: pve1(active, since 23h), standbys: pve3, pve2
    mds: 1/1 daemons up, 2 standby
    osd: 3 osds: 3 up (since 43s), 3 in (since 43s)

  data:
    volumes: 1/1 healthy
    pools:   4 pools, 82 pgs
    objects: 497.58k objects, 269 GiB
    usage:   810 GiB used, 120 GiB / 930 GiB avail
    pgs:     81 active+clean
             1  active+clean+scrubbing+deep

  io:
    client:   103 KiB/s wr, 0 op/s rd, 11 op/s wr

root@pve2:~# ceph status
  cluster:
    id:     e7628d51-32b5-4f5c-8eec-1cafb41ead74
    health: HEALTH_WARN
            mon pve3 is low on available space
            1 backfillfull osd(s)
            2 nearfull osd(s)
            4 pool(s) backfillfull
            1792 daemons have recently crashed

  services:
    mon: 3 daemons, quorum pve1,pve3,pve2 (age 22h)
    mgr: pve1(active, since 23h), standbys: pve3, pve2
    mds: 1/1 daemons up, 2 standby
    osd: 3 osds: 3 up (since 7m), 3 in (since 7m)

  data:
    volumes: 1/1 healthy
    pools:   4 pools, 82 pgs
    objects: 497.58k objects, 269 GiB
    usage:   810 GiB used, 120 GiB / 930 GiB avail
    pgs:     82 active+clean

  io:
    client:   247 KiB/s wr, 0 op/s rd, 42 op/s wr

Do you know how relevant are the bluefs-bdev-expand errors ?

Anyway, we should not reach that situation. What if I was on physical device ?

Many thanks for your support.
Feel free to ask any more detail.

Have a nice day ;-)

Pivert Dubuisson wrote:

Hi,

Obviously, I've been able to get out of this terrible situation.
Since I'm on lvm (on top of nvme) and I was keeping some 27GB for Ceph DB for extra SSD volume, I was able to extend the underlying volume. This unlocked the situation. I did this on all the nodes (on pve3 I just gave 5GB instead of the 27GB on pve1 and 2, and probably should give the 27GB / 100% free on this node as well):

[...]

Do you know how relevant are the bluefs-bdev-expand errors ?

You can ignore them.

Anyway, we should not reach that situation. What if I was on physical device ?

Many thanks for your support.
Feel free to ask any more detail.

Have a nice day ;-)

Well, you've found good enough workaround but unfortunately this hides the root cause of the issue.

Which IMO might be either software bug in hybrid allocator or the lack of free continuous 64K block due to high fragmentation and limited amount of free space.
Bad news is that the workaround doesn't guarantee the issue from the reappearance in the future, particularly if space goes low again. And right, it wouldn't work for the physical partitions.

Just in case let me try to do free space fragmentation analysis for the current allocation map. To do so please dump free extents with 'ceph tell osd.N bluestore allocator dump block' command.

Thanks in advance!

Hi,
the file size exceed the max 1MB rule.... The file is temporarily there:
www.pivert.org/osd.2_bluestore_allocator_dump_block.xz

osd.2 on pve3 was the first to fail. Do you need the 2 other nodes as well ?

Thanks,

Pivert Dubuisson wrote:

Hi,
the file size exceed the max 1MB rule.... The file is temporarily there:
www.pivert.org/osd.2_bluestore_allocator_dump_block.xz

osd.2 on pve3 was the first to fail. Do you need the 2 other nodes as well ?

Thanks,

Unfortunately the allocator's state looks totally different now - it's got 69GB free space vs. ~20GB one observed when crashed. So it makes no sense for any analysis.

Let's try dumps from other nodes but I expect they're in the similar state....

Regards,
Igor

Hi,

• https://www.pivert.org/osd.0_bluestore_allocator_dump_block.xz
• https://www.pivert.org/osd.1_bluestore_allocator_dump_block.xz

• Ceph BlueStore on LVM on Proxmox7 (Debian 11.2) with ceph version 16.2.7
• Using the default pve VG, on top of a 512GB NVME SSD
• I did scratch & reconfigure the Ceph & data setup a couple of time using a self made script every nodes. The script is just below. (Don't try it unless your ready to loose all the data, including data from PVE local storage and PVE cluster data, basically resets PVE as if it was freshly installed)

When I look back at the script, I should also have 'rm -rf /var/lib/ceph' at the end of the script to also delete other configs such as osd... But it should not be the cause of the problem since the OSD config is in a mounted tmpfs.

1. scratch_pve_cluster.sh to delete all data and reset PVE as freshly installed

systemctl stop ceph-crash.service
systemctl stop ceph-mon.target
systemctl stop ceph-osd.target
systemctl stop ceph-mgr.target
systemctl stop ceph
pveceph purge
systemctl stop pvestatd.service
systemctl stop pvedaemon.service
systemctl stop pve-cluster.service
systemctl stop corosync
systemctl stop pve-cluster

1. rm /etc/corosync/uidgid.d/*
   rm /var/lib/corosync/*
   rm -rf /var/lib/ceph/mon/ceph-pve*
   apt purge ceph-base -y
   apt purge ceph -y
   rm -rf /etc/ceph
   [/code]

So, if someone experience the same situation, please run the below command on all the nodes before extending the BlueStore LV:
[code]
ceph tell osd.x bluestore allocator dump block | xz -c > osd.x_bluestore_allocator_dump_block_on_${HOSTNAME}.xz
[/code]
Replace x with the concerned OSD id (different on each node). You'll find info about OSD in PVE GUI or in subfolders of /var/lib/ceph/osd/

Re-posting the script as indentation broke it:

#!/bin/bash
# scratch_pve_cluster.sh to delete all data and reset PVE as freshly installed

systemctl stop ceph-crash.service
systemctl stop ceph-mon.target
systemctl stop ceph-osd.target
systemctl stop ceph-mgr.target
systemctl stop ceph
pveceph purge
systemctl stop pvestatd.service
systemctl stop pvedaemon.service
systemctl stop pve-cluster.service
systemctl stop corosync
systemctl stop pve-cluster

mkdir /root/$(date +%Y%m%d)
mv -f /var/lib/pve-cluster/config.db /root/$(date +%Y%m%d)
mv /etc/pve/* /root/$(date +%Y%m%d)
rm -rf /etc/corosync/*
# rm /etc/corosync/uidgid.d/*
rm /var/lib/corosync/*
rm -rf /var/lib/ceph/mon/ceph-pve*
apt purge ceph-base -y
apt purge ceph -y
rm -rf /etc/ceph

Thanks for the information!

Pivert Dubuisson wrote:

Hi,

I added the 2 other dumps to the same location. But I expect the same:

• https://www.pivert.org/osd.0_bluestore_allocator_dump_block.xz
• https://www.pivert.org/osd.1_bluestore_allocator_dump_block.xz

Yeah, this shows the same - much more free sace is currently available hence the issue isn't reproducible.

Specificity of my setup that might be related:

I don't think this was caused by any specifics of your setup other than low free space conditions. The major question is whether this was a proper failure caused by the lack of enough amount continuous 16K extents or this was a bug in allocator which was unable to provide these extents although they're available. IMO the former is highly likely.

Anyway we need proper allocator dumps for that, so let's wait for another occurrence.

Hi,

I got the same issue with some of my OSDs (pacific v16.2.7 & SSD)

Feb 16 14:14:48 osd-server docker[13282]: 2022-02-16T14:14:48.499+0330 7fd2cfad3080 -1 bluefs _allocate allocation failed, needed 0x73d8e
Feb 16 14:14:48 osd-server docker[13282]: 2022-02-16T14:14:48.499+0330 7fd2cfad3080 -1 bluefs _flush_range allocated: 0x390000 offset: 0x383b90 length: 0x801fe
Feb 16 14:14:48 osd-server docker[13282]: /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.2.7/rpm/el8/BUILD/ceph-16.2.7/src/os/bluestore/BlueFS.cc: In function 'int BlueFS::_flush_range(BlueFS::FileWriter*, uint64_t, uint64_t)' thread 7fd2cfad3080 time 2022-02-16T14:14:48.502032+0330
Feb 16 14:14:48 osd-server docker[13282]: /home/jenkins-build/build/workspace/ceph-build/ARCH/x86_64/AVAILABLE_ARCH/x86_64/AVAILABLE_DIST/centos8/DIST/centos8/MACHINE_SIZE/gigantic/release/16.2.7/rpm/el8/BUILD/ceph-16.2.7/src/os/bluestore/BlueFS.cc: 2768: ceph_abort_msg("bluefs enospc")
Feb 16 14:14:48 osd-server docker[13282]:  ceph version 16.2.7 (dd0603118f56ab514f133c8d2e3adfc983942503) pacific (stable)
Feb 16 14:14:48 osd-server docker[13282]:  1: (ceph::__ceph_abort(char const*, int, char const*, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0xe5) [0x5571561272be]
Feb 16 14:14:48 osd-server docker[13282]:  2: (BlueFS::_flush_range(BlueFS::FileWriter*, unsigned long, unsigned long)+0x1131) [0x557156822eb1]
Feb 16 14:14:48 osd-server docker[13282]:  3: (BlueFS::_flush(BlueFS::FileWriter*, bool, bool*)+0x90) [0x557156823190]
Feb 16 14:14:48 osd-server docker[13282]:  4: (BlueFS::_flush(BlueFS::FileWriter*, bool, std::unique_lock<std::mutex>&)+0x32) [0x5571568342a2]
Feb 16 14:14:48 osd-server docker[13282]:  5: (BlueRocksWritableFile::Append(rocksdb::Slice const&)+0x11b) [0x55715684cbdb]
Feb 16 14:14:48 osd-server docker[13282]:  6: (rocksdb::LegacyWritableFileWrapper::Append(rocksdb::Slice const&, rocksdb::IOOptions const&, rocksdb::IODebugContext*)+0x1f) [0x557156ce6e0f]
Feb 16 14:14:48 osd-server docker[13282]:  7: (rocksdb::WritableFileWriter::WriteBuffered(char const*, unsigned long)+0x58a) [0x557156df8b5a]
Feb 16 14:14:48 osd-server docker[13282]:  8: (rocksdb::WritableFileWriter::Append(rocksdb::Slice const&)+0x2d0) [0x557156df9fb0]
Feb 16 14:14:48 osd-server docker[13282]:  9: (rocksdb::BlockBasedTableBuilder::WriteRawBlock(rocksdb::Slice const&, rocksdb::CompressionType, rocksdb::BlockHandle*, bool)+0xb6) [0x557156f15736]
Feb 16 14:14:48 osd-server docker[13282]:  10: (rocksdb::BlockBasedTableBuilder::WriteBlock(rocksdb::Slice const&, rocksdb::BlockHandle*, bool)+0x26c) [0x557156f1607c]
Feb 16 14:14:48 osd-server docker[13282]:  11: (rocksdb::BlockBasedTableBuilder::WriteBlock(rocksdb::BlockBuilder*, rocksdb::BlockHandle*, bool)+0x3c) [0x557156f1677c]
Feb 16 14:14:48 osd-server docker[13282]:  12: (rocksdb::BlockBasedTableBuilder::Flush()+0x6d) [0x557156f1680d]
Feb 16 14:14:48 osd-server docker[13282]:  13: (rocksdb::BlockBasedTableBuilder::Add(rocksdb::Slice const&, rocksdb::Slice const&)+0x2b8) [0x557156f19c78]
Feb 16 14:14:48 osd-server docker[13282]:  14: (rocksdb::BuildTable(std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, rocksdb::Env*, rocksdb::FileSystem*, rocksdb::ImmutableCFOptions const&, rocksdb::MutableCFOptions const&, rocksdb::FileOptions const&, rocksdb::TableCache*, rocksdb::InternalIteratorBase<rocksdb::Slice>*, std::vector<std::unique_ptr<rocksdb::FragmentedRangeTombstoneIterator, std::default_delete<rocksdb::FragmentedRangeTombstoneIterator> >, std::allocator<std::unique_ptr<rocksdb::FragmentedRangeTombstoneIterator, std::default_delete<rocksdb::FragmentedRangeTombstoneIterator> > > >, rocksdb::FileMetaData*, rocksdb::InternalKeyComparator const&, std::vector<std::unique_ptr<rocksdb::IntTblPropCollectorFactory, std::default_delete<rocksdb::IntTblPropCollectorFactory> >, std::allocator<std::unique_ptr<rocksdb::IntTblPropCollectorFactory, std::default_delete<rocksdb::IntTblPropCollectorFactory> > > > const*, unsigned int, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<unsigned long, std::allocator<unsigned long> >, unsigned long, rocksdb::SnapshotChecker*, rocksdb::CompressionType, unsigned long, rocksdb::CompressionOptions const&, bool, rocksdb::InternalStats*, rocksdb::TableFileCreationReason, rocksdb::EventLogger*, int, rocksdb::Env::IOPriority, rocksdb::TableProperties*, int, unsigned long, unsigned long, rocksdb::Env::WriteLifeTimeHint, unsigned long)+0xa45) [0x557156ec46f5]
Feb 16 14:14:48 osd-server docker[13282]:  15: (rocksdb::DBImpl::WriteLevel0TableForRecovery(int, rocksdb::ColumnFamilyData*, rocksdb::MemTable*, rocksdb::VersionEdit*)+0xcf5) [0x557156d29755]
Feb 16 14:14:48 osd-server docker[13282]:  16: (rocksdb::DBImpl::RecoverLogFiles(std::vector<unsigned long, std::allocator<unsigned long> > const&, unsigned long*, bool, bool*)+0x1c2e) [0x557156d2be8e]
Feb 16 14:14:48 osd-server docker[13282]:  17: (rocksdb::DBImpl::Recover(std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFamilyDescriptor> > const&, bool, bool, bool, unsigned long*)+0xae8) [0x557156d2d1e8]
Feb 16 14:14:48 osd-server docker[13282]:  18: (rocksdb::DBImpl::Open(rocksdb::DBOptions const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFamilyDescriptor> > const&, std::vector<rocksdb::ColumnFamilyHandle*, std::allocator<rocksdb::ColumnFamilyHandle*> >*, rocksdb::DB**, bool, bool)+0x59d) [0x557156d26f0d]
Feb 16 14:14:48 osd-server docker[13282]:  19: (rocksdb::DB::Open(rocksdb::DBOptions const&, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&, std::vector<rocksdb::ColumnFamilyDescriptor, std::allocator<rocksdb::ColumnFamilyDescriptor> > const&, std::vector<rocksdb::ColumnFamilyHandle*, std::allocator<rocksdb::ColumnFamilyHandle*> >*, rocksdb::DB**)+0x15) [0x557156d282a5]
Feb 16 14:14:48 osd-server docker[13282]:  20: (RocksDBStore::do_open(std::ostream&, bool, bool, std::__cxx11::basic_string<char, std::char_traits<char>, std::allocator<char> > const&)+0x10c1) [0x557156ca0201]
Feb 16 14:14:48 osd-server docker[13282]:  21: (BlueStore::_open_db(bool, bool, bool)+0x8c7) [0x55715671d027]
Feb 16 14:14:48 osd-server docker[13282]:  22: (BlueStore::_open_db_and_around(bool, bool)+0x2f7) [0x557156787ab7]
Feb 16 14:14:48 osd-server docker[13282]:  23: (BlueStore::_mount()+0x204) [0x55715678a974]
Feb 16 14:14:48 osd-server docker[13282]:  24: (OSD::init()+0x380) [0x55715625e400]
Feb 16 14:14:48 osd-server docker[13282]:  25: main()
Feb 16 14:14:48 osd-server docker[13282]:  26: __libc_start_main()
Feb 16 14:14:48 osd-server docker[13282]:  27: _start()

Seena Fallah wrote:

Hi,

I got the same issue with some of my OSDs (pacific v16.2.7 & SSD)
[...]

I tried to boot my OSD with `bitmap` and `stupid` allocator but it doesn't help!

Hi Seena,
I presume you're sharing stderr output only, right?
Could you please share more verbose OSD startup log.

Additionally please run ceph-bluestore-tool's free-dump command and share the output for the inspection.

Igor Fedotov wrote:

Hi Seena,
I presume you're sharing stderr output only, right?
Could you please share more verbose OSD startup log.

Additionally please run ceph-bluestore-tool's free-dump command and share the output for the inspection.

free dump output is 2G and after compression, to tar.gz it gets 100MB and I can't upload more than 1MB here! =)
Do you want me to extract data for you?
For example, do you need these datas?

{
            "offset": "0x3900001000",
            "length": "0x1000" 
        },
        {
            "offset": "0x3900005000",
            "length": "0x1000" 
        },
        {
            "offset": "0x3900007000",
            "length": "0x4000" 
        },
        {
            "offset": "0x390000d000",
            "length": "0x2000" 
        },
        {
            "offset": "0x383b909000",
            "length": "0x1000" 
        },
        {
            "offset": "0x383b90c000",
            "length": "0x2000" 
        },

Hi Seena,
no. that's right. The dump might be pretty large if your disk is very big. But unfortunately I need the full dump to simulate the allocation. So please use some external cloud storage to transfer it.

As for osd startup log I primarily need the line which has "_allocate unable to allocate 0x" substring as it contains all the failing allocation attempt's details. So you can omit sending the full OSD log...

Igor Fedotov wrote:

Hi Seena,
no. that's right. The dump might be pretty large if your disk is very big. But unfortunately I need the full dump to simulate the allocation. So please use some external cloud storage to transfer it.

As for osd startup log I primarily need the line which has "_allocate unable to allocate 0x" substring as it contains all the failing allocation attempt's details. So you can omit sending the full OSD log...

Here you can find the free dump: https://ceph-debug.s3.ir-thr-at1.arvanstorage.com/osd.92.free-dump.tar.gz

This is the allocation that failed on OSD:

2022-02-16T20:19:35.333+0330 7f78ec092080  1 bluefs _allocate unable to allocate 0x80000 on bdev 1, allocator name block, allocator type hybrid, capacity 0x1bf1f800000, block size 0x1000, free 0x50ccc46000, fragmentation 0.876362, allocated 0x0
2022-02-16T20:19:35.333+0330 7f78ec092080 -1 bluefs _allocate allocation failed, needed 0x73d8e

Igor Fedotov wrote:

Hi Seena,
no. that's right. The dump might be pretty large if your disk is very big. But unfortunately I need the full dump to simulate the allocation. So please use some external cloud storage to transfer it.

As for osd startup log I primarily need the line which has "_allocate unable to allocate 0x" substring as it contains all the failing allocation attempt's details. So you can omit sending the full OSD log...

Also, I got interested in how do you simulate it =)
If it's an open-source tool or a written blogged please share it otherwise ignore it:)

Thanks :D

Seena Fallah wrote:

Igor Fedotov wrote:

Hi Seena,
no. that's right. The dump might be pretty large if your disk is very big. But unfortunately I need the full dump to simulate the allocation. So please use some external cloud storage to transfer it.

As for osd startup log I primarily need the line which has "_allocate unable to allocate 0x" substring as it contains all the failing allocation attempt's details. So you can omit sending the full OSD log...

Also, I got interested in how do you simulate it =)
If it's an open-source tool or a written blogged please share it otherwise ignore it:)

Thanks :D

There is a tool ceph_test_alloc_replay in Ceph's codebase which allows to replay that free-dump output and perform some operations (e.g. an allocation) against the resulting allocator.

One has to build it manually as it isn't published along with regular Ceph binaries though... Just some dev stuff....

Seena Fallah wrote:

Igor Fedotov wrote:

Hi Seena,
no. that's right. The dump might be pretty large if your disk is very big. But unfortunately I need the full dump to simulate the allocation. So please use some external cloud storage to transfer it.

As for osd startup log I primarily need the line which has "_allocate unable to allocate 0x" substring as it contains all the failing allocation attempt's details. So you can omit sending the full OSD log...

Here you can find the free dump: https://ceph-debug.s3.ir-thr-at1.arvanstorage.com/osd.92.free-dump.tar.gz

This is the allocation that failed on OSD:
[...]

I'm curious if free dump and log output are for exactly the same OSD? There are some minor mismatch, e.g. in available space which makes me suspect they aren't... If so could you please share log output from osd.92

Igor Fedotov wrote:

Seena Fallah wrote:

Igor Fedotov wrote:

Hi Seena,
no. that's right. The dump might be pretty large if your disk is very big. But unfortunately I need the full dump to simulate the allocation. So please use some external cloud storage to transfer it.

As for osd startup log I primarily need the line which has "_allocate unable to allocate 0x" substring as it contains all the failing allocation attempt's details. So you can omit sending the full OSD log...

Here you can find the free dump: https://ceph-debug.s3.ir-thr-at1.arvanstorage.com/osd.92.free-dump.tar.gz

This is the allocation that failed on OSD:
[...]

I'm curious if free dump and log output are for exactly the same OSD? There are some minor mismatch, e.g. in available space which makes me suspect they aren't... If so could you please share log output from osd.92

I've dumped it again both from the same time (start osd first after it goes down, free-dump it)
free-dump: https://www.dropbox.com/s/5zkqjrenh1h0g60/osd.92.free-dump.tar.gz?dl=0
full log: https://www.dropbox.com/s/dug0j7avwphcwhp/ceph-osd.92.log?dl=0

Seena, thanks a lot for the logs.
So everything is fine (I mean there is no bug) with the allocator, your volume just doesn't have enough 64K chunks to allocate.
That's what I obtained from your free dump:
Free:50ccff6000
Available: 0xa7b00000 Available(strict align): 0x3b0000 alloc_unit: 0x10000

Note that just 0x3b0000 bytes are available for contiguous 64K block allocations.

And from osd.92 log BlueFS needs 0x390000 + 0x80000 bytes:
-4> 2022-02-17T13:14:53.281+0330 7f4141b23080 1 bluefs _allocate unable to allocate 0x80000 on bdev 1, allocator name block, allocator type hybrid, capacity 0x1bf1f800000, block size 0x1000, free 0x50ccc46000, fragmentation 0.876362, allocated 0x0
-3> 2022-02-17T13:14:53.281+0330 7f4141b23080 -1 bluefs _allocate allocation failed, needed 0x73d8e
-2> 2022-02-17T13:14:53.281+0330 7f4141b23080 -1 bluefs _flush_range allocated: 0x390000 offset: 0x383b90 length: 0x801fe

Hence the exception.
The root cause for the issue is a high fragmentation of the main volume and DB and main volumes collocation. The main one uses 4K allocation unit while DB uses 64K one. And under high utilization one can get the state when there are not enough available contiguous 64K blocks despite the fact that the amount of free space still looks fine.
Unfortunately at this point I can't recommend anything but redeploy the OSD and start using standalone logical DB volume even if it physically collocates the same disk with the main one. See my comment #6 at https://tracker.ceph.com/issues/53466 for a bit more details on this approach.

Small addition: `ceph osd status` shows the following:

# ceph osd status
ID  HOST          USED  AVAIL  WR OPS  WR DATA  RD OPS  RD DATA  STATE                
 0  backupfs-1    122G  45.3G      0        0       0        0   exists,up          
...
12  backupfs-2      0      0       0        0       0        0   autoout,exists,full  

Hi Niklas,

looks like your BlueFS is almost full. Given the following output
-5> 2024-03-28T23:55:26.039+0000 7fcf3ca7ee80 1 bluefs _allocate unable to allocate 0x90000 on bdev 1, allocator name block, allocator type hybrid, capacity 0x29e7e00000, block size 0x1000, alloc unit 0x10000, free 0x3b8000, fragmentation 0.16, allocated 0x0
-4> 2024-03-28T23:55:26.072+0000 7fcf3ca7ee80 1 bluefs _allocate unable to allocate 0x80000 on bdev 1, allocator name block, allocator type hybrid, capacity 0x29e7e00000, block size 0x1000, alloc unit 0x1000, free 0x35000, fragmentation 0.56, allocated 0x35000

we can see "free 0x3b8000" (=3899392) bytes are free only.
There is small discrepancy as the requested amount is 0x90000 (=589824) bytes which is less than free space and hence the allocation request should be rather satisfied. But that just makes the failure happen a couple allocation iterations earlier as free space is almost over.

Thanks Igor for investigating.

I worked around it now by re-provisioning the OSD, and letting redundancy fix it.

But I feel I was lucky that it happened only to 1 OSD, so I had no downtime in the cluster.

Should it be possible that the BlueFS becomes this full? Do you think it's possible of the 0-Bytes inodes as I suspected above?

You're using DB volume collocated with main one. So BlueFS shares the same space as user data. And your OSD ran out of that space.
Can't say for sure what triggered that but highly likely that's the issue you mentioned " created a huge amount of objects on my SSDs that were too small".
I believe you should be seeing some alerts about OSDs being too full in 'ceph -s" output or something...