Skip to content

sql: fix and rename sql stats session transaction received time#83590

Merged
craig[bot] merged 1 commit intocockroachdb:masterfrom
THardy98:fix_transaction_time
Jul 7, 2022
Merged

sql: fix and rename sql stats session transaction received time#83590
craig[bot] merged 1 commit intocockroachdb:masterfrom
THardy98:fix_transaction_time

Conversation

@THardy98
Copy link
Copy Markdown

@THardy98 THardy98 commented Jun 29, 2022 •
edited
Loading

Resolves: #82894

Due to a change from #76792, implicit transactions can start before
SessionQueryReceived session phase time is set by the sqlstats system.
In turn, this caused the SessionTransactionReceived (now renamed as
SessionTransactionStarted) session phase time to be recorded
incorrectly, causing extremely large transactions times on the UI. This
change fixes this mistake by setting the actual transaction start time
as the SessionTransactionStarted session phase time, instead of
SessionQueryReceived.

Release note (bug fix): The SessionTransactionReceived session phase
time is no longer recorded incorrectly, fixing large transaction times
from appearing on the UI, also renamed to SessionTransactionStarted.

@cockroach-teamcity
Copy link
Copy Markdown
Member

cockroach-teamcity commented Jun 29, 2022

This change is Reviewable

@THardy98 THardy98 force-pushed the fix_transaction_time branch 2 times, most recently from 819d811 to 414a5e7 Compare June 29, 2022 21:26
@THardy98 THardy98 requested review from a team and rafiss June 29, 2022 21:37
xinhaoz
xinhaoz reviewed Jun 29, 2022
View reviewed changes
Copy link
Copy Markdown
Contributor

@xinhaoz xinhaoz left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

pkg/sql/conn_executor_exec.go line 2186 at r1 (raw file):

	// Transaction received time is the time at which the statement that prompted
	// the creation of this transaction was received.

Should we change this comment? Also maybe we should include a test with the failing case Rafi saw using a query executing with the extended protocol

Code quote:

	// Transaction received time is the time at which the statement that prompted
	// the creation of this transaction was received.

rafiss
rafiss reviewed Jun 30, 2022
View reviewed changes
Copy link
Copy Markdown
Collaborator

@rafiss rafiss left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

pkg/sql/conn_executor_exec.go line 2186 at r1 (raw file):

Previously, xinhaoz (Xin Hao Zhang) wrote…

Should we change this comment? Also maybe we should include a test with the failing case Rafi saw using a query executing with the extended protocol

Yeah, and maybe instead of SessionTransactionReceived we should call it SessionTransactionStarted. the comment would be something about how it's the time the connExecutor created the transaction

@THardy98 THardy98 force-pushed the fix_transaction_time branch from 414a5e7 to e39c947 Compare June 30, 2022 20:40
@THardy98 THardy98 changed the title sql: fix sql stats session transaction received time sql: fix and rename sql stats session transaction received time Jun 30, 2022
@THardy98 THardy98 force-pushed the fix_transaction_time branch 2 times, most recently from 9bd6865 to 4fe1f17 Compare June 30, 2022 20:42
THardy98
THardy98 commented Jun 30, 2022
View reviewed changes
Copy link
Copy Markdown
Author

@THardy98 THardy98 left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

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

pkg/sql/conn_executor_exec.go line 2186 at r1 (raw file):

Previously, rafiss (Rafi Shamim) wrote…

Yeah, and maybe instead of SessionTransactionReceived we should call it SessionTransactionStarted. the comment would be something about how it's the time the connExecutor created the transaction

Yeah, renamed to SessionTransactionStarted, removed the comment in conn_executor_exec.go, the variable names are pretty self-explanatory now.

Added a test to sql_stats_test.go 👍

@THardy98
Copy link
Copy Markdown
Author

THardy98 commented Jun 30, 2022

Added use of the pgx driver.

Hmm, test passes whether I use SessionQueryReceived or the new txnStart as the SessionTransactionStarted phase time. Should definitely fail on SessionQueryReceived, am I missing something here?

@THardy98 THardy98 force-pushed the fix_transaction_time branch from 4fe1f17 to 019cf0b Compare June 30, 2022 21:01
@THardy98 THardy98 requested a review from rafiss June 30, 2022 21:01
@THardy98 THardy98 force-pushed the fix_transaction_time branch from 019cf0b to 63d6859 Compare June 30, 2022 21:09
@THardy98
Copy link
Copy Markdown
Author

THardy98 commented Jun 30, 2022

Even when I specify pgx.QuerySimpleProtocol(false) it passes using SessionQueryReceived

@xinhaoz
Copy link
Copy Markdown
Contributor

xinhaoz commented Jul 5, 2022

@THardy98 I believe in your testCase loop you might be accessing the copy of phaseTimes from the start of the loop execution, and not the version from after your test case is executed, so it might be the phase times from an internal query. Maybe try accessing it via the index to get the up to date version and also not copy the times from internal queries.

@THardy98 THardy98 force-pushed the fix_transaction_time branch from 63d6859 to 76976db Compare July 6, 2022 15:02
@THardy98
Copy link
Copy Markdown
Author

THardy98 commented Jul 6, 2022

@THardy98 I believe in your testCase loop you might be accessing the copy of phaseTimes from the start of the loop execution, and not the version from after your test case is executed, so it might be the phase times from an internal query. Maybe try accessing it via the index to get the up to date version and also not copy the times from internal queries.

Yup that was exactly it, muchos gracias :)

@THardy98 THardy98 force-pushed the fix_transaction_time branch from 76976db to f20a1f3 Compare July 6, 2022 15:13
@THardy98 THardy98 force-pushed the fix_transaction_time branch 2 times, most recently from 438d80d to d264d23 Compare July 6, 2022 17:32
sql: fix and rename sql stats session transaction received time
f8f7459 
Resolves: cockroachdb#82894

Due to a change from cockroachdb#76792, implicit transactions can start before
`SessionQueryReceived` session phase time is set by the sqlstats system.
In turn, this caused the `SessionTransactionReceived` (now renamed as
`SessionTransactionStarted`) session phase time to be recorded
incorrectly, causing extremely large transactions times on the UI. This
change fixes this mistake by setting the actual transaction start time
as the `SessionTransactionStarted` session phase time, instead of
`SessionQueryReceived`.

Release note (bug fix): The `SessionTransactionReceived` session phase
time is no longer recorded incorrectly, fixing large transaction times
from appearing on the UI, also renamed to `SessionTransactionStarted`.
@THardy98 THardy98 force-pushed the fix_transaction_time branch from d264d23 to f8f7459 Compare July 6, 2022 17:48
maryliag
maryliag approved these changes Jul 6, 2022
View reviewed changes
Copy link
Copy Markdown
Contributor

@maryliag maryliag left a comment

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

great! :lgtm:

Reviewed 1 of 4 files at r2, 1 of 3 files at r4, 3 of 3 files at r5, all commit messages.
Reviewable status: :shipit: complete! 1 of 0 LGTMs obtained (waiting on @xinhaoz)

@THardy98
Copy link
Copy Markdown
Author

THardy98 commented Jul 7, 2022 •
edited
Loading

Bazel CI failing on a flaky test, going to merge

TYFR :)

@THardy98
Copy link
Copy Markdown
Author

THardy98 commented Jul 7, 2022

bors r+

@craig
Copy link
Copy Markdown
Contributor

craig bot commented Jul 7, 2022

Build succeeded:

@craig craig bot merged commit bce2267 into cockroachdb:master Jul 7, 2022
@blathers-crl blathers-crl bot mentioned this pull request Jul 7, 2022
Closed
@THardy98 THardy98 mentioned this pull request Jul 7, 2022
Merged
@renatolabs renatolabs mentioned this pull request Jul 21, 2022
Closed
30 tasks
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@rafiss rafiss rafiss approved these changes

+2 more reviewers

@xinhaoz xinhaoz xinhaoz left review comments

@maryliag maryliag maryliag approved these changes

Reviewers whose approvals may not affect merge requirements

Assignees

No one assigned

Labels

None yet

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

ui: transaction time reporting extremely large number

5 participants

@THardy98 @cockroach-teamcity @xinhaoz @maryliag @rafiss