New index backfill schema change causes a spike in latency

[awoods187]

Describe the problem

New index backfill schema change causes a spike in latency when running on TPC-C 1K.

To Reproduce

To Reproduce
Setup TPC-C 1K like normal.

Set flag for new schema change implementation:
Roachprod sql $CLUSTER:1
SET CLUSTER SETTING schemachanger.bulk_index_backfill.enabled = true

Run for 6 hours.
roachprod run $CLUSTER:4 "./workload run tpcc --ramp=5m --warehouses=2000 --duration=6h --split --scatter {pgurl:1-3}"

After five minutes, in another shell, change the zone config ttl to 10 minutes
Roachprod sql $CLUSTER:1
ALTER RANGE default CONFIGURE ZONE USING gc.ttlseconds = 600;

Then create an index or non-unique on any column:
Roachprod sql $CLUSTER:1
use tpcc
CREATE INDEX ON district (d_name, d_w_id, d_zip)

Expected behavior
Index < 10 minutes
Look at the front page on admin ui metrics SQL QPS and make sure it never went to less than 80% pre index

Environment:
v2.2.0-alpha.20181217-1144-ge3e4f96

Jira issue: CRDB-4631

[awoods187]

Spike occurs during drop index too (note that 10 minutes of the 11 minutes is due to the zone config ttl that i set for 10 minutes).

[awoods187]

I see this same spike on today's master v19.1.0-beta.20190304-458-g70e3468 on a three-node tpc-c cluster:

When adding the index:

root@localhost:26257/tpcc> CREATE INDEX ON item (i_price)                                                                                                                                                                                                                ;
CREATE INDEX

Time: 13m34.247855729s

[awoods187]

Spike does seem to be worse with a more complex index:

[awoods187]

The spike can actually cause a transaction deadline exceeded error:
ALTER TABLE customer ADD CONSTRAINT foo UNIQUE (b);

Error: error in delivery: ERROR: TransactionStatusError: transaction deadline exceeded by 10.728530819s (1552682894.492556657,1 > 1552682883.764025838,0), original timestamp 13.673612514s ago (1552682880.818944143,0): id=fcc9e69c key=/Table/55/1/480/1/-2317/0 rw=true pri=0.00920654 stat=PENDING epo=0 ts=1552682894.492556657,1 orig=1552682880.818944143,0 max=1552682881.318944143,0 wto=false seq=149 (REASON_UNKNOWN) (SQLSTATE XX000)
Error:  exit status 1

Re-running this with --tolerate-errors

[awoods187]

Still seeing "long" schema changes:

root@localhost:26257/tpcc> ALTER TABLE customer ADD CONSTRAINT foo UNIQUE (b);
ALTER TABLE

Time: 41m57.53144898s

When running TPC-C on 3 nodes with 2500 loaded warehouses with 2300 active warehouses. This also has corresponding latency spikes @vivekmenezes

[petermattis]

What is the max number of warehouses on this setup? I believe it is close to 2500 warehouses, which means you're running a schema change when the system is at 92% of capacity. While ideally we should handle this situation well, in practice we should recommend never running a schema change when a cluster is so close to capacity. In the near term, I'd love to see what happens when you're running with 2000 active warehouses (80% capacity). If that fails, drop down to 70%, 60%, etc.

[awoods187]

I see the latency spike while running 2000 warehouses on today's master v19.1.0-beta.20190304-507-gc2939ec on a three-node tpc-c cluster:

root@localhost:26257/tpcc> CREATE INDEX ON item (i_price);
CREATE INDEX

Time: 13m17.143226144s

Similar spikes exist for:
ALTER TABLE customer ADD CONSTRAINT foo UNIQUE (b);

Although create index on tpcc.public.district (d_name, d_w_id, d_zip) did not spike.

[awoods187]

I then tried CREATE INDEX ON item (i_price); on 1800 warehouses:

It now spikes to over 8 seconds and is constantly above 1 second!

I'm thinking this has less to do with what's happening under load. When it finishes I'm going to try on low load for comparison.

[awoods187]

No real spike at 1000 warehouses.

[awoods187]

Like 1000, no real spike 1500. Both times CREATE INDEX ON item (i_price) took about 1m (as opposed to the 13m under tpc-c 2000).