Skip to content

*: improve log about stale-read query#52494

Merged
ti-chi-bot[bot] merged 5 commits intopingcap:masterfrom
crazycs520:refine-stale-read-log
Apr 15, 2024
Merged

*: improve log about stale-read query#52494
ti-chi-bot[bot] merged 5 commits intopingcap:masterfrom
crazycs520:refine-stale-read-log

Conversation

@crazycs520
Copy link
Contributor

@crazycs520 crazycs520 commented Apr 11, 2024 •
edited
Loading

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/errors@v0.11.5-0.20240318064555-6bd07397691f/errors.go:178\ngithub.com/pingcap/errors.(*Error).GenWithStackByArgs\n\t/Users/cs/code/goread/pkg/mod/github.com/pingcap/errors@v0.11.5-0.20240318064555-6bd07397691f/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

@crazycs520
*: improve log about stale-read query
19e61e2 
Signed-off-by: crazycs520 <crazycs520@gmail.com>
@ti-chi-bot ti-chi-bot bot added release-note-none Denotes a PR that doesn't merit a release note. sig/planner SIG: Planner size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Apr 11, 2024
@tiprow
Copy link

tiprow bot commented Apr 11, 2024

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.

Details

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.

@ti-chi-bot ti-chi-bot bot added the needs-1-more-lgtm Indicates a PR needs 1 more LGTM. label Apr 11, 2024
@codecov
Copy link

codecov bot commented Apr 11, 2024 •
edited
Loading

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%) ⬆️

zyguan
zyguan reviewed Apr 11, 2024
View reviewed changes
@crazycs520
refine
da20118 
Signed-off-by: crazycs520 <crazycs520@gmail.com>
@crazycs520
refine
3e9a079 
Signed-off-by: crazycs520 <crazycs520@gmail.com>
@ti-chi-bot ti-chi-bot bot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Apr 12, 2024
@crazycs520 crazycs520 mentioned this pull request Apr 12, 2024
Closed
13 tasks
@crazycs520 crazycs520 requested a review from MyonKeminta April 12, 2024 09:34
zyguan
zyguan approved these changes Apr 12, 2024
View reviewed changes
@ti-chi-bot ti-chi-bot bot added lgtm and removed needs-1-more-lgtm Indicates a PR needs 1 more LGTM. labels Apr 12, 2024
@ti-chi-bot
Copy link

ti-chi-bot bot commented Apr 12, 2024

[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
add todo comment
baa42ac 
Signed-off-by: crazycs520 <crazycs520@gmail.com>
MyonKeminta
MyonKeminta approved these changes Apr 15, 2024
View reviewed changes
@crazycs520
address comment
f710ac7 
Signed-off-by: crazycs520 <crazycs520@gmail.com>
@crazycs520
Copy link
Contributor Author

crazycs520 commented Apr 15, 2024

/retest-required

@tiprow
Copy link

tiprow bot commented Apr 15, 2024

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

Details

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
Copy link

easonn7 commented Apr 15, 2024

/approve

@ti-chi-bot
Copy link

ti-chi-bot bot commented Apr 15, 2024

[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

Details Needs approval from an approver in each of these files:

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

@ti-chi-bot ti-chi-bot bot added the approved label Apr 15, 2024
@ti-chi-bot ti-chi-bot bot merged commit 224ae15 into pingcap:master Apr 15, 2024
3AceShowHand pushed a commit to 3AceShowHand/tidb that referenced this pull request Apr 16, 2024
@crazycs520 @3AceShowHand
*: improve log about stale-read query (pingcap#52494)
2973a76 
close pingcap#52492
@crazycs520 crazycs520 deleted the refine-stale-read-log branch April 19, 2024 02:04
crazycs520 added a commit to crazycs520/tidb that referenced this pull request May 15, 2024
@crazycs520
*: improve log about stale-read query (pingcap#52494)
773de8f 
Signed-off-by: crazycs520 <crazycs520@gmail.com>
@crazycs520 crazycs520 mentioned this pull request May 21, 2024
Merged
13 tasks
cfzjywxk pushed a commit that referenced this pull request May 21, 2024
@crazycs520 @zyguan
*: add rpc error stats and refine log for diagnose (#53335)
4be26db 
* sessionctx: add sysvar to control exp feats of replica selector

Signed-off-by: zyguan <zhongyangguan@gmail.com>

* *: add rpc error stats and refine log (#52810)

Signed-off-by: crazycs520 <crazycs520@gmail.com>

* store: refine coprocessor error log (#52729)

Signed-off-by: crazycs520 <crazycs520@gmail.com>

* *: improve log about stale-read query (#52494)

Signed-off-by: crazycs520 <crazycs520@gmail.com>

* *: refine tikv/client-go log to print context information(such as conn id) as much as possible (#45559)

Signed-off-by: crazycs520 <crazycs520@gmail.com>

* add leader peer id log

Signed-off-by: crazycs520 <crazycs520@gmail.com>

* update log

Signed-off-by: crazycs520 <crazycs520@gmail.com>

* executor: fix issue that some query execution stats was omitted when execution was interrupted (#51787)

close #51660

Signed-off-by: crazycs520 <crazycs520@gmail.com>

* update go.mod

Signed-off-by: crazycs520 <crazycs520@gmail.com>

---------

Signed-off-by: zyguan <zhongyangguan@gmail.com>
Signed-off-by: crazycs520 <crazycs520@gmail.com>
Co-authored-by: zyguan <zhongyangguan@gmail.com>
This was referenced May 26, 2025
Closed
Closed
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@zyguan zyguan zyguan approved these changes

@qw4990 qw4990 qw4990 approved these changes

@MyonKeminta MyonKeminta MyonKeminta approved these changes

Assignees

No one assigned

Labels

approved lgtm release-note-none Denotes a PR that doesn't merit a release note. sig/planner SIG: Planner size/M Denotes a PR that changes 30-99 lines, ignoring generated files.

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

improve log about stale-read query

5 participants

@crazycs520 @easonn7 @zyguan @qw4990 @MyonKeminta