Improve skipping sync condition and add more logs

Signed-off-by: JmPotato <[email protected]>

pkg/tso/tso.go

@@ -167,9 +167,10 @@ func (t *timestampOracle) SyncTimestamp(leadership *election.Leadership) error {
 		return err
 	}
 	lastSavedTime := t.getLastSavedTime()
-	// If `lastSavedTime` is not zero, it means that the `timestampOracle` has already been initialized
-	// before, so we could safely skip the sync if `lastSavedTime` is equal to `last`.
-	if lastSavedTime != typeutil.ZeroTime && typeutil.SubRealTimeByWallClock(lastSavedTime, last) == 0 {
+	// If `last` and `lastSavedTime` are the same and both not zero, it means that the
+	// timestamp has been synchronized before. We could skip the synchronization safely.
+	if last != typeutil.ZeroTime && lastSavedTime != typeutil.ZeroTime &&
+		typeutil.SubRealTimeByWallClock(lastSavedTime, last) == 0 {
 		t.metrics.skipSyncEvent.Inc()
 		return nil
 	}
@@ -185,7 +186,9 @@ func (t *timestampOracle) SyncTimestamp(leadership *election.Leadership) error {
 	// the timestamp allocation will start from the saved etcd timestamp temporarily.
 	if typeutil.SubRealTimeByWallClock(next, last) < UpdateTimestampGuard {
 		log.Warn("system time may be incorrect",
-			zap.Time("last", last), zap.Time("next", next), errs.ZapError(errs.ErrIncorrectSystemTime))
+			zap.Uint32("keyspace-group-id", t.keyspaceGroupID),
+			zap.Time("last", last), zap.Time("next", next),
+			errs.ZapError(errs.ErrIncorrectSystemTime))
 		next = last.Add(UpdateTimestampGuard)
 	}
 	failpoint.Inject("failedToSaveTimestamp", func() {
@@ -201,7 +204,9 @@ func (t *timestampOracle) SyncTimestamp(leadership *election.Leadership) error {
 	t.lastSavedTime.Store(save)
 
 	t.metrics.syncOKEvent.Inc()
-	log.Info("sync and save timestamp", zap.Time("last", last), zap.Time("save", save), zap.Time("next", next))
+	log.Info("sync and save timestamp",
+		zap.Uint32("keyspace-group-id", t.keyspaceGroupID),
+		zap.Time("last", last), zap.Time("save", save), zap.Time("next", next))
 	// save into memory
 	t.setTSOPhysical(next, true)
 	return nil
@@ -313,6 +318,7 @@ func (t *timestampOracle) UpdateTimestamp(leadership *election.Leadership) error
 	jetLag := typeutil.SubRealTimeByWallClock(now, prevPhysical)
 	if jetLag > 3*t.updatePhysicalInterval && jetLag > jetLagWarningThreshold {
 		log.Warn("clock offset",
+			zap.Uint32("keyspace-group-id", t.keyspaceGroupID),
 			zap.Duration("jet-lag", jetLag),
 			zap.Time("prev-physical", prevPhysical),
 			zap.Time("now", now),
@@ -331,7 +337,9 @@ func (t *timestampOracle) UpdateTimestamp(leadership *election.Leadership) error
 	} else if prevLogical > maxLogical/2 {
 		// The reason choosing maxLogical/2 here is that it's big enough for common cases.
 		// Because there is enough timestamp can be allocated before next update.
-		log.Warn("the logical time may be not enough", zap.Int64("prev-logical", prevLogical))
+		log.Warn("the logical time may be not enough",
+			zap.Uint32("keyspace-group-id", t.keyspaceGroupID),
+			zap.Int64("prev-logical", prevLogical))
 		next = prevPhysical.Add(time.Millisecond)
 	} else {
 		// It will still use the previous physical time to alloc the timestamp.
@@ -346,6 +354,7 @@ func (t *timestampOracle) UpdateTimestamp(leadership *election.Leadership) error
 		start := time.Now()
 		if err := t.storage.SaveTimestamp(t.GetTimestampPath(), save); err != nil {
 			log.Warn("save timestamp failed",
+				zap.Uint32("keyspace-group-id", t.keyspaceGroupID),
 				zap.String("dc-location", t.dcLocation),
 				zap.String("timestamp-path", t.GetTimestampPath()),
 				zap.Error(err))
@@ -388,6 +397,7 @@ func (t *timestampOracle) getTS(ctx context.Context, leadership *election.Leader
 		}
 		if resp.GetLogical() >= maxLogical {
 			log.Warn("logical part outside of max logical interval, please check ntp time, or adjust config item `tso-update-physical-interval`",
+				zap.Uint32("keyspace-group-id", t.keyspaceGroupID),
 				zap.Reflect("response", resp),
 				zap.Int("retry-count", i), errs.ZapError(errs.ErrLogicOverflow))
 			t.metrics.logicalOverflowEvent.Inc()
@@ -409,7 +419,7 @@ func (t *timestampOracle) getTS(ctx context.Context, leadership *election.Leader
 func (t *timestampOracle) ResetTimestamp() {
 	t.tsoMux.Lock()
 	defer t.tsoMux.Unlock()
-	log.Info("reset the timestamp in memory")
+	log.Info("reset the timestamp in memory", zap.Uint32("keyspace-group-id", t.keyspaceGroupID))
 	t.tsoMux.physical = typeutil.ZeroTime
 	t.tsoMux.logical = 0
 	t.tsoMux.updateTime = typeutil.ZeroTime