*: make grpc request duration more accurate (#253)

Signed-off-by: Shuaipeng Yu <jackysp@gmail.com>

internal/client/client.go

@@ -353,15 +353,6 @@ func (c *RPCClient) SendRequest(ctx context.Context, addr string, req *tikvrpc.R
 	}
 
 	start := time.Now()
-	defer func() {
-		stmtExec := ctx.Value(util.ExecDetailsKey)
-		if stmtExec != nil {
-			detail := stmtExec.(*util.ExecDetails)
-			atomic.AddInt64(&detail.WaitKVRespDuration, int64(time.Since(start)))
-		}
-		c.updateTiKVSendReqHistogram(req, start)
-	}()
-
 	if atomic.CompareAndSwapUint32(&c.idleNotify, 1, 0) {
 		c.recycleMu.Lock()
 		c.recycleIdleConnArray()
@@ -376,6 +367,17 @@ func (c *RPCClient) SendRequest(ctx context.Context, addr string, req *tikvrpc.R
 	if err != nil {
 		return nil, errors.Trace(err)
 	}
+	metrics.TiKVBatchClientRecycle.Observe(time.Since(start).Seconds())
+
+	start = time.Now()
+	defer func() {
+		stmtExec := ctx.Value(util.ExecDetailsKey)
+		if stmtExec != nil {
+			detail := stmtExec.(*util.ExecDetails)
+			atomic.AddInt64(&detail.WaitKVRespDuration, int64(time.Since(start)))
+		}
+		c.updateTiKVSendReqHistogram(req, start)
+	}()
 
 	// TiDB RPC server supports batch RPC, but batch connection will send heart beat, It's not necessary since
 	// request to TiDB is not high frequency.

metrics/metrics.go

@@ -63,6 +63,7 @@ var (
 	TiKVBatchRequests                        *prometheus.HistogramVec
 	TiKVBatchClientUnavailable               prometheus.Histogram
 	TiKVBatchClientWaitEstablish             prometheus.Histogram
+	TiKVBatchClientRecycle                   prometheus.Histogram
 	TiKVRangeTaskStats                       *prometheus.GaugeVec
 	TiKVRangeTaskPushDuration                *prometheus.HistogramVec
 	TiKVTokenWaitDuration                    prometheus.Histogram
@@ -316,6 +317,15 @@ func initMetrics(namespace, subsystem string) {
 			Help:      "batch client wait new connection establish",
 		})
 
+	TiKVBatchClientRecycle = prometheus.NewHistogram(
+		prometheus.HistogramOpts{
+			Namespace: namespace,
+			Subsystem: subsystem,
+			Name:      "batch_client_reset",
+			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 28), // 1ms ~ 1.5days
+			Help:      "batch client recycle connection and reconnect duration",
+		})
+
 	TiKVRangeTaskStats = prometheus.NewGaugeVec(
 		prometheus.GaugeOpts{
 			Namespace: namespace,
@@ -547,6 +557,7 @@ func RegisterMetrics() {
 	prometheus.MustRegister(TiKVBatchRequests)
 	prometheus.MustRegister(TiKVBatchClientUnavailable)
 	prometheus.MustRegister(TiKVBatchClientWaitEstablish)
+	prometheus.MustRegister(TiKVBatchClientRecycle)
 	prometheus.MustRegister(TiKVRangeTaskStats)
 	prometheus.MustRegister(TiKVRangeTaskPushDuration)
 	prometheus.MustRegister(TiKVTokenWaitDuration)