Skip to content

Commit

Permalink
sql: fix inflated "overhead" in statement timings
Browse files Browse the repository at this point in the history
Fixes #40675
Fixes #50108

Release justification: Low-risk, high-reward fix to existing
functionality.

Release note (admin ui change): In some cases, the Execution Stats page
would show a confusingly high Overhead latency for a statement. This
could happen due to multiple statements being parsed together or due to
statement execution being retried. To avoid this, we stop considering
the time between when parsing ends and execution begins when determining
service latency.
  • Loading branch information
solongordon committed Sep 2, 2020
1 parent 9e4387f commit 6371d37
Showing 1 changed file with 8 additions and 1 deletion.
9 changes: 8 additions & 1 deletion pkg/sql/executor_statement_metrics.go
Original file line number Diff line number Diff line change
Expand Up @@ -67,7 +67,14 @@ type phaseTimes [sessionNumPhases]time.Time
// getServiceLatency returns the time between a query being received and the end
// of run.
func (p *phaseTimes) getServiceLatency() time.Duration {
return p[plannerEndExecStmt].Sub(p[sessionQueryReceived])
// To have an accurate representation of how long it took to service this
// single query, we ignore the time between when parsing ends and planning
// begins. This avoids the latency being inflated in a few different cases:
// when there are internal transaction retries, and when multiple statements
// are submitted together, e.g. "SELECT 1; SELECT 2".
parseLatency := p[sessionEndParse].Sub(p[sessionQueryReceived])
planAndExecuteLatency := p[plannerEndExecStmt].Sub(p[plannerStartLogicalPlan])
return parseLatency + planAndExecuteLatency
}

// getRunLatency returns the time between a query execution starting and ending.
Expand Down

0 comments on commit 6371d37

Please sign in to comment.