Index shards get too big during build

[kunga]

Description

If we add an index to a huge table its shards might get bigger than 2GB limit:

Steps to reproduce

1. Upload TPC-C dataset with 10K warehouses (you may delete all tables except customer)
2. Drop existing index (if exists)

ALTER TABLE `customer` DROP INDEX `idx_customer_name`

3. Create a new one

ALTER TABLE `customer` ADD INDEX `idx_customer_name` GLOBAL ON (C_W_ID, C_D_ID, C_LAST, C_FIRST)

Internal diagnostic metrics

• Shard sizes
• CPU

[kunga]

How it happens

Index shard splits during inserts

SchemeShard receives DataShard stats:

2024-04-01T18:13:23.781065Z :FLAT_TX_SCHEMESHARD INFO: Got periodic table stats at tablet 72075186224037889 from shard 72075186224042302 pathId [OwnerId: 72075186224037889, LocalPathId: 95] state 'Ready' dataSize 2552463338 rowCount 33902472 cpuUsage 0

SchemeShard triggers borrow compaction before splitting DataShard:

2024-04-01T18:13:23.868587Z :FLAT_TX_SCHEMESHARD INFO: RunBorrowedCompaction for pathId# [OwnerId: 72075186224037889, LocalPathId: 95], datashard# 72075186224042302, next wakeup# 14.878693s, rate# 0, in queue# 1 shards, running# 1 shards at schemeshard 72075186224037889

DataShard receives borrow compaction request:

2024-04-01T18:13:23.878011Z :TX_DATASHARD INFO: TEvCompactBorrowed request from [50001:7352955884218816164:97] for table [OwnerId: 72075186224037889, LocalPathId: 95] at tablet 72075186224042302

But after a check decides that there is no data to compact (because it is kept in shadow table):

2024-04-01T18:13:23.878014Z :TX_DATASHARD DEBUG: TEvCompactBorrowed request from [50001:7352955884218816164:97] for table [OwnerId: 72075186224037889, LocalPathId: 95] has no borrowed parts at tablet 72075186224042302

And immediately replies it to SchemeShard:

2024-04-01T18:13:23.878031Z :FLAT_TX_SCHEMESHARD INFO: Finished borrowed compaction for pathId# [OwnerId: 72075186224037889, LocalPathId: 95], datashard# 72075186224042302, shardIdx# 72075186224037889:4415 in# 9, next wakeup# 14.869252s, rate# 0, in queue# 0 shards, running# 0 shards at schemeshard 72075186224037889

This loop repeats until DataShard compacts itself:

2024-04-01T18:14:13.834722Z :FLAT_TX_SCHEMESHARD INFO: Got periodic table stats at tablet 72075186224037889 from shard 72075186224042302 pathId [OwnerId: 72075186224037889, LocalPathId: 95] state 'Ready' dataSize 4815949423 rowCount 64097082 cpuUsage 233.1412
2024-04-01T18:14:23.858807Z :FLAT_TX_SCHEMESHARD INFO: Got periodic table stats at tablet 72075186224037889 from shard 72075186224042302 pathId [OwnerId: 72075186224037889, LocalPathId: 95] state 'Ready' dataSize 5349475466 rowCount 71320323 cpuUsage 233.1412

2024-04-01T18:14:21.269885Z :TX_DATASHARD DEBUG: 72075186224042302 CompletedLoansChanged
2024-04-01T18:14:21.257793Z :RESOURCE_BROKER DEBUG: Finish task gen2-table-1002-tablet-72075186224042302 (374 by [50001:7352963366057141970:223]) (release resources {1, 0})
2024-04-01T18:14:21.261246Z :TX_DATASHARD DEBUG: CompactionComplete of tablet# 72075186224042302, table# 1002, finished edge# 0, front# 0

Finally, SchemeShard splits it:

2024-04-01T18:14:33.861850Z :FLAT_TX_SCHEMESHARD INFO: Got periodic table stats at tablet 72075186224037889 from shard 72075186224042302 pathId [OwnerId: 72075186224037889, LocalPathId: 95] state 'Ready' dataSize 5968772986 rowCount 78402927 cpuUsage 231.2835
2024-04-01T18:14:33.869610Z :FLAT_TX_SCHEMESHARD DEBUG: Requesting full stats from datashard 72075186224042302
2024-04-01T18:14:33.892111Z :FLAT_TX_SCHEMESHARD DEBUG: Got partition histogram at tablet 72075186224037889 from datashard 72075186224042302 state: 'Ready' data size: 5970415738 row count: 78413927
2024-04-01T18:14:33.892119Z :FLAT_TX_SCHEMESHARD INFO: TTxPartitionHistogram::Execute partition histogram at tablet 72075186224037889 from datashard 72075186224042302 for pathId [OwnerId: 72075186224037889, LocalPathId: 95] state 'Ready' dataSize 5970415738 rowCount 78413927
2024-04-01T18:14:33.902946Z :FLAT_TX_SCHEMESHARD DEBUG: TSplitMerge TTransferData operationId#562949955166332:0 Starting split on src datashard 72075186224042302 splitOpId# 562949955166332:0 at tablet 72075186224037889

log.txt

[kunga]

After TEvCompactBorrowed fix

Index shard splits during inserts

SchemeShard receives DataShard stats:

2024-04-03T12:27:45.864320Z :FLAT_TX_SCHEMESHARD INFO: Add stats from shard with datashardId(TabletID)=72075186224042389, pathId 101: RowCount 49359323, DataSize 3737620801, with borrowed parts

SchemeShard triggers borrow compaction before splitting DataShard:

2024-04-03T12:27:45.864322Z :FLAT_TX_SCHEMESHARD INFO: RunBorrowedCompaction for pathId# [OwnerId: 72075186224037889, LocalPathId: 101], datashard# 72075186224042389, next wakeup# 4.876228s, rate# 0, in queue# 1 shards, running# 1 shards at schemeshard 72075186224037889

DataShard receives borrow compaction request and starts it for shadowed table:

2024-04-03T12:27:55.874604Z :TX_DATASHARD DEBUG: TEvCompactBorrowed request from [50001:7353612021983102284:67] for table [OwnerId: 72075186224037889, LocalPathId: 101] starting compaction for local table 1002 at tablet 72075186224042389

But nothing happens after the compaction:

2024-04-03T12:27:45.868128Z :RESOURCE_BROKER DEBUG: Submitted new compaction_borrowed task gen255-table-1002-tablet-72075186224042389 (15 by [50003:7353616467104197217:113]) priority=5 resources={1, 0}
2024-04-03T12:27:45.936619Z :RESOURCE_BROKER DEBUG: Finish task gen255-table-1002-tablet-72075186224042389 (15 by [50003:7353616467104197217:113]) (release resources {1, 0})

We still have borrowed data for about a minute:

2024-04-03T12:27:35.928119Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 49359323, DataSize, with borrowed parts
2024-04-03T12:27:45.951315Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 50873823, DataSize, with borrowed parts
2024-04-03T12:27:55.972081Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 58245554, DataSize, with borrowed parts
2024-04-03T12:28:06.040824Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 65487731, DataSize, with borrowed parts
2024-04-03T12:28:16.082624Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 73249475, DataSize, with borrowed parts
2024-04-03T12:28:26.232625Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 81007485, DataSize, with borrowed parts
2024-04-03T12:28:36.373620Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 88827534, DataSize, with borrowed parts
2024-04-03T12:28:42.863212Z :TX_DATASHARD INFO: 72075186224042389 CompletedLoansChanged
2024-04-03T12:28:46.539739Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042389, for tableId 101: RowCount 96259907, DataSize

log.txt

[kunga]

Compactions investigation

Index shard splits during inserts, SchemeShard receives DataShard stats:

2024-04-04T10:37:13.828752Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042532, for tableId 111: RowCount 46333577, DataSize 3493051847, with borrowed parts

SchemeShard triggers borrow compaction before splitting DataShard:

2024-04-04T10:37:23.853656Z :TX_DATASHARD INFO: TEvCompactBorrowed request from [50003:7353956952003842340:68] for table [OwnerId: 72075186224037889, LocalPathId: 111] at tablet 72075186224042532
2024-04-04T10:37:23.853661Z :TX_DATASHARD DEBUG: TEvCompactBorrowed request from [50003:7353956952003842340:68] for table [OwnerId: 72075186224037889, LocalPathId: 111] starting compaction for local table 1002 at tablet 72075186224042532

DataShard initiates a borrow compaction:

2024-04-04T10:37:23.853676Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy SubmitTask for 72075186224042532: type compaction_borrowed, priority 5, generation 255
2024-04-04T10:37:23.856126Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy BeginGenCompaction for 72075186224042532: task 14, generation 255
2024-04-04T10:37:23.856131Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy PrepareCompaction for 72075186224042532: task 14, edge 0/0, generation 255
2024-04-04T10:37:23.856175Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy PrepareCompaction for 72075186224042532 started compaction 27 generation 255

DataShard also runs gen3 compaction and cancels previously started borrow compaction:

2024-04-04T10:37:23.926139Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy CheckGeneration for 72075186224042532 generation 1, state Free, final id 0, final level 255
2024-04-04T10:37:23.926143Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy CheckGeneration for 72075186224042532 generation 2, state Free, final id 0, final level 255
2024-04-04T10:37:23.926144Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy CheckGeneration for 72075186224042532 generation 3, state Free, final id 0, final level 255
2024-04-04T10:37:23.926146Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy SubmitTask for 72075186224042532: type background_compaction, priority 99, generation 3
2024-04-04T10:37:23.929167Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy PrepareCompaction for 72075186224042532 started compaction 31 generation 3
2024-04-04T10:37:23.929168Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy PrepareCompaction for 72075186224042532 cancel running compaction 27

It finishes after a minute, when the shard size is more than 7GB:

2024-04-04T10:37:44.125561Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042532, for tableId 111: RowCount 62202444, DataSize 4669015244, with borrowed parts
2024-04-04T10:38:04.293587Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042532, for tableId 111: RowCount 76889944, DataSize 5779555195, with borrowed parts
2024-04-04T10:38:24.353516Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042532, for tableId 111: RowCount 90637560, DataSize 6829807347, with borrowed parts

2024-04-04T10:38:38.592592Z :TABLET_EXECUTOR INFO: Leader{72075186224042532:1:9473} Compact 31 on TGenCompactionParams{1002: gen 3 epoch 0, 28 parts} step 234, product {1 parts epoch 0} done
2024-04-04T10:38:38.595188Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy CompactionFinished for 72075186224042532: compaction 31, generation 3
2024-04-04T10:38:39.881805Z :TX_DATASHARD INFO: 72075186224042532 CompletedLoansChanged

2024-04-04T10:38:44.522971Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042532, for tableId 111: RowCount 105350928, DataSize 8027138267

[kunga]

After the investigation it seems that we need to split data shards more aggressively.

For now, if we have split some shard, it might be getting compacting for a few minutes before the next split can occur (because of borrowed data) and during that time it is getting even bigger. That loop continues until an index is fully built. Also I can imagine the same behaviour during huge data upload.

So, I propose to teach SchemeShard to split a DataShard to more than two parts when it executes split by size. For example, if current DataShard size is 5GB we should split it to it 5 parts so that each part is 1GB size.

UPD: we've discussed that it isn't a good solution because the compaction process may still be slower than index build upload.

[kunga]

Compaction time investigation

2024-04-05T14:44:13.568665Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy PrepareCompaction for 72075186224042721: task 17, edge 0/0, generation 3
2024-04-05T14:44:13.568669Z :TABLET_EXECUTOR INFO: Leader{72075186224042721:1:278} starting compaction
2024-04-05T14:44:13.568690Z :TABLET_EXECUTOR INFO: Leader{72075186224042721:1:279} starting Scan{33 on 1002, Compact{72075186224042721.1.278, eph 1829}}
2024-04-05T14:44:13.568696Z :TABLET_EXECUTOR INFO: Leader{72075186224042721:1:279} started compaction 33

2024-04-05T14:44:03.505196Z :TX_DATASHARD DEBUG: Stats rebuilt at datashard 72075186224042721, for tableId 125: RowCount 56832343, DataSize 4280855661, with borrowed parts

2024-04-05T14:44:13.568772Z :TABLET_OPS_HOST INFO: Scan{33 on 1002, Compact{72075186224042721.1.278, eph 1829}} begin on TSubset{head 0, 0m 29p 0c}

2024-04-05T14:45:20.992367Z :TABLET_OPS_HOST INFO: Scan{33 on 1002, Compact{72075186224042721.1.278, eph 1829}} end=0, 56832343r seen, TFwd{fetch=4280855661,saved=4280855661,usage=4280855661,after=0,before=0}, bio Spent{1.117m wa 34.30s cnt 5488}, trace 0 of 0 ~30p

2024-04-05T14:45:20.994742Z :TABLET_EXECUTOR DEBUG: TGenCompactionStrategy CompactionFinished for 72075186224042721: compaction 33, generation 3

logs.txt

Force compact of shard 1.5 GB:

2024-04-05T15:20:09.408988Z :TABLET_OPS_HOST INFO: Scan{101 on 1001, Compact{72075186224042710.1.6137, eph -1}} end=0, 26640000r seen, TFwd{fetch=1631602152,saved=1631602152,usage=1631602152,after=0,before=0}, bio Spent{16.21s wa 5.256s cnt 2118}, trace 0 of 0 ~2p

[kunga]

After fixes #3419 and #3710 got much better: