Skip to content

txn: add more debug information for the txn commands#12779

Merged
ti-chi-bot merged 4 commits intotikv:masterfrom
cfzjywxk:debug_info_enhancement
Jun 13, 2022
Merged

txn: add more debug information for the txn commands#12779
ti-chi-bot merged 4 commits intotikv:masterfrom
cfzjywxk:debug_info_enhancement

Conversation

@cfzjywxk
Copy link
Collaborator

@cfzjywxk cfzjywxk commented Jun 8, 2022 •
edited
Loading

Signed-off-by: cfzjywxk lsswxrxr@163.com

What is changed and how it works?

Issue Number: close #12803

What's Changed:

In the investigation process, the debug log information helps a lot, but there's still some important information 
missing such as retrying or 1pc flags. 
Changed:
1. Add more useful information displaying commands.
2. Redact necessary parts.

Related changes

Check List

Tests

  • Manual test (add detailed scripts or steps below)

Side effects

Release note 

NONE

@cfzjywxk
add more debug information for the txn commands
6411072 
Signed-off-by: cfzjywxk <lsswxrxr@163.com>
@cfzjywxk cfzjywxk added the sig/transaction SIG: Transaction label Jun 8, 2022
@ti-chi-bot
Copy link
Member

ti-chi-bot commented Jun 8, 2022 •
edited
Loading

[REVIEW NOTIFICATION]

This pull request has been approved by:

  • ekexium
  • zhangjinpeng1987

To complete the pull request process, please ask the reviewers in the list to review by filling /cc @reviewer in the comment.
After your PR has acquired the required number of LGTMs, you can assign this pull request to the committer in the list by filling /assign @committer in the comment to help you merge this pull request.

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

Details

Reviewer can indicate their review by submitting an approval review.
Reviewer can cancel approval by submitting a request changes review.

@ti-chi-bot ti-chi-bot added release-note-none Denotes a PR that doesn't merit a release note. do-not-merge/needs-linked-issue size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Jun 8, 2022
@ekexium
Copy link
Contributor

ekexium commented Jun 8, 2022

Seems some fields are not redacted when setting redact-info-log=true. Is it expected?

[2022/06/08 12:12:35.422 +08:00] [DEBUG] [scheduler.rs:414] ["received new command"] [cmd="kv::command::prewrite mutations([Put((?, [8, 2, 2, 40, 116, 105, 107, 118, 95, 103, 99, 95, 108, 101, 97, 100, 101, 114, 95, 108, 101, 97, 115, 101, 8, 4, 2, 46, 50, 48, 50, 50, 48, 54, 48, 56, 45, 49, 50, 58, 49, 52, 58, 51, 53, 32, 43, 48, 56, 48, 48, 8, 6, 2, 90, 67, 117, 114, 114, 101, 110, 116, 32, 71, 67, 32, 119, 111, 114, 107, 101, 114, 32, 108, 101, 97, 100, 101, 114, 32, 108, 101, 97, 115, 101, 46, 32, 40, 68, 79, 32, 78, 79, 84, 32, 69, 68, 73, 84, 41]), None)]) primary([116, 128, 0, 0, 0, 0, 0, 0, 17, 95, 114, 128, 0, 0, 0, 0, 1, 102, 241]) secondary(None)@ 433759598777466883 3002 false 1 433759598777466884 0 false| region_id: 18 region_epoch { conf_ver: 1 version: 9 } peer { id: 19 store_id: 1 } max_execution_duration_ms: 20000 resource_group_tag: ? disk_full_opt: AllowedOnAlmostFull"] [cid=339]

@cfzjywxk
Copy link
Collaborator Author

cfzjywxk commented Jun 8, 2022 •
edited
Loading

[2022/06/08 12:12:35.422 +08:00] [DEBUG] [scheduler.rs:414] ["received new command"] [cmd="kv::command::prewrite mutations([Put((?, [8, 2, 2, 40, 116, 105, 107, 118, 95, 103, 99, 95, 108, 101, 97, 100, 101, 114, 95, 108, 101, 97, 115, 101, 8, 4, 2, 46, 50, 48, 50, 50, 48, 54, 48, 56, 45, 49, 50, 58, 49, 52, 58, 51, 53, 32, 43, 48, 56, 48, 48, 8, 6, 2, 90, 67, 117, 114, 114, 101, 110, 116, 32, 71, 67, 32, 119, 111, 114, 107, 101, 114, 32, 108, 101, 97, 100, 101, 114, 32, 108, 101, 97, 115, 101, 46, 32, 40, 68, 79, 32, 78, 79, 84, 32, 69, 68, 73, 84, 41]), None)]) primary([116, 128, 0, 0, 0, 0, 0, 0, 17, 95, 114, 128, 0, 0, 0, 0, 1, 102, 241]) secondary(None)@ 433759598777466883 3002 false 1 433759598777466884 0 false| region_id: 18 region_epoch { conf_ver: 1 version: 9 } peer { id: 19 store_id: 1 } max_execution_duration_ms: 20000 resource_group_tag: ? disk_full_opt: AllowedOnAlmostFull"] [cid=339]

It's needed, seems the Value in Mutation is not redacted before.

zhangjinpeng87
zhangjinpeng87 approved these changes Jun 8, 2022
View reviewed changes
Copy link
Member

@zhangjinpeng87 zhangjinpeng87 left a comment

Choose a reason for hiding this comment

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

LGTM

@ti-chi-bot ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Jun 8, 2022
@cfzjywxk
redact prewrite command related debug logs and mutations
b406613 
Signed-off-by: cfzjywxk <lsswxrxr@163.com>
@ti-chi-bot ti-chi-bot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/S Denotes a PR that changes 10-29 lines, ignoring generated files. labels Jun 8, 2022
@cfzjywxk
Copy link
Collaborator Author

cfzjywxk commented Jun 8, 2022

@ekexium
The non-redacted parts are processed accordingly, PTAL thx.

@ti-chi-bot ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Jun 8, 2022
@cfzjywxk
change back debug level
379e69a 
Signed-off-by: cfzjywxk <lsswxrxr@163.com>
MyonKeminta
MyonKeminta reviewed Jun 13, 2022
View reviewed changes
components/txn_types/src/types.rs
Mutation::Put((key, value), assertion) => write!(
f,
"Put key:{:?} value:{:?} assertion:{:?}",
key,
Copy link
Contributor

@MyonKeminta MyonKeminta Jun 13, 2022

Choose a reason for hiding this comment

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

Do the keys need to be redacted?

Copy link
Contributor

@ekexium ekexium Jun 13, 2022

Choose a reason for hiding this comment

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

Key has implemented Debug and Display using log_wrappers

src/storage/txn/commands/acquire_pessimistic_lock.rs
AcquirePessimisticLock:
cmd_ty => StorageResult<PessimisticLockRes>,
display => "kv::command::acquirepessimisticlock keys({}) @ {} {} | {:?}", (keys.len, start_ts, for_update_ts, ctx),
display => "kv::command::acquirepessimisticlock keys({:?}) @ {} {} {} {:?} {} {} | {:?}",
Copy link
Contributor

@MyonKeminta MyonKeminta Jun 13, 2022

Choose a reason for hiding this comment

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

I'm afraid it looks a little hard to recognize which field is each value in the logs.

MyonKeminta
MyonKeminta approved these changes Jun 13, 2022
View reviewed changes
Copy link
Contributor

@MyonKeminta MyonKeminta left a comment

Choose a reason for hiding this comment

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

Ah, I'm sorry. Just noticed that the Key type already has built-in redaction.

@MyonKeminta
Copy link
Contributor

MyonKeminta commented Jun 13, 2022

/merge

@ti-chi-bot
Copy link
Member

ti-chi-bot commented Jun 13, 2022

@MyonKeminta: It seems you want to merge this PR, I will help you trigger all the tests:

/run-all-tests

You only need to trigger /merge once, and if the CI test fails, you just re-trigger the test that failed and the bot will merge the PR for you after the CI passes.

If you have any questions about the PR merge process, please refer to pr process.

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 ti-community-infra/tichi repository.

@ti-chi-bot
Copy link
Member

ti-chi-bot commented Jun 13, 2022

This pull request has been accepted and is ready to merge.

DetailsCommit hash: 379e69a

@ti-chi-bot ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Jun 13, 2022
@cfzjywxk
Copy link
Collaborator Author

cfzjywxk commented Jun 13, 2022

/test

@ti-chi-bot ti-chi-bot merged commit 17b8468 into tikv:master Jun 13, 2022
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment

Reviewers

@ekexium ekexium ekexium approved these changes

@MyonKeminta MyonKeminta MyonKeminta approved these changes

@zhangjinpeng87 zhangjinpeng87 zhangjinpeng87 approved these changes

@you06 you06 Awaiting requested review from you06

@sticnarf sticnarf Awaiting requested review from sticnarf

Assignees

No one assigned

Labels

release-note-none Denotes a PR that doesn't merit a release note. sig/transaction SIG: Transaction size/L Denotes a PR that changes 100-499 lines, ignoring generated files. status/can-merge Indicates a PR has been approved by a committer. status/LGT2 Indicates that a PR has LGTM 2.

Projects

None yet

Milestone

No milestone

Development

Successfully merging this pull request may close these issues.

txn: enhance the debug information

5 participants

@cfzjywxk @ti-chi-bot @ekexium @MyonKeminta @zhangjinpeng87