Skip to content
New issue

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

Sign up for GitHub

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

Already on GitHub? Sign in to your account

Jump to bottom

[FAIL] ddl TestCacheTableSizeLimit #33764

Closed
Tracked by #33745
tiancaiamao opened this issue Apr 7, 2022 · 2 comments · Fixed by #38822
Closed
Tracked by #33745

[FAIL] ddl TestCacheTableSizeLimit #33764

tiancaiamao opened this issue Apr 7, 2022 · 2 comments · Fixed by #38822
Assignees
@tiancaiamao
Labels
component/test type/enhancement The issue or PR belongs to an enhancement.

Comments

@tiancaiamao
Copy link
Contributor

No description provided.

@tiancaiamao tiancaiamao mentioned this issue Apr 7, 2022
Open
25 tasks
@tiancaiamao
Copy link
Contributor Author 

...skipping...
[2022/04/07 10:06:50.226 +08:00] [WARN] [session.go:1897] ["run statement failed"] [schemaVersion=0] [error="[schema:1049]Unknown database 'mysql'"] [errorVerbose="[schema:1049]Unknown database 'mysql'\ngithub.com/pingcap/errors.AddStack\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:164\ngithub.com/pingcap/tidb/executor.(*SimpleExec).executeUse\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/simple.go:557\ngithub.com/pingcap/tidb/executor.(*SimpleExec).Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/simple.go:127\ngithub.com/pingcap/tidb/executor.Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/executor.go:302\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:635\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:490\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:439\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2017\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1894\ngithub.com/pingcap/tidb/session.(*session).ExecuteInternal\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1506\ngithub.com/pingcap/tidb/session.checkBootstrapped\n\t/home/genius/project/src/github.com/pingcap/tidb/session/bootstrap.go:708\ngithub.com/pingcap/tidb/session.bootstrap\n\t/home/genius/project/src/github.com/pingcap/tidb/session/bootstrap.go:424\ngithub.com/pingcap/tidb/session.runInBootstrapSession\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2915\ngithub.com/pingcap/tidb/session.BootstrapSession\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2804\ngithub.com/pingcap/tidb/testkit.bootstrap\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/mockstore.go:50\ngithub.com/pingcap/tidb/testkit.CreateMockStoreAndDomain\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/mockstore.go:43\ngithub.com/pingcap/tidb/testkit.CreateMockStore\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/mockstore.go:35\ngithub.com/pingcap/tidb/ddl_test.TestCacheTableSizeLimit\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/db_cache_test.go:204\ntesting.tRunner\n\t/home/genius/project/go/src/testing/testing.go:1439\nruntime.goexit\n\t/home/genius/project/go/src/runtime/asm_amd64.s:1571"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 0,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": null\n}"]
[2022/04/07 10:06:50.227 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=0] [cur_db=] [sql="CREATE DATABASE IF NOT EXISTS test"] [user=]
[2022/04/07 10:06:50.228 +08:00] [INFO] [ddl_worker.go:161] ["[ddl] start DDL worker"] [worker="worker 1, tp general"]
[2022/04/07 10:06:50.229 +08:00] [INFO] [ddl_worker.go:161] ["[ddl] start DDL worker"] [worker="worker 2, tp add index"]
[2022/04/07 10:06:50.229 +08:00] [INFO] [delete_range.go:138] ["[ddl] start delRange emulator"]
[2022/04/07 10:06:50.234 +08:00] [INFO] [ddl_worker.go:334] ["[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: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:06:50.234 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:2, Type:create schema, State:none, SchemaState:queueing, SchemaID:1, TableID:0, RowCount:0, ArgLen:1, start time: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE IF NOT EXISTS test"]
[2022/04/07 10:06:50.235 +08:00] [INFO] [ddl_worker.go:814] ["[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: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.239 +08:00] [INFO] [ddl_worker.go:470] ["[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: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.241 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=2]
[2022/04/07 10:06:50.242 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:06:50.249 +08:00] [INFO] [domain.go:171] ["full load InfoSchema success"] [currentSchemaVersion=0] [neededSchemaVersion=1] ["start time"=7.164151ms]
[2022/04/07 10:06:50.249 +08:00] [INFO] [domain.go:431] ["full load and reset schema validator"]
[2022/04/07 10:06:50.250 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=1] [cur_db=] [sql="CREATE DATABASE IF NOT EXISTS `mysql`"] [user=]
[2022/04/07 10:06:50.253 +08:00] [INFO] [ddl_worker.go:334] ["[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: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:06:50.253 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:4, Type:create schema, State:none, SchemaState:queueing, SchemaID:3, TableID:0, RowCount:0, ArgLen:1, start time: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE IF NOT EXISTS `mysql`"]
[2022/04/07 10:06:50.254 +08:00] [INFO] [ddl_worker.go:814] ["[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: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.258 +08:00] [INFO] [ddl_worker.go:470] ["[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: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.260 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=4]
[2022/04/07 10:06:50.260 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:06:50.261 +08:00] [INFO] [domain.go:140] ["diff load InfoSchema success"] [currentSchemaVersion=1] [neededSchemaVersion=2] ["start time"=458.973µs] [phyTblIDs="[]"] [actionTypes="[]"]
[2022/04/07 10:06:50.265 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=2] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.user (\n\t\tHost\t\t\t\t\tCHAR(255),\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=]
[2022/04/07 10:06:50.274 +08:00] [INFO] [ddl_worker.go:334] ["[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: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:06:50.274 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:6, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:5, RowCount:0, ArgLen:1, start time: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.user (\n\t\tHost\t\t\t\t\tCHAR(255),\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));"]
[2022/04/07 10:06:50.282 +08:00] [INFO] [ddl_worker.go:814] ["[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: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.322 +08:00] [INFO] [ddl_worker.go:470] ["[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: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.332 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=6]
[2022/04/07 10:06:50.332 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:06:50.337 +08:00] [INFO] [domain.go:140] ["diff load InfoSchema success"] [currentSchemaVersion=2] [neededSchemaVersion=3] ["start time"=4.511393ms] [phyTblIDs="[5]"] [actionTypes="[8]"]
[2022/04/07 10:06:50.338 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=3] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.global_priv (Host CHAR(255) NOT NULL DEFAULT '',User CHAR(80) NOT NULL DEFAULT '',Priv LONGTEXT NOT NULL DEFAULT '...skipping...
[2022/04/07 10:07:34.379 +08:00] [WARN] [session.go:1897] ["run statement failed"] [schemaVersion=36] [error="[ddl:8242]'table too large' is unsupported on cache tables."] [errorVerbose="[ddl:8242]'table too large' is unsupported on cache tables.\ngithub.com/pingcap/errors.AddStack\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:164\ngithub.com/pingcap/tidb/ddl.(*ddl).AlterTableCache\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/ddl_api.go:6952\ngithub.com/pingcap/tidb/ddl.(*ddl).AlterTable\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/ddl_api.go:3200\ngithub.com/pingcap/tidb/executor.(*DDLExec).executeAlterTable\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/ddl.go:557\ngithub.com/pingcap/tidb/executor.(*DDLExec).Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/ddl.go:144\ngithub.com/pingcap/tidb/executor.Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/executor.go:302\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:635\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:490\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:439\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2017\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1894\ngithub.com/pingcap/tidb/testkit.(*TestKit).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:209\ngithub.com/pingcap/tidb/testkit.(*TestKit).MustGetErrCode\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:268\ngithub.com/pingcap/tidb/ddl_test.TestCacheTableSizeLimit\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/db_cache_test.go:227\ntesting.tRunner\n\t/home/genius/project/go/src/testing/testing.go:1439\nruntime.goexit\n\t/home/genius/project/go/src/runtime/asm_amd64.s:1571"] [session="{\n  \"currDBName\": \"test\",\n  \"id\": 1,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": null\n}"]
[2022/04/07 10:07:34.380 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=1] [schemaVersion=36] [cur_db=test] [sql="alter table cache_t2 cache"] [user=]
[2022/04/07 10:07:34.811 +08:00] [INFO] [levels.go:546] ["compact send discard stats"] [stats="numSkips:0, skippedBytes:0"]
[2022/04/07 10:07:34.812 +08:00] [INFO] [levels.go:628] ["compaction done"] [def="0 top:[0:5](58330904), bot:[0:7](759780), skip:6, write_amp:1.01"] [deleted=6] [added=9] [duration=2.465455897s]
[2022/04/07 10:07:34.812 +08:00] [INFO] [levels.go:670] ["compaction done"] [level=0]
[2022/04/07 10:07:35.305 +08:00] [INFO] [ddl_worker.go:334] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:73, Type:alter table cache, State:none, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:07:35.305 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:73, Type:alter table cache, State:none, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="alter table cache_t2 cache"]
[2022/04/07 10:07:35.306 +08:00] [INFO] [ddl_worker.go:814] ["[ddl] run DDL job"] [worker="worker 3, tp general"] [job="ID:73, Type:alter table cache, State:none, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:07:35.311 +08:00] [INFO] [ddl_worker.go:814] ["[ddl] run DDL job"] [worker="worker 3, tp general"] [job="ID:73, Type:alter table cache, State:running, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:07:35.316 +08:00] [INFO] [ddl_worker.go:470] ["[ddl] finish DDL job"] [worker="worker 3, tp general"] [job="ID:73, Type:alter table cache, State:synced, SchemaState:public, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:07:35.320 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=73]
[2022/04/07 10:07:35.320 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:07:35.322 +08:00] [INFO] [domain.go:140] ["diff load InfoSchema success"] [currentSchemaVersion=36] [neededSchemaVersion=38] ["start time"=1.523481ms] [phyTblIDs="[69,69]"] [actionTypes="[144115188075855872,144115188075855872]"]
[2022/04/07 10:07:39.725 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.806143224s txnStartTS:432353380379131904 region_id:2 store_addr:store1 kv_process_ms:1579 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:41.305 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.501044725s txnStartTS:432353380873273344 region_id:2 store_addr:store1 kv_process_ms:1276 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:43.419 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.038683214s txnStartTS:432353381286150144 region_id:2 store_addr:store1 kv_process_ms:1582 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:45.573 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.029659205s txnStartTS:432353381854216192 region_id:2 store_addr:store1 kv_process_ms:1536 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:47.799 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.107801027s txnStartTS:432353382417039360 region_id:2 store_addr:store1 kv_process_ms:1616 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:50.188 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.279648502s txnStartTS:432353382998212608 region_id:2 store_addr:store1 kv_process_ms:1723 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:51.861 +08:00] [INFO] [data_window.go:249] ["Error exists when getting the SQL Metric."]
[2022/04/07 10:07:52.544 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.237716381s txnStartTS:432353383626833920 region_id:2 store_addr:store1 kv_process_ms:1732 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:54.935 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.264700353s txnStartTS:432353384246804480 region_id:2 store_addr:store1 kv_process_ms:1748 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:57.258 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.215132419s txnStartTS:432353384868610048 region_id:2 store_addr:store1 kv_process_ms:1699 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:59.600 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.239888097s txnStartTS:432353385475997696 region_id:2 store_addr:store1 kv_process_ms:1670 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:01.156 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.454252574s txnStartTS:432353386089676800 region_id:2 store_addr:store1 kv_process_ms:1265 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:02.737 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.508701174s txnStartTS:432353386489184256 region_id:2 store_addr:store1 kv_process_ms:1121 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:04.281 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.446962029s txnStartTS:432353386911236096 region_id:2 store_addr:store1 kv_process_ms:1072 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:05.854 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.500892686s txnStartTS:432353387309432832 region_id:2 store_addr:store1 kv_process_ms:1124 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:07.392 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.4680365s txnStartTS:432353387720474624 region_id:2 store_addr:store1 kv_process_ms:1082 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:08.866 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.405462159s txnStartTS:432353388123914240 region_id:2 store_addr:store1 kv_process_ms:1069 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:10.328 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.37916271s txnStartTS:432353388513984512 region_id:2 store_addr:store1 kv_process_ms:1045 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:11.726 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.309871067s txnStartTS:432353388898811904 region_id:2 store_addr:store1 kv_process_ms:1049 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:13.244 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.450137339s txnStartTS:432353389259784192 region_id:2 store_addr:store1 kv_process_ms:1117 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:14.805 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.467969145s txnStartTS:432353389664534528 region_id:2 store_addr:store1 kv_process_ms:1103 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:16.267 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.391457771s txnStartTS:432353390067712000 region_id:2 store_addr:store1 kv_process_ms:1059 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:17.554 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.190126727s txnStartTS:432353390457782272 region_id:2 store_addr:store1 kv_process_ms:1030 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:19.057 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.435725705s txnStartTS:432353390787559424 region_id:2 store_addr:store1 kv_process_ms:1102 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:20.521 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.38086538s txnStartTS:432353391185494016 region_id:2 store_addr:store1 kv_process_ms:1028 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:22.047 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.428967224s txnStartTS:432353391573204992 region_id:2 store_addr:store1 kv_process_ms:1065 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:23.352 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.215598141s txnStartTS:432353391971139584 region_id:2 store_addr:store1 kv_process_ms:1036 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:24.933 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.510321342s txnStartTS:432353392308256768 region_id:2 store_addr:store1 kv_process_ms:1146 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:26.470 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.439606669s txnStartTS:432353392729784320 region_id:2 store_addr:store1 kv_process_ms:1082 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:27.970 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.431526587s txnStartTS:432353393125097472 region_id:2 store_addr:store1 kv_process_ms:1098 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:29.289 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.250134596s txnStartTS:432353393518313472 region_id:2 store_addr:store1 kv_process_ms:1077 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:30.826 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.466279953s txnStartTS:432353393864081408 region_id:2 store_addr:store1 kv_process_ms:1142 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:32.276 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.379696163s txnStartTS:432353394267521024 region_id:2 store_addr:store1 kv_process_ms:1048 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:33.734 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.389249762s txnStartTS:432353394647105536 region_id:2 store_addr:store1 kv_process_ms:1063 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:35.090 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.287839143s txnStartTS:432353395029311488 region_id:2 store_addr:store1 kv_process_ms:1068 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:36.605 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.444510969s txnStartTS:432353395384516608 region_id:2 store_addr:store1 kv_process_ms:1114 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:38.080 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.383102684s txnStartTS:432353395787956224 region_id:2 store_addr:store1 kv_process_ms:1046 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:39.554 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.378676057s txnStartTS:432353396175405056 region_id:2 store_addr:store1 kv_process_ms:1023 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:40.844 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.221320746s txnStartTS:432353396554989568 region_id:2 store_addr:store1 kv_process_ms:1048 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:42.358 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.443329315s txnStartTS:432353396893155328 region_id:2 store_addr:store1 kv_process_ms:1105 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:43.843 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.392493833s txnStartTS:432353397296332800 region_id:2 store_addr:store1 kv_process_ms:1059 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:06:50.226 +08:00] [WARN] [session.go:1897] ["run statement failed"] [schemaVersion=0] [error="[schema:1049]Unknown database 'mysql'"] [errorVerbose="[schema:1049]Unknown database 'mysql'\ngithub.com/pingcap/errors.AddStack\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:164\ngithub.com/pingcap/tidb/executor.(*SimpleExec).executeUse\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/simple.go:557\ngithub.com/pingcap/tidb/executor.(*SimpleExec).Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/simple.go:127\ngithub.com/pingcap/tidb/executor.Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/executor.go:302\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:635\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:490\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:439\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2017\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1894\ngithub.com/pingcap/tidb/session.(*session).ExecuteInternal\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1506\ngithub.com/pingcap/tidb/session.checkBootstrapped\n\t/home/genius/project/src/github.com/pingcap/tidb/session/bootstrap.go:708\ngithub.com/pingcap/tidb/session.bootstrap\n\t/home/genius/project/src/github.com/pingcap/tidb/session/bootstrap.go:424\ngithub.com/pingcap/tidb/session.runInBootstrapSession\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2915\ngithub.com/pingcap/tidb/session.BootstrapSession\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2804\ngithub.com/pingcap/tidb/testkit.bootstrap\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/mockstore.go:50\ngithub.com/pingcap/tidb/testkit.CreateMockStoreAndDomain\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/mockstore.go:43\ngithub.com/pingcap/tidb/testkit.CreateMockStore\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/mockstore.go:35\ngithub.com/pingcap/tidb/ddl_test.TestCacheTableSizeLimit\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/db_cache_test.go:204\ntesting.tRunner\n\t/home/genius/project/go/src/testing/testing.go:1439\nruntime.goexit\n\t/home/genius/project/go/src/runtime/asm_amd64.s:1571"] [session="{\n  \"currDBName\": \"\",\n  \"id\": 0,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": null\n}"]
[2022/04/07 10:06:50.227 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=0] [cur_db=] [sql="CREATE DATABASE IF NOT EXISTS test"] [user=]
[2022/04/07 10:06:50.228 +08:00] [INFO] [ddl_worker.go:161] ["[ddl] start DDL worker"] [worker="worker 1, tp general"]
[2022/04/07 10:06:50.229 +08:00] [INFO] [ddl_worker.go:161] ["[ddl] start DDL worker"] [worker="worker 2, tp add index"]
[2022/04/07 10:06:50.229 +08:00] [INFO] [delete_range.go:138] ["[ddl] start delRange emulator"]
[2022/04/07 10:06:50.234 +08:00] [INFO] [ddl_worker.go:334] ["[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: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:06:50.234 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:2, Type:create schema, State:none, SchemaState:queueing, SchemaID:1, TableID:0, RowCount:0, ArgLen:1, start time: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE IF NOT EXISTS test"]
[2022/04/07 10:06:50.235 +08:00] [INFO] [ddl_worker.go:814] ["[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: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.239 +08:00] [INFO] [ddl_worker.go:470] ["[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: 2022-04-07 10:06:50.229 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.241 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=2]
[2022/04/07 10:06:50.242 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:06:50.249 +08:00] [INFO] [domain.go:171] ["full load InfoSchema success"] [currentSchemaVersion=0] [neededSchemaVersion=1] ["start time"=7.164151ms]
[2022/04/07 10:06:50.249 +08:00] [INFO] [domain.go:431] ["full load and reset schema validator"]
[2022/04/07 10:06:50.250 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=1] [cur_db=] [sql="CREATE DATABASE IF NOT EXISTS `mysql`"] [user=]
[2022/04/07 10:06:50.253 +08:00] [INFO] [ddl_worker.go:334] ["[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: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:06:50.253 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:4, Type:create schema, State:none, SchemaState:queueing, SchemaID:3, TableID:0, RowCount:0, ArgLen:1, start time: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE DATABASE IF NOT EXISTS `mysql`"]
[2022/04/07 10:06:50.254 +08:00] [INFO] [ddl_worker.go:814] ["[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: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.258 +08:00] [INFO] [ddl_worker.go:470] ["[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: 2022-04-07 10:06:50.251 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.260 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=4]
[2022/04/07 10:06:50.260 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:06:50.261 +08:00] [INFO] [domain.go:140] ["diff load InfoSchema success"] [currentSchemaVersion=1] [neededSchemaVersion=2] ["start time"=458.973µs] [phyTblIDs="[]"] [actionTypes="[]"]
[2022/04/07 10:06:50.265 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=2] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.user (\n\t\tHost\t\t\t\t\tCHAR(255),\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=]
[2022/04/07 10:06:50.274 +08:00] [INFO] [ddl_worker.go:334] ["[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: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:06:50.274 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:6, Type:create table, State:none, SchemaState:queueing, SchemaID:3, TableID:5, RowCount:0, ArgLen:1, start time: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="CREATE TABLE IF NOT EXISTS mysql.user (\n\t\tHost\t\t\t\t\tCHAR(255),\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));"]
[2022/04/07 10:06:50.282 +08:00] [INFO] [ddl_worker.go:814] ["[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: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.322 +08:00] [INFO] [ddl_worker.go:470] ["[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: 2022-04-07 10:06:50.267 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:06:50.332 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=6]
[2022/04/07 10:06:50.332 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:06:50.337 +08:00] [INFO] [domain.go:140] ["diff load InfoSchema success"] [currentSchemaVersion=2] [neededSchemaVersion=3] ["start time"=4.511393ms] [phyTblIDs="[5]"] [actionTypes="[8]"]
[2022/04/07 10:06:50.338 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=0] [schemaVersion=3] [cur_db=] [sql="CREATE TABLE IF NOT EXISTS mysql.global_priv (Host CHAR(255) NOT NULL DEFAULT '',User CHAR(80) NOT NULL DEFAULT '',Priv LONGTEXT NOT NULL DEFAULT '...skipping...
cywgYXV0b19pZF9hbGxvY2F0b3I6IHthAQxkX2NudDogMiwgR2V0OntudW1fcnBjOjgsIHQBQABfBWVgMS4yM21zfSwgY29tbWl0X3R4bjoge2NvdQ07WHByZXdyaXRlOjU2Mi44wrVzLCBnZXRfES4Uczo0OC40BRcJExQ6ODgzLjcFETRyZWdpb25fbnVtOjIsIAVGEF9rZXlzGQ5UYnl0ZTo2NX19fSwgaW5zZXJ0OjQuMAH1CU0NjhWEDDYuMDdCgQAAMxFwCTQcOjgwLjFtcywufwAAMTJ/ABA1NzY2NBESCYM8MDg5MzE4NH0JNjAuMCBNQiGHkAoxCTMxXzcJMAkxMDAwMAlkYXRhOlRhYmxlRnVsbFNjYW5fNgkFTCmvDDIuNDY1rwQ1OCFSHHBfdGFzazogIXwwOiAxLCBtYXg6IDIuMQHGEHByb2NfJRAcIDAsIHRvdF8BEhQ6IDEuNjIBvwRwYyU7ATcBDCWuETx8Y29wcl9jYWNoZV9oaXRfcmF0aW86IDAuMDB9CTU2LjYRwyAyCTQzXzYJMV8RxQB0AcAAOgk6iHQxLCBrZWVwIG9yZGVyOmZhbHNlLCBzdGF0czpwc2V1ZG8JEd8Ea3YJygB7BYYNokmZKDB9CU4vQQlOL0EK')\n# Plan_digest: a436e121dc720de3385ab4af0240e4465435215aa2af290440c6c405723e1625\nuse test;\ninsert into cache_t2 select * from cache_t1;"]
[2022/04/07 10:07:27.701 +08:00] [INFO] [db.go:831] ["flushing memtable"] ["memtable size"=12582642] ["size of flushChan"=0]
[2022/04/07 10:07:27.709 +08:00] [INFO] [db.go:935] ["flush memtable storing offset"] [fid=0] [offset=0]
[2022/04/07 10:07:27.738 +08:00] [INFO] [db.go:831] ["flushing memtable"] ["memtable size"=12582444] ["size of flushChan"=1]
[2022/04/07 10:07:27.800 +08:00] [INFO] [db.go:831] ["flushing memtable"] ["memtable size"=12582444] ["size of flushChan"=2]
[2022/04/07 10:07:27.962 +08:00] [INFO] [db.go:831] ["flushing memtable"] ["memtable size"=12582444] ["size of flushChan"=3]
[2022/04/07 10:07:28.283 +08:00] [INFO] [db.go:935] ["flush memtable storing offset"] [fid=0] [offset=0]
[2022/04/07 10:07:28.309 +08:00] [INFO] [db.go:831] ["flushing memtable"] ["memtable size"=12582444] ["size of flushChan"=3]
[2022/04/07 10:07:29.009 +08:00] [INFO] [db.go:935] ["flush memtable storing offset"] [fid=0] [offset=0]
[2022/04/07 10:07:30.625 +08:00] [INFO] [db.go:935] ["flush memtable storing offset"] [fid=0] [offset=0]
[2022/04/07 10:07:31.355 +08:00] [INFO] [db.go:831] ["flushing memtable"] ["memtable size"=12582553] ["size of flushChan"=2]
[2022/04/07 10:07:32.230 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=1] [schemaVersion=36] [cur_db=test] [sql="alter table cache_t1 cache"] [user=]
[2022/04/07 10:07:32.289 +08:00] [INFO] [db.go:935] ["flush memtable storing offset"] [fid=0] [offset=0]
[2022/04/07 10:07:32.346 +08:00] [INFO] [levels.go:645] ["start compaction"] [level=0] [score=1.25]
[2022/04/07 10:07:32.346 +08:00] [INFO] [levels.go:663] ["running compaction"] [def="0 top:[0:5](58330904), bot:[0:7](759780), skip:6, write_amp:1.01"]
[2022/04/07 10:07:32.856 +08:00] [INFO] [db.go:935] ["flush memtable storing offset"] [fid=0] [offset=0]
[2022/04/07 10:07:34.379 +08:00] [INFO] [tidb.go:260] ["rollbackTxn called due to ddl/autocommit failure"]
[2022/04/07 10:07:34.379 +08:00] [WARN] [session.go:1897] ["run statement failed"] [schemaVersion=36] [error="[ddl:8242]'table too large' is unsupported on cache tables."] [errorVerbose="[ddl:8242]'table too large' is unsupported on cache tables.\ngithub.com/pingcap/errors.AddStack\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/errors.go:174\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/home/genius/go/pkg/mod/github.com/pingcap/[email protected]/normalize.go:164\ngithub.com/pingcap/tidb/ddl.(*ddl).AlterTableCache\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/ddl_api.go:6952\ngithub.com/pingcap/tidb/ddl.(*ddl).AlterTable\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/ddl_api.go:3200\ngithub.com/pingcap/tidb/executor.(*DDLExec).executeAlterTable\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/ddl.go:557\ngithub.com/pingcap/tidb/executor.(*DDLExec).Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/ddl.go:144\ngithub.com/pingcap/tidb/executor.Next\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/executor.go:302\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelayExecutor\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:635\ngithub.com/pingcap/tidb/executor.(*ExecStmt).handleNoDelay\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:490\ngithub.com/pingcap/tidb/executor.(*ExecStmt).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/executor/adapter.go:439\ngithub.com/pingcap/tidb/session.runStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:2017\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/genius/project/src/github.com/pingcap/tidb/session/session.go:1894\ngithub.com/pingcap/tidb/testkit.(*TestKit).Exec\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:209\ngithub.com/pingcap/tidb/testkit.(*TestKit).MustGetErrCode\n\t/home/genius/project/src/github.com/pingcap/tidb/testkit/testkit.go:268\ngithub.com/pingcap/tidb/ddl_test.TestCacheTableSizeLimit\n\t/home/genius/project/src/github.com/pingcap/tidb/ddl/db_cache_test.go:227\ntesting.tRunner\n\t/home/genius/project/go/src/testing/testing.go:1439\nruntime.goexit\n\t/home/genius/project/go/src/runtime/asm_amd64.s:1571"] [session="{\n  \"currDBName\": \"test\",\n  \"id\": 1,\n  \"status\": 2,\n  \"strictMode\": true,\n  \"user\": null\n}"]
[2022/04/07 10:07:34.380 +08:00] [INFO] [session.go:3228] ["CRUCIAL OPERATION"] [conn=1] [schemaVersion=36] [cur_db=test] [sql="alter table cache_t2 cache"] [user=]
[2022/04/07 10:07:34.811 +08:00] [INFO] [levels.go:546] ["compact send discard stats"] [stats="numSkips:0, skippedBytes:0"]
[2022/04/07 10:07:34.812 +08:00] [INFO] [levels.go:628] ["compaction done"] [def="0 top:[0:5](58330904), bot:[0:7](759780), skip:6, write_amp:1.01"] [deleted=6] [added=9] [duration=2.465455897s]
[2022/04/07 10:07:34.812 +08:00] [INFO] [levels.go:670] ["compaction done"] [level=0]
[2022/04/07 10:07:35.305 +08:00] [INFO] [ddl_worker.go:334] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:73, Type:alter table cache, State:none, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2022/04/07 10:07:35.305 +08:00] [INFO] [ddl.go:645] ["[ddl] start DDL job"] [job="ID:73, Type:alter table cache, State:none, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="alter table cache_t2 cache"]
[2022/04/07 10:07:35.306 +08:00] [INFO] [ddl_worker.go:814] ["[ddl] run DDL job"] [worker="worker 3, tp general"] [job="ID:73, Type:alter table cache, State:none, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:07:35.311 +08:00] [INFO] [ddl_worker.go:814] ["[ddl] run DDL job"] [worker="worker 3, tp general"] [job="ID:73, Type:alter table cache, State:running, SchemaState:queueing, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:07:35.316 +08:00] [INFO] [ddl_worker.go:470] ["[ddl] finish DDL job"] [worker="worker 3, tp general"] [job="ID:73, Type:alter table cache, State:synced, SchemaState:public, SchemaID:1, TableID:69, RowCount:0, ArgLen:0, start time: 2022-04-07 10:07:35.302 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:07:35.320 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=73]
[2022/04/07 10:07:35.320 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:07:35.322 +08:00] [INFO] [domain.go:140] ["diff load InfoSchema success"] [currentSchemaVersion=36] [neededSchemaVersion=38] ["start time"=1.523481ms] [phyTblIDs="[69,69]"] [actionTypes="[144115188075855872,144115188075855872]"]
[2022/04/07 10:07:39.725 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.806143224s txnStartTS:432353380379131904 region_id:2 store_addr:store1 kv_process_ms:1579 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:41.305 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.501044725s txnStartTS:432353380873273344 region_id:2 store_addr:store1 kv_process_ms:1276 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:43.419 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.038683214s txnStartTS:432353381286150144 region_id:2 store_addr:store1 kv_process_ms:1582 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:45.573 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.029659205s txnStartTS:432353381854216192 region_id:2 store_addr:store1 kv_process_ms:1536 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:47.799 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.107801027s txnStartTS:432353382417039360 region_id:2 store_addr:store1 kv_process_ms:1616 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:50.188 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.279648502s txnStartTS:432353382998212608 region_id:2 store_addr:store1 kv_process_ms:1723 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:51.861 +08:00] [INFO] [data_window.go:249] ["Error exists when getting the SQL Metric."]
[2022/04/07 10:07:52.544 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.237716381s txnStartTS:432353383626833920 region_id:2 store_addr:store1 kv_process_ms:1732 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:54.935 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.264700353s txnStartTS:432353384246804480 region_id:2 store_addr:store1 kv_process_ms:1748 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:57.258 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.215132419s txnStartTS:432353384868610048 region_id:2 store_addr:store1 kv_process_ms:1699 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:07:59.600 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:2.239888097s txnStartTS:432353385475997696 region_id:2 store_addr:store1 kv_process_ms:1670 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:01.156 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.454252574s txnStartTS:432353386089676800 region_id:2 store_addr:store1 kv_process_ms:1265 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:02.737 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.508701174s txnStartTS:432353386489184256 region_id:2 store_addr:store1 kv_process_ms:1121 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:04.281 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.446962029s txnStartTS:432353386911236096 region_id:2 store_addr:store1 kv_process_ms:1072 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:05.854 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.500892686s txnStartTS:432353387309432832 region_id:2 store_addr:store1 kv_process_ms:1124 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:07.392 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.4680365s txnStartTS:432353387720474624 region_id:2 store_addr:store1 kv_process_ms:1082 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:08.866 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.405462159s txnStartTS:432353388123914240 region_id:2 store_addr:store1 kv_process_ms:1069 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:10.328 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.37916271s txnStartTS:432353388513984512 region_id:2 store_addr:store1 kv_process_ms:1045 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:11.726 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.309871067s txnStartTS:432353388898811904 region_id:2 store_addr:store1 kv_process_ms:1049 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:13.244 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.450137339s txnStartTS:432353389259784192 region_id:2 store_addr:store1 kv_process_ms:1117 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:14.805 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.467969145s txnStartTS:432353389664534528 region_id:2 store_addr:store1 kv_process_ms:1103 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:16.267 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.391457771s txnStartTS:432353390067712000 region_id:2 store_addr:store1 kv_process_ms:1059 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:17.554 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.190126727s txnStartTS:432353390457782272 region_id:2 store_addr:store1 kv_process_ms:1030 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:19.057 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.435725705s txnStartTS:432353390787559424 region_id:2 store_addr:store1 kv_process_ms:1102 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:20.521 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.38086538s txnStartTS:432353391185494016 region_id:2 store_addr:store1 kv_process_ms:1028 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:22.047 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.428967224s txnStartTS:432353391573204992 region_id:2 store_addr:store1 kv_process_ms:1065 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:23.352 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.215598141s txnStartTS:432353391971139584 region_id:2 store_addr:store1 kv_process_ms:1036 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:24.933 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.510321342s txnStartTS:432353392308256768 region_id:2 store_addr:store1 kv_process_ms:1146 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:26.470 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.439606669s txnStartTS:432353392729784320 region_id:2 store_addr:store1 kv_process_ms:1082 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:27.970 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.431526587s txnStartTS:432353393125097472 region_id:2 store_addr:store1 kv_process_ms:1098 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:29.289 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.250134596s txnStartTS:432353393518313472 region_id:2 store_addr:store1 kv_process_ms:1077 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:30.826 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.466279953s txnStartTS:432353393864081408 region_id:2 store_addr:store1 kv_process_ms:1142 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:32.276 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.379696163s txnStartTS:432353394267521024 region_id:2 store_addr:store1 kv_process_ms:1048 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:33.734 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.389249762s txnStartTS:432353394647105536 region_id:2 store_addr:store1 kv_process_ms:1063 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:35.090 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.287839143s txnStartTS:432353395029311488 region_id:2 store_addr:store1 kv_process_ms:1068 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:36.605 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.444510969s txnStartTS:432353395384516608 region_id:2 store_addr:store1 kv_process_ms:1114 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:38.080 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.383102684s txnStartTS:432353395787956224 region_id:2 store_addr:store1 kv_process_ms:1046 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:39.554 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.378676057s txnStartTS:432353396175405056 region_id:2 store_addr:store1 kv_process_ms:1023 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:40.844 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.221320746s txnStartTS:432353396554989568 region_id:2 store_addr:store1 kv_process_ms:1048 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:42.358 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.443329315s txnStartTS:432353396893155328 region_id:2 store_addr:store1 kv_process_ms:1105 kv_wait_ms:0 kv_read_ms:0"]
[2022/04/07 10:08:43.843 +08:00] [INFO] [coprocessor.go:852] ["[TIME_COP_PROCESS] resp_time:1.392493833s txnStartTS:432353397296332800 region_id:2 store_addr:store1 kv_process_ms:1059 kv_wait_ms:0 kv_read_ms:0"]
...skipping...
[2022/04/07 10:12:34.091 +08:00] [INFO] [delete_range.go:103] ["[ddl] add job into delete-range table"] [jobID=74] [jobType="drop table"]
[2022/04/07 10:12:34.092 +08:00] [INFO] [ddl_worker.go:470] ["[ddl] finish DDL job"] [worker="worker 3, tp general"] [job="ID:74, Type:drop table, State:synced, SchemaState:queueing, SchemaID:1, TableID:67, RowCount:0, ArgLen:3, start time: 2022-04-07 10:12:34.068 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2022/04/07 10:12:34.120 +08:00] [INFO] [ddl.go:711] ["[ddl] DDL job is finished"] [jobID=74]
[2022/04/07 10:12:34.120 +08:00] [INFO] [callback.go:107] ["performing DDL change, must reload"]
[2022/04/07 10:12:34.120 +08:00] [INFO] [domain.go:140] ["diff load InfoSchema success"] [currentSchemaVersion=38] [neededSchemaVersion=41] ["start time"=305.005µs] [phyTblIDs="[67]"] [actionTypes="[16]"]
[2022/04/07 10:12:34.121 +08:00] [INFO] [ddl_worker.go:155] ["[ddl] DDL worker closed"] [worker="worker 3, tp general"] ["take time"=1.39µs]
[2022/04/07 10:12:34.121 +08:00] [INFO] [ddl_worker.go:155] ["[ddl] DDL worker closed"] [worker="worker 4, tp add index"] ["take time"=1.06µs]
[2022/04/07 10:12:34.121 +08:00] [INFO] [delete_range.go:128] ["[ddl] closing delRange"]
[2022/04/07 10:12:35.349 +08:00] [INFO] [2pc.go:628] ["[BIG_TXN]"] [session=0] ["key sample"=7480000000000000435f728000000000000001] [size=1245184] [keys=65536] [puts=0] [dels=65536] [locks=0] [checks=0] [txnStartTS=432353458022252544]
[2022/04/07 10:12:38.274 +08:00] [INFO] [db.go:831] ["flushing memtable"] ["memtable size"=12582853] ["size of flushChan"=0]
[2022/04/07 10:12:38.316 +08:00] [INFO] [db.go:935] ["flush memtable storing offset"] [fid=0] [offset=0]
[2022/04/07 10:12:38.873 +08:00] [INFO] [delete_range.go:219] ["[ddl] delRange emulator complete task"] [jobID=74] [elementID=67] [startKey=748000000000000043] [endKey=748000000000000044]
[2022/04/07 10:12:38.873 +08:00] [INFO] [session_pool.go:90] ["[ddl] closing sessionPool"]
[2022/04/07 10:12:38.873 +08:00] [INFO] [ddl.go:462] ["[ddl] DDL closed"] [ID=52ee54a1-a16f-4013-8cf4-aadf9822dce9] ["take time"=4.752429553s]
[2022/04/07 10:12:38.873 +08:00] [INFO] [ddl.go:360] ["[ddl] stop DDL"] [ID=52ee54a1-a16f-4013-8cf4-aadf9822dce9]
[2022/04/07 10:12:38.873 +08:00] [INFO] [handle_hist.go:144] ["SubLoadWorker exited."]
[2022/04/07 10:12:38.873 +08:00] [INFO] [domain.go:1148] ["handleEvolvePlanTasksLoop exited."]
[2022/04/07 10:12:38.873 +08:00] [INFO] [domain.go:1105] ["globalBindHandleWorkerLoop exited."]
[2022/04/07 10:12:38.873 +08:00] [INFO] [domain.go:1027] ["LoadSysVarCacheLoop exited."]
[2022/04/07 10:12:38.873 +08:00] [INFO] [domain.go:557] ["topologySyncerKeeper exited."]
[2022/04/07 10:12:38.873 +08:00] [INFO] [domain.go:1211] ["TelemetryRotateSubWindowLoop exited."]
[2022/04/07 10:12:38.873 +08:00] [INFO] [domain.go:977] ["loadPrivilegeInLoop exited."]
[2022/04/07 10:12:38.873 +08:00] [INFO] [domain.go:509] ["infoSyncerKeeper exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [handle_hist.go:144] ["SubLoadWorker exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [domain.go:1233] ["dumpFileGcChecker exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [handle_hist.go:144] ["SubLoadWorker exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [handle_hist.go:144] ["SubLoadWorker exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [domain.go:1181] ["TelemetryReportLoop exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [handle_hist.go:144] ["SubLoadWorker exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [domain.go:534] ["globalConfigSyncerKeeper exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [domain.go:480] ["topNSlowQueryLoop exited."]
[2022/04/07 10:12:38.874 +08:00] [INFO] [domain.go:715] ["domain closed"] ["take time"=4.753547931s]
[2022/04/07 10:12:38.875 +08:00] [INFO] [db.go:567] ["Closing database"]
[2022/04/07 10:12:38.888 +08:00] [INFO] [db.go:592] ["Memtable flushed"]
[2022/04/07 10:12:38.889 +08:00] [INFO] [db.go:596] ["Compaction finished"]
[2022/04/07 10:12:38.889 +08:00] [INFO] [db.go:615] ["BlobManager finished"]
[2022/04/07 10:12:38.889 +08:00] [INFO] [db.go:619] ["ResourceManager finished"]
[2022/04/07 10:12:38.889 +08:00] [INFO] [db.go:625] ["Waiting for closer"]
--- FAIL: TestCacheTableSizeLimit (348.73s)
    db_cache_test.go:252:
                Error Trace:    db_cache_test.go:252
                Error:          Should be true
                Test:           TestCacheTableSizeLimit
FAIL

@tiancaiamao tiancaiamao self-assigned this Apr 8, 2022
@hawkingrei
Copy link
Member

it is still an unstable test.

         	Error Trace:	/home/jenkins/.tidb/tmp/04446c229c5a73c16deb3edddcb4db34/sandbox/processwrapper-sandbox/10315/execroot/__main__/bazel-out/k8-fastbuild/bin/ddl/ddl_test_/ddl_test.runfiles/__main__/ddl/db_cache_test.go:246
        	Error:      	Should be true
        	Test:       	TestCacheTableSizeLimit

https://prow.pingcap.net/view/gs/pingcapprow/logs/bazel_test_tidb/1564103182567608320#1:build-log.txt%3A6065

@tiancaiamao tiancaiamao mentioned this issue Nov 2, 2022
Merged
12 tasks
ti-chi-bot pushed a commit that referenced this issue Nov 3, 2022
@tiancaiamao
ddl: make test case TestCacheTableSizeLimit stable (#38822)
4c75850 
close #33764
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Assignees

@tiancaiamao tiancaiamao

Labels
component/test type/enhancement The issue or PR belongs to an enhancement.
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

ddl: make test case TestCacheTableSizeLimit stable tiancaiamao/tidb
2 participants
@tiancaiamao @hawkingrei