diff --git a/pkg/sqlutil/monitor.go b/pkg/sqlutil/monitor.go index c9b29b9c0e..27c6ab074a 100644 --- a/pkg/sqlutil/monitor.go +++ b/pkg/sqlutil/monitor.go @@ -116,22 +116,37 @@ func (q *queryLogger) logError(err error) { q.lggr.Errorw("SQL ERROR", "err", err, "sql", q) } -// logTiming logs about context cancellation and timing after a query returns. -// Queries which use their full timeout log critical level. More than 50% log error, and 10% warn. +// logTiming logs about context errors and timing. Queries which use their full timeout log critical level. More than 50% log error, and 10% warn. +// To be deferred to run after a query returns. func (q *queryLogger) logTiming(ctx context.Context, start time.Time) { elapsed := time.Since(start) - if ctx.Err() != nil { - q.lggr.Debugw("SQL CONTEXT CANCELLED", "ms", elapsed.Milliseconds(), "err", ctx.Err(), "sql", q) + + if err := ctx.Err(); err != nil { + if errors.Is(err, context.Canceled) { + q.lggr.Debugw("SQL Context Canceled", "ms", elapsed.Milliseconds(), "err", context.Cause(ctx), "sql", q) + return + } else if !errors.Is(err, context.DeadlineExceeded) { + q.lggr.Debugw("SQL Context Error", "ms", elapsed.Milliseconds(), "err", err, "sql", q) + return + } + q.lggr.Debugw("SQL Deadline Exceeded", "ms", elapsed.Milliseconds(), "err", err, "sql", q) } + // Success or Deadline Exceeded, so calculate how much of the timeout was used. deadline, ok := ctx.Deadline() if !ok { return } timeout := deadline.Sub(start) - pct := float64(elapsed) / float64(timeout) - pct *= 100 + var pct float64 // percent of timeout used + if timeout > 0 { + pct = float64(elapsed) / float64(timeout) + pct *= 100 + } else { + timeout = 0 + pct = 100 + } kvs := []any{"ms", elapsed.Milliseconds(), "timeout", timeout.Milliseconds(), "percent", strconv.FormatFloat(pct, 'f', 1, 64), "sql", q}