Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sql: different schema update logic in tests and real sessions #17347

Closed
knz opened this issue Aug 1, 2017 · 12 comments
Closed

sql: different schema update logic in tests and real sessions #17347

knz opened this issue Aug 1, 2017 · 12 comments
Assignees

Comments

@knz
Copy link
Contributor

knz commented Aug 1, 2017

I am running the following statements:

CREATE DATABASE test;
CREATE TABLE test.x(x INT);
CREATE INDEX y ON test.x(x);
SELECT x FROM test.x@y;

When I run this in a regular session, the SELECT works fine, and I observe the following server log:

I170801 14:51:27.780578 278 sql/executor.go:704  [client=127.0.0.1:55002,user=root,n1] execRequest: CREATE DATABASE test; CREATE TABLE test.x (x INT); CREATE INDEX y ON test.x(x); SELECT x FROM test.x@y;
I170801 14:51:27.780751 278 sql/executor.go:1098  [client=127.0.0.1:55002,user=root,n1] executing 1/1: CREATE DATABASE test
I170801 14:51:27.780773 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] CREATE DATABASE test
I170801 14:51:27.780818 278 sql/executor.go:1773  [client=127.0.0.1:55002,user=root,n1] query not supported for distSQL: unsupported node *sql.createDatabaseNode
I170801 14:51:27.790741 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] CREATE DATABASE done
I170801 14:51:27.793767 278 sql/event_log.go:101  [client=127.0.0.1:55002,user=root,n1] Event: "create_database", target: 84, info: {DatabaseName:test Statement:CREATE DATABASE test User:root}
I170801 14:51:27.793802 278 sql/session.go:1127  [client=127.0.0.1:55002,user=root,n1] execSchemaChanges() called
I170801 14:51:27.793848 278 sql/executor.go:1098  [client=127.0.0.1:55002,user=root,n1] executing 1/1: CREATE TABLE test.x (x INT)
I170801 14:51:27.793866 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] CREATE TABLE test.x (x INT)
I170801 14:51:27.794276 278 sql/executor.go:1773  [client=127.0.0.1:55002,user=root,n1] query not supported for distSQL: unsupported node *sql.createTableNode
I170801 14:51:27.799549 115 storage/replica_command.go:2673  [split,n1,s1,r202/1:/{Table/83-Max}] initiating a split of this range at key /Table/84 [r211]
I170801 14:51:27.806073 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] CREATE TABLE done
I170801 14:51:27.809263 278 sql/event_log.go:101  [client=127.0.0.1:55002,user=root,n1] Event: "create_table", target: 85, info: {TableName:test.x Statement:CREATE TABLE test.x (x INT) User:root}
I170801 14:51:27.809303 278 sql/session.go:1127  [client=127.0.0.1:55002,user=root,n1] execSchemaChanges() called
I170801 14:51:27.809351 278 sql/executor.go:1098  [client=127.0.0.1:55002,user=root,n1] executing 1/1: CREATE INDEX y ON test.x (x)
I170801 14:51:27.809385 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] CREATE INDEX y ON test.x (x)
I170801 14:51:27.810230 278 sql/executor.go:1773  [client=127.0.0.1:55002,user=root,n1] query not supported for distSQL: unsupported node *sql.createIndexNode
I170801 14:51:27.812099 69 storage/replica_proposal.go:454  [n1,s1,r8/1:/Table/1{3-4}] new range lease repl=(n1,s1):1 start=0.000000000,0 epo=29 pro=1501599087.804252723,0 following repl=(n1,s1):1 start=0.000000000,0 epo=28 pro=1501598562.651272126,0
I170801 14:51:27.821820 62 storage/replica_proposal.go:454  [n1,s1,r202/1:/{Table/83-Max}] new range lease repl=(n1,s1):1 start=0.000000000,0 epo=29 pro=1501599083.434363204,0 following repl=(n1,s1):1 start=0.000000000,0 epo=29 pro=1501599083.434363204,0
I170801 14:51:27.822512 115 storage/replica_command.go:2673  [split,n1,s1,r211/1:/{Table/84-Max}] initiating a split of this range at key /Table/85 [r212]
I170801 14:51:27.829113 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] CREATE INDEX done
I170801 14:51:27.835107 278 sql/event_log.go:101  [client=127.0.0.1:55002,user=root,n1] Event: "create_index", target: 85, info: {TableName:x IndexName:y Statement:CREATE INDEX y ON test.x (x) User:root MutationID:1}
I170801 14:51:27.835154 278 sql/session.go:1127  [client=127.0.0.1:55002,user=root,n1] execSchemaChanges() called
I170801 14:51:27.846505 278 sql/lease.go:360  [client=127.0.0.1:55002,user=root,n1] publish: descID=85 (x) version=2 mtime=2017-08-01 14:51:27.846334128 +0000 UTC
I170801 14:51:27.846679 65 storage/replica_proposal.go:454  [n1,s1,r211/1:/{Table/84-Max}] new range lease repl=(n1,s1):1 start=0.000000000,0 epo=29 pro=1501599083.434363204,0 following repl=(n1,s1):1 start=0.000000000,0 epo=29 pro=1501599083.434363204,0
I170801 14:51:27.855181 78 storage/replica_proposal.go:454  [replicate,n1,s1,r32/1:/Table/5{7-8}] new range lease repl=(n1,s1):1 start=0.000000000,0 epo=29 pro=1501599087.847516873,0 following repl=(n1,s1):1 start=0.000000000,0 epo=28 pro=1501598561.448022364,0
I170801 14:51:27.864301 278 sql/lease.go:360  [client=127.0.0.1:55002,user=root,n1] publish: descID=85 (x) version=3 mtime=2017-08-01 14:51:27.864119709 +0000 UTC
I170801 14:51:27.876996 278 sql/backfill.go:135  [client=127.0.0.1:55002,user=root,n1] Running backfill for "x", v=3, m=1
I170801 14:51:27.901048 278 sql/lease.go:360  [client=127.0.0.1:55002,user=root,n1] publish: descID=85 (x) version=4 mtime=2017-08-01 14:51:27.900855938 +0000 UTC
I170801 14:51:27.916478 278 sql/event_log.go:101  [client=127.0.0.1:55002,user=root,n1] Event: "finish_schema_change", target: 85, info: {MutationID:1}
I170801 14:51:27.917998 278 sql/lease.go:286  publish (count leases): descID=85 name=x version=3 count=1
I170801 14:51:27.947621 278 sql/executor.go:1098  [client=127.0.0.1:55002,user=root,n1] executing 1/1: SELECT x FROM test.x@y
I170801 14:51:27.947658 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] SELECT x FROM test.x@y
I170801 14:51:27.948761 278 sql/executor.go:1324  [client=127.0.0.1:55002,user=root,n1] SELECT (0 results) done
I170801 14:51:27.948795 278 sql/session.go:1127  [client=127.0.0.1:55002,user=root,n1] execSchemaChanges() called

When run in a test however, (TestServer with manually created session) I observe the following trace instead, with an error:

I170801 14:49:23.433707 10 sql/executor.go:704  [n1] execRequest: CREATE DATABASE test; CREATE TABLE test.x(x INT); CREATE INDEX y ON test.x(x); SELECT x FROM test.x@y
I170801 14:49:23.433951 10 sql/executor.go:1098  [n1] executing 1/1: CREATE DATABASE test
I170801 14:49:23.434005 10 sql/executor.go:1324  [n1] CREATE DATABASE test
I170801 14:49:23.434062 10 sql/executor.go:1773  [n1] query not supported for distSQL: unsupported node *sql.createDatabaseNode
I170801 14:49:23.437163 10 sql/executor.go:1324  [n1] CREATE DATABASE done
I170801 14:49:23.437792 10 sql/event_log.go:101  [n1] Event: "create_database", target: 50, info: {DatabaseName:test Statement:CREATE DATABASE test User:root}
I170801 14:49:23.437823 10 sql/session.go:1127  [n1] execSchemaChanges() called
I170801 14:49:23.437857 10 sql/executor.go:1098  [n1] executing 1/1: CREATE TABLE test.x (x INT)
I170801 14:49:23.438006 39 storage/replica_command.go:2673  [split,n1,s1,r9/1:/{Table/14-Max}] initiating a split of this range at key /Table/50 [r10]
I170801 14:49:23.438139 10 sql/executor.go:1324  [n1] CREATE TABLE test.x (x INT)
I170801 14:49:23.438495 10 sql/executor.go:1773  [n1] query not supported for distSQL: unsupported node *sql.createTableNode
I170801 14:49:23.441340 10 sql/executor.go:1324  [n1] CREATE TABLE done
I170801 14:49:23.442095 10 sql/event_log.go:101  [n1] Event: "create_table", target: 51, info: {TableName:test.x Statement:CREATE TABLE test.x (x INT) User:root}
I170801 14:49:23.442121 10 sql/session.go:1127  [n1] execSchemaChanges() called
I170801 14:49:23.442150 10 sql/executor.go:1098  [n1] executing 1/1: CREATE INDEX y ON test.x (x)
I170801 14:49:23.442166 10 sql/executor.go:1324  [n1] CREATE INDEX y ON test.x (x)
I170801 14:49:23.442888 10 sql/executor.go:1773  [n1] query not supported for distSQL: unsupported node *sql.createIndexNode
I170801 14:49:23.443031 39 storage/replica_command.go:2673  [split,n1,s1,r10/1:/{Table/50-Max}] initiating a split of this range at key /Table/51 [r11]
I170801 14:49:23.446059 10 sql/executor.go:1324  [n1] CREATE INDEX done
I170801 14:49:23.446951 10 sql/event_log.go:101  [n1] Event: "create_index", target: 51, info: {TableName:x IndexName:y Statement:CREATE INDEX y ON test.x (x) User:root MutationID:0}
I170801 14:49:23.446975 10 sql/session.go:1127  [n1] execSchemaChanges() called
I170801 14:49:23.450355 10 sql/lease.go:360  [n1] publish: descID=51 (x) version=2 mtime=2017-08-01 14:49:23.450095963 +0000 UTC
I170801 14:49:23.453265 10 sql/executor.go:1098  [n1] executing 1/1: SELECT x FROM test.x@y
I170801 14:49:23.453307 10 sql/executor.go:1324  [n1] SELECT x FROM test.x@y
I170801 14:49:23.457225 10 sql/executor.go:1324  [n1] ERROR: index "y" not found
I170801 14:49:23.457295 10 sql/executor.go:870  [n1] execRequest: error: index "y" not found
I170801 14:49:23.457316 10 sql/session.go:1127  [n1] execSchemaChanges() called

It is as if the schema change is not fully executed. How do I ensure the schema change is complete (incl backfill) when running a test?

My test code looks like this:

  s, _, kvDB := serverutils.StartServer(t, base.TestServerArgs{})
  defer s.Stopper().Stop(ctx)
  e := s.Executor().(*sql.Executor)
  session := sql.NewSession(ctx, sql.SessionArgs{User: security.RootUser}, e, nil, memMetrics)
  session.StartUnlimitedMonitor()
  defer session.Finish(e)

  res := e.ExecuteStatements(session, `CREATE DATABASE test; CREATE TABLE test.x(x INT); CREATE INDEX y ON test.x(x); SELECT x FROM test.x@y`, nil)
  defer res.Close(ctx)
  if err := checkQueryResults(res.ResultList, 4); err != nil {
    t.Fatal(err)
  }

Note that the same problem persists whether I run all the statements in a single call to ExecuteStatements, or using 1 statement per call.

What am I missing? Do I need to initialize my test differently?

cc @jordanlewis @vivekmenezes

(found via #17310)

@jordanlewis
Copy link
Member

@knz I think this is happening because you're using the Executor to send statements. I don't exactly know why the Executor won't wait for schema changes when called internally at the moment - perhaps that's something we need to fix.

Anyway, a workaround is to use the sqlDB return value of serverutil.StartServer, and then use that later to run your statements, with sqlDB.Exec("CREATE INDEX ...").

@knz
Copy link
Contributor Author

knz commented Aug 1, 2017

I changed my test code to use sqlDB.Exec instead. The error persists.

@knz
Copy link
Contributor Author

knz commented Aug 1, 2017

Note that the same test not using an index works fine, i.e. db and table descriptors are properly created/updated/published. The problem is specific to indexes.

@vivekmenezes
Copy link
Contributor

I170801 14:49:23.442888 10 sql/executor.go:1773 [n1] query not supported for distSQL: unsupported node *sql.createIndexNode is suspicious

@knz
Copy link
Contributor Author

knz commented Aug 1, 2017

The distsql error happens in both cases, both the successful and erroneous cases. IT is expected, distsql doesn't run the CREATE statements.

@jordanlewis
Copy link
Member

@vivekmenezes that always gets printed by any query plan that isn't distsql enabled, I think it's normal.

Looks like this is a problem others have hit as well - check out what backup_test.go has to do:

		sqlDB.Exec(`CREATE INDEX balance_idx ON data.bank (balance)`)
		testutils.SucceedsSoon(t, func() error {
			var unused string
			var createTable string
			sqlDB.QueryRow(`SHOW CREATE TABLE data.bank`).Scan(&unused, &createTable)
			if !strings.Contains(createTable, "balance_idx") {
				return errors.New("expected a balance_idx index")
			}
			return nil
		})

@vivekmenezes
Copy link
Contributor

vivekmenezes commented Aug 1, 2017 via email

@knz
Copy link
Contributor Author

knz commented Aug 1, 2017

(I solved my problem in #17310 by creating the index and the table together, i.e. CREATE TABLE t(x INT, INDEX y(x)). So it's not blocking me now. However it would be nice to have some sort of guidance for the future.)

@jordanlewis
Copy link
Member

I bet the statement is accidentally getting routed through the asynchronous path.

@vivekmenezes
Copy link
Contributor

func TestIndexReadiness(t *testing.T) {
	defer leaktest.AfterTest(t)()
	ctx := context.TODO()
	s, sqlDB, _ := serverutils.StartServer(t, base.TestServerArgs{})
	defer s.Stopper().Stop(ctx)

	if _, err := sqlDB.Exec(`CREATE DATABASE test; CREATE TABLE test.x(x INT); CREATE INDEX y ON test.x(x); SELECT x FROM test.x@y`); err != nil {
		t.Fatal(err)
	}

works. Can you attach an example that doesn't

@knz
Copy link
Contributor Author

knz commented Aug 1, 2017

I thought the example above was sufficient. I was observing this in the branch #17310 forked from, perhaps another commit on master fixed the problem already. I will try again after rebasing.

@knz
Copy link
Contributor Author

knz commented Aug 1, 2017

Ok I found the error! My test was incorrectly skipping the migration responsible for creating the system.jobs table. So the schema change was not able to access it and was not queued properly.

I am surprised that the lack of system.jobs does not result in a louder error! But for the time being, my problem is resolved. Thanks for your help investigating this.

@knz knz closed this as completed Aug 1, 2017
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

No branches or pull requests

3 participants