From 9c69389886e79b54147cb88f1eb0e226baa0c2a3 Mon Sep 17 00:00:00 2001 From: Lynn Date: Fri, 31 May 2019 14:51:20 +0800 Subject: [PATCH] ddl, session: update logs (#10546) (#10661) --- ddl/ddl.go | 3 ++- ddl/ddl_worker.go | 8 ++++++-- domain/domain.go | 3 ++- owner/manager.go | 3 ++- session/bootstrap.go | 23 ++++++++++++++++------- 5 files changed, 28 insertions(+), 12 deletions(-) diff --git a/ddl/ddl.go b/ddl/ddl.go index ddbf92fe5ea4b..d6e3dd58b396c 100644 --- a/ddl/ddl.go +++ b/ddl/ddl.go @@ -421,7 +421,8 @@ func (d *ddl) close() { if d.sessPool != nil { d.sessPool.close() } - logutil.Logger(ddlLogCtx).Info("[ddl] closing DDL", zap.String("ID", d.uuid), zap.Duration("takeTime", time.Since(startTime))) + + logutil.Logger(ddlLogCtx).Info("[ddl] DDL closed", zap.String("ID", d.uuid), zap.Duration("take time", time.Since(startTime))) } // GetLease implements DDL.GetLease interface. diff --git a/ddl/ddl_worker.go b/ddl/ddl_worker.go index 872c3ecf6d532..1fc9ae53c1355 100644 --- a/ddl/ddl_worker.go +++ b/ddl/ddl_worker.go @@ -107,11 +107,12 @@ func (w *worker) String() string { } func (w *worker) close() { + startTime := time.Now() close(w.quitCh) w.delRangeManager.clear() w.sessPool.close() w.wg.Wait() - logutil.Logger(w.logCtx).Info("[ddl] close DDL worker") + logutil.Logger(w.logCtx).Info("[ddl] DDL worker closed", zap.Duration("take time", time.Since(startTime))) } // start is used for async online schema changing, it will try to become the owner firstly, @@ -599,7 +600,10 @@ func (w *worker) waitSchemaChanged(ctx context.Context, d *ddlCtx, waitTime time return } } - logutil.Logger(w.logCtx).Info("[ddl] wait latest schema version changed", zap.Int64("ver", latestSchemaVersion), zap.Duration("takeTime", time.Since(timeStart)), zap.String("job", job.String())) + logutil.Logger(w.logCtx).Info("[ddl] wait latest schema version changed", + zap.Int64("ver", latestSchemaVersion), + zap.Duration("take time", time.Since(timeStart)), + zap.String("job", job.String())) return } diff --git a/domain/domain.go b/domain/domain.go index 6f7fd7329feee..dfc91dbf622f5 100644 --- a/domain/domain.go +++ b/domain/domain.go @@ -525,6 +525,7 @@ func (do *Domain) mustReload() (exitLoop bool) { // Close closes the Domain and release its resource. func (do *Domain) Close() { + startTime := time.Now() if do.ddl != nil { terror.Log(errors.Trace(do.ddl.Stop())) } @@ -538,7 +539,7 @@ func (do *Domain) Close() { do.sysSessionPool.Close() do.slowQuery.Close() do.wg.Wait() - logutil.Logger(context.Background()).Info("domain closed") + logutil.Logger(context.Background()).Info("domain closed", zap.Duration("take time", time.Since(startTime))) } type ddlCallback struct { diff --git a/owner/manager.go b/owner/manager.go index a30cb2f1d09a5..4b4ad1e237dff 100644 --- a/owner/manager.go +++ b/owner/manager.go @@ -243,6 +243,7 @@ func (m *ownerManager) campaignLoop(ctx context.Context, etcdSession *concurrenc return } case <-ctx.Done(): + logutil.Logger(logCtx).Info("break campaign loop, context is done") m.revokeSession(logPrefix, etcdSession.Lease()) return default: @@ -286,7 +287,7 @@ func (m *ownerManager) revokeSession(logPrefix string, leaseID clientv3.LeaseID) time.Duration(ManagerSessionTTL)*time.Second) _, err := m.etcdCli.Revoke(cancelCtx, leaseID) cancel() - logutil.Logger(m.logCtx).Info("break campaign loop, revoke err", zap.Error(err)) + logutil.Logger(m.logCtx).Info("revoke session", zap.Error(err)) } // GetOwnerID implements Manager.GetOwnerID interface. diff --git a/session/bootstrap.go b/session/bootstrap.go index 109e8bf73989f..333b8238d00d8 100644 --- a/session/bootstrap.go +++ b/session/bootstrap.go @@ -215,6 +215,7 @@ const ( // bootstrap initiates system DB for a store. func bootstrap(s Session) { + startTime := time.Now() dom := domain.GetDomain(s) for { b, err := checkBootstrapped(s) @@ -225,6 +226,8 @@ func bootstrap(s Session) { // For rolling upgrade, we can't do upgrade only in the owner. if b { upgrade(s) + logutil.Logger(context.Background()).Info("upgrade successful in bootstrap", + zap.Duration("take time", time.Since(startTime))) return } // To reduce conflict when multiple TiDB-server start at the same time. @@ -232,6 +235,8 @@ func bootstrap(s Session) { if dom.DDL().OwnerManager().IsOwner() { doDDLWorks(s) doDMLWorks(s) + logutil.Logger(context.Background()).Info("bootstrap successful", + zap.Duration("take time", time.Since(startTime))) return } time.Sleep(200 * time.Millisecond) @@ -434,18 +439,20 @@ func upgrade(s Session) { _, err = s.Execute(context.Background(), "COMMIT") if err != nil { - time.Sleep(1 * time.Second) + sleepTime := 1 * time.Second + logutil.Logger(context.Background()).Info("update bootstrap ver failed", + zap.Error(err), zap.Duration("sleeping time", sleepTime)) + time.Sleep(sleepTime) // Check if TiDB is already upgraded. v, err1 := getBootstrapVersion(s) if err1 != nil { - logutil.Logger(context.Background()).Fatal("upgrade error", - zap.Error(err1)) + logutil.Logger(context.Background()).Fatal("upgrade failed", zap.Error(err1)) } if v >= currentBootstrapVersion { // It is already bootstrapped/upgraded by a higher version TiDB server. return } - logutil.Logger(context.Background()).Fatal("[Upgrade] upgrade error", + logutil.Logger(context.Background()).Fatal("[Upgrade] upgrade failed", zap.Int64("from", ver), zap.Int("to", currentBootstrapVersion), zap.Error(err)) @@ -773,16 +780,18 @@ func doDMLWorks(s Session) { writeSystemTZ(s) _, err := s.Execute(context.Background(), "COMMIT") if err != nil { - time.Sleep(1 * time.Second) + sleepTime := 1 * time.Second + logutil.Logger(context.Background()).Info("doDMLWorks failed", zap.Error(err), zap.Duration("sleeping time", sleepTime)) + time.Sleep(sleepTime) // Check if TiDB is already bootstrapped. b, err1 := checkBootstrapped(s) if err1 != nil { - logutil.Logger(context.Background()).Fatal("doDMLWorks error", zap.Error(err1)) + logutil.Logger(context.Background()).Fatal("doDMLWorks failed", zap.Error(err1)) } if b { return } - logutil.Logger(context.Background()).Fatal("doDMLWorks error", zap.Error(err)) + logutil.Logger(context.Background()).Fatal("doDMLWorks failed", zap.Error(err)) } }