storage: slower incremental backups on Pebble

[petermattis]

In internal testing of Pebble on one node of an internal test cluster, we noticed increased read ops on the Pebble node. (Pebble is n3, the node shown in red).

Further investigation is pointing the finger at the read op increase occurring during backups. Incremental backups when Pebble was enabled on n3 were taking ~40min. After switching n3 back to RocksDB the next incremental backup took 7m12s.

Nightly backup roachtests which perform full backups do not show any time difference between RocksDB and Pebble.

It is possible there is a big in the timebound iterator code, or in the ExportToSst code (which lies at the heart of backup) which is causing significantly increased reads that in turn leads to slower backups. @dt will be doing some experimentation on another test cluster. @joshimhoff is pulling the sizes of recent Pebble and RocksDB generated incremental backups to see if they are similar in size.

This is a developing story and will be updated soon.

[blathers-crl]

Hi @petermattis, please add a C-ategory label to your issue. Check out the label system docs.

While you're here, please consider adding an A- label to help keep our repository tidy.

_{🦉 Hoot! I am a Blathers, a bot for CockroachDB. My owner is otan.}

[petermattis]

Full backup on May 28 took 51m29s. Full backup on May 29 took 3h25m27s. So perhaps this isn’t an incremental backup problem, but simply a backup problem.

[itsbilal]

Based on my own testing today, this can be generalized to all backups, not just incremental backups.

I spun up two clusters on AWS with these parameters:
roachprod create $CLUSTER --aws-ebs-iops 1300 --aws-ebs-volume-size 250 --aws-ebs-volume-type io1 --local-ssd=false --aws-machine-type m5.xlarge -n 4 --clouds aws

Both were running 20.1.1, one with pebble and one with rocksdb.

Then imported tpcc with 2000 warehouses into both clusters, started running the tpcc workload, and in parallel I kicked off a backup to s3. The almost-identical backup took 35 mins to finish in rocksdb, while it has been ongoing on the pebble one for 1h21m so far (and is still ~60% done).

I noticed that both rocksdb and pebble took full advantage of the provisioned 1300 IOPS at the start of the backup, before declining to just under the limit, but more interestingly, rocksdb had much higher read bytes/throughput numbers than pebble did, throughout the backup run:

(rocksdb on top, pebble on the bottom)

I'd say this is a good enough reproduction. Will profile and see what's actually going on tomorrow.

[petermattis]

I'd say this is a good enough reproduction. Will profile and see what's actually going on tomorrow.

Yeah, this looks like a solid reproduction. The timings even match as it looks like the Pebble backup will take ~4x as long as the RocksDB one which matches what we saw on the test cluster. Definitely curious what is limiting Pebble here.

[itsbilal]

Another day of investigation. I looked at CPU profiles but nothing really stood out; I tried out some improvements to sstable.MemFile around pre-growing the bytes.Buffer up to targetSize and that helped increase the CPU time used by the export goroutine, but not at all significantly.

Running the pebble and rocks clusters side-by-side and blktrace-ing the writes on the data directory showed something interesting: the reads done with pebble max out at 24 file blocks requested, while the rocksdb reads max out at a much higher block count (288).

More interestingly, the first read in a "new" region of disk seems to be pretty large (always larger than 24) under rocksdb, after which we see many "small" sequential reads (8,16,24 blocks). With pebble, the first initial read is also small, requiring many more IO operations to begin reading data blocks in the file.

The summary stats under both engines also agree with what the admin UI showed: fewer IO events resulting in more data being returned.

I haven't dived deep into the block based table reader code in RocksDB yet, but at first glance there seems to be quite a bit of prefetching of index/filter blocks happening there - maybe that helps make read I/O more efficient under rocksdb?

[petermattis]

I haven't dived deep into the block based table reader code in RocksDB yet, but at first glance there seems to be quite a bit of prefetching of index/filter blocks happening there - maybe that helps make read I/O more efficient under rocksdb?

Certainly possible. I assume you're referring to the code in BlockBasedTableIterator<TBlockIter, TValue>::InitDataBlock. Rather than try to duplicate this code in Pebble, a quicker way to test your theory is to disable the implicit read-ahead code in RocksDB.

[petermattis]

A reminder about cockroachdb/pebble#198. Pebble should be specifying the same fadvise settings as RocksDB. Worthwhile to double-check that, though. I'd do so by instrumenting the RocksDB code as trying to trace through what it uses based on code inspection is error prone.

[petermattis]

Here's the RocksDB PR where the dynamic read-ahead code landed: facebook/rocksdb#3282.

[petermattis]

TIL about the readahead syscall. If this is the source of the perf discrepancy, adding support for this in Pebble should be straightforward.

[itsbilal]

Disabling the dynamic readahead code in rocksdb completely closed the backup performance/time gap in my tpcc-2k test setup; in that it was just as bad as Pebble then. I've added a simple change to implement the same functionality in Pebble: cockroachdb/pebble#726

From early test runs with this change, I can see Pebble backups slightly outperform RocksDB (with implicit automatic readahead added back in). Doing more testing to confirm my early results.

[petermattis]

@itsbilal Can this be closed now?

[itsbilal]

@petermattis I was thinking of keeping this open until the fix is in 20.1 and we can confirm it works in the telemetry cluster. But I'm confident enough with closing this as that may not happen for a long time, and it addresses the issue we saw in my test cluster.

[joshimhoff]

Excited for the fix!

[itsbilal]

A series of test runs with tpcc-3k before/after the readahead change showed that the gap with rocksdb is almost closed: a RocksDB backup took 20-25mins, a Pebble (w/ readahead) backup took 25-30 mins, and Pebble without readahead took 1h-1h15m.

The RocksDB-like simpler-but-more-wasteful readahead implementation that I prototyped earlier performed slightly better on backups than the more conservative implementation that landed, but I didn't really benchmark other read-heavy workloads with that prototype (vs. the new one). I'm sure there are some cases where the RocksDB-like implementation performs worse (reads ahead too early when it's not necessary) than the pebble solution.

I think it's fair to close this issue at this point.