help wantedsig/sql-infratype/enhancement
仓库指标
- Star
- (40,090 star)
- PR 合并指标
- (平均合并 14天 4小时) (30 天内合并 346 个 PR)
描述
The annoyance
The logs of TiDB are verbose and annoying, in my mind, it is partially due to the fact that: (1) we don't want to lose any detail, even when it is hardly useful. (2) we didn't pay much attention to them.
Give a possible example, a simple ERROR 1046 (3D000): No database selected error like
tidb> select * from t;
ERROR 1046 (3D000): No database selected
Make 2 long annoying entries in TiDB log:
[2021/05/17 22:04:31.486 +08:00] [WARN] [session.go:1410] ["compile SQL failed"] [conn=5] [error="[planner:1046]No database selected"] [errorVerbose="[planner:1046]No database selected\ngithub.com/pingcap/errors.AddStack\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/juju_adaptor.go:15\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).handleTableName\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:1116\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).Leave\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:355\ngithub.com/pingcap/parser/ast.(*TableName).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:403\ngithub.com/pingcap/parser/ast.(*TableSource).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:546\ngithub.com/pingcap/parser/ast.(*Join).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:231\ngithub.com/pingcap/parser/ast.(*TableRefsClause).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:744\ngithub.com/pingcap/parser/ast.(*SelectStmt).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:1231\ngithub.com/pingcap/tidb/planner/core.Preprocess\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:89\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/executor/compiler.go:57\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/session/session.go:1403\ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:218\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1623\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1496\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1030\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:795\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/server.go:477\nruntime.goexit\n\t/home/bb7133/Softwares/go/src/runtime/asm_amd64.s:1357"] [SQL="select * from t"]
[2021/05/17 22:04:31.486 +08:00] [INFO] [conn.go:812] ["command dispatched failed"] [conn=5] [connInfo="id:5, addr:127.0.0.1:41398 status:10, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="select * from t"] [txn_mode=OPTIMISTIC] [err="[planner:1046]No database selected\ngithub.com/pingcap/errors.AddStack\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/errors.go:174\ngithub.com/pingcap/errors.Trace\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20201126102027-b0a155152ca3/juju_adaptor.go:15\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).handleTableName\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:1116\ngithub.com/pingcap/tidb/planner/core.(*preprocessor).Leave\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:355\ngithub.com/pingcap/parser/ast.(*TableName).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:403\ngithub.com/pingcap/parser/ast.(*TableSource).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:546\ngithub.com/pingcap/parser/ast.(*Join).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:231\ngithub.com/pingcap/parser/ast.(*TableRefsClause).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:744\ngithub.com/pingcap/parser/ast.(*SelectStmt).Accept\n\t/home/bb7133/Projects/gopath/pkg/mod/github.com/pingcap/parser@v0.0.0-20210325072920-0d17053a8a69/ast/dml.go:1231\ngithub.com/pingcap/tidb/planner/core.Preprocess\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/planner/core/preprocess.go:89\ngithub.com/pingcap/tidb/executor.(*Compiler).Compile\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/executor/compiler.go:57\ngithub.com/pingcap/tidb/session.(*session).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/session/session.go:1403\ngithub.com/pingcap/tidb/server.(*TiDBContext).ExecuteStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/driver_tidb.go:218\ngithub.com/pingcap/tidb/server.(*clientConn).handleStmt\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1623\ngithub.com/pingcap/tidb/server.(*clientConn).handleQuery\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1496\ngithub.com/pingcap/tidb/server.(*clientConn).dispatch\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:1030\ngithub.com/pingcap/tidb/server.(*clientConn).Run\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/conn.go:795\ngithub.com/pingcap/tidb/server.(*Server).onConn\n\t/home/bb7133/Projects/gopath/src/github.com/pingcap/tidb/server/server.go:477\nruntime.goexit\n\t/home/bb7133/Softwares/go/src/runtime/asm_amd64.s:1357"]
It is annoying for at least 2 reasons: (1) We don't need the stack at all because the cause is clear enough. (2) The stack is too long because the full path of the source code is given, which is obviously unnecessary.
The proposal
IMO we can try to refine the logs of TiDB by:
- Examine the errors, remove/simplify the unnecessary stacks reported according to their semantics:
- Simple errors caused by the client, or can be easily reproduced can be removed. Example:
ERROR 1046: No database selected,ERROR 1064: Error in SQL syntax). - Logs that are duplicated can be removed, as you can see from the example given above.
- To be added.
- Simple errors caused by the client, or can be easily reproduced can be removed. Example:
- Shorten the stack by trimming the path of source code. Although we've the compatibility issue of
go build --trimwith the plugin(https://github.com/golang/go/issues/31278#issuecomment-541106229), it is still possible to trim them without the built-in mechanism of Golang. - Try to shorten the log entries by a more 'compact' format than the current one:
- zap is structured and powerful, but the current format like "[name': 'body']"can be simplified.
- WARNING: change of the format can be complicated and break the ecosystem framework by the users if they rely on the current one.
- Close the existing issues that related to 'log refinements':
- To be added.