Feat: automatically log slow sql executions

pkg/drivers/generic/generic.go

@@ -239,11 +239,15 @@ func Open(ctx context.Context, driverName, dataSourceName string, connPoolConfig
 
 func (d *Generic) query(ctx context.Context, sql string, args ...interface{}) (*sql.Rows, error) {
 	logrus.Tracef("QUERY %v : %s", args, Stripped(sql))
+	trace := NewTrace()
+	defer trace.LogSlowSQL(Stripped(sql), args)
 	return d.DB.QueryContext(ctx, sql, args...)
 }
 
 func (d *Generic) queryRow(ctx context.Context, sql string, args ...interface{}) *sql.Row {
 	logrus.Tracef("QUERY ROW %v : %s", args, Stripped(sql))
+	trace := NewTrace()
+	defer trace.LogSlowSQL(Stripped(sql), args)
 	return d.DB.QueryRowContext(ctx, sql, args...)
 }
 
@@ -256,7 +260,9 @@ func (d *Generic) execute(ctx context.Context, sql string, args ...interface{})
 	wait := strategy.Backoff(backoff.Linear(100 + time.Millisecond))
 	for i := uint(0); i < 20; i++ {
 		logrus.Tracef("EXEC (try: %d) %v : %s", i, args, Stripped(sql))
+		trace := NewTrace()
 		result, err = d.DB.ExecContext(ctx, sql, args...)
+		trace.LogSlowSQL(Stripped(sql), args)
 		if err != nil && d.Retry != nil && d.Retry(err) {
 			wait(i)
 			continue

pkg/drivers/generic/tx.go

@@ -95,15 +95,21 @@ func (t *Tx) CurrentRevision(ctx context.Context) (int64, error) {
 
 func (t *Tx) query(ctx context.Context, sql string, args ...interface{}) (*sql.Rows, error) {
 	logrus.Tracef("TX QUERY %v : %s", args, Stripped(sql))
+	trace := NewTrace()
+	defer trace.LogSlowSQL(Stripped(sql), args)
 	return t.x.QueryContext(ctx, sql, args...)
 }
 
 func (t *Tx) queryRow(ctx context.Context, sql string, args ...interface{}) *sql.Row {
 	logrus.Tracef("TX QUERY ROW %v : %s", args, Stripped(sql))
+	trace := NewTrace()
+	defer trace.LogSlowSQL(Stripped(sql), args)
 	return t.x.QueryRowContext(ctx, sql, args...)
 }
 
 func (t *Tx) execute(ctx context.Context, sql string, args ...interface{}) (result sql.Result, err error) {
 	logrus.Tracef("TX EXEC %v : %s", args, Stripped(sql))
+	trace := NewTrace()
+	defer trace.LogSlowSQL(Stripped(sql), args)
 	return t.x.ExecContext(ctx, sql, args...)
 }

pkg/drivers/generic/util.go

@@ -0,0 +1,26 @@
+package generic
+
+import (
+	"time"
+
+	"github.com/sirupsen/logrus"
+)
+
+const (
+	slowSQLThreshold = time.Second
+)
+
+type Trace struct {
+	startTime time.Time
+}
+
+func NewTrace() *Trace {
+	return &Trace{startTime: time.Now()}
+}
+
+func (t *Trace) LogSlowSQL(sql Stripped, args ...interface{}) {
+	totalTime := time.Since(t.startTime)
+	if totalTime >= slowSQLThreshold {
+		logrus.Infof("Slow SQL (started: %v) (total time: %v): %s : %v", t.startTime, totalTime, sql, args)
+	}
+}