sqlstats: record idle latency for statements

[matthewtodd]

Part of #86667

In an attempt to identify application callsites holding transactions open while doing adjacent work, we measure a per-statement fingerprint "idle latency" and surface it in the sqlstats tables.

Developers may then search for statements with higher-than-usual idle latencies to find slow spots in their applications.

Release note (sql change): A new NumericStat, idleLat, was introduced to the statistics column of crdb_internal.statement_statistics, reporting the time spent waiting for the client to send the statement while holding a transaction open. Developers may use this stat to identify opportunities for restructuring their apps (perhaps moving unrelated work out of the transaction or splitting it into smaller transactions) to reduce contention.

[cockroach-teamcity]

This change is 

[rafiss]

the approach looks good to me! i had a few nits, and also i think we should expose this in the transaction stats in the DB internals as well.

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter and @matthewtodd)

---

-- commits line 13 at r1:
nit: it should be Release note (sql change) and include something about how a user can access this new data

---

pkg/roachpb/app_stats.go line 122 at r1 (raw file):

// Add combines other into TransactionStatistics.
func (t *TransactionStatistics) Add(other *TransactionStatistics) {

shouldn't this new metric be in TransactionStatistics instead of (or maybe in addition to) StatementStatistics?

---

pkg/roachpb/app_stats.proto line 65 at r1 (raw file):

  // ClientLat is the time spent waiting for the client to send the statement.
  optional NumericStat client_lat = 28 [(gogoproto.nullable) = false];

nit: i think "client latency" might be a bit confusing to understand. to me, it sounds like "total latency as experienced by the client."

what about a name like "idle latency" or "statement wait latency"

also, here and in the release note, do we need some clarification that this really is only meaningful for explicit transactions?

---

pkg/sql/executor_statement_metrics.go line 127 at r1 (raw file):

	// Collect the statistics.
	clientLatRaw := phaseTimes.GetClientLatency(ex.statsCollector.PreviousPhaseTimes())

this step will compute the "client latency" for the current statement. i couldn't find the place where we compute the running total and show the total "client latency" for the transaction. is that what the frontend aggregateNumericStats function does?

---

pkg/sql/sessionphase/session_phase.go line 215 at r1 (raw file):

// GetClientLatency deduces the rough amount of time spent waiting
// for the client while the transaction is open.

nit: can the comment specify what the behavior is for implicit transactions? it should just return 0 right?

[yuzefovich]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter and @matthewtodd)

---

pkg/sql/sessionphase/session_phase.go line 226 at r1 (raw file):

	}

	// In general, we have been waiting for the client since the end

I'm curious how accurate will this be if the previous statement returned a lot of data (i.e. the query resulted in millions of rows that were communicated to the client)?

[matthewtodd]

Thanks, Rafi! Agreed re: transaction stats. I'll be adding those in a second PR.

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter and @rafiss)

---

-- commits line 13 at r1:

Previously, rafiss (Rafi Shamim) wrote…

nit: it should be Release note (sql change) and include something about how a user can access this new data

Oops, thanks, I forgot crdb_internal.statement_statistics was one of the documented ones.

---

pkg/roachpb/app_stats.go line 122 at r1 (raw file):

Previously, rafiss (Rafi Shamim) wrote…

shouldn't this new metric be in TransactionStatistics instead of (or maybe in addition to) StatementStatistics?

It will be, coming in a second PR. Per @bobvawter, the per-statement timings were the most interesting for his approach.

---

pkg/roachpb/app_stats.proto line 65 at r1 (raw file):

Previously, rafiss (Rafi Shamim) wrote…

nit: i think "client latency" might be a bit confusing to understand. to me, it sounds like "total latency as experienced by the client."

what about a name like "idle latency" or "statement wait latency"

also, here and in the release note, do we need some clarification that this really is only meaningful for explicit transactions?

That's good, I do like "idle latency" better. And will clarify the explicit transaction bit.

---

pkg/sql/executor_statement_metrics.go line 127 at r1 (raw file):

Previously, rafiss (Rafi Shamim) wrote…

this step will compute the "client latency" for the current statement. i couldn't find the place where we compute the running total and show the total "client latency" for the transaction. is that what the frontend aggregateNumericStats function does?

The transaction-level aggregation will come in a second PR.

---

pkg/sql/sessionphase/session_phase.go line 215 at r1 (raw file):

Previously, rafiss (Rafi Shamim) wrote…

nit: can the comment specify what the behavior is for implicit transactions? it should just return 0 right?

Good idea, will change.

[j82w]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter, @matthewtodd, and @rafiss)

---

pkg/sql/sessionphase/session_phase.go line 228 at r3 (raw file):

	// In general, we have been waiting for the client since the end
	// of the previous execution.
	waitingSince := previous.times[PlannerEndExecStmt]

Is the IdleLatency alway the time before the statement? If so how does it track the latency between the last statement and the commit?

[j82w]

pkg/sql/sqlstats/sslocal/sql_stats_test.go line 1218 at r3 (raw file):

		},
		{
			name: "multiple transactions",

How about adding a test scenario with 'select pg_sleep(1)' to verify it doesn't include the execution time of the previous statement?

[matthewtodd]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter, @rafiss, and @yuzefovich)

---

pkg/sql/sessionphase/session_phase.go line 226 at r1 (raw file):

Previously, yuzefovich (Yahor Yuzefovich) wrote…

I'm curious how accurate will this be if the previous statement returned a lot of data (i.e. the query resulted in millions of rows that were communicated to the client)?

That's a good question! Let me look back at SessionQueryServiced to see (a) if it might give us better accuracy and (b) if it's available when we need it.

I had also spent some time looking into Jordan's suggestion of measuring the wait time for pgwire messages, but the mapping from those up to actual SQL executions felt hard to get (and keep?) right. That may be worth revisiting if we're not able to get satisfying accuracy this way.

[matthewtodd]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter, @j82w, @rafiss, and @yuzefovich)

---

pkg/sql/sessionphase/session_phase.go line 228 at r3 (raw file):

Previously, j82w wrote…

Is the IdleLatency alway the time before the statement? If so how does it track the latency between the last statement and the commit?

Yes, it is. We don't yet track the latency between the last statement and the commit; that'll be for the PR that introduces the transaction-level stat.

---

pkg/sql/sqlstats/sslocal/sql_stats_test.go line 1218 at r3 (raw file):

Previously, j82w wrote…

How about adding a test scenario with 'select pg_sleep(1)' to verify it doesn't include the execution time of the previous statement?

Good idea, will do.

[matthewtodd]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter, @j82w, @rafiss, and @yuzefovich)

---

pkg/sql/sessionphase/session_phase.go line 226 at r1 (raw file):

Previously, matthewtodd (Matthew Todd) wrote…

That's a good question! Let me look back at SessionQueryServiced to see (a) if it might give us better accuracy and (b) if it's available when we need it.

I had also spent some time looking into Jordan's suggestion of measuring the wait time for pgwire messages, but the mapping from those up to actual SQL executions felt hard to get (and keep?) right. That may be worth revisiting if we're not able to get satisfying accuracy this way.

SessionQueryServiced does happen slightly later, so I've switched to using it.

And I've gone down a bit of a rabbit hole looking for how this'll behave in the context of large result sets:

As far as I can tell, SessionQueryServiced won't be set until all of the results have been pushed down into to the network stack, at which point the "idle" clock will start ticking for the next query. (@yuzefovich, could you check me here?)

If that assessment is correct, then this idle clock will effectively penalize the client (i.e. mark its next query as having a large idle latency) for the essential overhead in handling these large responses.

...and I think we're okay with that? Since the intent of this feature is to identify unnecessarily long-running transactions that could be candidates for breaking apart, I think we do want these large responses to stand out.

---

I did find the results_buffer_size session var, hoping to use it to somehow expose some synchronous interaction with the client (wondering if it would behave like the defaultRowFetchSize connection parameter to the pg jdbc driver), but it only appears to affect flushing frequency.

[rafiss]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter, @j82w, and @yuzefovich)

---

pkg/sql/sessionphase/session_phase.go line 226 at r1 (raw file):

If that assessment is correct, then this idle clock will effectively penalize the client (i.e. mark its next query as having a large idle latency) for the essential overhead in handling these large responses.

...and I think we're okay with that? Since the intent of this feature is to identify unnecessarily long-running transactions that could be candidates for breaking apart, I think we do want these large responses to stand out.

I also agree that this behavior sounds good and it's useful to track as part of this metric

[yuzefovich]

Reviewable status: complete! 0 of 0 LGTMs obtained (waiting on @bobvawter, @j82w, @matthewtodd, and @rafiss)

---

pkg/sql/sessionphase/session_phase.go line 226 at r1 (raw file):

Previously, rafiss (Rafi Shamim) wrote…

If that assessment is correct, then this idle clock will effectively penalize the client (i.e. mark its next query as having a large idle latency) for the essential overhead in handling these large responses.

...and I think we're okay with that? Since the intent of this feature is to identify unnecessarily long-running transactions that could be candidates for breaking apart, I think we do want these large responses to stand out.

I also agree that this behavior sounds good and it's useful to track as part of this metric

Sounds good to me too, thanks for checking!

[matthewtodd]

Thanks, everyone! The failing test here is #91420, to be fixed by #91421. I'll rebase and ping you all for the when that lands.

[jordanlewis]

If that assessment is correct, then this idle clock will effectively penalize the client (i.e. mark its next query as having a large idle latency) for the essential overhead in handling these large responses.

I'm not sure that this is a good idea. I think it could lead to confusing outcomes - people look at statements in isolation, and they might see a large idle team and won't know what to make of it.

A related question - are we measuring the delay in between two statements within a transaction with this PR? And, how would that delay show up in the UI?

I think it might be good to do some basic testing of different scenarios so we can figure out how this stat maps to common user behaviors.

cc @kevin-v-ngo for any thoughts as well.

[jordanlewis]

(My comment isn't blocking for merging the PR)

[bobvawter]

A related question - are we measuring the delay in between two statements within a transaction with this PR? And, how would that delay show up in the UI?

The questions that I want to answer for customers are:

1. Are transaction times long because there's an excessive amount of "think time" in the workload?
2. Which statement(s) in the transaction have the biggest think-time gaps?
3. If possible, identify cases where draining a large result set back to the client takes a non-trivial amount of time.

The goal of the above is to let us make specific recommendations to customers about where the biggest wins in breaking up transactions would be or where a workload isn't keeping up with CRDB.

[rafiss]

are we measuring the delay in between two statements within a transaction with this PR?

According to https://reviewable.io/reviews/cockroachdb/cockroach/91098#-NFsqt6g4024WqV5V8YZ:-NFsugzZ3DPIu3oIwiVY:b-msldg1 and https://reviewable.io/reviews/cockroachdb/cockroach/91098#-NFtsABhEKUu6lKhY34V:-NFtuq2mDqfaxrQvTAkC:b-ujc2q9, that is coming in a future commit

[rafiss]

lgtm!

Reviewable status: complete! 1 of 0 LGTMs obtained (waiting on @bobvawter, @j82w, and @matthewtodd)

[matthewtodd]

Thanks for the reviews, all!

Before merging, I've discovered these measurements are accurate when running queries in psql but zero-ish in cockroach sql. 🤔 I'm suspecting some optimizations in pgx (which we use in cockroach sql) may account for the difference. I'm going to wire in a pgx variant of the tests to investigate.

If that assessment is correct, then this idle clock will effectively penalize the client (i.e. mark its next query as having a large idle latency) for the essential overhead in handling these large responses.

I'm not sure that this is a good idea. I think it could lead to confusing outcomes - people look at statements in isolation, and they might see a large idle team and won't know what to make of it.

I do agree about confusing outcomes here, though as far as I can tell, we're starting & stopping the idle clock at the latest & earliest times we can (is that true?), and I think we're still providing a useful signal of something that has a real impact on contention: "go look at what happens before this statement." How does that sound?

[rafiss]

accurate when running queries in psql but zero-ish in cockroach sql

I would guess that this is because psql only executes the query you type in, where as cockroach sql runs additional things such as SHOW DATABASE, and SHOW LAST QUERY STATISTICS.

[matthewtodd]

I'm going to wire in a pgx variant of the tests to investigate.

I did do this locally, and all the tests passed, as expected. So it's not pgx.

accurate when running queries in psql but zero-ish in cockroach sql

I would guess that this is because psql only executes the query you type in, where as cockroach sql runs additional things such as SHOW DATABASE, and SHOW LAST QUERY STATISTICS.

Thanks, @rafiss, that was it! 🎉

Poking around, I can now get accurate idle latencies from cockroach sql sessions by running \set check_syntax = false in those sessions. I think we're good to merge here!

bors r+

[craig]

This PR was included in a batch that was canceled, it will be automatically retried

[craig]

Build failed (retrying...):

• Bazel Essential CI (Cockroach)

[craig]

Build failed (retrying...):

• Bazel Essential CI (Cockroach)

[craig]

Build failed:

• Bazel Essential CI (Cockroach)

[matthewtodd]

bors r+

[craig]

Build succeeded:

• Bazel Essential CI (Cockroach)