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

executor, session: replace new line and add user in query log #6748

Merged
merged 7 commits into from
Jun 11, 2018
Merged

executor, session: replace new line and add user in query log #6748

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
7 commits
Select commit Hold shift + click to select a range
be234d3
executor, session: replace new line and add user in query log
coocood Jun 4, 2018
955cdae
refine general log and slow log format
coocood Jun 4, 2018
b3fbac0
address comment
coocood Jun 5, 2018
f59855a
address comment
coocood Jun 6, 2018
95b2dde
address comment
coocood Jun 11, 2018
62314b6
Merge branch 'master' into refine-query-log
coocood Jun 11, 2018
784d3dc
Merge branch 'master' into refine-query-log
zimulala Jun 11, 2018
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
29 changes: 20 additions & 9 deletions executor/adapter.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -324,6 +324,9 @@ func (a *ExecStmt) buildExecutor(ctx sessionctx.Context) (Executor, error) {
return e, nil
}

// QueryReplacer replaces new line and tab for grep result including query string.
var QueryReplacer = strings.NewReplacer("\r", " ", "\n", " ", "\t", " ")

func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) {
level := log.GetLevel()
if level < log.WarnLevel {
Expand All @@ -339,19 +342,27 @@ func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) {
if len(sql) > int(cfg.Log.QueryLogMaxLen) {
sql = fmt.Sprintf("%.*q(len:%d)", cfg.Log.QueryLogMaxLen, sql, len(a.Text))
}
connID := a.Ctx.GetSessionVars().ConnectionID
currentDB := a.Ctx.GetSessionVars().CurrentDB
tableIDs := strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.TableIDs), " ", ",", -1)
indexIDs := strings.Replace(fmt.Sprintf("%v", a.Ctx.GetSessionVars().StmtCtx.IndexIDs), " ", ",", -1)

sql = QueryReplacer.Replace(sql)

sessVars := a.Ctx.GetSessionVars()
connID := sessVars.ConnectionID
currentDB := sessVars.CurrentDB
var tableIDs, indexIDs string
if len(sessVars.StmtCtx.TableIDs) > 0 {
tableIDs = strings.Replace(fmt.Sprintf("table_ids:%v ", a.Ctx.GetSessionVars().StmtCtx.TableIDs), " ", ",", -1)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Why do you want to replace spaces with commas? I think it has a certain loss of performance. If it is not necessary, it may not be done.

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

It is useful when we need to use ' ' as fields separator.

Copy link
Contributor

@lysu lysu Jun 6, 2018 •
edited
Loading

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

or should we Itoa to []string and strings.Join if performance is critial?

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

The performance is not critical here, we better use a simpler solution.

}
if len(sessVars.StmtCtx.IndexIDs) > 0 {
indexIDs = strings.Replace(fmt.Sprintf("index_ids:%v ", a.Ctx.GetSessionVars().StmtCtx.IndexIDs), " ", ",", -1)
}
user := a.Ctx.GetSessionVars().User
if costTime < threshold {
logutil.SlowQueryLogger.Debugf(
"[QUERY] cost_time:%v succ:%v connection_id:%v txn_start_ts:%v database:%v table_ids:%v index_ids:%v sql:%v",
costTime, succ, connID, txnTS, currentDB, tableIDs, indexIDs, sql)
"[QUERY] cost_time:%v succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

maybe not use %v if it know real type~

Copy link
Member Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I think it doesn't matter much.

costTime, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
} else {
logutil.SlowQueryLogger.Warnf(
"[SLOW_QUERY] cost_time:%v succ:%v connection_id:%v txn_start_ts:%v database:%v table_ids:%v index_ids:%v sql:%v",
costTime, succ, connID, txnTS, currentDB, tableIDs, indexIDs, sql)
"[SLOW_QUERY] cost_time:%v succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
costTime, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
}
}

Expand Down
15 changes: 8 additions & 7 deletions session/session.go
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -500,9 +500,9 @@ func (s *session) retry(ctx context.Context, maxCnt uint) error {
if retryCnt == 0 {
// We do not have to log the query every time.
// We print the queries at the first try only.
log.Warnf("[con:%d][schema ver:%d] Retry:%d query:%d %s", connID, schemaVersion, retryCnt, i, sqlForLog(st.OriginText()))
log.Warnf("con:%d schema_ver:%d retry_cnt:%d query_num:%d sql:%s", connID, schemaVersion, retryCnt, i, sqlForLog(st.OriginText()))
} else {
log.Warnf("[con:%d][schema ver:%d] Retry:%d query:%d", connID, schemaVersion, retryCnt, i)
log.Warnf("con:%d schema_ver:%d retry_cnt:%d query_num:%d", connID, schemaVersion, retryCnt, i)
}
s.sessionVars.StmtCtx = sr.stmtCtx
s.sessionVars.StmtCtx.ResetForRetry()
Expand Down Expand Up @@ -544,9 +544,9 @@ func (s *session) retry(ctx context.Context, maxCnt uint) error {

func sqlForLog(sql string) string {
if len(sql) > sqlLogMaxLen {
return sql[:sqlLogMaxLen] + fmt.Sprintf("(len:%d)", len(sql))
sql = sql[:sqlLogMaxLen] + fmt.Sprintf("(len:%d)", len(sql))
}
return sql
return executor.QueryReplacer.Replace(sql)
}

func (s *session) sysSessionPool() *pools.ResourcePool {
Expand Down Expand Up @@ -1429,9 +1429,9 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) {
user := vars.User
schemaVersion := vars.TxnCtx.SchemaVersion
if ss, ok := node.(ast.SensitiveStmtNode); ok {
log.Infof("[CRUCIAL OPERATION] [con:%d][schema ver:%d] %s (by %s).", vars.ConnectionID, schemaVersion, ss.SecureText(), user)
log.Infof("[CRUCIAL OPERATION] con:%d schema_ver:%d %s (by %s).", vars.ConnectionID, schemaVersion, ss.SecureText(), user)
Copy link
Contributor

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Do we need to make the same changes to unify the log format in line 503?

} else {
log.Infof("[CRUCIAL OPERATION] [con:%d][schema ver:%d] %s (by %s).", vars.ConnectionID, schemaVersion, stmt.Text(), user)
log.Infof("[CRUCIAL OPERATION] con:%d schema_ver:%d %s (by %s).", vars.ConnectionID, schemaVersion, stmt.Text(), user)
}
default:
logQuery(node.Text(), vars)
Expand All @@ -1440,6 +1440,7 @@ func logStmt(node ast.StmtNode, vars *variable.SessionVars) {

func logQuery(query string, vars *variable.SessionVars) {
if atomic.LoadUint32(&variable.ProcessGeneralLog) != 0 && !vars.InRestrictedSQL {
log.Infof("[con:%d][schema ver:%d][txn:%d] %s", vars.ConnectionID, vars.TxnCtx.SchemaVersion, vars.TxnCtx.StartTS, query)
query = executor.QueryReplacer.Replace(query)
log.Infof("[GENERAL_LOG] con:%d user:%s schema_ver:%d start_ts:%d sql:%s", vars.ConnectionID, vars.User, vars.TxnCtx.SchemaVersion, vars.TxnCtx.StartTS, query)
}
}