reduce the info log for create table

[zz-jason]

Development Task

I run a SQL create table t(a bigint, b bigint), then the following log shows up:

1 SQL -> 12 logs

[2020/03/29 01:19:17.650 +08:00] [INFO] [session.go:2112] ["CRUCIAL OPERATION"] [conn=3] [schemaVersion=768] [cur_db=test] [sql="create table t(a bigint, b bigint)"] [user=root@127.0.0.1]
[2020/03/29 01:19:17.650 +08:00] [INFO] [ddl_worker.go:253] ["[ddl] add DDL jobs"] ["batch count"=1] [jobs="ID:646, Type:create table, State:none, SchemaState:none, SchemaID:1, TableID:645, RowCount:0, ArgLen:1, start time: 2020-03-29 01:19:17.65 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0; "]
[2020/03/29 01:19:17.650 +08:00] [INFO] [ddl.go:457] ["[ddl] start DDL job"] [job="ID:646, Type:create table, State:none, SchemaState:none, SchemaID:1, TableID:645, RowCount:0, ArgLen:1, start time: 2020-03-29 01:19:17.65 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"] [query="create table t(a bigint, b bigint)"]
[2020/03/29 01:19:17.651 +08:00] [INFO] [ddl_worker.go:554] ["[ddl] run DDL job"] [worker="worker 1, tp general"] [job="ID:646, Type:create table, State:none, SchemaState:none, SchemaID:1, TableID:645, RowCount:0, ArgLen:0, start time: 2020-03-29 01:19:17.65 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/29 01:19:17.651 +08:00] [INFO] [domain.go:126] ["diff load InfoSchema success"] [usedSchemaVersion=768] [neededSchemaVersion=769] ["start time"=121.57µs] [tblIDs="[645]"]
[2020/03/29 01:19:17.654 +08:00] [INFO] [ddl_worker.go:739] ["[ddl] wait latest schema version changed"] [worker="worker 1, tp general"] [ver=769] ["take time"=2.567429ms] [job="ID:646, Type:create table, State:done, SchemaState:public, SchemaID:1, TableID:645, RowCount:0, ArgLen:1, start time: 2020-03-29 01:19:17.65 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/29 01:19:17.654 +08:00] [INFO] [ddl_worker.go:359] ["[ddl] finish DDL job"] [worker="worker 1, tp general"] [job="ID:646, Type:create table, State:synced, SchemaState:public, SchemaID:1, TableID:645, RowCount:0, ArgLen:0, start time: 2020-03-29 01:19:17.65 +0800 CST, Err:<nil>, ErrCount:0, SnapshotVersion:0"]
[2020/03/29 01:19:17.655 +08:00] [INFO] [ddl.go:489] ["[ddl] DDL job is finished"] [jobID=646]
[2020/03/29 01:19:17.655 +08:00] [INFO] [domain.go:619] ["performing DDL change, must reload"]
[2020/03/29 01:19:17.655 +08:00] [INFO] [split_region.go:56] ["split batch regions request"] ["split key count"=1] ["batch count"=1] ["first batch, region ID"=14] ["first split key"=748000000000000285]
[2020/03/29 01:19:17.655 +08:00] [INFO] [split_region.go:153] ["batch split regions complete"] ["batch region ID"=14] ["first at"=748000000000000285] ["first new region left"="{Id:14 StartKey:7480000000000002ff8200000000000000f8 EndKey: RegionEpoch:{ConfVer:0 Version:1} Peers:[id:15 store_id:1 ]}"] ["new region count"=1]
[2020/03/29 01:19:17.655 +08:00] [INFO] [split_region.go:205] ["split regions complete"] ["region count"=1] ["region IDs"="[14]"]

The log exposes too many details

[zz-jason]

@bb7133 PTAL

[bb7133]

Sure, we'll refine it soon.

[wjhuang2016]

Because the DDL operation is very complex, these log is used to help we identify the bug when DDL went wrong.
We don't' t think there is any log we can reduce here.

[zz-jason]

can we change these internal logs to debug level?

[zz-jason]

can we only log the required information when there is an error in the DDL operation?

[wjhuang2016]

can we only log the required information when there is an error in the DDL operation?

Many problems with DDL are slow or block. It doesn't meet the error.

[zz-jason]

Many problems with DDL are slow or block. It doesn't meet the error.

IMHO, it's better to diagnosis these slow DDL issues via the Grafana monitor.