util/profile: migrate test-infra to testify #26205

tisonkun · 2021-07-13T09:23:39Z

What problem does this PR solve?

Issue Number:

Release note

No release note.

Signed-off-by: tison <wander4096@gmail.com>

tisonkun · 2021-07-13T09:26:20Z

/hold
/cc @xhebox @disksing @tiancaiamao

two pending topics:

Please validate whether we implement TestKit properly. So far, it is nearly a copy from the gocheck version.
goleak failed with

errlog

=== RUN   TestProfileToDatum
=== PAUSE TestProfileToDatum
=== RUN   TestHeapProfileRecorder
=== PAUSE TestHeapProfileRecorder
=== RUN   TestProfiles
=== PAUSE TestProfiles
=== CONT  TestProfileToDatum
=== CONT  TestProfiles
=== CONT  TestHeapProfileRecorder
--- PASS: TestProfileToDatum (0.00s)
[2021/07/13 17:24:40.104 +08:00] [INFO] [tidb.go:70] ["new domain"] [store=944cfeaf-7514-479f-b9eb-4dc149cc0165] ["ddl lease"=1s] ["stats lease"=-1ns] ["index usage sync lease"=0s]
[2021/07/13 17:24:40.106 +08:00] [INFO] [ddl.go:342] ["[ddl] start DDL"] [ID=22a80d78-2b16-42f1-9ac5-2a4cf5318080] [runWorker=true]
[2021/07/13 17:24:40.106 +08:00] [INFO] [ddl.go:331] ["[ddl] start delRangeManager OK"] ["is a emulator"=true]
[2021/07/13 17:24:40.106 +08:00] [INFO] [delete_range.go:140] ["[ddl] start delRange emulator"]
[2021/07/13 17:24:40.107 +08:00] [INFO] [ddl_worker.go:134] ["[ddl] start DDL worker"] [worker="worker 1, tp general"]
[2021/07/13 17:24:40.107 +08:00] [INFO] [ddl_worker.go:134] ["[ddl] start DDL worker"] [worker="worker 2, tp add index"]
[2021/07/13 17:24:40.107 +08:00] [INFO] [domain.go:155] ["full load InfoSchema success"] [currentSchemaVersion=0] [neededSchemaVersion=0] ["start time"=944.143µs]
[2021/07/13 17:24:40.107 +08:00] [INFO] [domain.go:370] ["full load and reset schema validator"]
[2021/07/13 17:24:40.108 +08:00] [INFO] [tidb.go:242] ["rollbackTxn called due to ddl/autocommit failure"]
[2021/07/13 17:24:40.108 +08:00] [WARN] [session.go:1617] ["run statement failed"] [schemaVersion=0] [error="[schema:1049]Unknown database 'mysql'"] [errorVerbose="[schema:1049]Unknown database 'mysql'\ngithub.com/pingcap/errors.AddStack\n\t/Users/tison/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20210425183316-da1aaba5fb63/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/Users/tison/go/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20210425183316-da1aaba5fb63/normalize.go:159\ngithub.com/pingcap/tidb/executor.(*SimpleExec).executeUse\n\t/Users/tison/go/src/github.com/pingcap/tidb/executor/simple.go:555\ngithub.com/pingcap/tidb/executor.(*SimpleExec).Next\n\t/Users/tison/go/src/github.com/pingcap/tidb/executor/simple.go:125\ngithub.com/pingcap/tidb/executor.Next\n\t/Users/tison/go/src/github.com/pingcap/tidb/executor/executor.go:286\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor\n\t/Users/tison/go/src/github.com/pingcap/tidb/executor/adapter.go:589\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/Users/tison/go/src/github.com/pingcap/tidb/executor/adapter.go:470\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/Users/tison/go/src/github.com/pingcap/tidb/executor/adapter.go:419\ngithub.com/pingcap/tidb/session.runStmt\n\t/Users/tison/go/src/github.com/pingcap/tidb/session/session.go:1719\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/Users/tison/go/src/github.com/pingcap/tidb/session/session.go:1614\ngithub.com/pingcap/tidb/session.(*session).ExecuteInternal\n\t/Users/tison/go/src/github.com/pingcap/tidb/session/session.go:1334\ngithub.com/pingcap/tidb/session.checkBootstrapped\n\t/Users/tison/go/src/github.com/pingcap/tidb/session/bootstrap.go:586\ngithub.com/pingcap/tidb/session.bootstrap\n\t/Users/tison/go/src/github.com/pingcap/tidb/session/bootstrap.go:349\ngithub.com/pingcap/tidb/session.runInBootstrapSession\n\t/Users/tison/go/src/github.com/pingcap/tidb/session/session.go:2611\ngithub.com/pingcap/tidb/session.BootstrapSession\n\t/Users/tison/go/src/github.com/pingcap/tidb/session/session.go:2467\ngithub.com/pingcap/tidb/util/profile_test.TestProfiles\n\t/Users/tison/go/src/github.com/pingcap/tidb/util/profile/profile_test.go:44\ntesting.tRunner\n\t/usr/local/Cellar/go/1.16/libexec/src/testing/testing.go:1194\nruntime.goexit\n\t/usr/local/Cellar/go/1.16/libexec/src/runtime/asm_amd64.s:1371"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 0,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": null\n}"]
[2021/07/13 17:24:40.108 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=0] [cur_db=] [sql="CREATE DATABASE IF NOT EXISTS test"] [user=]
[2021/07/13 17:24:40.109 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:2, Type:create schema, State:none, SchemaState:queueing, SchemaID:1, TableID:0, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.109 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.109 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:2, Type:create schema, State:none, SchemaState:queueing, SchemaID:1, TableID:0, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.109 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE IF NOT EXISTS test"]
[2021/07/13 17:24:40.110 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:2, Type:create schema, State:none, SchemaState:queueing, SchemaID:1, TableID:0, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.109 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.111 +08:00] [INFO] [domain.go:155] ["full load InfoSchema success"] [currentSchemaVersion=0] [neededSchemaVersion=1] ["start time"=750.664µs]
[2021/07/13 17:24:40.111 +08:00] [INFO] [domain.go:370] ["full load and reset schema validator"]
[2021/07/13 17:24:40.112 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=1] ["take time"=2.111982ms] [job="ID:2, Type:create schema, State:done, SchemaState:public, SchemaID:1, TableID:0, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.109 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.112 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:2, Type:create schema, State:synced, SchemaState:public, SchemaID:1, TableID:0, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.109 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.113 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=2]
[2021/07/13 17:24:40.113 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.113 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=1] [cur_db=] [sql="CREATE DATABASE IF NOT EXISTS `mysql`"] [user=]
[2021/07/13 17:24:40.113 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:4, Type:create schema, State:none, SchemaState:queueing, SchemaID:3, TableID:0, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.113 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.113 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:4, Type:create schema, State:none, SchemaState:queueing, SchemaID:3, TableID:0, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.113 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE IF NOT EXISTS `mysql`"]
[2021/07/13 17:24:40.113 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:4, Type:create schema, State:none, SchemaState:queueing, SchemaID:3, TableID:0, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.113 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.114 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=1] [neededSchemaVersion=2] ["start time"=67.458µs] [phyTblIDs="[]"] [actionTypes="[]"]
[2021/07/13 17:24:40.116 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=2] ["take time"=2.297959ms] [job="ID:4, Type:create schema, State:done, SchemaState:public, SchemaID:3, TableID:0, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.113 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.116 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:4, Type:create schema, State:synced, SchemaState:public, SchemaID:3, TableID:0, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.113 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.117 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=4]
[2021/07/13 17:24:40.117 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.117 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=2] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.user (\n\t\tHost\t\t\t\t\tCHAR(64),\n\t\tUser\t\t\t\t\tCHAR(32),\n\t\tauthentication_string\tTEXT,\n\t\tplugin\t\t\t\t\tCHAR(64),\n\t\tSelect_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tInsert_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tUpdate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDelete_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDrop_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tProcess_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tGrant_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tReferences_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShow_db_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tSuper_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_tmp_table_priv\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tLock_tables_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tExecute_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_view_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShow_view_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tIndex_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_user_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tEvent_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tTrigger_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_role_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDrop_role_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAccount_locked\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShutdown_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tReload_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tFILE_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tConfig_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_Tablespace_Priv  ENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tRepl_slave_priv\t    \tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tRepl_client_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (Host, User));"] [user=]
[2021/07/13 17:24:40.118 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:6, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:5, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.117 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.118 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:6, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:5, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.117 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.user (\n\t\tHost\t\t\t\t\tCHAR(64),\n\t\tUser\t\t\t\t\tCHAR(32),\n\t\tauthentication_string\tTEXT,\n\t\tplugin\t\t\t\t\tCHAR(64),\n\t\tSelect_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tInsert_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tUpdate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDelete_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDrop_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tProcess_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tGrant_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tReferences_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShow_db_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tSuper_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_tmp_table_priv\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tLock_tables_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tExecute_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_view_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShow_view_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tIndex_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_user_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tEvent_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tTrigger_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_role_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDrop_role_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAccount_locked\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShutdown_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tReload_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tFILE_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tConfig_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_Tablespace_Priv  ENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tRepl_slave_priv\t    \tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tRepl_client_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (Host, User));"]
[2021/07/13 17:24:40.118 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:6, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.117 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.120 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=2] [neededSchemaVersion=3] ["start time"=356.524µs] [phyTblIDs="[5]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.122 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=3] ["take time"=2.251064ms] [job="ID:6, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:5, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.117 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.123 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:6, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:5, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.117 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.123 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=6]
[2021/07/13 17:24:40.123 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.123 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=3] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.global_priv (Host CHAR(60) NOT NULL DEFAULT '',User CHAR(80) NOT NULL DEFAULT '',Priv LONGTEXT NOT NULL DEFAULT '',PRIMARY KEY (Host, User))"] [user=]
[2021/07/13 17:24:40.124 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:8, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:7, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.124 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.124 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:8, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:7, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.124 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.global_priv (Host CHAR(60) NOT NULL DEFAULT '',User CHAR(80) NOT NULL DEFAULT '',Priv LONGTEXT NOT NULL DEFAULT '',PRIMARY KEY (Host, User))"]
[2021/07/13 17:24:40.124 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:8, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:7, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.124 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.124 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=3] [neededSchemaVersion=4] ["start time"=75.225µs] [phyTblIDs="[7]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.127 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=4] ["take time"=2.425831ms] [job="ID:8, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:7, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.124 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.127 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:8, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:7, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.124 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.127 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=8]
[2021/07/13 17:24:40.127 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.128 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=4] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.db (\n\t\tHost\t\t\t\t\tCHAR(60),\n\t\tDB\t\t\t\t\t\tCHAR(64),\n\t\tUser\t\t\t\t\tCHAR(32),\n\t\tSelect_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tInsert_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tUpdate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDelete_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDrop_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tGrant_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tReferences_priv \t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tIndex_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_tmp_table_priv\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tLock_tables_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_view_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShow_view_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tExecute_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tEvent_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tTrigger_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (Host, DB, User));"] [user=]
[2021/07/13 17:24:40.128 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:10, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:9, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.128 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.128 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:10, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:9, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.128 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.db (\n\t\tHost\t\t\t\t\tCHAR(60),\n\t\tDB\t\t\t\t\t\tCHAR(64),\n\t\tUser\t\t\t\t\tCHAR(32),\n\t\tSelect_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tInsert_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tUpdate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDelete_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tDrop_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tGrant_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tReferences_priv \t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tIndex_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_tmp_table_priv\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tLock_tables_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_view_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tShow_view_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tCreate_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tAlter_routine_priv\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tExecute_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tEvent_priv\t\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tTrigger_priv\t\t\tENUM('N','Y') NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (Host, DB, User));"]
[2021/07/13 17:24:40.129 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:10, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:9, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.128 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.130 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=4] [neededSchemaVersion=5] ["start time"=254.641µs] [phyTblIDs="[9]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.131 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=5] ["take time"=2.040704ms] [job="ID:10, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:9, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.128 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.132 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:10, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:9, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.128 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.133 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=10]
[2021/07/13 17:24:40.133 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.133 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=5] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.tables_priv (\n\t\tHost\t\tCHAR(60),\n\t\tDB\t\t\tCHAR(64),\n\t\tUser\t\tCHAR(32),\n\t\tTable_name\tCHAR(64),\n\t\tGrantor\t\tCHAR(77),\n\t\tTimestamp\tTIMESTAMP DEFAULT CURRENT_TIMESTAMP,\n\t\tTable_priv\tSET('Select','Insert','Update','Delete','Create','Drop','Grant','Index','Alter','Create View','Show View','Trigger','References'),\n\t\tColumn_priv\tSET('Select','Insert','Update'),\n\t\tPRIMARY KEY (Host, DB, User, Table_name));"] [user=]
[2021/07/13 17:24:40.133 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:12, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:11, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.133 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.133 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:12, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:11, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.133 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.tables_priv (\n\t\tHost\t\tCHAR(60),\n\t\tDB\t\t\tCHAR(64),\n\t\tUser\t\tCHAR(32),\n\t\tTable_name\tCHAR(64),\n\t\tGrantor\t\tCHAR(77),\n\t\tTimestamp\tTIMESTAMP DEFAULT CURRENT_TIMESTAMP,\n\t\tTable_priv\tSET('Select','Insert','Update','Delete','Create','Drop','Grant','Index','Alter','Create View','Show View','Trigger','References'),\n\t\tColumn_priv\tSET('Select','Insert','Update'),\n\t\tPRIMARY KEY (Host, DB, User, Table_name));"]
[2021/07/13 17:24:40.134 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:12, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:11, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.133 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.134 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=5] [neededSchemaVersion=6] ["start time"=155.106µs] [phyTblIDs="[11]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.136 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=6] ["take time"=2.008995ms] [job="ID:12, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:11, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.133 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.137 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:12, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:11, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.133 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.138 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=12]
[2021/07/13 17:24:40.138 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.138 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=6] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.columns_priv(\n\t\tHost\t\tCHAR(60),\n\t\tDB\t\t\tCHAR(64),\n\t\tUser\t\tCHAR(32),\n\t\tTable_name\tCHAR(64),\n\t\tColumn_name\tCHAR(64),\n\t\tTimestamp\tTIMESTAMP DEFAULT CURRENT_TIMESTAMP,\n\t\tColumn_priv\tSET('Select','Insert','Update'),\n\t\tPRIMARY KEY (Host, DB, User, Table_name, Column_name));"] [user=]
[2021/07/13 17:24:40.139 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:14, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:13, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.138 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.139 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:14, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:13, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.138 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.columns_priv(\n\t\tHost\t\tCHAR(60),\n\t\tDB\t\t\tCHAR(64),\n\t\tUser\t\tCHAR(32),\n\t\tTable_name\tCHAR(64),\n\t\tColumn_name\tCHAR(64),\n\t\tTimestamp\tTIMESTAMP DEFAULT CURRENT_TIMESTAMP,\n\t\tColumn_priv\tSET('Select','Insert','Update'),\n\t\tPRIMARY KEY (Host, DB, User, Table_name, Column_name));"]
[2021/07/13 17:24:40.139 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:14, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:13, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.138 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.140 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=6] [neededSchemaVersion=7] ["start time"=152.149µs] [phyTblIDs="[13]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.142 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=7] ["take time"=2.50691ms] [job="ID:14, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:13, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.138 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.142 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:14, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:13, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.138 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.143 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=14]
[2021/07/13 17:24:40.143 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.143 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=7] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.GLOBAL_VARIABLES(\n\t\tVARIABLE_NAME  VARCHAR(64) NOT NULL PRIMARY KEY,\n\t\tVARIABLE_VALUE VARCHAR(1024) DEFAULT NULL);"] [user=]
[2021/07/13 17:24:40.143 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:16, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:15, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.143 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.143 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:16, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:15, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.143 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.GLOBAL_VARIABLES(\n\t\tVARIABLE_NAME  VARCHAR(64) NOT NULL PRIMARY KEY,\n\t\tVARIABLE_VALUE VARCHAR(1024) DEFAULT NULL);"]
[2021/07/13 17:24:40.144 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:16, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:15, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.143 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.144 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=7] [neededSchemaVersion=8] ["start time"=94.381µs] [phyTblIDs="[15]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.146 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=8] ["take time"=2.409303ms] [job="ID:16, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:15, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.143 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.147 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:16, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:15, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.143 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.147 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=16]
[2021/07/13 17:24:40.147 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.147 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=8] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.tidb(\n\t\tVARIABLE_NAME  \tVARCHAR(64) NOT NULL PRIMARY KEY,\n\t\tVARIABLE_VALUE \tVARCHAR(1024) DEFAULT NULL,\n\t\tCOMMENT \t\tVARCHAR(1024));"] [user=]
[2021/07/13 17:24:40.148 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:18, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:17, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.147 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.148 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:18, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:17, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.147 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.tidb(\n\t\tVARIABLE_NAME  \tVARCHAR(64) NOT NULL PRIMARY KEY,\n\t\tVARIABLE_VALUE \tVARCHAR(1024) DEFAULT NULL,\n\t\tCOMMENT \t\tVARCHAR(1024));"]
[2021/07/13 17:24:40.148 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:18, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:17, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.147 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.148 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=8] [neededSchemaVersion=9] ["start time"=116.209µs] [phyTblIDs="[17]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.150 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=9] ["take time"=2.075535ms] [job="ID:18, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:17, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.147 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.151 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:18, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:17, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.147 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.151 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=18]
[2021/07/13 17:24:40.151 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.151 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=9] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.help_topic (\n  \t\thelp_topic_id \t\tINT(10) UNSIGNED NOT NULL,\n  \t\tname \t\t\t\tCHAR(64) NOT NULL,\n  \t\thelp_category_id \tSMALLINT(5) UNSIGNED NOT NULL,\n  \t\tdescription \t\tTEXT NOT NULL,\n  \t\texample \t\t\tTEXT NOT NULL,\n  \t\turl \t\t\t\tTEXT NOT NULL,\n  \t\tPRIMARY KEY (help_topic_id) clustered,\n  \t\tUNIQUE KEY name (name)\n\t\t) ENGINE=InnoDB DEFAULT CHARSET=utf8 STATS_PERSISTENT=0 COMMENT='help topics';"] [user=]
[2021/07/13 17:24:40.152 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:20, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:19, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.152 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.152 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:20, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:19, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.152 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.help_topic (\n  \t\thelp_topic_id \t\tINT(10) UNSIGNED NOT NULL,\n  \t\tname \t\t\t\tCHAR(64) NOT NULL,\n  \t\thelp_category_id \tSMALLINT(5) UNSIGNED NOT NULL,\n  \t\tdescription \t\tTEXT NOT NULL,\n  \t\texample \t\t\tTEXT NOT NULL,\n  \t\turl \t\t\t\tTEXT NOT NULL,\n  \t\tPRIMARY KEY (help_topic_id) clustered,\n  \t\tUNIQUE KEY name (name)\n\t\t) ENGINE=InnoDB DEFAULT CHARSET=utf8 STATS_PERSISTENT=0 COMMENT='help topics';"]
[2021/07/13 17:24:40.152 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:20, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:19, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.152 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.152 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=9] [neededSchemaVersion=10] ["start time"=98.524µs] [phyTblIDs="[19]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.155 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=10] ["take time"=2.386106ms] [job="ID:20, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:19, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.152 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.155 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:20, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:19, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.152 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.155 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=20]
[2021/07/13 17:24:40.155 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.156 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=10] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.stats_meta (\n\t\tversion \t\tBIGINT(64) UNSIGNED NOT NULL,\n\t\ttable_id \t\tBIGINT(64) NOT NULL,\n\t\tmodify_count\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tcount \t\t\tBIGINT(64) UNSIGNED NOT NULL DEFAULT 0,\n\t\tsnapshot        BIGINT(64) UNSIGNED NOT NULL DEFAULT 0,\n\t\tINDEX idx_ver(version),\n\t\tUNIQUE INDEX tbl(table_id)\n\t);"] [user=]
[2021/07/13 17:24:40.156 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:22, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:21, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.156 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.156 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:22, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:21, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.156 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.stats_meta (\n\t\tversion \t\tBIGINT(64) UNSIGNED NOT NULL,\n\t\ttable_id \t\tBIGINT(64) NOT NULL,\n\t\tmodify_count\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tcount \t\t\tBIGINT(64) UNSIGNED NOT NULL DEFAULT 0,\n\t\tsnapshot        BIGINT(64) UNSIGNED NOT NULL DEFAULT 0,\n\t\tINDEX idx_ver(version),\n\t\tUNIQUE INDEX tbl(table_id)\n\t);"]
[2021/07/13 17:24:40.156 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:22, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:21, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.156 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.157 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=10] [neededSchemaVersion=11] ["start time"=121.377µs] [phyTblIDs="[21]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.159 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=11] ["take time"=2.134367ms] [job="ID:22, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:21, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.156 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.159 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:22, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:21, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.156 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.160 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=22]
[2021/07/13 17:24:40.160 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.160 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=11] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.stats_histograms (\n\t\ttable_id \t\t\tBIGINT(64) NOT NULL,\n\t\tis_index \t\t\tTINYINT(2) NOT NULL,\n\t\thist_id \t\t\tBIGINT(64) NOT NULL,\n\t\tdistinct_count \t\tBIGINT(64) NOT NULL,\n\t\tnull_count \t\t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\ttot_col_size \t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tmodify_count \t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tversion \t\t\tBIGINT(64) UNSIGNED NOT NULL DEFAULT 0,\n\t\tcm_sketch \t\t\tBLOB(6291456),\n\t\tstats_ver \t\t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tflag \t\t\t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tcorrelation \t\tDOUBLE NOT NULL DEFAULT 0,\n\t\tlast_analyze_pos \tBLOB DEFAULT NULL,\n\t\tUNIQUE INDEX tbl(table_id, is_index, hist_id)\n\t);"] [user=]
[2021/07/13 17:24:40.160 +08:00] [INFO] [ddl_api.go:564] ["Automatically convert BLOB(6291456) to MEDIUMBLOB"]
[2021/07/13 17:24:40.160 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:24, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:23, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.16 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.160 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:24, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:23, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.16 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.stats_histograms (\n\t\ttable_id \t\t\tBIGINT(64) NOT NULL,\n\t\tis_index \t\t\tTINYINT(2) NOT NULL,\n\t\thist_id \t\t\tBIGINT(64) NOT NULL,\n\t\tdistinct_count \t\tBIGINT(64) NOT NULL,\n\t\tnull_count \t\t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\ttot_col_size \t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tmodify_count \t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tversion \t\t\tBIGINT(64) UNSIGNED NOT NULL DEFAULT 0,\n\t\tcm_sketch \t\t\tBLOB(6291456),\n\t\tstats_ver \t\t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tflag \t\t\t\tBIGINT(64) NOT NULL DEFAULT 0,\n\t\tcorrelation \t\tDOUBLE NOT NULL DEFAULT 0,\n\t\tlast_analyze_pos \tBLOB DEFAULT NULL,\n\t\tUNIQUE INDEX tbl(table_id, is_index, hist_id)\n\t);"]
[2021/07/13 17:24:40.161 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:24, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:23, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.16 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.162 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=11] [neededSchemaVersion=12] ["start time"=234.484µs] [phyTblIDs="[23]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.163 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=12] ["take time"=2.051056ms] [job="ID:24, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:23, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.16 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.164 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:24, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:23, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.16 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.164 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=24]
[2021/07/13 17:24:40.164 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.164 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=12] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.stats_buckets (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tbucket_id \tBIGINT(64) NOT NULL,\n\t\tcount \t\tBIGINT(64) NOT NULL,\n\t\trepeats \tBIGINT(64) NOT NULL,\n\t\tupper_bound BLOB NOT NULL,\n\t\tlower_bound BLOB ,\n\t\tndv         BIGINT NOT NULL DEFAULT 0,\n\t\tUNIQUE INDEX tbl(table_id, is_index, hist_id, bucket_id)\n\t);"] [user=]
[2021/07/13 17:24:40.165 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:26, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:25, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.164 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.165 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:26, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:25, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.164 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.stats_buckets (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tbucket_id \tBIGINT(64) NOT NULL,\n\t\tcount \t\tBIGINT(64) NOT NULL,\n\t\trepeats \tBIGINT(64) NOT NULL,\n\t\tupper_bound BLOB NOT NULL,\n\t\tlower_bound BLOB ,\n\t\tndv         BIGINT NOT NULL DEFAULT 0,\n\t\tUNIQUE INDEX tbl(table_id, is_index, hist_id, bucket_id)\n\t);"]
[2021/07/13 17:24:40.165 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:26, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:25, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.164 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.165 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=12] [neededSchemaVersion=13] ["start time"=123.18µs] [phyTblIDs="[25]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.167 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=13] ["take time"=2.05167ms] [job="ID:26, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:25, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.164 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.167 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:26, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:25, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.164 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.168 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=26]
[2021/07/13 17:24:40.168 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.168 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=13] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.gc_delete_range (\n\t\tjob_id \t\tBIGINT NOT NULL COMMENT \"the DDL job ID\",\n\t\telement_id \tBIGINT NOT NULL COMMENT \"the schema element ID\",\n\t\tstart_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tend_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tts \t\t\tBIGINT NOT NULL COMMENT \"timestamp in uint64\",\n\t\tUNIQUE KEY delete_range_index (job_id, element_id)\n\t);"] [user=]
[2021/07/13 17:24:40.168 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:28, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:27, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.168 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.168 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:28, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:27, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.168 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.gc_delete_range (\n\t\tjob_id \t\tBIGINT NOT NULL COMMENT \"the DDL job ID\",\n\t\telement_id \tBIGINT NOT NULL COMMENT \"the schema element ID\",\n\t\tstart_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tend_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tts \t\t\tBIGINT NOT NULL COMMENT \"timestamp in uint64\",\n\t\tUNIQUE KEY delete_range_index (job_id, element_id)\n\t);"]
[2021/07/13 17:24:40.168 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:28, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:27, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.168 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.169 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=13] [neededSchemaVersion=14] ["start time"=86.522µs] [phyTblIDs="[27]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.171 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=14] ["take time"=2.289489ms] [job="ID:28, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:27, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.168 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.171 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:28, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:27, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.168 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.171 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=28]
[2021/07/13 17:24:40.171 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.172 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=14] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.gc_delete_range_done (\n\t\tjob_id \t\tBIGINT NOT NULL COMMENT \"the DDL job ID\",\n\t\telement_id \tBIGINT NOT NULL COMMENT \"the schema element ID\",\n\t\tstart_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tend_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tts \t\t\tBIGINT NOT NULL COMMENT \"timestamp in uint64\",\n\t\tUNIQUE KEY delete_range_done_index (job_id, element_id)\n\t);"] [user=]
[2021/07/13 17:24:40.172 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:30, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:29, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.172 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.172 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:30, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:29, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.172 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.gc_delete_range_done (\n\t\tjob_id \t\tBIGINT NOT NULL COMMENT \"the DDL job ID\",\n\t\telement_id \tBIGINT NOT NULL COMMENT \"the schema element ID\",\n\t\tstart_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tend_key \tVARCHAR(255) NOT NULL COMMENT \"encoded in hex\",\n\t\tts \t\t\tBIGINT NOT NULL COMMENT \"timestamp in uint64\",\n\t\tUNIQUE KEY delete_range_done_index (job_id, element_id)\n\t);"]
[2021/07/13 17:24:40.172 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:30, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:29, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.172 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.172 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=14] [neededSchemaVersion=15] ["start time"=87.797µs] [phyTblIDs="[29]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.174 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=15] ["take time"=2.045645ms] [job="ID:30, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:29, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.172 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.175 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:30, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:29, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.172 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.175 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=30]
[2021/07/13 17:24:40.175 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.175 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=15] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.stats_feedback (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tfeedback \tBLOB NOT NULL,\n\t\tINDEX hist(table_id, is_index, hist_id)\n\t);"] [user=]
[2021/07/13 17:24:40.175 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:32, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:31, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.175 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.175 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:32, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:31, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.175 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.stats_feedback (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tfeedback \tBLOB NOT NULL,\n\t\tINDEX hist(table_id, is_index, hist_id)\n\t);"]
[2021/07/13 17:24:40.175 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:32, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:31, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.175 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.176 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=15] [neededSchemaVersion=16] ["start time"=83.285µs] [phyTblIDs="[31]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.178 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=16] ["take time"=2.196119ms] [job="ID:32, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:31, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.175 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.178 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:32, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:31, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.175 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.178 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=32]
[2021/07/13 17:24:40.178 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.178 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=16] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.role_edges (\n\t\tFROM_HOST \t\t\tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tFROM_USER \t\t\tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tTO_HOST \t\t\tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tTO_USER \t\t\tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tWITH_ADMIN_OPTION \tENUM('N','Y') CHARACTER SET utf8 COLLATE utf8_general_ci NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (FROM_HOST,FROM_USER,TO_HOST,TO_USER)\n\t);"] [user=]
[2021/07/13 17:24:40.179 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:34, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:33, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.179 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.179 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:34, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:33, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.179 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.role_edges (\n\t\tFROM_HOST \t\t\tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tFROM_USER \t\t\tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tTO_HOST \t\t\tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tTO_USER \t\t\tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tWITH_ADMIN_OPTION \tENUM('N','Y') CHARACTER SET utf8 COLLATE utf8_general_ci NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (FROM_HOST,FROM_USER,TO_HOST,TO_USER)\n\t);"]
[2021/07/13 17:24:40.179 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:34, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:33, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.179 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.179 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=16] [neededSchemaVersion=17] ["start time"=102.712µs] [phyTblIDs="[33]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.181 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=17] ["take time"=2.051032ms] [job="ID:34, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:33, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.179 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.182 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:34, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:33, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.179 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.182 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=34]
[2021/07/13 17:24:40.182 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.182 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=17] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.default_roles (\n\t\tHOST \t\t\t\tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tUSER \t\t\t\tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tDEFAULT_ROLE_HOST \tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '%',\n\t\tDEFAULT_ROLE_USER \tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tPRIMARY KEY (HOST,USER,DEFAULT_ROLE_HOST,DEFAULT_ROLE_USER)\n\t)"] [user=]
[2021/07/13 17:24:40.183 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:36, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:35, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.183 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.183 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:36, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:35, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.183 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.default_roles (\n\t\tHOST \t\t\t\tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tUSER \t\t\t\tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tDEFAULT_ROLE_HOST \tCHAR(60) COLLATE utf8_bin NOT NULL DEFAULT '%',\n\t\tDEFAULT_ROLE_USER \tCHAR(32) COLLATE utf8_bin NOT NULL DEFAULT '',\n\t\tPRIMARY KEY (HOST,USER,DEFAULT_ROLE_HOST,DEFAULT_ROLE_USER)\n\t)"]
[2021/07/13 17:24:40.183 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:36, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:35, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.183 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.184 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=17] [neededSchemaVersion=18] ["start time"=165.858µs] [phyTblIDs="[35]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.186 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=18] ["take time"=2.459758ms] [job="ID:36, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:35, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.183 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.186 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:36, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:35, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.183 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.187 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=36]
[2021/07/13 17:24:40.187 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.187 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=18] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.bind_info (\n\t\toriginal_sql TEXT NOT NULL,\n\t\tbind_sql TEXT NOT NULL,\n\t\tdefault_db TEXT NOT NULL,\n\t\tstatus TEXT NOT NULL,\n\t\tcreate_time TIMESTAMP(3) NOT NULL,\n\t\tupdate_time TIMESTAMP(3) NOT NULL,\n\t\tcharset TEXT NOT NULL,\n\t\tcollation TEXT NOT NULL,\n\t\tsource VARCHAR(10) NOT NULL DEFAULT 'unknown',\n\t\tINDEX sql_index(original_sql(1024),default_db(1024)) COMMENT \"accelerate the speed when add global binding query\",\n\t\tINDEX time_index(update_time) COMMENT \"accelerate the speed when querying with last update time\"\n\t) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;"] [user=]
[2021/07/13 17:24:40.187 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:38, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:37, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.187 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.187 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:38, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:37, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.187 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.bind_info (\n\t\toriginal_sql TEXT NOT NULL,\n\t\tbind_sql TEXT NOT NULL,\n\t\tdefault_db TEXT NOT NULL,\n\t\tstatus TEXT NOT NULL,\n\t\tcreate_time TIMESTAMP(3) NOT NULL,\n\t\tupdate_time TIMESTAMP(3) NOT NULL,\n\t\tcharset TEXT NOT NULL,\n\t\tcollation TEXT NOT NULL,\n\t\tsource VARCHAR(10) NOT NULL DEFAULT 'unknown',\n\t\tINDEX sql_index(original_sql(1024),default_db(1024)) COMMENT \"accelerate the speed when add global binding query\",\n\t\tINDEX time_index(update_time) COMMENT \"accelerate the speed when querying with last update time\"\n\t) ENGINE=InnoDB DEFAULT CHARSET=utf8mb4 COLLATE=utf8mb4_bin;"]
[2021/07/13 17:24:40.188 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:38, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:37, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.187 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.188 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=18] [neededSchemaVersion=19] ["start time"=241.82µs] [phyTblIDs="[37]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.191 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=19] ["take time"=2.500887ms] [job="ID:38, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:37, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.187 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.191 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:38, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:37, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.187 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.192 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=38]
[2021/07/13 17:24:40.192 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.192 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=19] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.stats_top_n (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tvalue \t\tLONGBLOB,\n\t\tcount \t\tBIGINT(64) UNSIGNED NOT NULL,\n\t\tINDEX tbl(table_id, is_index, hist_id)\n\t);"] [user=]
[2021/07/13 17:24:40.193 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:40, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:39, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.193 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.193 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:40, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:39, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.193 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.stats_top_n (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tvalue \t\tLONGBLOB,\n\t\tcount \t\tBIGINT(64) UNSIGNED NOT NULL,\n\t\tINDEX tbl(table_id, is_index, hist_id)\n\t);"]
[2021/07/13 17:24:40.193 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:40, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:39, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.193 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.194 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=19] [neededSchemaVersion=20] ["start time"=136.696µs] [phyTblIDs="[39]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.196 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=20] ["take time"=2.319843ms] [job="ID:40, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:39, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.193 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.196 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:40, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:39, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.193 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.197 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=40]
[2021/07/13 17:24:40.197 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.197 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=20] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.expr_pushdown_blacklist (\n\t\tname \t\tCHAR(100) NOT NULL,\n\t\tstore_type \tCHAR(100) NOT NULL DEFAULT 'tikv,tiflash,tidb',\n\t\treason \t\tVARCHAR(200)\n\t);"] [user=]
[2021/07/13 17:24:40.198 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:42, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:41, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.197 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.198 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:42, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:41, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.197 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.expr_pushdown_blacklist (\n\t\tname \t\tCHAR(100) NOT NULL,\n\t\tstore_type \tCHAR(100) NOT NULL DEFAULT 'tikv,tiflash,tidb',\n\t\treason \t\tVARCHAR(200)\n\t);"]
[2021/07/13 17:24:40.198 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:42, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:41, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.197 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.199 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=20] [neededSchemaVersion=21] ["start time"=99.529µs] [phyTblIDs="[41]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.201 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=21] ["take time"=2.086464ms] [job="ID:42, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:41, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.197 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.201 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:42, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:41, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.197 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.201 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=42]
[2021/07/13 17:24:40.201 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.201 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=21] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.opt_rule_blacklist (\n\t\tname \tCHAR(100) NOT NULL\n\t);"] [user=]
[2021/07/13 17:24:40.202 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:44, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:43, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.202 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.202 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:44, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:43, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.202 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.opt_rule_blacklist (\n\t\tname \tCHAR(100) NOT NULL\n\t);"]
[2021/07/13 17:24:40.202 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:44, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:43, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.202 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.202 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=21] [neededSchemaVersion=22] ["start time"=67.663µs] [phyTblIDs="[43]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.204 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=22] ["take time"=2.124114ms] [job="ID:44, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:43, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.202 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.205 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:44, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:43, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.202 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.205 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=44]
[2021/07/13 17:24:40.205 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.205 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=22] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.stats_extended (\n\t\tname varchar(32) NOT NULL,\n\t\ttype tinyint(4) NOT NULL,\n\t\ttable_id bigint(64) NOT NULL,\n\t\tcolumn_ids varchar(32) NOT NULL,\n\t\tstats blob DEFAULT NULL,\n\t\tversion bigint(64) unsigned NOT NULL,\n\t\tstatus tinyint(4) NOT NULL,\n\t\tPRIMARY KEY(name, table_id),\n\t\tKEY idx_1 (table_id, status, version),\n\t\tKEY idx_2 (status, version)\n\t);"] [user=]
[2021/07/13 17:24:40.205 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:46, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:45, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.205 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.205 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:46, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:45, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.205 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.stats_extended (\n\t\tname varchar(32) NOT NULL,\n\t\ttype tinyint(4) NOT NULL,\n\t\ttable_id bigint(64) NOT NULL,\n\t\tcolumn_ids varchar(32) NOT NULL,\n\t\tstats blob DEFAULT NULL,\n\t\tversion bigint(64) unsigned NOT NULL,\n\t\tstatus tinyint(4) NOT NULL,\n\t\tPRIMARY KEY(name, table_id),\n\t\tKEY idx_1 (table_id, status, version),\n\t\tKEY idx_2 (status, version)\n\t);"]
[2021/07/13 17:24:40.206 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:46, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:45, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.205 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.206 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=22] [neededSchemaVersion=23] ["start time"=152.891µs] [phyTblIDs="[45]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.208 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=23] ["take time"=2.360699ms] [job="ID:46, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:45, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.205 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.209 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:46, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:45, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.205 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.209 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=46]
[2021/07/13 17:24:40.209 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.209 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=23] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.schema_index_usage (\n\t\tTABLE_ID bigint(64),\n\t\tINDEX_ID bigint(21),\n\t\tQUERY_COUNT bigint(64),\n\t\tROWS_SELECTED bigint(64),\n\t\tLAST_USED_AT timestamp,\n\t\tPRIMARY KEY(TABLE_ID, INDEX_ID)\n\t);"] [user=]
[2021/07/13 17:24:40.209 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:48, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:47, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.209 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.209 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:48, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:47, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.209 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.schema_index_usage (\n\t\tTABLE_ID bigint(64),\n\t\tINDEX_ID bigint(21),\n\t\tQUERY_COUNT bigint(64),\n\t\tROWS_SELECTED bigint(64),\n\t\tLAST_USED_AT timestamp,\n\t\tPRIMARY KEY(TABLE_ID, INDEX_ID)\n\t);"]
[2021/07/13 17:24:40.210 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:48, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:47, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.209 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.210 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=23] [neededSchemaVersion=24] ["start time"=108.517µs] [phyTblIDs="[47]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.212 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=24] ["take time"=2.392508ms] [job="ID:48, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:47, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.209 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.213 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:48, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:47, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.209 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.213 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=48]
[2021/07/13 17:24:40.213 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.213 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=24] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.stats_fm_sketch (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tvalue \t\tLONGBLOB,\n\t\tINDEX tbl(table_id, is_index, hist_id)\n\t);"] [user=]
[2021/07/13 17:24:40.213 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:50, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:49, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.213 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.213 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:50, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:49, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.213 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.stats_fm_sketch (\n\t\ttable_id \tBIGINT(64) NOT NULL,\n\t\tis_index \tTINYINT(2) NOT NULL,\n\t\thist_id \tBIGINT(64) NOT NULL,\n\t\tvalue \t\tLONGBLOB,\n\t\tINDEX tbl(table_id, is_index, hist_id)\n\t);"]
[2021/07/13 17:24:40.213 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:50, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:49, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.213 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.214 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=24] [neededSchemaVersion=25] ["start time"=98.37µs] [phyTblIDs="[49]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.216 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=25] ["take time"=2.365186ms] [job="ID:50, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:49, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.213 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.216 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:50, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:49, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.213 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.217 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=50]
[2021/07/13 17:24:40.217 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.217 +08:00] [INFO] [session.go:2880] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=25] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.global_grants (\n\t\tUSER char(32) NOT NULL DEFAULT '',\n\t\tHOST char(255) NOT NULL DEFAULT '',\n\t\tPRIV char(32) NOT NULL DEFAULT '',\n\t\tWITH_GRANT_OPTION enum('N','Y') NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (USER,HOST,PRIV)\n\t  );"] [user=]
[2021/07/13 17:24:40.217 +08:00] [INFO] [ddl_worker.go:297] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:52, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:51, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.217 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0; "]
[2021/07/13 17:24:40.217 +08:00] [INFO] [ddl.go:546] ["[ddl] start DDL job"] [job="ID:52, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:51, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.217 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.global_grants (\n\t\tUSER char(32) NOT NULL DEFAULT '',\n\t\tHOST char(255) NOT NULL DEFAULT '',\n\t\tPRIV char(32) NOT NULL DEFAULT '',\n\t\tWITH_GRANT_OPTION enum('N','Y') NOT NULL DEFAULT 'N',\n\t\tPRIMARY KEY (USER,HOST,PRIV)\n\t  );"]
[2021/07/13 17:24:40.217 +08:00] [INFO] [ddl_worker.go:682] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:52, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:51, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.217 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.218 +08:00] [INFO] [domain.go:129] ["diff load InfoSchema success"] [currentSchemaVersion=25] [neededSchemaVersion=26] ["start time"=99.042µs] [phyTblIDs="[51]"] [actionTypes="[8]"]
[2021/07/13 17:24:40.220 +08:00] [INFO] [ddl_worker.go:865] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=26] ["take time"=2.036301ms] [job="ID:52, Type:create table, State:done, SchemaState:public, SchemaID:3, TableID:51, RowCount:0, ArgLen:1, start time: 2021-07-13 17:24:40.217 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.220 +08:00] [INFO] [ddl_worker.go:402] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:52, Type:create table, State:synced, SchemaState:public, SchemaID:3, TableID:51, RowCount:0, ArgLen:0, start time: 2021-07-13 17:24:40.217 +0800 CST, Err:, ErrCount:0, SnapshotVersion:0"]
[2021/07/13 17:24:40.220 +08:00] [INFO] [ddl.go:601] ["[ddl] DDL job is finished"] [jobID=52]
[2021/07/13 17:24:40.220 +08:00] [INFO] [callback.go:106] ["performing DDL change, must reload"]
[2021/07/13 17:24:40.232 +08:00] [INFO] [bootstrap.go:366] ["bootstrap successful"] ["take time"=124.468052ms]
[2021/07/13 17:24:40.232 +08:00] [INFO] [ddl_worker.go:128] ["[ddl] DDL worker closed"] [worker="worker 1, tp general"] ["take time"=590ns]
[2021/07/13 17:24:40.232 +08:00] [INFO] [ddl_worker.go:128] ["[ddl] DDL worker closed"] [worker="worker 2, tp add index"] ["take time"=102ns]
[2021/07/13 17:24:40.232 +08:00] [INFO] [delete_range.go:130] ["[ddl] closing delRange"]
[2021/07/13 17:24:40.232 +08:00] [INFO] [session_pool.go:85] ["[ddl] closing sessionPool"]
[2021/07/13 17:24:40.232 +08:00] [INFO] [ddl.go:410] ["[ddl] DDL closed"] [ID=22a80d78-2b16-42f1-9ac5-2a4cf5318080] ["take time"=51.084µs]
[2021/07/13 17:24:40.232 +08:00] [INFO] [ddl.go:323] ["[ddl] stop DDL"] [ID=22a80d78-2b16-42f1-9ac5-2a4cf5318080]
[2021/07/13 17:24:40.232 +08:00] [INFO] [domain.go:420] ["topNSlowQueryLoop exited."]
[2021/07/13 17:24:40.232 +08:00] [INFO] [domain.go:508] ["loadSchemaInLoop exited."]
[2021/07/13 17:24:40.232 +08:00] [INFO] [domain.go:477] ["topologySyncerKeeper exited."]
[2021/07/13 17:24:40.232 +08:00] [INFO] [domain.go:449] ["infoSyncerKeeper exited."]
[2021/07/13 17:24:40.232 +08:00] [INFO] [domain.go:632] ["domain closed"] ["take time"=119.671µs]
[2021/07/13 17:24:40.232 +08:00] [INFO] [tidb.go:70] ["new domain"] [store=944cfeaf-7514-479f-b9eb-4dc149cc0165] ["ddl lease"=1s] ["stats lease"=-1ns] ["index usage sync lease"=0s]
[2021/07/13 17:24:40.232 +08:00] [INFO] [ddl.go:342] ["[ddl] start DDL"] [ID=d15afb81-2e49-4310-b024-68957bad1a7f] [runWorker=true]
[2021/07/13 17:24:40.233 +08:00] [INFO] [ddl.go:331] ["[ddl] start delRangeManager OK"] ["is a emulator"=true]
[2021/07/13 17:24:40.233 +08:00] [INFO] [delete_range.go:140] ["[ddl] start delRange emulator"]
[2021/07/13 17:24:40.233 +08:00] [INFO] [ddl_worker.go:134] ["[ddl] start DDL worker"] [worker="worker 3, tp general"]
[2021/07/13 17:24:40.233 +08:00] [INFO] [ddl_worker.go:134] ["[ddl] start DDL worker"] [worker="worker 4, tp add index"]
[2021/07/13 17:24:40.236 +08:00] [INFO] [domain.go:155] ["full load InfoSchema success"] [currentSchemaVersion=0] [neededSchemaVersion=26] ["start time"=3.309947ms]
[2021/07/13 17:24:40.236 +08:00] [INFO] [domain.go:370] ["full load and reset schema validator"]
[2021/07/13 17:24:40.238 +08:00] [WARN] [sysvar_cache.go:52] ["sysvar cache is empty, triggering rebuild"]
[2021/07/13 17:24:40.242 +08:00] [INFO] [telemetry.go:173] ["Telemetry configuration"] [endpoint=https://telemetry.pingcap.com/api/v1/tidb/report] [report_interval=6h0m0s] [enabled=true]
[2021/07/13 17:24:40.243 +08:00] [INFO] [ddl_worker.go:128] ["[ddl] DDL worker closed"] [worker="worker 4, tp add index"] ["take time"=5.391µs]
[2021/07/13 17:24:40.243 +08:00] [INFO] [ddl_worker.go:128] ["[ddl] DDL worker closed"] [worker="worker 3, tp general"] ["take time"=144ns]
[2021/07/13 17:24:40.243 +08:00] [INFO] [delete_range.go:130] ["[ddl] closing delRange"]
[2021/07/13 17:24:40.243 +08:00] [INFO] [session_pool.go:85] ["[ddl] closing sessionPool"]
[2021/07/13 17:24:40.243 +08:00] [INFO] [ddl.go:410] ["[ddl] DDL closed"] [ID=d15afb81-2e49-4310-b024-68957bad1a7f] ["take time"=66.955µs]
[2021/07/13 17:24:40.243 +08:00] [INFO] [ddl.go:323] ["[ddl] stop DDL"] [ID=d15afb81-2e49-4310-b024-68957bad1a7f]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:420] ["topNSlowQueryLoop exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:449] ["infoSyncerKeeper exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:477] ["topologySyncerKeeper exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:508] ["loadSchemaInLoop exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:1031] ["handleEvolvePlanTasksLoop exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:1095] ["TelemetryRotateSubWindowLoop exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:925] ["LoadSysVarCacheLoop exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:876] ["loadPrivilegeInLoop exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:1002] ["globalBindHandleWorkerLoop exited."]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:632] ["domain closed"] ["take time"=154.007µs]
[2021/07/13 17:24:40.243 +08:00] [INFO] [domain.go:1065] ["TelemetryReportLoop exited."]
[2021/07/13 17:24:40.263 +08:00] [INFO] [db.go:565] ["Closing database"]
[2021/07/13 17:24:40.264 +08:00] [INFO] [db.go:590] ["Memtable flushed"]
[2021/07/13 17:24:40.264 +08:00] [INFO] [db.go:594] ["Compaction finished"]
[2021/07/13 17:24:40.264 +08:00] [INFO] [db.go:613] ["BlobManager finished"]
[2021/07/13 17:24:40.264 +08:00] [INFO] [db.go:617] ["ResourceManager finished"]
[2021/07/13 17:24:40.264 +08:00] [INFO] [db.go:623] ["Waiting for closer"]
--- PASS: TestProfiles (0.25s)
--- PASS: TestHeapProfileRecorder (0.62s)
PASS
goleak: Errors on successful test run: found unexpected goroutines:
[Goroutine 8 in state select, with go.opencensus.io/stats/view.(*worker).start on top of the stack:
goroutine 8 [select]:
go.opencensus.io/stats/view.(*worker).start(0xc00030f9a0)
	/Users/tison/go/pkg/mod/go.opencensus.io@v0.22.3/stats/view/worker.go:154 +0xcd
created by go.opencensus.io/stats/view.init.0
	/Users/tison/go/pkg/mod/go.opencensus.io@v0.22.3/stats/view/worker.go:32 +0x57
Goroutine 77 in state chan receive, with go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop on top of the stack:

goroutine 77 [chan receive]:

go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0xc000306828)

/Users/tison/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20200824191128-ae9734ed278b/pkg/logutil/merge_logger.go:173 +0x3ac

created by go.etcd.io/etcd/pkg/logutil.NewMergeLogger

/Users/tison/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20200824191128-ae9734ed278b/pkg/logutil/merge_logger.go:91 +0x85
Goroutine 123 in state chan receive, with go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop on top of the stack:

goroutine 123 [chan receive]:

go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0xc00000f128)

/Users/tison/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20200824191128-ae9734ed278b/pkg/logutil/merge_logger.go:173 +0x3ac

created by go.etcd.io/etcd/pkg/logutil.NewMergeLogger

/Users/tison/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20200824191128-ae9734ed278b/pkg/logutil/merge_logger.go:91 +0x85
Goroutine 136 in state chan receive, with go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop on top of the stack:

goroutine 136 [chan receive]:

go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop(0xc000690ab0)

/Users/tison/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20200824191128-ae9734ed278b/pkg/logutil/merge_logger.go:173 +0x3ac

created by go.etcd.io/etcd/pkg/logutil.NewMergeLogger

/Users/tison/go/pkg/mod/go.etcd.io/etcd@v0.5.0-alpha.5.0.20200824191128-ae9734ed278b/pkg/logutil/merge_logger.go:91 +0x85

]

FAIL	github.com/pingcap/tidb/util/profile	1.704s

FAIL

... the original tests do not verify leak so I ignore it for now. Any suggestion we should fix bugs or setup ignore options?

xhebox · 2021-07-13T12:24:14Z

@tisonkun There is an ignore list

tidb/util/testleak/leaktest.go

Lines 34 to 68 in 86c8bf0

    
           ignoreList := []string{ 
        
           	"created by github.com/pingcap/tidb.init", 
        
           	"testing.RunTests", 
        
           	"check.(*resultTracker).start", 
        
           	"check.(*suiteRunner).runFunc", 
        
           	"check.(*suiteRunner).parallelRun", 
        
           	"localstore.(*dbStore).scheduler", 
        
           	"ddl.(*ddl).start", 
        
           	"ddl.(*delRange).startEmulator", 
        
           	"domain.NewDomain", 
        
           	"testing.(*T).Run", 
        
           	"domain.(*Domain).LoadPrivilegeLoop", 
        
           	"domain.(*Domain).UpdateTableStatsLoop", 
        
           	"testing.Main(", 
        
           	"runtime.goexit", 
        
           	"created by runtime.gc", 
        
           	"interestingGoroutines", 
        
           	"runtime.MHeap_Scavenger", 
        
           	"created by os/signal.init", 
        
           	"gopkg.in/natefinch/lumberjack%2ev2.(*Logger).millRun", 
        
           	// these go routines are async terminated, so they may still alive after test end, thus cause 
        
           	// false positive leak failures 
        
           	"google.golang.org/grpc.(*addrConn).resetTransport", 
        
           	"google.golang.org/grpc.(*ccBalancerWrapper).watcher", 
        
           	"github.com/pingcap/goleveldb/leveldb/util.(*BufferPool).drain", 
        
           	"github.com/pingcap/goleveldb/leveldb.(*DB).compactionError", 
        
           	"github.com/pingcap/goleveldb/leveldb.(*DB).mpoolDrain", 
        
           	"go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop", 
        
           	"go.etcd.io/etcd/v3/pkg/logutil.(*MergeLogger).outputLoop", 
        
           	"oracles.(*pdOracle).updateTS", 
        
           	"tikv.(*KVStore).runSafePointChecker", 
        
           	"tikv.(*RegionCache).asyncCheckAndResolveLoop", 
        
           	"github.com/pingcap/badger", 
        
           	"github.com/ngaut/unistore/tikv.(*MVCCStore).runUpdateSafePointLoop", 
        
           }

.

We should try to bypass goroutines in the list, otherwise trying to fix the bug.

xhebox

Rest LGTM

util/profile/profile_test.go

testkit/testkit.go

Signed-off-by: tison <wander4096@gmail.com>

tisonkun · 2021-07-13T13:05:02Z

@xhebox Thanks for your review! I can see top functions should be ignored here are

goleak.IgnoreTopFunction("go.etcd.io/etcd/pkg/logutil.(*MergeLogger).outputLoop"),
goleak.IgnoreTopFunction("go.opencensus.io/stats/view.(*worker).start"),

... while 1 is known issue, 2 is new. I don't spend too much effort now but leave it as a follow up to investigate and improve.

tisonkun · 2021-07-13T13:05:09Z

/unhold

Signed-off-by: tison <wander4096@gmail.com>

ti-chi-bot · 2021-07-14T02:50:05Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

disksing
xhebox

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

The full list of commands accepted by this bot can be found here.

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

disksing · 2021-07-14T02:50:17Z

/merge

ti-chi-bot · 2021-07-14T02:50:19Z

This pull request has been accepted and is ready to merge.

Commit hash: 70b6bcd

util/profile: migrate test-infra to testify

e2ac918

Signed-off-by: tison <wander4096@gmail.com>

ti-chi-bot added the size/XL Denotes a PR that changes 500-999 lines, ignoring generated files. label Jul 13, 2021

ti-chi-bot requested review from disksing, tiancaiamao and xhebox July 13, 2021 09:26

ti-chi-bot added the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jul 13, 2021

tisonkun added 2 commits July 13, 2021 17:26

Merge branch 'master' into issue-26204

e2108c4

*: go fmt

f312dc9

Merge branch 'master' into issue-26204

47f6f0a

xhebox reviewed Jul 13, 2021

View reviewed changes

util/profile/profile_test.go Show resolved Hide resolved

testkit/testkit.go Outdated Show resolved Hide resolved

xhebox approved these changes Jul 13, 2021

View reviewed changes

ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Jul 13, 2021

address comments

48a3eef

Signed-off-by: tison <wander4096@gmail.com>

ti-chi-bot removed the do-not-merge/hold Indicates that a PR should not merge because someone has issued a /hold command. label Jul 13, 2021

remove check.Commentf

70b6bcd

Signed-off-by: tison <wander4096@gmail.com>

disksing approved these changes Jul 14, 2021

View reviewed changes

ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Jul 14, 2021

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Jul 14, 2021

ti-chi-bot added 3 commits July 14, 2021 10:50

Merge branch 'master' into issue-26204

fc45cce

Merge branch 'master' into issue-26204

4f2080a

Merge branch 'master' into issue-26204

0e6fa78

ti-chi-bot merged commit ed659df into pingcap:master Jul 14, 2021

tisonkun deleted the issue-26204 branch March 4, 2022 11:36

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

util/profile: migrate test-infra to testify #26205

util/profile: migrate test-infra to testify #26205

tisonkun commented Jul 13, 2021

tisonkun commented Jul 13, 2021 •

edited

Loading

xhebox commented Jul 13, 2021 •

edited

Loading

xhebox left a comment

tisonkun commented Jul 13, 2021 •

edited

Loading

tisonkun commented Jul 13, 2021

ti-chi-bot commented Jul 14, 2021

disksing commented Jul 14, 2021

ti-chi-bot commented Jul 14, 2021

util/profile: migrate test-infra to testify #26205

util/profile: migrate test-infra to testify #26205

Conversation

tisonkun commented Jul 13, 2021

What problem does this PR solve?

Release note

tisonkun commented Jul 13, 2021 • edited Loading

xhebox commented Jul 13, 2021 • edited Loading

xhebox left a comment

Choose a reason for hiding this comment

tisonkun commented Jul 13, 2021 • edited Loading

tisonkun commented Jul 13, 2021

ti-chi-bot commented Jul 14, 2021

disksing commented Jul 14, 2021

ti-chi-bot commented Jul 14, 2021

tisonkun commented Jul 13, 2021 •

edited

Loading

xhebox commented Jul 13, 2021 •

edited

Loading

tisonkun commented Jul 13, 2021 •

edited

Loading