diff --git a/pkg/drivers/generic/generic.go b/pkg/drivers/generic/generic.go index c76db0e8..7ba892f2 100644 --- a/pkg/drivers/generic/generic.go +++ b/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 diff --git a/pkg/drivers/generic/tx.go b/pkg/drivers/generic/tx.go index 166af372..8a70c16f 100644 --- a/pkg/drivers/generic/tx.go +++ b/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...) } diff --git a/pkg/drivers/generic/util.go b/pkg/drivers/generic/util.go new file mode 100644 index 00000000..4fd19950 --- /dev/null +++ b/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) + } +}