diff --git a/client/tso_batch_controller.go b/client/tso_batch_controller.go index a91f434f8dd2..f44b597391d5 100644 --- a/client/tso_batch_controller.go +++ b/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() } diff --git a/client/tso_client.go b/client/tso_client.go index 8b51c48d276d..90d3287c2e17 100644 --- a/client/tso_client.go +++ b/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 diff --git a/client/tso_request.go b/client/tso_request.go index b912fa354973..ba9af1d2c9ba 100644 --- a/client/tso_request.go +++ b/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())