diff --git a/executor/adapter.go b/executor/adapter.go index acdafbd386291..aee4bdf23c045 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -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 { @@ -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) + } + 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", + 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) } } diff --git a/session/session.go b/session/session.go index 6fe10ed1f106f..e8a82bae1d4cd 100644 --- a/session/session.go +++ b/session/session.go @@ -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() @@ -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 { @@ -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) } 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) @@ -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) } }