ddl, session: update logs (#10546) (#10661)

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.

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
 }
 

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 {

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.

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,13 +226,17 @@ 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.
 		// Actually only one server need to do the bootstrap. So we chose DDL owner to do this.
 		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))
 	}
 }