diff --git a/pkg/tso/tso.go b/pkg/tso/tso.go index 93392cecfcf6..13ed92930d3c 100644 --- a/pkg/tso/tso.go +++ b/pkg/tso/tso.go @@ -156,6 +156,7 @@ func (t *timestampOracle) GetTimestampPath() string { // SyncTimestamp is used to synchronize the timestamp. func (t *timestampOracle) SyncTimestamp(leadership *election.Leadership) error { + log.Info("start to sync timestamp", zap.Uint32("keyspace-group-id", t.keyspaceGroupID)) t.metrics.syncEvent.Inc() failpoint.Inject("delaySyncTimestamp", func() { @@ -167,9 +168,11 @@ 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 { + log.Info("skip sync timestamp", zap.Uint32("keyspace-group-id", t.keyspaceGroupID)) t.metrics.skipSyncEvent.Inc() return nil } @@ -185,7 +188,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 +206,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 +320,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 +339,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 +356,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 +399,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 +421,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