ApplySchema: do not ReloadSchema on ExecuteFetchAsDba by shlomi-noach · Pull Request #10739 · vitessio/vitess

shlomi-noach · 2022-07-19T09:22:08Z

Description

Followup to #10719
There is yet another location where ReloadSchema is called: from within the VTTablet, and this is controlled as a parameter in ExecuteFetchAsDba. We now strictly do not call ReloadSchema anywhere until all SQLs have been applied.

This specific PR applies to direct DDLs, not to Online DDLs.

Related Issue(s)

#10719

Checklist

"Backport me!" label has been added if this change should be backported
Tests were added or are not required
Documentation was added or is not required

Deployment Notes

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

vitess-bot · 2022-07-19T09:22:10Z

vitess-bot · 2022-07-19T09:22:10Z

shlomi-noach · 2022-07-19T10:44:52Z

vreplication_cellalias failure:

2022-07-19T10:41:26.7038578Z I0719 10:40:18.698782   23257 cluster_test.go:541] InitializeShard and make 100 primary
2022-07-19T10:41:26.7039618Z I0719 10:40:18.698842   23257 vtctlclient_process.go:209] Executing vtctlclient with command: vtctlclient --server 127.0.0.1:15999 PlannedReparentShard -- --keyspace_shard product/0 --wait_replicas_timeout 31s --new_primary zone1-100 (attempt 1 of 10)
2022-07-19T10:41:26.7042175Z I0719 10:40:18.779511   23257 cluster_test.go:543] Finished creating shard 0
2022-07-19T10:41:26.7042988Z I0719 10:40:18.779572   23257 vtctlclient_process.go:209] Executing vtctlclient with command: vtctlclient --server 127.0.0.1:15999 ApplySchema -- --sql 
2022-07-19T10:41:26.7043974Z create table product(pid int, description varbinary(128), date1 datetime not null default '0000-00-00 00:00:00', date2 datetime not null default '2021-00-01 00:00:00', primary key(pid)) CHARSET=utf8mb4;
2022-07-19T10:41:26.7045149Z create table customer(cid int, name varchar(128) collate utf8mb4_bin, meta json default null, typ enum('individual','soho','enterprise'), sport set('football','cricket','baseball'),
2022-07-19T10:41:26.7046061Z 	ts timestamp not null default current_timestamp, bits bit(2) default b'11', date1 datetime not null default '0000-00-00 00:00:00', 
2022-07-19T10:41:26.7046860Z 	date2 datetime not null default '2021-00-01 00:00:00', primary key(cid,typ)) CHARSET=utf8mb4;
2022-07-19T10:41:26.7047535Z create table customer_seq(id int, next_id bigint, cache bigint, primary key(id)) comment 'vitess_sequence';
2022-07-19T10:41:26.7048114Z create table merchant(mname varchar(128), category varchar(128), primary key(mname)) CHARSET=utf8mb4 COLLATE=utf8mb4_general_ci;
2022-07-19T10:41:26.7048809Z create table orders(oid int, cid int, pid int, mname varchar(128), price int, qty int, total int as (qty * price), total2 int as (qty * price) stored, primary key(oid)) CHARSET=utf8;
2022-07-19T10:41:26.7049577Z create table order_seq(id int, next_id bigint, cache bigint, primary key(id)) comment 'vitess_sequence';
2022-07-19T10:41:26.7050571Z create table customer2(cid int, name varchar(128), typ enum('individual','soho','enterprise'), sport set('football','cricket','baseball'),ts timestamp not null default current_timestamp, primary key(cid)) CHARSET=utf8;
2022-07-19T10:41:26.7051417Z create table customer_seq2(id int, next_id bigint, cache bigint, primary key(id)) comment 'vitess_sequence';
2022-07-19T10:41:26.7052331Z create table `Lead`(`Lead-id` binary(16), name varbinary(16), date1 datetime not null default '0000-00-00 00:00:00', date2 datetime not null default '2021-00-01 00:00:00', primary key (`Lead-id`));
2022-07-19T10:41:26.7053321Z create table `Lead-1`(`Lead` binary(16), name varbinary(16), date1 datetime not null default '0000-00-00 00:00:00', date2 datetime not null default '2021-00-01 00:00:00', primary key (`Lead`));
2022-07-19T10:41:26.7053953Z create table _vt_PURGE_4f9194b43b2011eb8a0104ed332e05c2_20221210194431(id int, val varbinary(128), primary key(id));
2022-07-19T10:41:26.7055263Z create table db_order_test (c_uuid varchar(64) not null default '', created_at datetime not null, dstuff varchar(128), dtstuff text, dbstuff blob, cstuff char(32), primary key (c_uuid,created_at)) CHARSET=utf8mb4;
2022-07-19T10:41:26.7056255Z create table datze (id int, dt1 datetime not null default current_timestamp, dt2 datetime not null, ts1 timestamp default current_timestamp, primary key (id));
2022-07-19T10:41:26.7057053Z  --ddl_strategy direct -allow-zero-in-date --skip_preflight product (attempt 1 of 10)
2022-07-19T10:41:26.7057883Z I0719 10:40:18.892792   23257 vtctlclient_process.go:209] Executing vtctlclient with command: vtctlclient --server 127.0.0.1:15999 ApplyVSchema -- --vschema 
2022-07-19T10:41:26.7058285Z {
2022-07-19T10:41:26.7058500Z   "tables": {
2022-07-19T10:41:26.7058751Z 	"product": {},
2022-07-19T10:41:26.7059005Z 	"merchant": {},
2022-07-19T10:41:26.7059244Z 	"orders": {},
2022-07-19T10:41:26.7059491Z 	"customer": {},
2022-07-19T10:41:26.7059749Z 	"customer_seq": {
2022-07-19T10:41:26.7060006Z 		"type": "sequence"
2022-07-19T10:41:26.7060245Z 	},
2022-07-19T10:41:26.7060480Z 	"customer2": {},
2022-07-19T10:41:26.7060725Z 	"customer_seq2": {
2022-07-19T10:41:26.7060998Z 		"type": "sequence"
2022-07-19T10:41:26.7061226Z 	},
2022-07-19T10:41:26.7061483Z 	"order_seq": {
2022-07-19T10:41:26.7061729Z 		"type": "sequence"
2022-07-19T10:41:26.7061954Z 	},
2022-07-19T10:41:26.7062174Z 	"Lead": {},
2022-07-19T10:41:26.7062451Z 	"Lead-1": {},
2022-07-19T10:41:26.7062713Z 	"db_order_test": {},
2022-07-19T10:41:26.7062962Z 	"datze": {}
2022-07-19T10:41:26.7063164Z   }
2022-07-19T10:41:26.7063365Z }
2022-07-19T10:41:26.7063618Z  product (attempt 1 of 10)
2022-07-19T10:41:26.7063955Z I0719 10:40:18.908310   23257 cluster_test.go:411] Starting vtgate
2022-07-19T10:41:26.7064540Z I0719 10:40:18.948033   23257 mysqld.go:588] execCmd: /usr/sbin/mysqld /usr/sbin/mysqld [--version]
2022-07-19T10:41:26.7065513Z I0719 10:40:18.956999   23257 mysqld.go:602] execCmd: /usr/sbin/mysqld output: /usr/sbin/mysqld  Ver 5.7.38-0ubuntu0.18.04.1 for Linux on x86_64 ((Ubuntu))
2022-07-19T10:41:26.7068151Z I0719 10:40:18.957125   23257 vtgate_process.go:132] Running vtgate with command: vtgate --topo_implementation etcd2 --topo_global_server_address 127.0.0.1:2379 --topo_global_root /vitess/global --log_dir /tmp/vt_2534044224/vreple2e_828626/tmp --log_queries_to_file /tmp/vt_2534044224/vreple2e_828626/tmp/vtgate_querylog.txt --port 15001 --grpc_port 15991 --mysql_server_port 15306 --mysql_server_socket_path /tmp/vt_2534044224/vreple2e_828626/tmp/mysql.sock --cell zone1 --cells_to_watch zone1,zone2 --tablet_types_to_wait primary --service_map grpc-tabletmanager,grpc-throttler,grpc-queryservice,grpc-updatestream,grpc-vtctl,grpc-vtgateservice --mysql_auth_server_impl none --mysql_server_version 5.7.38-vitess --tablet_refresh_interval 10ms
2022-07-19T10:41:26.7069743Z I0719 10:40:19.563651   23257 cluster_test.go:411] Starting vtgate
2022-07-19T10:41:26.7070316Z I0719 10:40:19.611087   23257 mysqld.go:588] execCmd: /usr/sbin/mysqld /usr/sbin/mysqld [--version]
2022-07-19T10:41:26.7071065Z I0719 10:40:19.620235   23257 mysqld.go:602] execCmd: /usr/sbin/mysqld output: /usr/sbin/mysqld  Ver 5.7.38-0ubuntu0.18.04.1 for Linux on x86_64 ((Ubuntu))
2022-07-19T10:41:26.7073661Z I0719 10:40:19.620355   23257 vtgate_process.go:132] Running vtgate with command: vtgate --topo_implementation etcd2 --topo_global_server_address 127.0.0.1:2379 --topo_global_root /vitess/global --log_dir /tmp/vt_2534044224/vreple2e_828626/tmp --log_queries_to_file /tmp/vt_2534044224/vreple2e_828626/tmp/vtgate_querylog.txt --port 15001 --grpc_port 15991 --mysql_server_port 15306 --mysql_server_socket_path /tmp/vt_2534044224/vreple2e_828626/tmp/mysql.sock --cell zone2 --cells_to_watch zone1,zone2 --tablet_types_to_wait primary --service_map grpc-tabletmanager,grpc-throttler,grpc-queryservice,grpc-updatestream,grpc-vtctl,grpc-vtgateservice --mysql_auth_server_impl none --mysql_server_version 5.7.38-vitess --tablet_refresh_interval 10ms
2022-07-19T10:41:26.7075572Z I0719 10:40:19.621877   23257 vtctlclient_process.go:209] Executing vtctlclient with command: vtctlclient --server 127.0.0.1:15999 RebuildKeyspaceGraph product (attempt 1 of 10)
2022-07-19T10:41:26.7076533Z I0719 10:40:19.650155   23257 vtctlclient_process.go:209] Executing vtctlclient with command: vtctlclient --server 127.0.0.1:15999 AddCellsAlias -- --cells zone2 alias (attempt 1 of 10)
2022-07-19T10:41:26.7077353Z I0719 10:40:19.693908   23257 vtgate_process.go:204] Waiting for healthy status of 1 product.0.primary tablets in cell zone1
2022-07-19T10:41:26.7077905Z I0719 10:40:19.696049   23257 vtgate_process.go:204] Waiting for healthy status of 2 product.0.replica tablets in cell zone1
2022-07-19T10:41:26.7078411Z === RUN   TestCellAliasVreplicationWorkflow/insertInitialData
2022-07-19T10:41:26.7078869Z I0719 10:40:19.702016   23257 vreplication_test.go:425] Inserting initial data
2022-07-19T10:41:26.7079302Z I0719 10:40:21.149313   23257 vreplication_test.go:431] Done inserting initial data
2022-07-19T10:41:26.7079727Z === RUN   TestCellAliasVreplicationWorkflow/VStreamFrom
2022-07-19T10:41:26.7080160Z     vreplication_test.go:376: 
2022-07-19T10:41:26.7080651Z         	Error Trace:	vreplication_test.go:376
2022-07-19T10:41:26.7081174Z         	            				asm_amd64.s:1571
2022-07-19T10:41:26.7081615Z         	Error:      	Received unexpected error:
2022-07-19T10:41:26.7083038Z         	            	unexpected: query ended without no results and no error (errno 1105) (sqlstate HY000) during query: vstream * from product
2022-07-19T10:41:26.7083729Z         	Test:       	TestCellAliasVreplicationWorkflow/VStreamFrom
2022-07-19T10:41:26.7084251Z     vreplication_test.go:419: nothing streamed within timeout

seems like it might be related to changes in this PR, because the failure comes shortly after ApplySchema?

shlomi-noach · 2022-07-19T10:48:21Z

Cluster (12) consistent failure.

2022-07-19T10:36:39.1386134Z === RUN   TestSharded
2022-07-19T10:36:39.1563691Z     message_test.go:511: 
2022-07-19T10:36:39.1565147Z         	Error Trace:	message_test.go:511
2022-07-19T10:36:39.1566356Z         	            				message_test.go:368
2022-07-19T10:36:39.1567617Z         	Error:      	Expected nil, but got: Code: INVALID_ARGUMENT
2022-07-19T10:36:39.1570579Z         	            	rpc error: code = InvalidArgument desc = target: user.-80.primary: vttablet: rpc error: code = InvalidArgument desc = table sharded_message not found in schema (CallerID: unsecure_grpc_client)
2022-07-19T10:36:39.1573523Z         	            	target: user.80-.primary: vttablet: rpc error: code = InvalidArgument desc = table sharded_message not found in schema (CallerID: unsecure_grpc_client)
2022-07-19T10:36:39.1575588Z         	Test:       	TestSharded
2022-07-19T10:36:39.1576858Z --- FAIL: TestSharded (0.02s)
2022-07-19T10:36:39.1578162Z === RUN   TestUnsharded
2022-07-19T10:36:52.1909586Z --- PASS: TestUnsharded (13.03s)
2022-07-19T10:36:52.1911359Z === RUN   TestReparenting
2022-07-19T10:36:52.1913145Z I0719 10:36:52.190102   31342 message_test.go:600] Message stream ended: Code: CANCELED
2022-07-19T10:36:52.1915318Z rpc error: code = Canceled desc = grpc: the client connection is closing
2022-07-19T10:36:52.1943090Z     message_test.go:388: 
2022-07-19T10:36:52.1944030Z         	Error Trace:	message_test.go:388
2022-07-19T10:36:52.1945143Z         	Error:      	Expected nil, but got: Code: INVALID_ARGUMENT
2022-07-19T10:36:52.1948260Z         	            	rpc error: code = InvalidArgument desc = target: user.-80.primary: vttablet: rpc error: code = InvalidArgument desc = table sharded_message not found in schema (CallerID: unsecure_grpc_client)
2022-07-19T10:36:52.1951154Z         	            	target: user.80-.primary: vttablet: rpc error: code = InvalidArgument desc = table sharded_message not found in schema (CallerID: unsecure_grpc_client)
2022-07-19T10:36:52.1952601Z         	Test:       	TestReparenting
2022-07-19T10:36:52.1953736Z --- FAIL: TestReparenting (0.00s)
2022-07-19T10:36:52.1954919Z === RUN   TestConnection
2022-07-19T10:36:53.2056838Z     message_test.go:455: 
2022-07-19T10:36:53.2058851Z         	Error Trace:	message_test.go:455
2022-07-19T10:36:53.2060450Z         	Error:      	Expected nil, but got: Code: INVALID_ARGUMENT
2022-07-19T10:36:53.2064123Z         	            	rpc error: code = InvalidArgument desc = target: user.-80.primary: vttablet: rpc error: code = InvalidArgument desc = table sharded_message not found in schema (CallerID: unsecure_grpc_client)
2022-07-19T10:36:53.2068323Z         	            	target: user.80-.primary: vttablet: rpc error: code = InvalidArgument desc = table sharded_message not found in schema (CallerID: unsecure_grpc_client)
2022-07-19T10:36:53.2070517Z         	Test:       	TestConnection
2022-07-19T10:36:53.2072065Z --- FAIL: TestConnection (1.01s)
2022-07-19T10:36:53.2073130Z FAIL
2022-07-19T10:37:05.6304128Z FAIL	vitess.io/vitess/go/test/endtoend/messaging	52.892s
2022-07-19T10:37:05.6330069Z FAIL

seems related.

shlomi-noach · 2022-07-19T11:09:54Z

I'm lost with the test failures.

shlomi-noach · 2022-07-19T11:52:42Z

vtgate_queries, vtgate_reservedconn keep failing though I dont see how they're related. vstream* tests seem related but I can't make the connection.

shlomi-noach · 2022-07-19T11:54:09Z

OK I get it!

				schematools.ReloadShard(
					reloadCtx,
					exec.ts,
					exec.tmc,
					exec.logger,
					exec.keyspace,
					result.Shard,
					result.Position,
					concurrency,
					false, /* includePrimary */

says false, /* includePrimary */; we really do want to reload the schema on the primary though!

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

shlomi-noach · 2022-07-19T16:50:34Z

OK, tests still failing, and they're consistent, and they're persistent, and it has to do with ApplySchema and therefore also have to do with ReloadSchema().

shlomi-noach · 2022-07-19T16:50:41Z

e.g. https://github.com/vitessio/vitess/runs/7413675616?check_suite_focus=true

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

dbussink · 2022-07-20T08:25:20Z

 	}

-	if syncOperationExecuted {
+	if true || syncOperationExecuted {


I think we can drop this true now that we found the real issue?

Yes. refactoring and also reusing your defer approach to ensure we ReloadSchema even on early return.

Doing this is almost always a bug anyway so we should lint for this to avoid problems. This would have caught the bug that was plaguing us in vitessio#10739 as it's easy to overlook this type of issue. So we'd rather prefer the linter catches it for next time. Signed-off-by: Dirkjan Bussink <d.bussink@gmail.com>

shlomi-noach · 2022-07-20T08:34:42Z

Thanks @dbussink for helping to find the root cause, which was reusing an iteration argument's address.

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

dbussink

Yes 🎉

…nce (#10763) Doing this is almost always a bug anyway so we should lint for this to avoid problems. This would have caught the bug that was plaguing us in #10739 as it's easy to overlook this type of issue. So we'd rather prefer the linter catches it for next time. Signed-off-by: Dirkjan Bussink <d.bussink@gmail.com>

vitessio#848) * ApplySchema: do not ReloadSchema on ExecuteFetchAsDba Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com> * include primary in final ReloadSchema Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com> * experimental: always reload schema, even in Online DDL Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com> * RateLimiter: exit goroutine at Stop() Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com> * defer ticker.Stop() Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com> * fix shard iteration Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com> * ensure to ReloadSchema even on early return Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

ApplySchema: do not ReloadSchema on ExecuteFetchAsDba

6d331ab

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

shlomi-noach added Type: Enhancement Logical improvement (somewhere between a bug and feature) Component: Cluster management Component: Query Serving labels Jul 19, 2022

shlomi-noach requested a review from dbussink July 19, 2022 09:22

dbussink approved these changes Jul 19, 2022

View reviewed changes

shlomi-noach added 5 commits July 19, 2022 14:57

include primary in final ReloadSchema

ffceb05

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

experimental: always reload schema, even in Online DDL

8e08c99

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

RateLimiter: exit goroutine at Stop()

46feefa

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

Merge branch 'main' into apply-schema-no-reload-schema-on-execute

f3b2a03

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

defer ticker.Stop()

98e7402

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

dbussink mentioned this pull request Jul 19, 2022

Try always running reload schema #10758

Closed

fix shard iteration

3eb17b6

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

dbussink reviewed Jul 20, 2022

View reviewed changes

dbussink mentioned this pull request Jul 20, 2022

Add the linter for exporting a loop variable through a pointer reference #10763

Merged

3 tasks

shlomi-noach added 2 commits July 20, 2022 11:37

ensure to ReloadSchema even on early return

0c19870

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

merge main, resolve conflict

9b93e15

Signed-off-by: Shlomi Noach <2607934+shlomi-noach@users.noreply.github.com>

dbussink approved these changes Jul 20, 2022

View reviewed changes

dbussink mentioned this pull request Jul 20, 2022

Be explicit about capturing the pointer #10765

Merged

3 tasks

shlomi-noach mentioned this pull request Jul 20, 2022

Online DDL: issue a ReloadSchema at the completion of any migration #10766

Merged

3 tasks

shlomi-noach merged commit 94d155d into vitessio:main Jul 20, 2022

shlomi-noach deleted the apply-schema-no-reload-schema-on-execute branch July 20, 2022 10:29

shlomi-noach mentioned this pull request Jul 24, 2022

Backport v14: reduce ApplySchema complexity, normalize calls to ReloadSchema #10796

Merged

Conversation

shlomi-noach commented Jul 19, 2022

Description

Related Issue(s)

Checklist

Deployment Notes

Uh oh!

vitess-bot Bot commented Jul 19, 2022 • edited by dbussink Loading Uh oh! There was an error while loading. Please reload this page.

Uh oh!

Review Checklist

General

Bug fixes

Non-trivial changes

New/Existing features

Backward compatibility

Uh oh!

vitess-bot Bot commented Jul 19, 2022

Review Checklist

General

Bug fixes

Non-trivial changes

New/Existing features

Backward compatibility

Uh oh!

shlomi-noach commented Jul 19, 2022

Uh oh!

shlomi-noach commented Jul 19, 2022

Uh oh!

shlomi-noach commented Jul 19, 2022

Uh oh!

shlomi-noach commented Jul 19, 2022

Uh oh!

shlomi-noach commented Jul 19, 2022

Uh oh!

shlomi-noach commented Jul 19, 2022

Uh oh!

shlomi-noach commented Jul 19, 2022

Uh oh!

dbussink Jul 20, 2022

Choose a reason for hiding this comment

Uh oh!

shlomi-noach Jul 20, 2022

Choose a reason for hiding this comment

Uh oh!

shlomi-noach commented Jul 20, 2022

Uh oh!

dbussink left a comment

Choose a reason for hiding this comment

Uh oh!

Reviewers

Assignees

Labels

Projects

Milestone

Development

Uh oh!

2 participants

vitess-bot Bot commented Jul 19, 2022 •

edited by dbussink

Loading