From 9fdf362a6a7b5cd9b7f4c5bbf91c25b46a686b3c Mon Sep 17 00:00:00 2001
From: Ti Chi Robot <ti-community-prow-bot@tidb.io>
Date: Wed, 11 Oct 2023 12:30:25 +0800
Subject: [PATCH] autoid_service: add some debug log for rebase related
 operation (#46526) (#46530)

ref pingcap/tidb#46444
---
 autoid_service/autoid.go | 35 ++++++++++++++++++++++++++++++++++-
 1 file changed, 34 insertions(+), 1 deletion(-)

diff --git a/autoid_service/autoid.go b/autoid_service/autoid.go
index 5e3a3e02fec9f..37b143a64c94e 100644
--- a/autoid_service/autoid.go
+++ b/autoid_service/autoid.go
@@ -188,6 +188,7 @@ func (alloc *autoIDValue) rebase4Unsigned(ctx context.Context,
 	}
 
 	var newBase, newEnd uint64
+	var oldValue int64
 	startTime := time.Now()
 	ctx = kv.WithInternalSourceType(ctx, kv.InternalTxnMeta)
 	err := kv.RunInNewTxn(ctx, store, true, func(ctx context.Context, txn kv.Transaction) error {
@@ -196,6 +197,7 @@ func (alloc *autoIDValue) rebase4Unsigned(ctx context.Context,
 		if err1 != nil {
 			return err1
 		}
+		oldValue = currentEnd
 		uCurrentEnd := uint64(currentEnd)
 		newBase = mathutil.Max(uCurrentEnd, requiredBase)
 		newEnd = mathutil.Min(math.MaxUint64-uint64(batch), newBase) + uint64(batch)
@@ -206,6 +208,13 @@ func (alloc *autoIDValue) rebase4Unsigned(ctx context.Context,
 	if err != nil {
 		return err
 	}
+
+	logutil.BgLogger().Info("rebase4Unsigned from",
+		zap.String("category", "autoid service"),
+		zap.Int64("dbID", dbID),
+		zap.Int64("tblID", tblID),
+		zap.Int64("from", oldValue),
+		zap.Uint64("to", newEnd))
 	alloc.base, alloc.end = int64(newBase), int64(newEnd)
 	return nil
 }
@@ -221,7 +230,8 @@ func (alloc *autoIDValue) rebase4Signed(ctx context.Context, store kv.Storage, d
 		return nil
 	}
 
-	var newBase, newEnd int64
+	var oldValue, newBase, newEnd int64
+	startTime := time.Now()
 	ctx = kv.WithInternalSourceType(ctx, kv.InternalTxnMeta)
 	err := kv.RunInNewTxn(ctx, store, true, func(ctx context.Context, txn kv.Transaction) error {
 		idAcc := meta.NewMeta(txn).GetAutoIDAccessors(dbID, tblID).IncrementID(model.TableInfoVersion5)
@@ -229,14 +239,23 @@ func (alloc *autoIDValue) rebase4Signed(ctx context.Context, store kv.Storage, d
 		if err1 != nil {
 			return err1
 		}
+		oldValue = currentEnd
 		newBase = mathutil.Max(currentEnd, requiredBase)
 		newEnd = mathutil.Min(math.MaxInt64-batch, newBase) + batch
 		_, err1 = idAcc.Inc(newEnd - currentEnd)
 		return err1
 	})
+	metrics.AutoIDHistogram.WithLabelValues(metrics.TableAutoIDRebase, metrics.RetLabel(err)).Observe(time.Since(startTime).Seconds())
 	if err != nil {
 		return err
 	}
+
+	logutil.BgLogger().Info("rebase4Signed from",
+		zap.Int64("dbID", dbID),
+		zap.Int64("tblID", tblID),
+		zap.Int64("from", oldValue),
+		zap.Int64("to", newEnd),
+		zap.String("category", "autoid service"))
 	alloc.base, alloc.end = newBase, newEnd
 	return nil
 }
@@ -277,6 +296,11 @@ func New(selfAddr string, etcdAddr []string, store kv.Storage, tlsConfig *tls.Co
 
 func newWithCli(selfAddr string, cli *clientv3.Client, store kv.Storage) *Service {
 	l := owner.NewOwnerManager(context.Background(), cli, "autoid", selfAddr, autoIDLeaderPath)
+	l.SetBeOwnerHook(func() {
+		logutil.BgLogger().Info("leader change of autoid service, this node become owner",
+			zap.String("addr", selfAddr),
+			zap.String("category", "autoid service"))
+	})
 	// 10 means that autoid service's etcd lease is 10s.
 	err := l.CampaignOwner(10)
 	if err != nil {
@@ -471,12 +495,14 @@ func (s *Service) allocAutoID(ctx context.Context, req *autoid.AutoIDRequest) (*
 
 func (alloc *autoIDValue) forceRebase(ctx context.Context, store kv.Storage, dbID, tblID, requiredBase int64, isUnsigned bool) error {
 	ctx = kv.WithInternalSourceType(ctx, kv.InternalTxnMeta)
+	var oldValue int64
 	err := kv.RunInNewTxn(ctx, store, true, func(ctx context.Context, txn kv.Transaction) error {
 		idAcc := meta.NewMeta(txn).GetAutoIDAccessors(dbID, tblID).IncrementID(model.TableInfoVersion5)
 		currentEnd, err1 := idAcc.Get()
 		if err1 != nil {
 			return err1
 		}
+		oldValue = currentEnd
 		var step int64
 		if !isUnsigned {
 			step = requiredBase - currentEnd
@@ -490,6 +516,13 @@ func (alloc *autoIDValue) forceRebase(ctx context.Context, store kv.Storage, dbI
 	if err != nil {
 		return err
 	}
+	logutil.BgLogger().Info("forceRebase from",
+		zap.Int64("dbID", dbID),
+		zap.Int64("tblID", tblID),
+		zap.Int64("from", oldValue),
+		zap.Int64("to", requiredBase),
+		zap.Bool("isUnsigned", isUnsigned),
+		zap.String("category", "autoid service"))
 	alloc.base, alloc.end = requiredBase, requiredBase
 	return nil
 }