From 0f8ee9df485b55d2d784dc6823e174a0c0952846 Mon Sep 17 00:00:00 2001
From: crazycs <crazycs520@gmail.com>
Date: Tue, 25 Sep 2018 13:26:29 +0800
Subject: [PATCH] metric: add slow log metric (#7759)

---
 executor/adapter.go |  7 ++++++-
 metrics/metrics.go  |  3 +++
 metrics/server.go   | 25 +++++++++++++++++++++++++
 3 files changed, 34 insertions(+), 1 deletion(-)

diff --git a/executor/adapter.go b/executor/adapter.go
index 4de4b8f571a1d..7cc90cc84001e 100644
--- a/executor/adapter.go
+++ b/executor/adapter.go
@@ -25,6 +25,7 @@ import (
 	"github.com/pingcap/tidb/expression"
 	"github.com/pingcap/tidb/infoschema"
 	"github.com/pingcap/tidb/kv"
+	"github.com/pingcap/tidb/metrics"
 	"github.com/pingcap/tidb/model"
 	"github.com/pingcap/tidb/mysql"
 	plannercore "github.com/pingcap/tidb/planner/core"
@@ -369,9 +370,13 @@ func (a *ExecStmt) logSlowQuery(txnTS uint64, succ bool) {
 			"[QUERY] %vcost_time:%v %s succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
 			internal, costTime, sessVars.StmtCtx.GetExecDetails(), succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
 	} else {
+		execDetail := sessVars.StmtCtx.GetExecDetails()
 		logutil.SlowQueryLogger.Warnf(
 			"[SLOW_QUERY] %vcost_time:%v %s succ:%v con:%v user:%s txn_start_ts:%v database:%v %v%vsql:%v",
-			internal, costTime, sessVars.StmtCtx.GetExecDetails(), succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
+			internal, costTime, execDetail, succ, connID, user, txnTS, currentDB, tableIDs, indexIDs, sql)
+		metrics.TotalQueryProcHistogram.Observe(costTime.Seconds())
+		metrics.TotalCopProcHistogram.Observe(execDetail.ProcessTime.Seconds())
+		metrics.TotalCopWaitHistogram.Observe(execDetail.WaitTime.Seconds())
 		var userString string
 		if user != nil {
 			userString = user.String()
diff --git a/metrics/metrics.go b/metrics/metrics.go
index d8ef356ee7d4e..ef822d4b8a668 100644
--- a/metrics/metrics.go
+++ b/metrics/metrics.go
@@ -126,4 +126,7 @@ func RegisterMetrics() {
 	prometheus.MustRegister(GCRegionTooManyLocksCounter)
 	prometheus.MustRegister(GCWorkerCounter)
 	prometheus.MustRegister(TSFutureWaitDuration)
+	prometheus.MustRegister(TotalQueryProcHistogram)
+	prometheus.MustRegister(TotalCopProcHistogram)
+	prometheus.MustRegister(TotalCopWaitHistogram)
 }
diff --git a/metrics/server.go b/metrics/server.go
index caa99a632f33e..e8417274d2775 100644
--- a/metrics/server.go
+++ b/metrics/server.go
@@ -120,6 +120,31 @@ var (
 			Help:      "Duration (us) for getting token, it should be small until concurrency limit is reached.",
 			Buckets:   prometheus.ExponentialBuckets(1, 2, 22), // 1us ~ 2s
 		})
+
+	TotalQueryProcHistogram = prometheus.NewHistogram(
+		prometheus.HistogramOpts{
+			Namespace: "tidb",
+			Subsystem: "server",
+			Name:      "slow_query_process_duration_seconds",
+			Help:      "Bucketed histogram of processing time (s) of of slow queries.",
+			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 22), // 1ms ~ 4096s
+		})
+	TotalCopProcHistogram = prometheus.NewHistogram(
+		prometheus.HistogramOpts{
+			Namespace: "tidb",
+			Subsystem: "server",
+			Name:      "slow_query_cop_duration_seconds",
+			Help:      "Bucketed histogram of all cop processing time (s) of of slow queries.",
+			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 22),
+		})
+	TotalCopWaitHistogram = prometheus.NewHistogram(
+		prometheus.HistogramOpts{
+			Namespace: "tidb",
+			Subsystem: "server",
+			Name:      "slow_query_wait_duration_seconds",
+			Help:      "Bucketed histogram of all cop waiting time (s) of of slow queries.",
+			Buckets:   prometheus.ExponentialBuckets(0.001, 2, 22),
+		})
 )
 
 // ExecuteErrorToLabel converts an execute error to label.