diff --git a/loader/db.go b/loader/db.go index 3b61fac69c..52ebbc91a4 100644 --- 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 index 64963c606f..77b7b0b3e1 100644 --- 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 index 5a0123e6e9..12b36b80e0 100644 --- 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)