From 398521a0edba0a5ecc4a15609ebec6b0c562195a Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Tue, 10 Jul 2018 21:18:14 +0800 Subject: [PATCH 1/3] executor: shorter set system variable log Some application change system variable a lot, logging in short format saves disk space. --- executor/set.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/executor/set.go b/executor/set.go index f4927cf23103f..ff463211611dc 100644 --- a/executor/set.go +++ b/executor/set.go @@ -178,7 +178,7 @@ func (e *SetExecutor) setSysVariable(name string, v *expression.VarAssignment) e valStr, err = value.ToString() terror.Log(errors.Trace(err)) } - log.Infof("[con:%d] set system variable %s = %s", sessionVars.ConnectionID, name, valStr) + log.Infof("con:%d %s=%s", sessionVars.ConnectionID, name, valStr) } if name == variable.TxnIsolation { From 15f4dc9f18365db9dc3b96cd43b5fd7db951d67f Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Wed, 11 Jul 2018 08:24:43 +0800 Subject: [PATCH 2/3] remove brackets arround 'con:%d' --- executor/adapter.go | 4 ++-- executor/compiler.go | 2 +- executor/set.go | 2 +- executor/simple.go | 2 +- server/conn.go | 8 ++++---- server/server.go | 4 ++-- session/session.go | 18 +++++++++--------- store/tikv/2pc.go | 34 +++++++++++++++++----------------- table/column.go | 2 +- x-server/conn.go | 8 ++++---- x-server/server.go | 4 ++-- 11 files changed, 44 insertions(+), 44 deletions(-) diff --git a/executor/adapter.go b/executor/adapter.go index aee4bdf23c045..cba794e55363f 100644 --- a/executor/adapter.go +++ b/executor/adapter.go @@ -280,10 +280,10 @@ func (a *ExecStmt) buildExecutor(ctx sessionctx.Context) (Executor, error) { var err error isPointGet := IsPointGetWithPKOrUniqueKeyByAutoCommit(ctx, a.Plan) if isPointGet { - log.Debugf("[con:%d][InitTxnWithStartTS] %s", ctx.GetSessionVars().ConnectionID, a.Text) + log.Debugf("con:%d InitTxnWithStartTS %s", ctx.GetSessionVars().ConnectionID, a.Text) err = ctx.InitTxnWithStartTS(math.MaxUint64) } else { - log.Debugf("[con:%d][ActivePendingTxn] %s", ctx.GetSessionVars().ConnectionID, a.Text) + log.Debugf("con:%d ActivePendingTxn %s", ctx.GetSessionVars().ConnectionID, a.Text) err = ctx.ActivePendingTxn() } if err != nil { diff --git a/executor/compiler.go b/executor/compiler.go index 89fad761bb3eb..0520e0e1d623c 100644 --- a/executor/compiler.go +++ b/executor/compiler.go @@ -195,7 +195,7 @@ func GetInfoSchema(ctx sessionctx.Context) infoschema.InfoSchema { var is infoschema.InfoSchema if snap := sessVar.SnapshotInfoschema; snap != nil { is = snap.(infoschema.InfoSchema) - log.Infof("[con:%d] use snapshot schema %d", sessVar.ConnectionID, is.SchemaMetaVersion()) + log.Infof("con:%d use snapshot schema %d", sessVar.ConnectionID, is.SchemaMetaVersion()) } else { is = sessVar.TxnCtx.InfoSchema.(infoschema.InfoSchema) } diff --git a/executor/set.go b/executor/set.go index ff463211611dc..7742e6afda34e 100644 --- a/executor/set.go +++ b/executor/set.go @@ -259,7 +259,7 @@ func (e *SetExecutor) loadSnapshotInfoSchemaIfNeeded(name string) error { vars.SnapshotInfoschema = nil return nil } - log.Infof("[con:%d] loadSnapshotInfoSchema, SnapshotTS:%d", vars.ConnectionID, vars.SnapshotTS) + log.Infof("con:%d loadSnapshotInfoSchema, SnapshotTS:%d", vars.ConnectionID, vars.SnapshotTS) dom := domain.GetDomain(e.ctx) snapInfo, err := dom.GetSnapshotInfoSchema(vars.SnapshotTS) if err != nil { diff --git a/executor/simple.go b/executor/simple.go index 6bf8758c780d2..e235847103a89 100644 --- a/executor/simple.go +++ b/executor/simple.go @@ -121,7 +121,7 @@ func (e *SimpleExec) executeCommit(s *ast.CommitStmt) { func (e *SimpleExec) executeRollback(s *ast.RollbackStmt) error { sessVars := e.ctx.GetSessionVars() - log.Debugf("[con:%d] execute rollback statement", sessVars.ConnectionID) + log.Debugf("con:%d execute rollback statement", sessVars.ConnectionID) sessVars.SetStatusFlag(mysql.ServerStatusInTrans, false) if e.ctx.Txn().Valid() { e.ctx.GetSessionVars().TxnCtx.ClearDelta() diff --git a/server/conn.go b/server/conn.go index fd948d107f424..a1fc24952de34 100644 --- a/server/conn.go +++ b/server/conn.go @@ -452,7 +452,7 @@ func (cc *clientConn) Run() { if terror.ErrorNotEqual(err, io.EOF) { errStack := errors.ErrorStack(err) if !strings.Contains(errStack, "use of closed network connection") { - log.Errorf("[con:%d] read packet error, close this connection %s", + log.Errorf("con:%d read packet error, close this connection %s", cc.connectionID, errStack) } } @@ -472,11 +472,11 @@ func (cc *clientConn) Run() { cc.addMetrics(data[0], startTime, nil) return } else if terror.ErrResultUndetermined.Equal(err) { - log.Errorf("[con:%d] result undetermined error, close this connection %s", + log.Errorf("con:%d result undetermined error, close this connection %s", cc.connectionID, errors.ErrorStack(err)) return } else if terror.ErrCritical.Equal(err) { - log.Errorf("[con:%d] critical error, stop the server listener %s", + log.Errorf("con:%d critical error, stop the server listener %s", cc.connectionID, errors.ErrorStack(err)) metrics.CriticalErrorCounter.Add(1) select { @@ -485,7 +485,7 @@ func (cc *clientConn) Run() { } return } - log.Warnf("[con:%d] dispatch error:\n%s\n%q\n%s", + log.Warnf("con:%d dispatch error:\n%s\n%q\n%s", cc.connectionID, cc, queryStrForLog(string(data[1:])), errStrForLog(err)) err1 := cc.writeError(err) terror.Log(errors.Trace(err1)) diff --git a/server/server.go b/server/server.go index 16da9c8abad5f..b4b91f35d1308 100644 --- a/server/server.go +++ b/server/server.go @@ -307,9 +307,9 @@ func (s *Server) onConn(c net.Conn) { terror.Log(errors.Trace(err)) return } - log.Infof("[con:%d] new connection %s", conn.connectionID, c.RemoteAddr().String()) + log.Infof("con:%d new connection %s", conn.connectionID, c.RemoteAddr().String()) defer func() { - log.Infof("[con:%d] close connection", conn.connectionID) + log.Infof("con:%d close connection", conn.connectionID) }() s.rwlock.Lock() s.clients[conn.connectionID] = conn diff --git a/session/session.go b/session/session.go index 7e084fc3a3d3e..233091b6c4a94 100644 --- a/session/session.go +++ b/session/session.go @@ -334,7 +334,7 @@ func (s *session) doCommitWithRetry(ctx context.Context) error { // BatchInsert already commit the first batch 1000 rows, then it commit 1000-2000 and retry the statement, // Finally t1 will have more data than t2, with no errors return to user! if s.isRetryableError(err) && !s.sessionVars.BatchInsert && commitRetryLimit > 0 { - log.Warnf("[con:%d] retryable error: %v, txn: %v", s.sessionVars.ConnectionID, err, s.txn) + log.Warnf("con:%d retryable error: %v, txn: %v", s.sessionVars.ConnectionID, err, s.txn) // Transactions will retry 2 ~ commitRetryLimit times. // We make larger transactions retry less times to prevent cluster resource outage. txnSizeRate := float64(txnSize) / float64(kv.TxnTotalSizeLimit) @@ -359,7 +359,7 @@ func (s *session) doCommitWithRetry(ctx context.Context) error { } if err != nil { - log.Warnf("[con:%d] finished txn:%v, %v", s.sessionVars.ConnectionID, s.txn, err) + log.Warnf("con:%d finished txn:%v, %v", s.sessionVars.ConnectionID, s.txn, err) return errors.Trace(err) } mapper := s.GetSessionVars().TxnCtx.TableDeltaMap @@ -508,17 +508,17 @@ func (s *session) retry(ctx context.Context, maxCnt uint) error { } } if !s.isRetryableError(err) { - log.Warnf("[con:%d] session:%v, err:%v in retry", connID, s, err) + log.Warnf("con:%d session:%v, err:%v in retry", connID, s, err) metrics.SessionRetryErrorCounter.WithLabelValues(metrics.LblUnretryable) return errors.Trace(err) } retryCnt++ if retryCnt >= maxCnt { - log.Warnf("[con:%d] Retry reached max count %d", connID, retryCnt) + log.Warnf("con:%d Retry reached max count %d", connID, retryCnt) metrics.SessionRetryErrorCounter.WithLabelValues(metrics.LblReachMax) return errors.Trace(err) } - log.Warnf("[con:%d] retryable error: %v, txn: %v", connID, err, s.txn) + log.Warnf("con:%d retryable error: %v, txn: %v", connID, err, s.txn) kv.BackOff(retryCnt) s.txn.changeToInvalid() s.sessionVars.SetStatusFlag(mysql.ServerStatusInTrans, false) @@ -739,7 +739,7 @@ func (s *session) executeStatement(ctx context.Context, connID uint64, stmtNode recordSet, err := runStmt(ctx, s, stmt) if err != nil { if !kv.ErrKeyExists.Equal(err) { - log.Warnf("[con:%d][schema ver:%d] session error:\n%v\n%s", + log.Warnf("con:%d schema_ver:%d session error:\n%v\n%s", connID, s.sessionVars.TxnCtx.SchemaVersion, errors.ErrorStack(err), s) } return nil, errors.Trace(err) @@ -815,7 +815,7 @@ func (s *session) execute(ctx context.Context, sql string) (recordSets []ast.Rec stmtNodes, err := s.ParseSQL(ctx, sql, charsetInfo, collation) if err != nil { s.rollbackOnError(ctx) - log.Warnf("[con:%d] parse error:\n%v\n%s", connID, err, sql) + log.Warnf("con:%d parse error:\n%v\n%s", connID, err, sql) return nil, errors.Trace(err) } metrics.SessionExecuteParseDuration.Observe(time.Since(startTS).Seconds()) @@ -833,7 +833,7 @@ func (s *session) execute(ctx context.Context, sql string) (recordSets []ast.Rec stmt, err := compiler.Compile(ctx, stmtNode) if err != nil { s.rollbackOnError(ctx) - log.Warnf("[con:%d] compile error:\n%v\n%s", connID, err, sql) + log.Warnf("con:%d compile error:\n%v\n%s", connID, err, sql) return nil, errors.Trace(err) } metrics.SessionExecuteCompileDuration.Observe(time.Since(startTS).Seconds()) @@ -986,7 +986,7 @@ func (s *session) NewTxn() error { return errors.Trace(err) } vars := s.GetSessionVars() - log.Infof("[con:%d][schema ver:%d] NewTxn() inside a transaction auto commit: %d", vars.ConnectionID, vars.TxnCtx.SchemaVersion, txnID) + log.Infof("con:%d[schema ver:%d] NewTxn() inside a transaction auto commit: %d", vars.ConnectionID, vars.TxnCtx.SchemaVersion, txnID) } txn, err := s.store.Begin() diff --git a/store/tikv/2pc.go b/store/tikv/2pc.go index 3a517faf124d8..848588dc65782 100644 --- a/store/tikv/2pc.go +++ b/store/tikv/2pc.go @@ -140,7 +140,7 @@ func newTwoPhaseCommitter(txn *tikvTxn, connID uint64) (*twoPhaseCommitter, erro const logSize = 4 * 1024 * 1024 // 4MB if len(keys) > logEntryCount || size > logSize { tableID := tablecodec.DecodeTableID(keys[0]) - log.Infof("[BIG_TXN] [con:%d] table id:%d size:%d, keys:%d, puts:%d, dels:%d, locks:%d, startTS:%d", + log.Infof("[BIG_TXN] con:%d table id:%d size:%d, keys:%d, puts:%d, dels:%d, locks:%d, startTS:%d", connID, tableID, size, len(keys), putCnt, delCnt, lockCnt, txn.startTS) } @@ -229,7 +229,7 @@ func (c *twoPhaseCommitter) doActionOnKeys(bo *Backoffer, action twoPhaseCommitA twoPhaseCommitGP.Go(func() { e := c.doActionOnBatches(bo, action, batches) if e != nil { - log.Debugf("[con:%d] 2PC async doActionOnBatches %s err: %v", c.connID, action, e) + log.Debugf("con:%d 2PC async doActionOnBatches %s err: %v", c.connID, action, e) metrics.TiKVSecondaryLockCleanupFailureCounter.WithLabelValues("commit").Inc() } }) @@ -256,7 +256,7 @@ func (c *twoPhaseCommitter) doActionOnBatches(bo *Backoffer, action twoPhaseComm if len(batches) == 1 { e := singleBatchActionFunc(bo, batches[0]) if e != nil { - log.Debugf("[con:%d] 2PC doActionOnBatches %s failed: %v, tid: %d", c.connID, action, e, c.startTS) + log.Debugf("con:%d 2PC doActionOnBatches %s failed: %v, tid: %d", c.connID, action, e, c.startTS) } return errors.Trace(e) } @@ -294,10 +294,10 @@ func (c *twoPhaseCommitter) doActionOnBatches(bo *Backoffer, action twoPhaseComm var err error for i := 0; i < len(batches); i++ { if e := <-ch; e != nil { - log.Debugf("[con:%d] 2PC doActionOnBatches %s failed: %v, tid: %d", c.connID, action, e, c.startTS) + log.Debugf("con:%d 2PC doActionOnBatches %s failed: %v, tid: %d", c.connID, action, e, c.startTS) // Cancel other requests and return the first error. if cancel != nil { - log.Debugf("[con:%d] 2PC doActionOnBatches %s to cancel other actions, tid: %d", c.connID, action, c.startTS) + log.Debugf("con:%d 2PC doActionOnBatches %s to cancel other actions, tid: %d", c.connID, action, c.startTS) cancel() } if err == nil { @@ -370,7 +370,7 @@ func (c *twoPhaseCommitter) prewriteSingleBatch(bo *Backoffer, batch batchKeys) if err1 != nil { return errors.Trace(err1) } - log.Debugf("[con:%d] 2PC prewrite encounters lock: %v", c.connID, lock) + log.Debugf("con:%d 2PC prewrite encounters lock: %v", c.connID, lock) locks = append(locks, lock) } ok, err := c.store.lockResolver.ResolveLocks(bo, locks) @@ -478,7 +478,7 @@ func (c *twoPhaseCommitter) commitSingleBatch(bo *Backoffer, batch batchKeys) er if keyErr := commitResp.GetError(); keyErr != nil { c.mu.RLock() defer c.mu.RUnlock() - err = errors.Errorf("[con:%d] 2PC commit failed: %v", c.connID, keyErr.String()) + err = errors.Errorf("con:%d 2PC commit failed: %v", c.connID, keyErr.String()) if c.mu.committed { // No secondary key could be rolled back after it's primary key is committed. // There must be a serious bug somewhere. @@ -527,7 +527,7 @@ func (c *twoPhaseCommitter) cleanupSingleBatch(bo *Backoffer, batch batchKeys) e return errors.Trace(err) } if keyErr := resp.BatchRollback.GetError(); keyErr != nil { - err = errors.Errorf("[con:%d] 2PC cleanup failed: %s", c.connID, keyErr) + err = errors.Errorf("con:%d 2PC cleanup failed: %s", c.connID, keyErr) log.Debugf("2PC failed cleanup key: %v, tid: %d", err, c.startTS) return errors.Trace(err) } @@ -576,9 +576,9 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) error { err := c.cleanupKeys(NewBackoffer(context.Background(), cleanupMaxBackoff).WithVars(c.txn.vars), c.keys) if err != nil { metrics.TiKVSecondaryLockCleanupFailureCounter.WithLabelValues("rollback").Inc() - log.Infof("[con:%d] 2PC cleanup err: %v, tid: %d", c.connID, err, c.startTS) + log.Infof("con:%d 2PC cleanup err: %v, tid: %d", c.connID, err, c.startTS) } else { - log.Infof("[con:%d] 2PC clean up done, tid: %d", c.connID, c.startTS) + log.Infof("con:%d 2PC clean up done, tid: %d", c.connID, c.startTS) } c.cleanWg.Done() }) @@ -608,19 +608,19 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) error { } } if err != nil { - log.Debugf("[con:%d] 2PC failed on prewrite: %v, tid: %d", c.connID, err, c.startTS) + log.Debugf("con:%d 2PC failed on prewrite: %v, tid: %d", c.connID, err, c.startTS) return errors.Trace(err) } commitTS, err := c.store.getTimestampWithRetry(NewBackoffer(ctx, tsoMaxBackoff).WithVars(c.txn.vars)) if err != nil { - log.Warnf("[con:%d] 2PC get commitTS failed: %v, tid: %d", c.connID, err, c.startTS) + log.Warnf("con:%d 2PC get commitTS failed: %v, tid: %d", c.connID, err, c.startTS) return errors.Trace(err) } // check commitTS if commitTS <= c.startTS { - err = errors.Errorf("[con:%d] Invalid transaction tso with start_ts=%v while commit_ts=%v", + err = errors.Errorf("con:%d Invalid transaction tso with start_ts=%v while commit_ts=%v", c.connID, c.startTS, commitTS) log.Error(err) return errors.Trace(err) @@ -631,21 +631,21 @@ func (c *twoPhaseCommitter) execute(ctx context.Context) error { } if c.store.oracle.IsExpired(c.startTS, maxTxnTimeUse) { - err = errors.Errorf("[con:%d] txn takes too much time, start: %d, commit: %d", c.connID, c.startTS, c.commitTS) + err = errors.Errorf("con:%d txn takes too much time, start: %d, commit: %d", c.connID, c.startTS, c.commitTS) return errors.Annotate(err, txnRetryableMark) } err = c.commitKeys(NewBackoffer(ctx, CommitMaxBackoff).WithVars(c.txn.vars), c.keys) if err != nil { if undeterminedErr := c.getUndeterminedErr(); undeterminedErr != nil { - log.Warnf("[con:%d] 2PC commit result undetermined, err: %v, rpcErr: %v, tid: %v", c.connID, err, undeterminedErr, c.startTS) + log.Warnf("con:%d 2PC commit result undetermined, err: %v, rpcErr: %v, tid: %v", c.connID, err, undeterminedErr, c.startTS) err = errors.Wrap(err, terror.ErrResultUndetermined) } if !c.mu.committed { - log.Debugf("[con:%d] 2PC failed on commit: %v, tid: %d", c.connID, err, c.startTS) + log.Debugf("con:%d 2PC failed on commit: %v, tid: %d", c.connID, err, c.startTS) return errors.Trace(err) } - log.Debugf("[con:%d] 2PC succeed with error: %v, tid: %d", c.connID, err, c.startTS) + log.Debugf("con:%d 2PC succeed with error: %v, tid: %d", c.connID, err, c.startTS) } return nil } diff --git a/table/column.go b/table/column.go index 8cefd656f3a50..c111c0fa9e589 100644 --- a/table/column.go +++ b/table/column.go @@ -171,7 +171,7 @@ func CastValue(ctx sessionctx.Context, val types.Datum, col *model.ColumnInfo) ( continue } err = ErrTruncateWrongValue.FastGen("incorrect utf8 value %x(%s) for column %s", casted.GetBytes(), str, col.Name) - log.Errorf("[con:%d] %v", ctx.GetSessionVars().ConnectionID, err) + log.Errorf("con:%d %v", ctx.GetSessionVars().ConnectionID, err) // Truncate to valid utf8 string. casted = types.NewStringDatum(str[:i]) err = sc.HandleTruncate(err) diff --git a/x-server/conn.go b/x-server/conn.go index 4b5111e1742a7..6368302a86cb4 100644 --- a/x-server/conn.go +++ b/x-server/conn.go @@ -51,24 +51,24 @@ func (cc *clientConn) Run() { tp, payload, err := cc.readPacket() if err != nil { if terror.ErrorNotEqual(err, io.EOF) { - log.Errorf("[con:%d] read packet error, close this connection %s", + log.Errorf("con:%d read packet error, close this connection %s", cc.connectionID, errors.ErrorStack(err)) } return } if err = cc.dispatch(tp, payload); err != nil { if terror.ErrorEqual(err, terror.ErrResultUndetermined) { - log.Errorf("[con:%d] result undetermined error, close this connection %s", + log.Errorf("con:%d result undetermined error, close this connection %s", cc.connectionID, errors.ErrorStack(err)) } else if terror.ErrorEqual(err, terror.ErrCritical) { - log.Errorf("[con:%d] critical error, stop the server listener %s", + log.Errorf("con:%d critical error, stop the server listener %s", cc.connectionID, errors.ErrorStack(err)) select { case cc.server.stopListenerCh <- struct{}{}: default: } } - log.Warnf("[con:%d] dispatch error: %s, %s", cc.connectionID, cc, err) + log.Warnf("con:%d dispatch error: %s, %s", cc.connectionID, cc, err) cc.writeError(err) return } diff --git a/x-server/server.go b/x-server/server.go index 23ce9865620d6..b5000b80567e0 100644 --- a/x-server/server.go +++ b/x-server/server.go @@ -121,7 +121,7 @@ func (s *Server) shouldStopListener() bool { func (s *Server) onConn(c net.Conn) { conn := s.newConn(c) defer func() { - log.Infof("[con:%d] close x protocol connection", conn.connectionID) + log.Infof("con:%d close x protocol connection", conn.connectionID) }() if err := conn.handshake(); err != nil { // Some keep alive services will send request to TiDB and disconnect immediately. @@ -144,7 +144,7 @@ func (s *Server) newConn(conn net.Conn) *clientConn { collation: mysql.DefaultCollationID, alloc: arena.NewAllocator(32 * 1024), } - log.Infof("[con:%d] new x protocol connection %s", cc.connectionID, conn.RemoteAddr().String()) + log.Infof("con:%d new x protocol connection %s", cc.connectionID, conn.RemoteAddr().String()) cc.salt = util.RandomBuf(20) return cc } From e4f649d7e0a4bb13c7d7f9b8a7b503df3893b53d Mon Sep 17 00:00:00 2001 From: Ewan Chou Date: Wed, 11 Jul 2018 13:25:39 +0800 Subject: [PATCH 3/3] address comment --- session/session.go | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/session/session.go b/session/session.go index 233091b6c4a94..79f22119c7e42 100644 --- a/session/session.go +++ b/session/session.go @@ -986,7 +986,7 @@ func (s *session) NewTxn() error { return errors.Trace(err) } vars := s.GetSessionVars() - log.Infof("con:%d[schema ver:%d] NewTxn() inside a transaction auto commit: %d", vars.ConnectionID, vars.TxnCtx.SchemaVersion, txnID) + log.Infof("con:%d schema_ver:%d NewTxn() inside a transaction auto commit: %d", vars.ConnectionID, vars.TxnCtx.SchemaVersion, txnID) } txn, err := s.store.Begin()