metric: add slow log metric (#7759)

pingcap · Sep 25, 2018 · 0f8ee9d · 0f8ee9d
1 parent 869e201
commit 0f8ee9d
Show file tree

Hide file tree

Showing 3 changed files with 34 additions and 1 deletion.
diff --git 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
@@ -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
@@ -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.