Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Commit_primary_rpc_detail is same to Slowest_prewrite_rpc_detail in some places #56445

Closed
you06 opened this issue Oct 4, 2024 · 0 comments · Fixed by #56448
Closed

Commit_primary_rpc_detail is same to Slowest_prewrite_rpc_detail in some places #56445

you06 opened this issue Oct 4, 2024 · 0 comments · Fixed by #56448
Assignees
Labels
severity/moderate sig/transaction SIG:Transaction type/bug The issue is confirmed as a bug.

Comments

@you06
Copy link
Contributor

you06 commented Oct 4, 2024

Bug Report

Please answer these questions before submitting your issue. Thanks!

1. Minimal reproduce step (Required)

Run minimal tidb cluster tiup playground nightly --tiflash=0 --without-monitor, then execute.

create table t(id int);
set session tidb_enable_async_commit=off;
set session tidb_enable_1pc=off;
set global tidb_slow_log_threshold=0;
insert into t values(114514);

Check slowlog (~/.tiup/data/xxx/tidb-0/tidb-slow.log), I added some line wraps for better view:

...
# Prewrite_time: 0.001071776 Commit_time: 0.000890237 ....
Slowest_prewrite_rpc_detail: {total:0.001s, region_id: 14, store: 127.0.0.1:20160, time_detail: {tikv_wall_time: 631.1µs}, scan_detail: {get_snapshot_time: 18.5µs, rocksdb: {block: {}}}, write_detail: {store_batch_wait: 9.92µs, propose_send_wait: 0s, persist_log: {total: 449.1µs, write_leader_wait: 40ns, sync_log: 435.8µs, write_memtable: 330ns}, commit_log: 451.8µs, apply_batch_wait: 12.9µs, apply: {total:14.3µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 3.54µs, write_memtable: 2.51µs}}}
Commit_primary_rpc_detail: {total:0.001s, region_id: 14, store: 127.0.0.1:20160, time_detail: {tikv_wall_time: 631.1µs}, scan_detail: {get_snapshot_time: 18.5µs, rocksdb: {block: {}}}, write_detail: {store_batch_wait: 9.92µs, propose_send_wait: 0s, persist_log: {total: 449.1µs,write_leader_wait: 40ns, sync_log: 435.8µs, write_memtable: 330ns}, commit_log: 451.8µs, apply_batch_wait: 12.9µs, apply: {total:14.3µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 3.54µs, write_memtable: 2.51µs}}}
...
# Plan: tidb_decode_plan('sxTwVTAJMjdfMQkwCTAJTi9BCTAJdGltZToxMC45bXMsIGxvb3BzOjEsIHByZXBhcmU6IHt0b3RhbDogMTIuN8K1cywgYXV0b19pZF9hbGxvY2F0b3I6IHthAQxQX2NudDogMSwgR2V0OntudW1fcnBjAUwFQgBfBWgoMjA4LjHCtXN9LCABEBxfZGV0YWlsOg1mHF9wcm9jZXNzCSwUIDQwLjTCAXMJQQx3YWl0ERoINy41HRooa3ZfcmVhZF93YWwNaAggOTERIghpa3YuGQAEMTEBOhh9LCBzY2FuPoAADGtleXMFwyhnZXRfc25hcHNobxF0BDE5DY5ocm9ja3NkYjoge2Jsb2NrOiB7fX19LCBjb21tAaFEeG46IHtwcmV3cml0ZTo5LjYxIVkBUREiFHM6ODUuNgXACRMMOjkxMA2vHHNsb3dlc3RfEUElRC0feDogMC4wMTBzLCByZWdpb25faWQ6IDEyMiwgc3RvcmUBDDA3LjAuMC4xOjIwMTYwQmQBOgsBEDkuNTJtRgsBAas6/AAAM3b7AAXrOUwFjhRfYmF0Y2gltQw6IDIxDUEocHJvcG9zZV9zZW4hrwxpdDogAdAocGVyc2lzdF9sb2cZ7Qw5LjM4ITsJXhRsZWFkZXINUCQ5MG5zLCBzeW5jCTMMOS4zNBkrNG1lbXRhYmxlOiA4MDBuAeEpZxUsBVcQYXBwbHkypgAEMTQthQUbFYkMMjMuMiWtFG11dGV4Xyn0AbZKmQAZFyB3YWw6IDUuNzkFOwkrGZkIMy40AVQuOQIYcHJpbWFyeULxAQgwMXP+8QEx8QQ4MkF2QvwCSvEBDDIuODMFuVrtAgnQdb5G8gEIOC44abyu8gEINjkxbRgJYDL0AQAzOvQBCDQzNS2vCS05XQQyN0b2AQw2OTgujcBG+AEAM4WUACw++AEANE21xvgBCDYuNQltPpsACDQuNCFYJfhtxQhudW2hJQkqhYEEMSwNDhhieXRlOjMyBS4UaW5zZXJ0talN0jpuBAwxLjA3YQgh0hEiCHM6NhHgCRMMOjg5ME3Sgm4EQn0CBDQs2m0ECDYzMSVmjn4CBDE4LdrefgIIOS45YV/Bx6ZwBAg0NDkFojF+Mn4CADRKfgIAOGUiKblZfgAzQanZEIXTCDQ1MQ0uSn4CBDIuiSQFG5V2CDE0LkEqACzKfgIIMy41aXw+mwAIMi415X3dr6J2BOL5AQQ4MFJxB0GjOmYGADlxNt73AQg4LjfG9wEENjQuqwMy9QEhyi5nBgQ0MymqQlgBADFKcQQENTBNTiXYMmkGCDQuOQlJBRs581H3xnEECDMuOSFmUbtZjgg0LjCl9CHzpnEENAk3MiBCeXRlcwlOL0EK')
...
insert into t values(114514);

2. What did you expect to see? (Required)

The prewrite and commit details are different, like what we decoded from plan field.

...
slowest_prewrite_rpc: {total: 0.001s, region_id: 14, store: 127.0.0.1:20160, time_detail: {tikv_wall_time: 631.1µs}, scan_detail: {get_snapshot_time: 18.5µs, rocksdb: {block: {}}}, write_detail: {store_batch_wait: 9.92µs, propose_send_wait: 0s, persist_log: {total: 449.1µs, write_leader_wait: 40ns, sync_log: 435.8µs, write_memtable: 330ns}, commit_log: 451.8µs, apply_batch_wait: 12.9µs, apply: {total:14.3µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 3.54µs, write_memtable: 2.51µs}}},
commit_primary_rpc: {total: 0.001s, region_id: 14, store: 127.0.0.1:20160, time_detail: {tikv_wall_time: 805µs}, scan_detail: {get_snapshot_time: 9.57µs, rocksdb: {block: {}}}, write_detail: {store_batch_wait: 8.72µs, propose_send_wait: 0s, persist_log: {total: 647µs, write_leader_wait: 30ns, sync_log: 439µs, write_memtable: 210ns}, commit_log: 650.1µs, apply_batch_wait: 4.99µs, apply: {total:18.5µs, mutex_lock: 0s, write_leader_wait: 0s, write_wal: 3.95µs, write_memtable: 4.06µs}}},
...

3. What did you see instead (Required)

The Commit_primary_rpc_detail is not correctly displayed.

4. What is your TiDB version? (Required)

Release Version: v8.4.0-alpha-315-g5ad55c2
Edition: Community
Git Commit Hash: 5ad55c212234e6cdad3e3f99628e33ab9bcfff29
Git Branch: HEAD
UTC Build Time: 2024-09-30 01:24:11
GoVersion: go1.21.13
Race Enabled: false
Check Table Before Drop: false
Store: tikv
@you06 you06 added type/bug The issue is confirmed as a bug. severity/moderate labels Oct 4, 2024
@you06 you06 self-assigned this Oct 4, 2024
@jebter jebter added the sig/transaction SIG:Transaction label Oct 8, 2024
@ti-chi-bot ti-chi-bot bot closed this as completed in 7bf8629 Oct 8, 2024
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
severity/moderate sig/transaction SIG:Transaction type/bug The issue is confirmed as a bug.
Projects
None yet
Development

Successfully merging a pull request may close this issue.

2 participants