store/tikv:Ignore error and do gc anyway

store/tikv/backoff.go

@@ -148,7 +148,7 @@ const (
 	getMaxBackoff           = 20000
 	prewriteMaxBackoff      = 20000
 	cleanupMaxBackoff       = 20000
-	GcMaxBackoff            = 100000
+	GcOneRegionMaxBackoff   = 20000
 	GcResolveLockMaxBackoff = 100000
 	GcDeleteRangeMaxBackoff = 100000
 	rawkvMaxBackoff         = 20000

store/tikv/client.go

@@ -52,6 +52,7 @@ const (
 	readTimeoutShort  = 20 * time.Second  // For requests that read/write several key-values.
 	ReadTimeoutMedium = 60 * time.Second  // For requests that may need scan region.
 	ReadTimeoutLong   = 150 * time.Second // For requests that may need scan region multiple times.
+	GCTimeout         = 5 * time.Minute
 
 	grpcInitialWindowSize     = 1 << 30
 	grpcInitialConnWindowSize = 1 << 30

store/tikv/gcworker/gc_worker.go

@@ -22,6 +22,7 @@ import (
 	"time"
 
 	"github.com/juju/errors"
+	"github.com/pingcap/kvproto/pkg/errorpb"
 	"github.com/pingcap/kvproto/pkg/kvrpcpb"
 	"github.com/pingcap/tidb"
 	"github.com/pingcap/tidb/ddl/util"
@@ -90,6 +91,7 @@ func (w *GCWorker) Close() {
 const (
 	gcTimeFormat         = "20060102-15:04:05 -0700 MST"
 	gcWorkerTickInterval = time.Minute
+	gcJobLogTickInterval = time.Minute * 10
 	gcWorkerLease        = time.Minute * 2
 	gcLeaderUUIDKey      = "tikv_gc_leader_uuid"
 	gcLeaderDescKey      = "tikv_gc_leader_desc"
@@ -327,7 +329,6 @@ func (w *GCWorker) runGCJob(ctx goctx.Context, safePoint uint64) {
 	}
 	err = doGC(ctx, w.store, safePoint, w.uuid)
 	if err != nil {
-		gcFailureCounter.WithLabelValues("gc").Inc()
 		log.Error("do GC returns an error", err)
 		w.gcIsRunning = false
 		w.done <- errors.Trace(err)
@@ -346,7 +347,7 @@ func (w *GCWorker) deleteRanges(ctx goctx.Context, safePoint uint64) error {
 		return errors.Trace(err)
 	}
 
-	bo := tikv.NewBackoffer(tikv.GcDeleteRangeMaxBackoff, goctx.Background())
+	bo := tikv.NewBackoffer(tikv.GcDeleteRangeMaxBackoff, ctx)
 	log.Infof("[gc worker] %s start delete %v ranges", w.uuid, len(ranges))
 	startTime := time.Now()
 	regions := 0
@@ -430,7 +431,7 @@ func resolveLocks(ctx goctx.Context, store tikv.Storage, safePoint uint64, ident
 			Limit:      gcScanLockLimit,
 		},
 	}
-	bo := tikv.NewBackoffer(tikv.GcResolveLockMaxBackoff, goctx.Background())
+	bo := tikv.NewBackoffer(tikv.GcResolveLockMaxBackoff, ctx)
 
 	log.Infof("[gc worker] %s start resolve locks, safePoint: %v.", identifier, safePoint)
 	startTime := time.Now()
@@ -515,63 +516,95 @@ func doGC(ctx goctx.Context, store tikv.Storage, safePoint uint64, identifier st
 	// Sleep to wait for all other tidb instances update their safepoint cache.
 	time.Sleep(gcSafePointCacheInterval)
 
+	log.Infof("[gc worker] %s start gc, safePoint: %v.", identifier, safePoint)
+	startTime := time.Now()
+	regions := 0
+	errRegions := 0
+
+	ticker := time.NewTicker(gcJobLogTickInterval)
+	defer ticker.Stop()
+
 	req := &tikvrpc.Request{
 		Type: tikvrpc.CmdGC,
 		GC: &kvrpcpb.GCRequest{
 			SafePoint: safePoint,
 		},
 	}
-	bo := tikv.NewBackoffer(tikv.GcMaxBackoff, goctx.Background())
-
-	log.Infof("[gc worker] %s start gc, safePoint: %v.", identifier, safePoint)
-	startTime := time.Now()
-	regions := 0
 
+	bo := tikv.NewBackoffer(tikv.GcOneRegionMaxBackoff, ctx)
 	var key []byte
 	for {
 		select {
 		case <-ctx.Done():
 			return errors.New("[gc worker] gc job canceled")
+		case <-ticker.C:
+			log.Infof("[gc worker] %s gc in process, safePoint: %v, regions: %v, ignored regions: %v, cost time: %s",
+				identifier, safePoint, regions, errRegions, time.Since(startTime))
 		default:
 		}
 
 		loc, err := store.GetRegionCache().LocateKey(bo, key)
 		if err != nil {
 			return errors.Trace(err)
 		}
-		resp, err := store.SendReq(bo, req, loc.Region, tikv.ReadTimeoutLong)
-		if err != nil {
-			return errors.Trace(err)
-		}
-		regionErr, err := resp.GetRegionError()
-		if err != nil {
-			return errors.Trace(err)
-		}
+
+		var regionErr *errorpb.Error
+		regionErr, err = doGCForOneRegion(bo, store, req, loc.Region)
+
+		// we check regionErr here first, because we know 'regionErr' and 'err' should not return together, to keep it to
+		// make the process correct.
 		if regionErr != nil {
 			err = bo.Backoff(tikv.BoRegionMiss, errors.New(regionErr.String()))
-			if err != nil {
-				return errors.Trace(err)
+			if err == nil {
+				continue
 			}
-			continue
-		}
-		gcResp := resp.GC
-		if gcResp == nil {
-			return errors.Trace(tikv.ErrBodyMissing)
 		}
-		if gcResp.GetError() != nil {
-			return errors.Errorf("unexpected gc error: %s", gcResp.GetError())
+
+		if err != nil {
+			errRegions++
+			log.Warnf("[gc worker] %s failed to do gc on region(%s, %s), ignore it", identifier, string(loc.StartKey), string(loc.EndKey))
+			gcFailureCounter.WithLabelValues("gc").Inc()
+		} else {
+			regions++
 		}
-		regions++
+
 		key = loc.EndKey
 		if len(key) == 0 {
 			break
 		}
+		bo = tikv.NewBackoffer(tikv.GcOneRegionMaxBackoff, ctx)
 	}
-	log.Infof("[gc worker] %s finish gc, safePoint: %v, regions: %v, cost time: %s", identifier, safePoint, regions, time.Since(startTime))
+	log.Infof("[gc worker] %s finish gc, safePoint: %v, regions: %v, ignored regions: %v, cost time: %s",
+		identifier, safePoint, regions, errRegions, time.Since(startTime))
 	gcHistogram.WithLabelValues("do_gc").Observe(time.Since(startTime).Seconds())
 	return nil
 }
 
+// these two errors should not return together, for more, see the func 'doGC'
+func doGCForOneRegion(bo *tikv.Backoffer, store tikv.Storage, req *tikvrpc.Request, region tikv.RegionVerID) (*errorpb.Error, error) {
+	resp, err := store.SendReq(bo, req, region, tikv.GCTimeout)
+	if err != nil {
+		return nil, errors.Trace(err)
+	}
+	regionErr, err := resp.GetRegionError()
+	if err != nil {
+		return nil, errors.Trace(err)
+	}
+	if regionErr != nil {
+		return regionErr, nil
+	}
+
+	gcResp := resp.GC
+	if gcResp == nil {
+		return nil, errors.Trace(tikv.ErrBodyMissing)
+	}
+	if gcResp.GetError() != nil {
+		return nil, errors.Errorf("unexpected gc error: %s", gcResp.GetError())
+	}
+
+	return nil, nil
+}
+
 func (w *GCWorker) checkLeader() (bool, error) {
 	gcWorkerCounter.WithLabelValues("check_leader").Inc()
 	session := createSession(w.store)