sql: index over tpcc.public.customer (c_last, c_first) takes a lot more time

[vivekmenezes]

On TPCC-100

CREATE INDEX ON tpcc.public.customer (c_last, c_first) =

"CREATE INDEX ON tpcc.customer (c_last, c_first);" took 13m4.242052s

is much slower than

"CREATE INDEX ON tpcc.order (o_carrier_id);" took 1m10.472743s

Jira issue: CRDB-4622

[vivekmenezes]

working on this.

[vivekmenezes]

I190315 17:46:37.853874 311071 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53301,user=root,scExec,IndexBackfiller=54] index backfill stats: entries 117533, prepare 721.215797ms, sort 218.041019ms, add-sst 175.839439ms
I190315 17:46:47.422799 327773 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53301,user=root,scExec,IndexBackfiller=54] index backfill stats: entries 58758, prepare 509.818426ms, sort 122.493081ms, add-sst 121.794379ms
I190315 17:46:52.543537 364739 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53301,user=root,scExec,IndexBackfiller=54] index backfill stats: entries 176303, prepare 1.257389212s, sort 468.006745ms, add-sst 254.146856ms
I190315 17:47:14.696147 433801 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53301,user=root,scExec,IndexBackfiller=54] index backfill stats: entries 215051, prepare 1.733752468s, sort 341.835774ms, add-sst 288.073321ms
I190315 17:47:20.419263 470125 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53301,user=root,scExec,IndexBackfiller=54] index backfill stats: entries 58771, prepare 273.59219ms, sort 66.649266ms, add-sst 2.286063546s
I190315 17:47:42.379993 530155 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53301,user=root,scExec,IndexBackfiller=54] index backfill stats: entries 58746, prepare 411.052603ms, sort 73.30766ms, add-sst 7.849116292s
I190315 17:47:54.117522 568115 sql/backfill.go:862  [n1,client=71.125.15.117:53301,user=root,scExec] index customer/customer_c_last_c_first_idx row count = 3000000, took 11.159257882s
I190315 17:48:13.134747 568148 sql/backfill.go:896  [n1,client=71.125.15.117:53301,user=root,scExec] table customer row count = 3000000, took 30.194097285s

this instance ran fast, but I believe the fundamental problem here is the SSTs are too small. I'm going to work on a change that increases the size of these SSTs

[vivekmenezes]

vivek@vivek-1552673080-schemachange-index-tpcc-w-100-0001:~$ grep backfill logs/cockroach.log 
I190315 18:12:07.779045 227551 sql/backfill.go:145  [n1,client=71.125.15.117:53668,user=root,scExec] Running backfill for "order", v=5, m=1
I190315 18:12:17.122581 247863 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=53] index backfill stats: entries 1188061, prepare 5.714018732s, sort 1.419256129s, add-sst 1.192664618s
I190315 18:12:30.379674 292464 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=53] index backfill stats: entries 1483690, prepare 7.562192419s, sort 1.952851335s, add-sst 1.562044139s
I190315 18:12:41.984093 360672 sql/backfill.go:862  [n1,client=71.125.15.117:53668,user=root,scExec] index order/order_o_entry_d_o_w_id_o_d_id_o_carrier_id_o_id_key row count = 3007812, took 7.227402649s
I190315 18:12:43.813399 360673 sql/backfill.go:896  [n1,client=71.125.15.117:53668,user=root,scExec] table order row count = 3007812, took 9.073490318s
I190315 18:13:56.484288 227551 sql/backfill.go:145  [n1,client=71.125.15.117:53668,user=root,scExec] Running backfill for "order", v=8, m=2
I190315 18:14:12.064343 744091 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=53] index backfill stats: entries 567069, prepare 12.857923034s, sort 836.834094ms, add-sst 757.155255ms
I190315 18:14:16.452630 808633 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=53] index backfill stats: entries 302629, prepare 1.194670953s, sort 347.444879ms, add-sst 307.351369ms
I190315 18:14:30.617038 823373 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=53] index backfill stats: entries 1489166, prepare 6.113748844s, sort 3.248149003s, add-sst 1.487611414s
I190315 18:14:56.388225 873082 sql/backfill.go:862  [n1,client=71.125.15.117:53668,user=root,scExec] index order/order_o_carrier_id_idx row count = 3019283, took 25.223638488s
I190315 18:14:56.609116 873083 sql/backfill.go:896  [n1,client=71.125.15.117:53668,user=root,scExec] table order row count = 3019283, took 25.447567767s
I190315 18:19:58.707554 227551 sql/backfill.go:145  [n1,client=71.125.15.117:53668,user=root,scExec] Running backfill for "customer", v=6, m=1
I190315 18:20:06.898390 2068366 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=60] index backfill stats: entries 117401, prepare 676.6104ms, sort 142.747742ms, add-sst 144.355802ms
I190315 18:20:15.290252 2084624 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=60] index backfill stats: entries 117534, prepare 1.009672304s, sort 289.997907ms, add-sst 206.179534ms
I190315 18:20:17.923038 2100184 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=60] index backfill stats: entries 58779, prepare 234.287073ms, sort 64.966569ms, add-sst 75.987488ms
I190315 18:20:43.316047 2156102 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=60] index backfill stats: entries 109353, prepare 756.007291ms, sort 186.310869ms, add-sst 4.675930902s
I190315 18:20:51.381476 2185431 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=60] index backfill stats: entries 58781, prepare 225.407655ms, sort 65.320097ms, add-sst 1.823444744s
I190315 18:21:04.634113 2215560 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=60] index backfill stats: entries 58755, prepare 269.960285ms, sort 88.3329ms, add-sst 4.525403075s
I190315 18:21:19.358344 2242581 sql/distsqlrun/indexbackfiller.go:174  [n1,client=71.125.15.117:53668,user=root,scExec,IndexBackfiller=60] index backfill stats: entries 122056, prepare 1.071642234s, sort 309.156787ms, add-sst 5.892733513s
I190315 18:22:18.417321 2257415 sql/backfill.go:862  [n1,client=71.125.15.117:53668,user=root,scExec] index customer/customer_c_last_c_first_idx row count = 3000000, took 7.298552189s
I190315 18:26:18.917735 2257416 sql/backfill.go:896  [n1,client=71.125.15.117:53668,user=root,scExec] table customer row count = 3000000, took 4m7.817473837s

this problem only happens if this particular schema change is the 3rd one to run. Also note the 4m7s time it took to run count(1) on the table in order to validate it.

At a minimum we should be creating fewer SSTs

[vivekmenezes]

I190319 16:45:31.264274 1736187 sql/backfill.go:867  [n1,client=104.129.137.246:50079,user=root,scExec] validation: index customer/customer_c_last_c_first_idx row count = 3000000, took 4m23.449620554s
I190319 16:48:14.551929 1736188 sql/backfill.go:902  [n1,client=104.129.137.246:50079,user=root,scExec] validation: table customer row count = 3000000, took 7m6.769293286s

the validation took many minutes. This table only has 3M rows.

[github-actions]

We have marked this issue as stale because it has been inactive for
18 months. If this issue is still relevant, removing the stale label
or adding a comment will keep it active. Otherwise, we'll close it in
10 days to keep the issue queue tidy. Thank you for your contribution
to CockroachDB!