cockroachdb / cockroachdb/cockroach

schema: potential 2X index backfill perf regression during `tpce init`

Open
#95,163 11 comments 0 reactions 0 assignees View on GitHub
C-investigation C-performance T-storage
Dominant language
Go
Stars
32.5k
Forks
4.1k
PR merge metrics
PR metrics pending

Description

**Describe the problem**

When init'ing the tpce/custumers=2m workload on 22.2, two large index backfills took a total of 40 hrs to add 10TB of replicated physical data to the cluster, which is double the amount of time reported in the [tpce eval](https://docs.google.com/document/d/1wzkBXaA3Ap_daMV1oY1AhQqlnAjO3pIVLZTXY53m0Xk/edit#heading=h.h7qxj5lp2qe) for the same workload/hardware setup on 22.1. Put another way, this 15 node/48 vcpu cluster performed these backfills with a throughput of 5 MB/S/Node when no foreground workload was running.

**NOTE**: during discussion below, I realized that I left the `COCKROACH_ROCKSDB_CONCURRENCY` set to the default of 4, while during Nathan's run with 22.1, he increased this env var to 16. Had I also done this, the regression probably would been alleviated. That being said, this backfill with default settings, is still slow as heck. A throughput of 5 - 10 mb/s/node is about 10 to 20 x slower than a comparable restore or import of this size.

**To Reproduce**

Follow the repro steps at the bottom of the tpce eval [doc](https://docs.google.com/document/d/1wzkBXaA3Ap_daMV1oY1AhQqlnAjO3pIVLZTXY53m0Xk/edit#). During the `tpce init` cmd, the following indices will be created:
```
// took 35 hrs (the particularly problematic one)
CREATE INDEX ON tpce.public.trade (t_s_symb, t_dts ASC) STORING (t_ca_id, t_exec_name, t_is_cash, t_trade_price, t_qty, t_tt_id)

// took 7 hrs
CREATE INDEX ON tpce.public.trade (t_ca_id, t_dts DESC) STORING (t_st_id, t_tt_id, t_is_cash, t_s_symb, t_qty, t_bid_price, t_exec_name, t_trade_price, t_chrg)
```

**Initial Investigation of the first backfill**
- During the first backfill, I observed:
- Hardware is not at fault: CPU utilization was ridiculously low (less than 20%); Disks had plenty of bandwidth.
- Disk throughput followed a sawtooth pattern that peaked at 300 Mb/s/node, well below pd-ssd throughput capacity of around 2.4 GB/s

- The logs indicate that stores across the cluster are throttling sstable writes. Specifically, this message:
https://github.com/cockroachdb/cockroach/blob/master/pkg/kv/kvserver/store_send.go#L359
` "SST ingestion was delayed by %v (%v for storage engine back-pressure)"`
- Initially, I thought the `kv.bulk_io_write.concurrent_addsstable_requests` limiter was the bottleneck, but increasing this cluster setting had no effect.
- After bumping the vmodule on `engine.go` , I saw a lot of log lines related to storage.PreIngestDelay() for a _select_ number of nodes https://github.com/cockroachdb/cockroach/blob/master/pkg/storage/engine.go#L1439_
```
I230112 23:40:42.475972 730617225 storage/engine.go:1404 ⋮ [n12,s12] 3074034 delaying SST ingestion 500ms. 474 L0 files, 21 L0 Sublevels
I230112 23:40:42.478005 730617161 storage/engine.go:1404 ⋮ [n12,s12] 3074035 delaying SST ingestion 500ms. 474 L0 files, 21 L0 Sublevels
I230112 23:40:42.479725 730617189 storage/engine.go:1404 ⋮ [n12,s12] 3074036 delaying SST ingestion 500ms. 474 L0 files, 21 L0 Sublevels
I230112 23:40:42.483992 730617133 storage/engine.go:1404 ⋮ [n12,s12] 3074037 delaying SST ingestion 500ms. 474 L0 files, 21 L0 Sublevels
I230112 23:40:42.485875 730617226 storage/engine.go:1404 ⋮ [n12,s12] 3074038 delaying SST ingestion 500ms. 474 L0 files, 21 L0 Sublevels
I230112 23:40:42.487637 730617033 storage/engine.go:1404 ⋮ [n12,s12] 3074039 delaying SST ingestion 500ms. 474 L0 files, 21 L0 Sublevels
I230112 23:40:42.490749 730617134 storage/engine.go:1404 ⋮ [n12,s12] 3074040 delaying SST ingestion 500ms. 474 L0 files, 21 L0 Sublevels
```
- So, the addSSTable request throttling here is due to the L0 sublevel count exceeding the 20 sublevel threshold, on a _**subset**_ of nodes, yet perf on _all_ nodes seems to suffer!
- The sawtooth pattern on with addSSTable send rate aligns with L0-sub level count and num files (see figure below)

This investigation leaves with me with 3 questions, in order of importance:
- The bursty workload across all nodes: If one or two stores are throttling addSSTable requests, why do all nodes seem to get throttled around the same time for the same amount of time? I’d hope that if only one node (e.g. n12) gets throttled, other kv servers could continue to process requests. That doesn’t seem to be the case-- they all get blocked, even if their l0-sublevel count is below 20. I wonder if this is due to KV or something in the dist sql processors.
- N12's extra work: why is n12 receiving extra work? I wonder if this has something to do with the index backfill dist-sql processors.
- L0 Write rate: Squinting at at the ratio of addSSTable.Recv to l0-numfiles, it seems 25% of add sstables are sadly written to L0 instead of straight to L6, across all nodes. If we could lower this, the problem would be less acute. Is the ratio a surprise? Idk.

To quote Sumeer, here are two places to look next:
- "if the call to PreIngestDelay is coming from addSSTablePreApply then the delaying is happening below raft, which could affect a replica even if the overloaded store is only a follower. That may widen the effect of a single overloaded store. There are other things involved like the raft proposalQuota pool etc., and there may be KV metrics to look at whether this is happening (KV folks would know)."
- one could potentially speed things up by setting "COCKROACH_ROCKSDB_CONCURRENCY to a much higher value (the default is 4), to increase the number of concurrent compactions."
image

Jira issue: CRDB-23380

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.