backfill: high latency when index backfill adds SSTs with large spans

[thoszhang]

We've been seeing significantly reduced throughput and increased latency for OLTP foreground traffic during index backfills in certain cases, as well as long running times for the index backfill itself.

This is related to what @awoods187 has also seen while testing with TPCC 1k (as reported in #34744), but this issue focuses on a workload specifically intended to demonstrate this behavior. It's possible that TPCC's variety and complexity in queries obscures some of the impact of a single index backfill.

I set up a roachtest to run the bulkingest workload on 4 nodes, which creates a table with 20 million rows with the table schema

CREATE TABLE bulkingest (
	a INT,
	b INT,
	c INT,
	payload BYTES,
	PRIMARY KEY (a, b, c)
)

where a is populated with sequential values and payload is populated with random values. (To reproduce, run the test in master...lucy-zhang:repro, with the environment variable COCKROACH_IMPORT_WORKLOAD_FASTER set to true.). The test creates an index on (payload, a) and then on (a, payload), and issues updates to the table in parallel. The two backfills are visible below (and took 8min and 2min, respectively):

There are multiple issues here:

1. When an AddSSTable command is queued, all other writes to the same span will be blocked. When the index order is uncorrelated with the primary key order (since payload has random values), the SSTs that are generated will cover very wide spans relative to the number of keys they contain, which is why adding the (payload, a) index is worse than adding the (a, payload) index.

   This is confirmed by logging the number of existing keys in the span in EvalAddSSTable. For the (payload, a) index, the number of existing keys in each span is much higher. We add a lot of SSTs with only a few thousand keys that span an entire range that already contains 100,000s of keys.

   @dt has pointed out that this could be mitigated if we flushed an SST every time we detected a large gap in the index keys being written, to produce a larger number of denser SSTs.

2. When writing SSTs to nonempty ranges, repeatedly computing MVCC stats for the range is expensive, and we run into the known issue where a single node spends a lot of time computing stats while others node are blocked on AddSSTable calls (see storage/bulk: split and scatter during ingest #35016 (comment) and the accompanying PR).

   I ran this test with batcheval: estimate stats in EvalAddSSTable #35231, which skips the stats recomputation in AddSSTable (and defers accurate stats recomputation to when ranges are split). This makes the first backfill much faster (from 8min to 4min), and I saw a similar 2x improvement when running a larger version of this test as well as the inverted index roachtest (which went from ~50 minutes to ~25 minutes).

   The effect of the backfill on foreground traffic seems just as large (maybe larger?), but batcheval: estimate stats in EvalAddSSTable #35231 will still be an improvement if the total amount of time the backfill is holding up traffic goes down.

   

3. Even with the improvement offered by batcheval: estimate stats in EvalAddSSTable #35231 and on the "well-behaved" index on (a, payload), the effect on foreground traffic is still significant, and I don't know of other reasons to pinpoint for this. Is this cluster underprovisioned?

Other notes:

• The inverted index roachtest, which also builds an index on a randomly generated payload, also consistently shows the severe drop in throughput for foreground traffic, and p99 latency increasing to 1s-10s.
• I tried running the test on @vivekmenezes's branch (WIP: sql: flush #35855) to store more KVs in memory before flushing SSTs and it didn't make an appreciable difference, at least for this workload.

Epic CRDB-8816

Jira issue: CRDB-4530

[petermattis]

Cc @ajkr for your thoughts on sstable ingestion and what we can be doing to improve it for restore/import/backfill.

[thoszhang]

I ran this with a larger table (with 100 million rows) on a 10-node cluster to get a sense of what happens with longer index backfills. With the changes in #35231, even though the backfill took less time, the p99 latency for table updates was much worse during that time (in the 1s-10s range, as opposed to generally <1s on master). So, with everything else being equal, #35231 might actually make the foreground traffic latency problem worse in the short term for certain tables/indexes, even though it does address one of the problems that contribute to it.

[dt]

I wonder if that p99 increase is because of splits taking longer? I wonder if combined with better presplitting we see an improvement.

[ajkr]

@petermattis I think @dt's plan to cut SSTs where there are large gaps is a good idea, both to prevent multiple ranges from being simultaneously blocked and to give RocksDB a greater chance to ingest files directly into L1+. Also @dt and I talked last week about increasing or disabling write stalls/stops while the ingest is happening. Not sure if this is already landed, or if write stalls during ingestion are currently a problem. I can help look if needed.

[dt]

I don't think we're currently hitting stalls -- lots of stats recomputes yes, and compactions certainly, but I have only observed a few runs logging non-zero l0_slowdown counts. If it is mostly stats and compactions, #35231 plus something like #35236 (or even more aggressive than that) might help coupled with more preemptive splitting,

[thoszhang]

I misspoke in my most recent comment: That was on a 4-node cluster with 50 million rows. With this same configuration and with stats recomputation turned off (which is the setup that generated ~10s p99 latency values), I actually see a lot of stalls. Here's a set of compaction stats that I grabbed at random while the backfill was running:

I190326 17:31:59.282542 168 storage/store.go:4155  [n3,s3] sstables (read amplification = 28):
0 [  27M  25 ]: 5M 3M 2M 1M[10] 723K 704K 687K 674K 576K 552K 548K 491K 482K 475K 105K 10K
4 [ 420M 106 ]: 4M[101] 3M 2M[2] 1M 541K
5 [ 612M 227 ]: 4M[143] 3M[2] 2M[3] 1M 685K 470K 460K 459K 456K 441K 430K 408K 400K 392K 390K 388K 387K 386K 385K[2] 384K 382K 381K 376K 375K 374K[2] 371K 360K 357K 356K[2] 355K 349K 331K 319K 311K 308K 294K 227K 212K 204K 198K 182K 77K 57K 53K 48K 47K 46K 45K 44K 43K[2] 32K 30K 29K 27K[3] 26K 25K 24K[5] 23K[2] 22K 21K 19K[2] 18K[3] 17K[2] 14K[2] 7K 1K
6 [   6G 590 ]: 37M[13] 36M[52] 33M 31M 28M[2] 26M 20M 19M 18M 15M[2] 12M[2] 10M 8M[383] 7M[22] 6M[5] 5M[6] 4M[76] 3M[4] 2M[5] 1M 969K 945K 940K 758K 413K 411K 55K 28K 24K 1K
I190326 17:31:59.282723 168 storage/store.go:4156  [n3,s3]
** Compaction Stats [default] **
Level    Files   Size     Score Read(GB)  Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop
----------------------------------------------------------------------------------------------------------------------------------------------------------
  L0     25/20  27.39 MB   2.5      2.1     0.0      2.1       2.2      0.1       2.7   0.3      4.8      4.9       453      2813    0.161     20M   3268
  L4    106/99  419.84 MB   0.3     25.8     2.8     23.1      25.9      2.8       0.0   9.4     81.5     81.7       324       102    3.179     85M   130K
  L5    227/0   612.23 MB   1.0      3.3     1.7      1.6       3.2      1.6       0.7   1.9     55.8     54.7        61       364    0.166     20M   133K
  L6    590/0    6.10 GB   0.0      6.5     1.1      5.3       5.3      0.0       6.1   4.7     88.1     72.9        75       451    0.166     56M   506K
 Sum    948/119  7.13 GB   0.0     37.7     5.6     32.1      36.6      4.5       9.6   4.4     42.3     41.1       913      3730    0.245    183M   773K
 Int      0/0    0.00 KB   0.0      1.5     0.2      1.2       1.4      0.2       0.1  15.4     39.7     38.5        37       175    0.214   7983K   1234
Uptime(secs): 1220.1 total, 10.0 interval
Flush(GB): cumulative 0.047, interval 0.000
AddFile(GB): cumulative 8.185, interval 0.091
AddFile(Total Files): cumulative 2386, interval 111
AddFile(L0 Files): cumulative 2217, interval 110
AddFile(Keys): cumulative 70502188, interval 874324
Cumulative compaction: 36.63 GB write, 30.74 MB/s write, 37.69 GB read, 31.63 MB/s read, 913.2 seconds
Interval compaction: 1.41 GB write, 143.95 MB/s write, 1.45 GB read, 148.69 MB/s read, 37.4 seconds
Stalls(count): 2551 level0_slowdown, 2214 level0_slowdown_with_compaction, 76 level0_numfiles, 67 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 43 memtable_compaction, 47 memtable_slowdown, interval 175 total count
estimated_pending_compaction_bytes: 4.0 GiB

Profiling also shows that 80%+ of CPU time is consistently spent in RocksDB during the index backfill. So this likely explains why the OLTP latency is so extreme.

(Re: splits taking too long, I managed to get in a state where the cluster was hung on splitting ranges, but this was with a severely underprovisioned cluster (10 nodes, 100 million rows), and my test died from a schema change lease has expired error before I could investigate further. I haven't seen this at any smaller sizes.)

Next up, I'm going to try running this with compaction turned off, and try splitting the index span into a new range before backfilling to reduce contention with writes going to the primary key span/other index.

[dt]

Wow, that is a lot of L0 ingestions, and a lot of slowdowns!

I hadn't observed that in my test, but I don't think I'd tested with #35231 also applied, to disable MVCCStats recompute, so as you pointed out in person, the stats recompute was probably rate-limiting the ingests for us and thus made it hard to hit that stall trigger.

It looks like the compactor has written 36gb there, compared to just 8gb that we've actually ingested -- combined with the stalls and the fact that 2.2k of 2.4k files went to L0, that makes me want to try testing with #35236 as well to let rocks know that we're going to be sending it a lot of files an it should hold off on compacting for a bit.

[danhhz]

I'd be quite interested to see if we rerun lucy's test but instead of the index backfill, we run an unrelated fixtures import with COCKROACH_IMPORT_WORKLOAD_FASTER, no stats, and compactions off entirely. Since there shouldn't be any traffic on the ranges being ingested, this should give us a sense of the speed of light. If the p99 spikes are resolved, then we know compactions are more-or-less entirely the issue. If they stay the same, then we have a problem in addition to compactions.

[danhhz]

Next up, I'm going to try running this with compaction turned off, and try splitting the index span into a new range before backfilling to reduce contention with writes going to the primary key span/other index.

Oh, I should have read more closely. Lucy just described almost exactly the same thing in #36091 (comment)

[thoszhang]

I tested with #35236 (also setting disable_auto_compactions to true) with stats recomputation off, and the number of stalls went down to the single digits, but the p99 latency still peaked at ~10s. (I don't have graphs, just logs.) One improvement was that the latency was slowly ramping up for a few minutes, instead of immediately jumping to ~10s as before. I was also no longer seeing intervals of several seconds during which QPS was 0.

Here are some stats from when the backfill was almost finished, before the compaction started:

I190326 20:47:46.591680 167 server/status/runtime.go:500  [n1] runtime stats: 7.5 GiB RSS, 248 goroutines, 197 MiB/2.5 GiB/2.8 GiB GO alloc/idle/total, 3.8 GiB/4.8 GiB CGO alloc/total, 98622.7 CGO/sec, 379.7/15.3 %(u/s)time, 0.4 %gc (7x), 42 MiB/63 MiB (r/w)net
I190326 20:47:47.085273 330733 storage/replica_consistency.go:140  [n1,consistencyChecker,s1,r334/2:/Table/53/2/"X{9JQEu…-`YZ,g…}] triggering stats recomputation to resolve delta of {ContainsEstimates:true LastUpdateNanos:1553633257978694620 IntentAge:0 GCBytesAge:-65909 LiveBytes:1310 LiveCount:10 KeyBytes:1140 KeyCount:10 ValBytes:0 ValCount:0 IntentBytes:0 IntentCount:0 SysBytes:0 SysCount:0 XXX_NoUnkeyedLiteral:{} XXX_sizecache:0}
I190326 20:47:54.732312 162 storage/store.go:4155  [n1,s1] sstables (read amplification = 5260):
0 [  2G 5257 ]: 6M[15] 5M[14] 4M[30] 2M[2] 1M[97] 1014K 1013K 1008K 1004K 1003K 1000K 998K 994K 991K 989K 988K 987K 986K 985K 982K[2] 979K[2] 976K 975K 974K[2] 973K 969K 968K 961K 958K 946K[2] 942K 941K 940K[2] 938K[2] 935K 932K 931K 928K 927K 925K[2] 921K 918K 916K[2] 915K[2] 913K 908K 906K[2] 905K[2] 902K 899K 898K 897K[4] 896K 895K[2] 894K[2] 893K[2] 891K 890K[2] 888K[2] 885K[3] 884K[2] 882K 881K[2] 880K 878K 875K 873K 872K 871K 870K 868K[4] 864K 863K 855K[4] 854K 853K 852K[2] 851K[2] 850K 849K[4] 848K 847K 845K 844K[2] 840K 838K 837K 836K 835K[2] 834K[2] 833K[4] 832K[2] 831K[2] 830K 829K 826K 819K 818K 816K[2] 815K 814K[2] 813K[2] 812K 811K[3] 810K[6] 809K[3] 808K[2] 807K 806K 805K 801K[2] 797K[2] 795K 794K 793K 791K 790K[2] 788K 785K 783K 782K[3] 780K[6] 779K[2] 778K[5] 777K[2] 776K[4] 775K 774K[4] 773K[2] 772K[3] 771K 770K[2] 769K[3] 768K[8] 767K[5] 766K[8] 765K[5] 764K 763K[11] 762K[9] 761K[5] 760K[4] 759K[3] 758K[2] 757K 756K 752K 749K 748K 747K 746K 744K[4] 743K[2] 742K 741K[4] 740K[2] 739K[2] 738K 736K[5] 735K 734K[6] 733K[4] 732K[13] 731K[16] 730K[12] 729K[19] 728K[7] 727K[9] 726K[2] 725K[5] 724K[6] 721K 720K 719K[2] 717K[3] 712K 710K 706K 704K 703K[2] 702K 699K[2] 698K[3] 697K[3] 696K[2] 695K 694K 692K[2] 691K[2] 689K 688K 687K 686K[2] 685K[2] 684K[5] 683K[2] 682K[2] 678K[2] 671K[2] 668K 666K 665K 659K 657K 656K 654K 652K 644K[2] 642K[3] 641K 640K 639K[2] 637K 636K 632K[2] 631K 630K[2] 629K[4] 628K 627K[2] 623K 622K 619K 618K[2] 615K[2] 614K 613K[5] 612K[4] 611K[6] 610K[2] 609K[5] 608K[2] 607K[3] 606K[3] 605K[3] 604K[5] 603K[3] 602K[7] 601K[3] 600K[2] 599K[7] 598K[9] 597K[10] 596K[5] 595K[7] 594K[5] 593K[4] 592K[3] 591K[5] 590K[3] 589K[2] 588K[7] 587K[6] 586K[3] 584K[5] 583K[2] 582K[7] 581K[3] 580K[9] 579K[10] 578K[6] 577K[9] 576K[2] 575K[4] 574K[7] 573K[7] 572K[3] 571K[5] 570K[10] 569K[6] 568K[16] 567K[11] 566K[9] 565K[9] 564K[9] 563K[8] 562K[8] 561K[6] 560K[8] 559K[7] 558K[7] 557K[17] 556K[7] 555K[12] 554K[9] 553K[8] 552K[9] 551K[6] 550K[8] 549K[4] 548K[11] 547K[4] 546K[3] 545K[8] 544K[3] 543K[4] 542K[3] 541K[7] 540K[6] 539K[7] 538K[3] 537K[3] 536K[4] 535K[4] 534K[2] 533K[5] 532K[4] 531K[5] 530K[5] 529K[4] 528K[9] 527K[5] 526K[8] 525K[14] 524K[2] 523K[10] 522K[11] 521K[17] 520K[8] 519K[13] 518K[11] 517K[13] 516K[9] 515K[7] 514K[7] 513K[10] 512K 511K[7] 510K[3] 509K[2] 508K[3] 507K[3] 503K[4] 502K[2] 500K[4] 499K 498K[3] 497K[5] 496K[7] 495K[11] 494K[15] 493K[15] 492K[11] 491K[16] 490K[21] 489K[22] 488K[13] 487K[7] 486K[9] 485K[2] 484K[3] 483K[4] 481K 477K 474K 472K 471K[2] 470K[2] 469K[2] 468K[2] 467K 466K 465K 464K 462K 461K 456K[2] 455K 454K[6] 453K[3] 452K[2] 450K[2] 449K[3] 448K[4] 447K[9] 446K[5] 445K[4] 444K[2] 443K[4] 442K[8] 441K[12] 440K[8] 439K[6] 438K[2] 437K[5] 436K[3] 435K[3] 434K[4] 432K[3] 430K[3] 429K 428K[4] 427K[2] 426K[2] 424K[2] 423K[2] 422K 421K 420K[2] 419K 418K[2] 417K 416K[3] 415K[3] 414K[5] 413K[8] 412K[8] 411K[6] 410K[7] 409K[15] 408K[7] 407K[7] 406K[10] 405K[19] 404K[13] 403K[14] 402K[9] 401K[11] 400K[2] 399K 398K 397K 396K[2] 395K[2] 394K[3] 393K[6] 392K[5] 391K[2] 390K[8] 389K[11] 388K[12] 387K[12] 386K[25] 385K[30] 384K[24] 383K[31] 382K[43] 381K[55] 380K[46] 379K[40] 378K[27] 377K[19] 376K[8] 375K[5] 374K[2] 373K[7] 372K[4] 371K[7] 370K[4] 369K[11] 368K[25] 367K[32] 366K[32] 365K[58] 364K[61] 363K[45] 362K[36] 361K[24] 360K[19] 359K[8] 358K[6] 357K[9] 356K[2] 355K[2] 354K[2] 353K[3] 352K 351K[4] 350K[5] 349K[6] 348K[10] 347K[11] 346K[7] 345K[3] 344K[9] 343K[6] 342K[7] 341K[7] 340K[5] 338K 337K[2] 336K 335K 334K[2] 331K[3] 330K 328K 327K[3] 326K 324K 323K[2] 322K[4] 321K[6] 320K[3] 319K[5] 318K[7] 317K[6] 316K[11] 315K[12] 314K[15] 313K[7] 312K[4] 311K[5] 310K[3] 309K[4] 308K[6] 307K[12] 306K[6] 305K[12] 304K[10] 303K[16] 302K[21] 301K[21] 300K[31] 299K[21] 298K[30] 297K[24] 296K[31] 295K[22] 294K[24] 293K[15] 292K[21] 291K[22] 290K[16] 289K[23] 288K[21] 287K[14] 286K[26] 285K[29] 284K[29] 283K[22] 282K[33] 281K[28] 280K[25] 279K[26] 278K[23] 277K[28] 276K[22] 275K[25] 274K[14] 273K[14] 272K[7] 271K[7] 270K[12] 269K[11] 268K[18] 267K[11] 266K[12] 265K[14] 264K[15] 263K[16] 262K[24] 261K[20] 260K[20] 259K[22] 258K[17] 257K[19] 256K[10] 255K[15] 254K[7] 253K[5] 252K[7] 251K[11] 250K[8] 249K[16] 248K[19] 247K[20] 246K[23] 245K[24] 244K[24] 243K[14] 242K[14] 241K[11] 240K[4] 239K[4] 238K[3] 237K[11] 236K[2] 235K[6] 234K 233K[3] 232K[4] 231K[4] 230K[2] 229K[7] 228K[6] 227K[7] 226K[6] 225K[7] 224K[11] 223K[5] 222K[7] 221K[3] 220K[4] 219K[4] 218K[5] 217K[4] 216K[4] 215K[3] 214K[5] 213K[4] 212K[4] 211K[4] 210K[2] 209K[5] 208K 207K[7] 206K[11] 205K[11] 204K[11] 203K[13] 202K[14] 201K[8] 200K[10] 199K[6] 198K[5] 197K[12] 196K[10] 195K[5] 194K[8] 193K[9] 192K[14] 191K[9] 190K[10] 189K[11] 188K[5] 187K[2] 186K[9] 185K[10] 184K[10] 183K[14] 182K[10] 181K[14] 180K[5] 179K 178K[3] 177K[5] 176K 174K 170K[2] 168K[2] 167K[6] 166K[2] 164K[3] 163K[3] 162K[3] 161K 159K 158K 157K[3] 156K[5] 155K[4] 154K[7] 153K[3] 152K[2] 151K[2] 149K[2] 145K 144K 143K[2] 142K[2] 140K 139K 138K[2] 136K[2] 135K[3] 134K[2] 132K 129K[4] 128K[2] 127K 123K 122K[2] 121K[2] 120K[2] 119K 118K 115K 112K 111K[2] 110K[2] 109K 108K 107K[4] 105K[5] 104K[6] 103K 102K[5] 101K[5] 100K[3] 99K[5] 98K 96K 95K[9] 94K[4] 93K[4] 92K[3] 91K[4] 90K[2] 89K[4] 88K 87K[4] 86K[4] 84K[2] 83K[7] 82K[3] 81K[8] 80K[7] 79K[4] 78K[8] 77K[7] 76K[8] 75K[6] 74K[5] 73K[4] 72K[6] 71K[3] 70K[2] 69K 68K 66K[2] 65K[2] 64K[9] 63K[4] 62K 61K[2] 60K[10] 59K[7] 58K[3] 57K[6] 56K[5] 55K[16] 54K[5] 53K[7] 52K[5] 51K[4] 50K[6] 49K[8] 48K[9] 47K[5] 46K[7] 45K[5] 44K[16] 43K[11] 42K[11] 41K[16] 40K[11] 39K[13] 38K[5] 37K[6] 36K[13] 35K[16] 34K[18] 33K[9] 32K[15] 31K[16] 30K[18] 29K[11] 28K[9] 27K[10] 26K[14] 25K[8] 24K[13] 23K[11] 22K[8] 21K[3] 20K[3] 19K[3] 18K[4] 17K[6] 16K[3] 15K[9] 14K[12] 13K[13] 12K[15] 11K[8] 10K[11] 9K[13] 8K[7] 7K[9] 6K[9] 5K[3] 4K[7] 3K[6] 2K[2]
4 [  2G  563 ]: 4M[562] 2M
5 [ 12M   40 ]: 3M 372K 363K 362K 350K 289K 270K 265K 256K 251K 250K 244K 242K 236K 234K[2] 231K 230K[2] 226K[2] 225K[2] 224K[2] 221K 218K[2] 216K 214K 210K 203K 202K 200K 192K 190K 153K 137K 126K 78K
6 [  5G  238 ]: 37M[31] 36M[61] 35M 34M 33M 31M 30M[2] 27M 26M 24M 14M 13M 12M 10M 9M 8M[115] 7M 6M[4] 5M[5] 4M 3M[2] 2M[2] 1M 34K
I190326 20:47:54.732652 162 storage/store.go:4156  [n1,s1]
** Compaction Stats [default] **
Level    Files   Size     Score Read(GB)  Rn(GB) Rnp1(GB) Write(GB) Wnew(GB) Moved(GB) W-Amp Rd(MB/s) Wr(MB/s) Comp(sec) Comp(cnt) Avg(sec) KeyIn KeyDrop
----------------------------------------------------------------------------------------------------------------------------------------------------------
  L0   5257/3846  2.11 GB  14.1      0.0     0.0      0.0       0.2      0.2       4.5   0.0      0.0      1.0       167      7347    0.023       0      0
  L4    563/563  2.24 GB   0.0      2.5     2.5      0.0       2.3      2.3       0.0   0.9     35.0     32.3        74         3   24.742     24M   104K
  L5     40/0   12.11 MB   0.1      0.0     0.0      0.0       0.0      0.0       0.1   1.4     19.8     19.0         2         7    0.334   1290K    18K
  L6    238/0    4.56 GB   0.0      2.2     0.1      2.1       1.8     -0.3       4.9  21.0     90.6     74.7        25       184    0.134     18M   563K
 Sum   6098/4409  8.92 GB   0.0      4.8     2.6      2.1       4.3      2.2       9.4   0.5     18.1     16.6       268      7541    0.036     44M   686K
 Int      0/0    0.00 KB   0.0      0.0     0.0      0.0       0.0      0.0       0.0   0.0      0.0      0.0         2        38    0.064       0      0
Uptime(secs): 1390.1 total, 9.3 interval
Flush(GB): cumulative 0.159, interval 0.000
AddFile(GB): cumulative 9.337, interval 0.016
AddFile(Total Files): cumulative 6908, interval 35
AddFile(L0 Files): cumulative 6754, interval 35
AddFile(Keys): cumulative 82491782, interval 158552
Cumulative compaction: 4.34 GB write, 3.19 MB/s write, 4.75 GB read, 3.50 MB/s read, 268.2 seconds
Interval compaction: 0.00 GB write, 0.01 MB/s write, 0.00 GB read, 0.00 MB/s read, 2.4 seconds
Stalls(count): 0 level0_slowdown, 0 level0_slowdown_with_compaction, 0 level0_numfiles, 0 level0_numfiles_with_compaction, 0 stop for pending_compaction_bytes, 0 slowdown for pending_compaction_bytes, 0 memtable_compaction, 0 memtable_slowdown, interval 0 total count
estimated_pending_compaction_bytes: 17 GiB

Could read amplification be the main source of latency now? That would be consistent with the latency getting worse as the backfill proceeded.

Also, the cluster hung and CPU was maxed out on several nodes for about a minute during the compaction. (The entire backfill took 13 minutes, which is about the same as without disabling compactions.)

[dt]

Yeah, 5257 files in L0 might be a bit far in the opposite direction -- like you say, that could be a lot of read-amp, e..g if a range wants to split and has to iterate for stats / to find a split key, I could see that becoming pretty expensive pretty quickly. I have a feeling the right answer might be somewhere in the middle -- i.e. compacting more than two files at a time, but not 5000. Note: I think as-is, #35236 might be missing calls for the pending bytes triggers in addition to the file count triggers, which I think is why you were still seeing it compacting so much until you added the hard disable_auto_compactions to it.

Those added files are averaging just over 1mb if I'm reading that right (9337mb/6908 files = 1.35mb/file). I wonder how much of that is forced due to a memory-constrained buffer spanning ranges, as opposed to underselling the buffer? If you're not already using Vivek's WIP patch, I'd suggest we try with it or my PR (#36192) to buffer across chunkBackfiller chunks, to avoid spurious flushes of underfilled batches.