Hi Hector,
Responses inline below.
On 6/24/25 10:11 PM, Hector Martin wrote:
Hi Mark,
Thanks a lot for the pointers and info, it's really helpful.
Glad to help, and thanks for looking into it. If we can figure out how
to disable bluefs_buffered_io without repercussions, I think it would be
a decent win overall.
Since the issue is happening in a live cluster (which is a homelab I can
screw around with to an extent, but not take down for very long periods
of time or lose data in), and since I don't have a lot of spare hours in
the coming weeks, I think this will probably be an investigation on the
longer side of things. So don't expect fast follow-ups, but rest assured
this is now on my radar and I'll be poking at it and seeing what I can
figure out.
Re the workload between snapshots, that's a bit hard to pin down right
now since I did some shuffling around and the snapshot deletions were
from different subtrees. At the time I saw this I had just wiped all my
snapshots in the cluster, ~2 weeks worth of daily snapshots in the
largest subtree, adding up to just over a terabyte of raw cluster
storage being freed going by stats graphs (5+4 EC, 8MB object CephFS,
probably mostly large files and full-size objects). In fact I just took
out the vast majority of that data from the tree that gets snapshotted
(that really shouldn't have been there); if it turns out I can't repro
after that I'm happy to revert it back though (but it would take another
2 weeks to recreate the exact scenario, if it comes to that).
A couple of potential hints here: First, 5+4 erasure coding. That means
you have 9 chunks per object, each of which will have its own metadata
in RocksDB. The larger 8MB CephFS objects may help offset this to some
extent, but EC does tend to have higher overhead and especially might if
you have a lot of small partial writes and snapshots. The second is
having just wiped away all of your snapshots when you first saw the
issue. That would trigger the creation of lots of tombstones in rocksdb
that would only get cleaned up with subsequent compaction. This is just
conjecture, but I wonder if you could have ended up with a bunch of
tombstones in L0 that had to be read and iterated over if those SST
files were evicted from the block cache regularly before a full
compaction across the other levels took place.
I also just deleted a legacy pool, which at the time was involved in the
snaptrim but had only negligible data actually being snapshotted/deleted
as part of it. Again, if it comes to that to make things repro, I don't
mind recreating it and trying to force the same scenario.
Same as above, just more tombstone insertion into RocksDB until
compaction takes place.
FWIW, the setup here is 3 nodes:
- M1 Mac Mini (4p4e), 16GB RAM, OSDs + Mon
- M2 Mac Mini (4p4e), 24GB RAM, OSDs + Mon + MDS + monitoring (prom)
- M2 Pro Mac Mini (6p4e), 32GB RAM, OSDs + Mon + MDS + a bunch of other
stuff
Each node has 4x 16TB HDDs and 1x 1TB NVMe SSD, attached via USB (10G,
except 5G for the HDDs on one node because reasons). The HDD block.db
volumes are on internal Mac NVMe storage (recent change, just before the
snapshot story; yes, I did force migrate the data over so there should
be no DB files left on the HDDs). SSDs don't have separate block.db.
10GbE networking for all nodes. I have no reason to suspect any
hardware/driver related issues relevant to the snaptrim story (I've had
a few of those but I keep an eye out for it, and the current setup
should be stable).
No real comment on the HW other than that it is what it is. The
behaviors are the interesting bit here imho!
One issue is that this may be hard to repro on demand. If I'm lucky I
can just instantly create and delete a pile of snapshots (without much
changes in between) and repro, but I might not be lucky. I'd usually
debug this by increasing logging verbosity and/or adding my own debug
logs, but if this ends up requiring days or weeks of real snapshots to
repro, that's going to get old fast. My best idea right now if it comes
to that is to attach gdb to an OSD currently experiencing the issue, let
the cluster mark it down in the meantime, and hope I can step through
the code and find out what the thrashing situation is before it notices
it got marked down and starts doing something else.
If you'd like, you can try my wallclock profiler. This was inspired by
poor-mans-profiling via gdb. Just be aware that the libdw backend is
kind of buggy and sometimes the callgraph ends up with misplaced bits.
Libunwind is slower but more reliable:
https://github.com/markhpc/uwpmp
Just attach it to one of your OSD processes and you'll get an ascii
callgraph of where time is being spent.
As I mentioned on Slack, one curious thing about my case is that it
seems to have been doing around ~100MB reads from BlueFS (probably
entire sst files?), but they *were* being satisfied from page cache, and
despite that the CPU time was almost all spent copying the data in RAM
in the kernel. So that suggests RocksDB wasn't actually *doing* almost
anything with the data (other than checksumming it, the only other place
I saw CPU usage), not even parsing through it once. It was just reading
it and throwing it away repeatedly, or at least that's what it looks
like to me. So I hope higher debug + gdb will point at where this
behavior comes from, and whether it even makes any sense or it's just a
bug. Same with the block cache not working as intended.
This is consistent with the behavior we've observed during prefetching,
though usually a small amount of the data was used while the rest was
thrown away. We hypothesized at the time that perhaps RocksDB is
relying on some characteristic of the posix backend that hides this
behavior and its being exposed via bluefs in BlueStore, but I don't
think we ever came to any conclusion there.
I do want to ask whether there are any debug/scaffolding tools to
possibly try to reproduce the RocksDB workload. I can't easily bring up
a full OSD outside the cluster with all the data (it's not impossible,
but a 16TB HDD is kind of a pain to copy around), but I do have block.db
in a separate volume. If there is some way to bring up that BlueFS
stand-alone, and then attempt to recreate the RocksDB workload (e.g. by
logging it from the real OSD), that might lead to a really handy
reproducer. I don't mind writing my own code, just want to know if
there's a good starting place for that or any existing tooling I could
jumpstart from.
I don't think there's anything quite like what you want, though Igor or
Adam might have better advice. Ceph-bluestore-tool is probably the
closest. You can however test a ceph objectstore directly via fio:
https://github.com/ceph/ceph/blob/main/src/test/fio/README.md
It might be tough to replicate the kind of behaviors you are observing
with CephFS snapshots using fio alone though. It's still an open
question of whether or not the snapshots themselves really matter, or if
its just a question of throwing a bunch of metadata at RocksDB on top of
bluefs and then deleting/fetching it aggressively.
Mark
Cheers,
- Hector
On 2025/06/25 7:48, Mark Nelson wrote:
Hi Hector,
Just as a follow-up,
Here are the comments I mentioned in the ceph slack channel from the PR
where we re-enabled bluestore_buffered_io. I recorded these notes back
when aclamk and I were digging into the RocksDB code to see if there was
anything we could do to improve the situation. They may be valuable if
you want to dig into the RocksDB side of what is going on.
https://github.com/ceph/ceph/pull/38044#issuecomment-789192720
https://github.com/ceph/ceph/pull/38044#issuecomment-790157415
In the end we never solved the problem afaik. We still rely on
bluestore_buffered_io and the linux page cache to hide excessive disk
reads (especially the repeated prefetch reads mentioned in the PR!) when
the block cache misses. In your case, with very limited memory and
potentially limited page cache, we are likely hitting RocksDB
exceptionally hard for metadata lookups and there's no guarantee that
the page cache itself isn't thrashing as well when the block cache
misses. If that's the case, the bluestore_buffered_io "fix" would not
be able to mitigate the repeated prefetch reads we observed. That may
be related to what you are observing in your setup as well.
Mark
On 6/24/25 08:06, Mark Nelson wrote:
Hi Hector,
Sorry I'm a bit late to the party on this one. I wrote the OSD memory
autotuning code and am probably one of the most recent people to
really dig in and refactor bluestore's caches. I'll respond inline
below.
On 6/22/25 05:51, Hector Martin wrote:
Hi all,
I have a small 3-node cluster (4 HDD + 1 SSD OSD per node, ceph version
19.2.2) and noticed that during snaptrim ops (?), the OSDs max out CPU
usage and cluster performance plummets. Most of the CPU usage was
accounted as "system", while actual disk I/O usage was low, so that
didn't sound right.
I perf traced the system, and found that most of the usage is in
__arch_copy_to_user in the kernel, in read() syscalls. That sounds like
the OSD is thrashing buffered block device reads which the kernel
satisfies from the page cache (hence no real I/O load, most of the CPU
usage is from data copies), so it's repeatedly reading the same disk
blocks, which doesn't sound right.
I suspect that what you are seeing here are RocksDB reads, since we
allow those to come from page cache. We have a long standing issue
where RocksDB was repeatedly re-reading the same blocks for readahead
when data isn't in the block cache and buffered IO is the crutch
basically allowing it to perform well. Tyler Stachecki mentioned the
bluefs_buffered_io setting and that indeed is directly related to this
issue and why we''ve flip-flopped on whether to leave it enabled.
This is a bit of a distraction imho though, see below.
I increased osd_memory_target to 2.4G (from 1.2G) live with `ceph
config`, and CPU usage immediately dropped to near zero. However,
waiting a bit eventually the CPU thrashing returns after memory usage
increases. Restarting an OSD has a similar effect. I believe that
something is wrong with the OSD bluestore cache allocation/flush policy,
and when the cache becomes full it starts thrashing reads instead of
evicting colder cached data (or perhaps some cache bucket is starving
another cache bucket of space).
In bluestore itself we have two primary caches: The onode cache and
the buffer cache. Onode cache stores the metadata about objects while
buffer cache stores object data. A cache miss in either of these will
result in data being read, but onode cache misses are far more
expensive because it requires extra work to go fetch the data from
RocksDB (even if the data is stored in RocksDB's block cache!) It may
even result in extra reads of the SST files if the data can't easily
be found in early RocksDB levels.
To me, what you are seeing sounds like severe onode cache misses,
potentially combined with additional read throughput overhead due to
cache thrashing during compaction if snaptrimming is resulting in a
lot of writes or deletes (combined with listings).
I would appreciate some hints on how to debug this. Are there any cache
stats I should be looking at, or info on how the cache is partitioned?
Just to start, the onode cache hit and miss rates in the OSD
performance counter is a good place to start. As Anthony mentioned,
things tend not to work very well once you drop below ~1.5-2GB of
memory. There are some tricks you can play that may help (reducing
various buffer sizes, pglog lengths, RocksDB WAL buffer sizes and
counts, etc). The honest truth though is that Ceph is incredibly
sensitive to onode cache missses, especially if the backend storage is
not very fast.
Here is a perf call trace of the thrashing:
- OSD::ShardedOpWQ::_process(unsigned int, ceph::heartbeat_handle_d*)
- 95.04% ceph::osd::scheduler::PGOpItem::run(OSD*, OSDShard*,
boost::intrusive_ptr<PG>&, ThreadPool::TPHandle&)
- OSD::dequeue_op(boost::intrusive_ptr<PG>,
boost::intrusive_ptr<OpRequest>, ThreadPool::TPHandle&)
- 95.03% PrimaryLogPG::do_request(boost::intrusive_ptr<OpRequest>&,
ThreadPool::TPHandle&)
- PGBackend::handle_message(boost::intrusive_ptr<OpRequest>)
- ECBackend::_handle_message(boost::intrusive_ptr<OpRequest>)
- 88.86% ECBackend::handle_sub_write(pg_shard_t,
boost::intrusive_ptr<OpRequest>, ECSubWrite&, ZTracer::Trace const&,
ECListener&)
- 88.78% non-virtual thunk to
PrimaryLogPG::queue_transactions(std::vector<ceph::os::Transaction,
std::allocator<ceph::os::Transaction> >&,
boost::intrusive_ptr<OpRequest>)
-
BlueStore::queue_transactions(boost::intrusive_ptr<ObjectStore::CollectionImpl>&,
std::vector<ceph::os::Transaction,
std::allocator<ceph::os::Transaction> >&, boost::intrusiv
- 88.75% BlueStore::_txc_add_transaction(BlueStore::TransContext*,
ceph::os::Transaction*)
- 88.71% BlueStore::_remove(BlueStore::TransContext*,
boost::intrusive_ptr<BlueStore::Collection>&,
boost::intrusive_ptr<BlueStore::Onode>&)
- BlueStore::_do_remove(BlueStore::TransContext*,
boost::intrusive_ptr<BlueStore::Collection>&,
boost::intrusive_ptr<BlueStore::Onode>&)
- 88.69% BlueStore::_do_truncate(BlueStore::TransContext*,
boost::intrusive_ptr<BlueStore::Collection>&,
boost::intrusive_ptr<BlueStore::Onode>&, unsigned long, std
- 88.68% BlueStore::_wctx_finish(BlueStore::TransContext*,
boost::intrusive_ptr<BlueStore::Collection>&,
boost::intrusive_ptr<BlueStore::Onode>&, BlueStore::Writ
- 88.65%
BlueStore::Collection::load_shared_blob(boost::intrusive_ptr<BlueStore::SharedBlob>)
- 88.64% RocksDBStore::get(std::__cxx11::basic_string<char,
std::char_traits<char>, std::allocator<char> > const&,
std::__cxx11::basic_string<char, std::ch
- 88.61% rocksdb::DBImpl::Get(rocksdb::ReadOptions const&,
rocksdb::ColumnFamilyHandle*, rocksdb::Slice const&,
rocksdb::PinnableSlice*)
- rocksdb::DBImpl::GetImpl(rocksdb::ReadOptions const&,
rocksdb::Slice const&, rocksdb::DBImpl::GetImplOptions&)
- 88.43% rocksdb::Version::Get(rocksdb::ReadOptions const&,
rocksdb::LookupKey const&, rocksdb::PinnableSlice*,
rocksdb::PinnableWideColumns*, std
- 88.41% rocksdb::TableCache::Get(rocksdb::ReadOptions const&,
rocksdb::InternalKeyComparator const&, rocksdb::FileMetaData const&,
rocksdb::Sl
- rocksdb::BlockBasedTable::Get(rocksdb::ReadOptions const&,
rocksdb::Slice const&, rocksdb::GetContext*, rocksdb::SliceTransform
const*, bo
- 88.32%
rocksdb::BlockBasedTable::FullFilterKeyMayMatch(rocksdb::FilterBlockReader*,
rocksdb::Slice const&, bool, rocksdb::SliceTransfor
- rocksdb::FullFilterBlockReader::MayMatch(rocksdb::Slice const&,
bool, rocksdb::GetContext*, rocksdb::BlockCacheLookupContext*, rocks
- 88.29%
rocksdb::FilterBlockReaderCommon<rocksdb::ParsedFullFilterBlock>::GetOrReadFilterBlock(bool,
rocksdb::GetContext*, rocksdb
-
rocksdb::FilterBlockReaderCommon<rocksdb::ParsedFullFilterBlock>::ReadFilterBlock(rocksdb::BlockBasedTable
const*, rocksdb::Fi
- rocksdb::Status
rocksdb::BlockBasedTable::RetrieveBlock<rocksdb::ParsedFullFilterBlock>(rocksdb::FilePrefetchBuffer*,
rocks
- rocksdb::Status
rocksdb::BlockBasedTable::MaybeReadBlockAndLoadToCache<rocksdb::ParsedFullFilterBlock>(rocksdb::FilePref
- 88.25% rocksdb::BlockFetcher::ReadBlockContents()
[ note: split, the rest is + 19.42% rocksdb::VerifyBlockChecksum]
- 68.80% rocksdb::RandomAccessFileReader::Read(rocksdb::IOOptions
const&, unsigned long, unsigned long, rocksdb::Sli
[ note: at this level the call trace splits into 4, but it all leads to
the same place ]
- 35.99% 0xaaaac0992e40
BlueRocksRandomAccessFile::Read(unsigned long, unsigned long,
rocksdb::Slice*, char*) const
BlueFS::_read_random(BlueFS::FileReader*, unsigned long, unsigned
long, char*)
- KernelDevice::read_random(unsigned long, unsigned long, char*, bool)
- 35.98% __libc_pread
- el0_svc
- invoke_syscall
- 35.97% __arm64_sys_pread64
- 35.96% vfs_read
- blkdev_read_iter
- 35.93% filemap_read
- 35.28% copy_page_to_iter
35.01% __arch_copy_to_user
Note how much of the perf call trace is spent in RocksDB fetching
blocks as a result of trying to load BlueStore shared_blobs via
onodes. Presumably your onode hit ratio is very low, and bluestore is
trying to fetch a significant ratio of the onodes from RocksDB, which
itself likely has very little block cache, so each onode read is
coming from RocksDB, which is likely trying to fetch a block from
disk, putting it in the block cache, but then may be immediately
discarding it if there is very little memory for the next block.
One thing that's missing here is a description of the workload that is
happening between snapshots. Are you doing a lot of IO that could
result in severe fragmentation between snapshots?
Thanks,
Mark
- Hector
_______________________________________________
ceph-users mailing list -- ceph-users@ceph.io
To unsubscribe send an email to ceph-users-le...@ceph.io
--
Best Regards,
Mark Nelson
Head of Research and Development
Clyso GmbH
p: +49 89 21552391 12 | a: Minnesota, USA
w: https://clyso.com | e: mark.nel...@clyso.com
We are hiring: https://www.clyso.com/jobs/
_______________________________________________
ceph-users mailing list -- ceph-users@ceph.io
To unsubscribe send an email to ceph-users-le...@ceph.io
