*: improve log about stale-read query

[crazycs520]

What problem does this PR solve?

Issue Number: close #52492 #45545

Problem Summary: improve log about stale-read query

What changed and how does it work?

Log

Before this PR, timestamp field in log is 0 when executing stale-read query.

This PR, timestamp field is stale-read ts.

[2024/04/11 13:40:12.617 +08:00] [INFO] [conn.go:1152] ["command dispatched failed"] [conn=2097154] [session_alias=] [connInfo="id:2097154, addr:127.0.0.1:49367 status:10, collation:utf8_general_ci, user:root"] [command=Query] [status="inTxn:0, autocommit:1"] [sql="select /*+ MAX_EXECUTION_TIME(10), SET_VAR(TIKV_CLIENT_READ_TIMEOUT=5) */ * from t as of timestamp NOW() - INTERVAL 1 SECOND"] [txn_mode=PESSIMISTIC] [timestamp=449003916099584000] [err="[executor:3024]Query execution was interrupted, maximum statement execution time exceeded\ngithub.com/pingcap/errors.AddStack\n\t/Users/cs/code/goread/pkg/mod/github.com/pingcap/[email protected]/errors.go:178\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/Users/cs/code/goread/pkg/mod/github.com/pingcap/[email protected]/normalize.go:175\ngithub.com/pingcap/tidb/pkg/util/sqlkiller.(*SQLKiller).HandleSignal\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/util/sqlkiller/sqlkiller.go:68\ngithub.com/pingcap/tidb/pkg/executor/internal/exec.(*executorKillerHandler).HandleSQLKillerSignal\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/executor/internal/exec/executor.go:251\ngithub.com/pingcap/tidb/pkg/executor/internal/exec.Next\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/executor/internal/exec/executor.go:409\ngithub.com/pingcap/tidb/pkg/executor.(*ExecStmt).next\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/executor/adapter.go:1209\ngithub.com/pingcap/tidb/pkg/executor.(*recordSet).Next\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/executor/adapter.go:158\ngithub.com/pingcap/tidb/pkg/server/internal/resultset.(*tidbResultSet).Next\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/internal/resultset/resultset.go:64\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).writeChunks\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/conn.go:2317\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).writeResultSet\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/conn.go:2260\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleStmt\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/conn.go:2053\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).handleQuery\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/conn.go:1775\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).dispatch\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/conn.go:1349\ngithub.com/pingcap/tidb/pkg/server.(*clientConn).Run\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/conn.go:1113\ngithub.com/pingcap/tidb/pkg/server.(*Server).onConn\n\t/Users/cs/code/goread/src/github.com/pingcap/tidb/pkg/server/server.go:737\nruntime.goexit\n\t/usr/local/go/src/runtime/asm_arm64.s:1197"]

Slow log

Before This PR

The slow log of stale-read query is the following, Txn_start_ts is 0, which is unexpected.

...
# Txn_start_ts: 0
...
select * from t;

This PR

...
# Txn_start_ts: 448987604713472000
...
select * from t;

Check List

Tests

• Unit test
• Integration test
• Manual test (add detailed scripts or steps below)
• No need to test

  • I checked and no code files have been changed.

Side effects

• Performance regression: Consumes more CPU
• Performance regression: Consumes more Memory
• Breaking backward compatibility

Documentation

• Affects user behaviors
• Contains syntax changes
• Contains variable changes
• Contains experimental features
• Changes MySQL compatibility

Release note

Please refer to Release Notes Language Style Guide to write a quality release note.

None

[tiprow]

Hi @crazycs520. Thanks for your PR.

PRs from untrusted users cannot be marked as trusted with /ok-to-test in this repo meaning untrusted PR authors can never trigger tests themselves. Collaborators can still trigger tests on the PR using /test all.

I understand the commands that are listed here.

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[codecov]

Codecov Report

Merging #52494 (baa42ac) into master (5872ccd) will increase coverage by 2.1722%.
Report is 17 commits behind head on master.
The diff coverage is 69.2307%.

Additional details and impacted files

@@               Coverage Diff                @@
##             master     #52494        +/-   ##
================================================
+ Coverage   72.2059%   74.3781%   +2.1722%     
================================================
  Files          1469       1470         +1     
  Lines        427109     432124      +5015     
================================================
+ Hits         308398     321406     +13008     
+ Misses        99536      90748      -8788     
- Partials      19175      19970       +795     

Flag	Coverage Δ
integration	49.0229% <69.2307%> (?)
unit	71.1882% <69.2307%> (+0.0898%)	⬆️

Flags with carried forward coverage won't be shown. Click here to find out more.

Components	Coverage Δ
dumpling	53.9957% <ø> (ø)
parser	∅ <ø> (∅)
br	49.7964% <ø> (+8.6997%)	⬆️

[ti-chi-bot]

[LGTM Timeline notifier]

Timeline:

• 2024-04-11 05:49:34.775280985 +0000 UTC m=+1114236.302821553: ☑️ agreed by MyonKeminta.
• 2024-04-12 09:55:31.122517039 +0000 UTC m=+1215392.650057584: ☑️ agreed by zyguan.

[crazycs520]

/retest-required

[tiprow]

@crazycs520: Cannot trigger testing until a trusted user reviews the PR and leaves an /ok-to-test message.

In response to this:

/retest-required

Instructions for interacting with me using PR comments are available here. If you have questions or suggestions related to my behavior, please file an issue against the kubernetes/test-infra repository.

[easonn7]

/approve

[ti-chi-bot]

[APPROVALNOTIFIER] This PR is APPROVED

This pull-request has been approved by: easonn7, MyonKeminta, qw4990, zyguan

The full list of commands accepted by this bot can be found here.

The pull request process is described here

Needs approval from an approver in each of these files:

• OWNERS [MyonKeminta,qw4990,zyguan]
• pkg/planner/OWNERS [qw4990]
• pkg/sessionctx/variable/OWNERS [easonn7]

Approvers can indicate their approval by writing /approve in a comment
Approvers can cancel approval by writing /approve cancel in a comment