Add debug log

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

client/tso_batch_controller.go

@@ -118,7 +118,7 @@ fetchPendingRequestsLoop:
 func (tbc *tsoBatchController) pushRequest(tsoReq *tsoRequest, beforeReceiveDurationHist *AutoDumpHistogram, now time.Time) {
 	tbc.collectedRequests[tbc.collectedRequestCount] = tsoReq
 	tbc.collectedRequestCount++
-	beforeReceiveDurationHist.Observe(math.Max(now.Sub(tsoReq.start).Seconds(), 0), now)
+	beforeReceiveDurationHist.Observe(math.Max(now.Sub(tsoReq.start2).Seconds(), 0), now)
 }
 
 func (tbc *tsoBatchController) getCollectedRequests() []*tsoRequest {
@@ -150,7 +150,11 @@ func (tbc *tsoBatchController) finishCollectedRequestsWithStatFunc(physical, fir
 		tsoReq.physical, tsoReq.logical = physical, tsoutil.AddLogical(firstLogical, int64(i), suffixBits)
 		tsoReq.tryDone(err)
 		if statFunc != nil {
-			statFunc(now.Sub(tsoReq.start), now)
+			if now.Before(tsoReq.start2) {
+				log.Error("negative request time", zap.Time("now", now), zap.Time("reqStart", tsoReq.start2), zap.Time("batchStart", tbc.batchStartTime))
+			} else {
+				statFunc(now.Sub(tsoReq.start2), now)
+			}
 		}
 		trace.StartRegion(requestCtx, "pdclient.tsoReqDequeue").End()
 	}

client/tso_client.go

@@ -194,7 +194,7 @@ func (c *tsoClient) allowTSOFollowerProxy(dc string) bool {
 func (c *tsoClient) getTSORequest(ctx context.Context, dcLocation string) *tsoRequest {
 	req := c.tsoReqPool.Get().(*tsoRequest)
 	// Set needed fields in the request before using it.
-	req.start = time.Now()
+	req.start2 = time.Now()
 	req.pool = c.tsoReqPool
 	req.requestCtx = ctx
 	req.clientCtx = c.ctx

client/tso_request.go

@@ -43,8 +43,8 @@ type tsoRequest struct {
 	dcLocation string
 
 	// Runtime fields.
-	start time.Time
-	pool  *sync.Pool
+	start2 time.Time
+	pool   *sync.Pool
 }
 
 // tryDone tries to send the result to the channel, it will not block.
@@ -60,20 +60,20 @@ func (req *tsoRequest) Wait() (physical int64, logical int64, err error) {
 	// If tso command duration is observed very high, the reason could be it
 	// takes too long for Wait() be called.
 	start := time.Now()
-	cmdDurationTSOAsyncWait.Observe(start.Sub(req.start).Seconds())
+	cmdDurationTSOAsyncWait.Observe(start.Sub(req.start2).Seconds())
 	select {
 	case err = <-req.done:
 		defer req.pool.Put(req)
 		defer trace.StartRegion(req.requestCtx, "pdclient.tsoReqDone").End()
 		err = errors.WithStack(err)
 		if err != nil {
-			cmdFailDurationTSO.Observe(time.Since(req.start).Seconds())
+			cmdFailDurationTSO.Observe(time.Since(req.start2).Seconds())
 			return 0, 0, err
 		}
 		physical, logical = req.physical, req.logical
 		now := time.Now()
 		cmdDurationWait.Observe(now.Sub(start).Seconds())
-		cmdDurationTSO.Observe(now.Sub(req.start).Seconds())
+		cmdDurationTSO.Observe(now.Sub(req.start2).Seconds())
 		return
 	case <-req.requestCtx.Done():
 		return 0, 0, errors.WithStack(req.requestCtx.Err())