facebook / facebook/rocksdb

Performance degradation with high volume writes and deletes

Open
#4,930 2 comments 0 reactions 0 assignees View on GitHub
Dominant language
C++
Stars
32.1k
Forks
6.9k
Avg merge
32m
Merged PRs (30d)
1

Description

> Note: Please use Issues only for bug reports. For questions, discussions, feature requests, etc. post to dev group: https://www.facebook.com/groups/rocksdb.dev

I am developing a drop in replacement for Boost multi-index containers that instead uses rocksdb as the backing data store. My implementation is correct and yields correct results for our existing workload and tests, but I am observing significant performance degradations at scale. Most of the runtime of the application is being spent in `DBIter::SeekToFirst` and `DBIter::Next`.

My application frequently uses one index as a queue. My theory is that because these keys change frequently, I am experiencing a higher number of iter skips than would normally be expected.

Below are statistics from a slice of a run.

> rocksdb_account_object stats:
> rocksdb.block.cache.miss COUNT : 628905
> rocksdb.block.cache.hit COUNT : 39635192
> rocksdb.block.cache.add COUNT : 628415
> rocksdb.block.cache.add.failures COUNT : 0
> rocksdb.block.cache.index.miss COUNT : 0
> rocksdb.block.cache.index.hit COUNT : 0
> rocksdb.block.cache.index.add COUNT : 0
> rocksdb.block.cache.index.bytes.insert COUNT : 0
> rocksdb.block.cache.index.bytes.evict COUNT : 0
> rocksdb.block.cache.filter.miss COUNT : 0
> rocksdb.block.cache.filter.hit COUNT : 0
> rocksdb.block.cache.filter.add COUNT : 0
> rocksdb.block.cache.filter.bytes.insert COUNT : 0
> rocksdb.block.cache.filter.bytes.evict COUNT : 0
> rocksdb.block.cache.data.miss COUNT : 628905
> rocksdb.block.cache.data.hit COUNT : 39635192
> rocksdb.block.cache.data.add COUNT : 628415
> rocksdb.block.cache.data.bytes.insert COUNT : 2601761453
> rocksdb.block.cache.bytes.read COUNT : 48820104456
> rocksdb.block.cache.bytes.write COUNT : 2601761453
> rocksdb.bloom.filter.useful COUNT : 0
> rocksdb.bloom.filter.full.positive COUNT : 0
> rocksdb.bloom.filter.full.true.positive COUNT : 0
> rocksdb.persistent.cache.hit COUNT : 0
> rocksdb.persistent.cache.miss COUNT : 0
> rocksdb.sim.block.cache.hit COUNT : 0
> rocksdb.sim.block.cache.miss COUNT : 0
> rocksdb.memtable.hit COUNT : 2306109
> rocksdb.memtable.miss COUNT : 1879058
> rocksdb.l0.hit COUNT : 190693
> rocksdb.l1.hit COUNT : 165409
> rocksdb.l2andup.hit COUNT : 0
> rocksdb.compaction.key.drop.new COUNT : 5090
> rocksdb.compaction.key.drop.obsolete COUNT : 0
> rocksdb.compaction.key.drop.range_del COUNT : 0
> rocksdb.compaction.key.drop.user COUNT : 0
> rocksdb.compaction.range_del.drop.obsolete COUNT : 0
> rocksdb.compaction.optimized.del.drop.obsolete COUNT : 0
> rocksdb.compaction.cancelled COUNT : 0
> rocksdb.number.keys.written COUNT : 13448501
> rocksdb.number.keys.read COUNT : 4185167
> rocksdb.number.keys.updated COUNT : 0
> rocksdb.bytes.written COUNT : 3666457298
> rocksdb.bytes.read COUNT : 755412717
> rocksdb.number.db.seek COUNT : 38319348
> rocksdb.number.db.next COUNT : 1497682
> rocksdb.number.db.prev COUNT : 0
> rocksdb.number.db.seek.found COUNT : 28416043
> rocksdb.number.db.next.found COUNT : 1497622
> rocksdb.number.db.prev.found COUNT : 0
> rocksdb.db.iter.bytes.read COUNT : 7019263629
> rocksdb.no.file.closes COUNT : 0
> rocksdb.no.file.opens COUNT : 99
> rocksdb.no.file.errors COUNT : 0
> rocksdb.l0.slowdown.micros COUNT : 0
> rocksdb.memtable.compaction.micros COUNT : 0
> rocksdb.l0.num.files.stall.micros COUNT : 0
> rocksdb.stall.micros COUNT : 0
> rocksdb.db.mutex.wait.micros COUNT : 0
> rocksdb.rate.limit.delay.millis COUNT : 0
> rocksdb.num.iterators COUNT : 0
> rocksdb.number.multiget.get COUNT : 0
> rocksdb.number.multiget.keys.read COUNT : 0
> rocksdb.number.multiget.bytes.read COUNT : 0
> rocksdb.number.deletes.filtered COUNT : 0
> rocksdb.number.merge.failures COUNT : 0
> rocksdb.bloom.filter.prefix.checked COUNT : 0
> rocksdb.bloom.filter.prefix.useful COUNT : 0
> rocksdb.number.reseeks.iteration COUNT : 46
> rocksdb.getupdatessince.calls COUNT : 0
> rocksdb.block.cachecompressed.miss COUNT : 0
> rocksdb.block.cachecompressed.hit COUNT : 0
> rocksdb.block.cachecompressed.add COUNT : 0
> rocksdb.block.cachecompressed.add.failures COUNT : 0
> rocksdb.wal.synced COUNT : 0
> rocksdb.wal.bytes COUNT : 3666457298
> rocksdb.write.self COUNT : 10509129
> rocksdb.write.other COUNT : 0
> rocksdb.write.timeout COUNT : 0
> rocksdb.write.wal COUNT : 21018258
> rocksdb.compact.read.bytes COUNT : 599283
> rocksdb.compact.write.bytes COUNT : 1021055
> rocksdb.flush.write.bytes COUNT : 20638957
> rocksdb.number.direct.load.table.properties COUNT : 0
> rocksdb.number.superversion_acquires COUNT : 204
> rocksdb.number.superversion_releases COUNT : 1
> rocksdb.number.superversion_cleanups COUNT : 1
> rocksdb.number.block.compressed COUNT : 12923
> rocksdb.number.block.decompressed COUNT : 628928
> rocksdb.number.block.not_compressed COUNT : 0
> rocksdb.merge.operation.time.nanos COUNT : 0
> rocksdb.filter.operation.time.nanos COUNT : 0
> rocksdb.row.cache.hit COUNT : 0
> rocksdb.row.cache.miss COUNT : 0
> rocksdb.read.amp.estimate.useful.bytes COUNT : 0
> rocksdb.read.amp.total.read.bytes COUNT : 0
> rocksdb.number.rate_limiter.drains COUNT : 0
> rocksdb.number.iter.skip COUNT : 4592785156
> rocksdb.blobdb.num.put COUNT : 0
> rocksdb.blobdb.num.write COUNT : 0
> rocksdb.blobdb.num.get COUNT : 0
> rocksdb.blobdb.num.multiget COUNT : 0
> rocksdb.blobdb.num.seek COUNT : 0
> rocksdb.blobdb.num.next COUNT : 0
> rocksdb.blobdb.num.prev COUNT : 0
> rocksdb.blobdb.num.keys.written COUNT : 0
> rocksdb.blobdb.num.keys.read COUNT : 0
> rocksdb.blobdb.bytes.written COUNT : 0
> rocksdb.blobdb.bytes.read COUNT : 0
> rocksdb.blobdb.write.inlined COUNT : 0
> rocksdb.blobdb.write.inlined.ttl COUNT : 0
> rocksdb.blobdb.write.blob COUNT : 0
> rocksdb.blobdb.write.blob.ttl COUNT : 0
> rocksdb.blobdb.blob.file.bytes.written COUNT : 0
> rocksdb.blobdb.blob.file.bytes.read COUNT : 0
> rocksdb.blobdb.blob.file.synced COUNT : 0
> rocksdb.blobdb.blob.index.expired.count COUNT : 0
> rocksdb.blobdb.blob.index.expired.size COUNT : 0
> rocksdb.blobdb.blob.index.evicted.count COUNT : 0
> rocksdb.blobdb.blob.index.evicted.size COUNT : 0
> rocksdb.blobdb.gc.num.files COUNT : 0
> rocksdb.blobdb.gc.num.new.files COUNT : 0
> rocksdb.blobdb.gc.failures COUNT : 0
> rocksdb.blobdb.gc.num.keys.overwritten COUNT : 0
> rocksdb.blobdb.gc.num.keys.expired COUNT : 0
> rocksdb.blobdb.gc.num.keys.relocated COUNT : 0
> rocksdb.blobdb.gc.bytes.overwritten COUNT : 0
> rocksdb.blobdb.gc.bytes.expired COUNT : 0
> rocksdb.blobdb.gc.bytes.relocated COUNT : 0
> rocksdb.blobdb.fifo.num.files.evicted COUNT : 0
> rocksdb.blobdb.fifo.num.keys.evicted COUNT : 0
> rocksdb.blobdb.fifo.bytes.evicted COUNT : 0
> rocksdb.txn.overhead.mutex.prepare COUNT : 0
> rocksdb.txn.overhead.mutex.old.commit.map COUNT : 0
> rocksdb.txn.overhead.duplicate.key COUNT : 0
> rocksdb.txn.overhead.mutex.snapshot COUNT : 0
> rocksdb.number.multiget.keys.found COUNT : 0
> rocksdb.db.get.micros P50 : 1.357170 P95 : 5.325676 P99 : 10.618234 P100 : 6415.000000 COUNT : 4185167 SUM : 9957969
> rocksdb.db.write.micros P50 : 7.226728 P95 : 14.014834 P99 : 23.827377 P100 : 22380.000000 COUNT : 10509129 SUM : 85902774
> rocksdb.compaction.times.micros P50 : 352.142857 P95 : 6751.000000 P99 : 6751.000000 P100 : 6751.000000 COUNT : 11 SUM : 15990
> rocksdb.subcompaction.setup.times.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.table.sync.micros P50 : 155.882353 P95 : 371.333333 P99 : 5632.000000 P100 : 6081.000000 COUNT : 88 SUM : 27280
> rocksdb.compaction.outfile.sync.micros P50 : 148.571429 P95 : 443.000000 P99 : 443.000000 P100 : 443.000000 COUNT : 11 SUM : 2085
> rocksdb.wal.file.sync.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.manifest.file.sync.micros P50 : 91.406250 P95 : 188.333333 P99 : 190.000000 P100 : 190.000000 COUNT : 185 SUM : 17591
> rocksdb.table.open.io.micros P50 : 48.508621 P95 : 76.850000 P99 : 251.300000 P100 : 297.000000 COUNT : 99 SUM : 5530
> rocksdb.db.multiget.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.read.block.compaction.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.read.block.get.micros P50 : 4.352976 P95 : 8.777943 P99 : 16.428933 P100 : 411.000000 COUNT : 628905 SUM : 3260977
> rocksdb.write.raw.block.micros P50 : 0.535897 P95 : 2.073499 P99 : 5.334074 P100 : 1054.000000 COUNT : 13197 SUM : 16083
> rocksdb.l0.slowdown.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.memtable.compaction.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.num.files.stall.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.hard.rate.limit.delay.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.soft.rate.limit.delay.count P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.numfiles.in.singlecompaction P50 : 4.000000 P95 : 4.000000 P99 : 4.000000 P100 : 4.000000 COUNT : 12 SUM : 48
> rocksdb.db.seek.micros P50 : 1.150458 P95 : 3.845508 P99 : 9.662481 P100 : 5999.000000 COUNT : 28415078 SUM : 150800652
> rocksdb.db.write.stall P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.sst.read.micros P50 : 1.320659 P95 : 2.900883 P99 : 5.741020 P100 : 405.000000 COUNT : 629301 SUM : 1212873
> rocksdb.num.subcompactions.scheduled P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.bytes.per.read P50 : 45.320826 P95 : 528.000000 P99 : 528.000000 P100 : 528.000000 COUNT : 4185167 SUM : 755412717
> rocksdb.bytes.per.write P50 : 323.419527 P95 : 526.875245 P99 : 569.887142 P100 : 21418.000000 COUNT : 10509129 SUM : 3666457298
> rocksdb.bytes.per.multiget P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.bytes.compressed P50 : 3644.732735 P95 : 4325.421381 P99 : 4385.927039 P100 : 215849.000000 COUNT : 12923 SUM : 52070096
> rocksdb.bytes.decompressed P50 : 3649.893849 P95 : 4325.008707 P99 : 4385.018916 P100 : 215849.000000 COUNT : 628928 SUM : 2553891241
> rocksdb.compression.times.nanos P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.decompression.times.nanos P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.read.num.merge_operands P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.key.size P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.value.size P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.write.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.get.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.multiget.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.seek.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.next.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.prev.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.blob.file.write.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.blob.file.read.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.blob.file.sync.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.gc.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.compression.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.blobdb.decompression.micros P50 : 0.000000 P95 : 0.000000 P99 : 0.000000 P100 : 0.000000 COUNT : 0 SUM : 0
> rocksdb.db.flush.micros P50 : 11730.357143 P95 : 53750.000000 P99 : 197470.000000 P100 : 197470.000000 COUNT : 57 SUM : 1125087

`rocksdb.number.iter.skip COUNT : 4592785156` seem to me to be the most concerning metric.

I noticed in #3760 a small discussion which seems to be related.

> Another performance issue is: If there are some small DeleteRange (each delete range about 10~100 keys) or many Deleted keys in the iterator range, it may impact the iterator performance greatly.
>
> Is there any way we can improve the iterator with some deleted keys?

> Writes taking long at low write tps is not normal for RocksDB. Can you profile the system to see what could be causing it? Is there a CPU spike or disk latency spike?
>
> Regarding your question about iterator performance, you can try to tune ReadOptions::max_skippable_internal_keys and/or ReadOptions::ignore_range_deletions. Keep in mind that changing these will alter the iteration results though.

Changing iteration results is not an option for my application.

The automated tuning tool has not yielded any results for me (the output is always zero).

### Expected behavior

Because keys are sorted, I expect that common iteration tasks, such as querying the first value and iterating to the next would be done in constant time.

### Actual behavior

While writes are still in the memtable, constant time behavior is not preserved.

### Steps to reproduce the behavior

Contributor guide

Open the contributing guide

Assessment

This issue has not been assessed yet.

Get new issues in your inbox

A short digest of beginner-friendly GitHub issues.