*: add metrics for sycner query; add slow log

pingcap · Apr 9, 2020 · 7c9890b · 7c9890b
1 parent 15f7a6f
commit 7c9890b
Show file tree

Hide file tree

Showing 3 changed files with 31 additions and 3 deletions.
diff --git a/loader/db.go b/loader/db.go
@@ -163,7 +163,10 @@ func (conn *DBConn) executeSQL(ctx *tcontext.Context, queries []string, args ...
 				cost := time.Since(startTime)
 				txnHistogram.WithLabelValues(conn.cfg.Name).Observe(cost.Seconds())
 				if cost.Seconds() > 1 {
-					ctx.L().Warn("transaction execute successfully", zap.Duration("cost time", cost))
+					ctx.L().Warn("execute transaction",
+						zap.String("query", utils.TruncateInterface(queries, -1)),
+						zap.String("argument", utils.TruncateInterface(args, -1)),
+						zap.Duration("cost time", cost))
 				}
 			}
 			return nil, err

diff --git a/syncer/db.go b/syncer/db.go
@@ -200,7 +200,19 @@ func (conn *DBConn) querySQL(tctx *tcontext.Context, query string, args ...inter
 		tctx,
 		params,
 		func(ctx *tcontext.Context) (interface{}, error) {
-			return conn.baseConn.QuerySQL(ctx, query, args...)
+			startTime := time.Now()
+			ret, err := conn.baseConn.QuerySQL(ctx, query, args...)
+			if err == nil {
+				cost := time.Since(startTime)
+				queryHistogram.WithLabelValues(conn.cfg.Name).Observe(cost.Seconds())
+				if cost.Seconds() > 1 {
+					ctx.L().Warn("query statement",
+						zap.String("query", utils.TruncateString(query, -1)),
+						zap.String("argument", utils.TruncateInterface(args, -1)),
+						zap.Duration("cost time", cost))
+				}
+			}
+			return ret, err
 		},
 	)
 
@@ -270,7 +282,10 @@ func (conn *DBConn) executeSQLWithIgnore(tctx *tcontext.Context, ignoreError fun
 				cost := time.Since(startTime)
 				txnHistogram.WithLabelValues(conn.cfg.Name).Observe(cost.Seconds())
 				if cost.Seconds() > 1 {
-					ctx.L().Warn("transaction execute successfully", zap.Duration("cost time", cost))
+					ctx.L().Warn("execute transaction",
+						zap.String("query", utils.TruncateInterface(queries, -1)),
+						zap.String("argument", utils.TruncateInterface(args, -1)),
+						zap.Duration("cost time", cost))
 				}
 			}
 			return ret, err

diff --git a/syncer/metrics.go b/syncer/metrics.go
@@ -129,6 +129,15 @@ var (
 			Buckets:   prometheus.ExponentialBuckets(0.0005, 2, 18),
 		}, []string{"task"})
 
+	queryHistogram = prometheus.NewHistogramVec(
+		prometheus.HistogramOpts{
+			Namespace: "dm",
+			Subsystem: "syncer",
+			Name:      "query_duration_time",
+			Help:      "Bucketed histogram of query time (s).",
+			Buckets:   prometheus.ExponentialBuckets(0.0005, 2, 18),
+		}, []string{"task"})
+
 	// FIXME: should I move it to dm-worker?
 	cpuUsageGauge = prometheus.NewGauge(
 		prometheus.GaugeOpts{
@@ -195,6 +204,7 @@ func RegisterMetrics(registry *prometheus.Registry) {
 	registry.MustRegister(binlogPosGauge)
 	registry.MustRegister(binlogFileGauge)
 	registry.MustRegister(txnHistogram)
+	registry.MustRegister(queryHistogram)
 	registry.MustRegister(cpuUsageGauge)
 	registry.MustRegister(syncerExitWithErrorCounter)
 	registry.MustRegister(replicationLagGauge)