txn: Slow txn log #41864

ekexium · 2023-03-02T07:31:32Z

What problem does this PR solve?

Issue Number: close #41863

Problem Summary:

What is changed and how it works?

Add a session variable tidb_slow_txn_log_threshold. Log transaction events observed by the transaction manager of any transaction that takes longer than the threshold. Setting it to 0 means disabling the log.

The log looks like

[2023/03/02 16:12:19.644 +08:00] [INFO] [txnmanager.go:194] ["slow transaction"] [duration=1.5955ms] [conn=1] [txnStartTS=439810717028974592] [events="[\"{event=\\\"enter txn\\\",gap=0s}\",\"{event=\\\"update pessimistic set v = 2 where v = 1\\\",gap=62.458µs}\",\"{event=\\\"stmt commit\\\",gap=1.157125ms}\",\"{event=\\\"txn end\\\",gap=375.167µs}\"]"]

Check List

Tests

Unit test
Integration test
Manual test (add detailed scripts or steps below)
No code

Side effects

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

Documentation

Release note

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

Add a session variable `tidb_slow_txn_log_threshold` to log slow transactions.

Signed-off-by: ekexium <eke@fastmail.com>

ti-chi-bot · 2023-03-02T07:31:34Z

[REVIEW NOTIFICATION]

This pull request has been approved by:

cfzjywxk
zyguan

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.

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

Signed-off-by: ekexium <eke@fastmail.com>

cfzjywxk · 2023-03-02T08:50:14Z

Is this change intended to resolve issues like #41471, if so we may need find out a way to show the long-running transactions like show processlist does.

ekexium · 2023-03-02T09:41:23Z

Is this change intended to resolve issues like #41471, if so we may need find out a way to show the long-running transactions like show processlist does.

No. I'd rather treat them as different problems. This PR is a counterpart of slow queries. I intend to use it as a tool to diagnose tail latencies. Though finished long-running transaction could be logged by it as well.

Signed-off-by: ekexium <eke@fastmail.com>

cfzjywxk · 2023-03-02T09:49:13Z

No. I'd rather treat them as different problems. This PR is a counterpart of slow queries. I intend to use it as a tool to diagnose tail latencies. Though finished long-running transaction could logged by it as well.

How to diagnose tail latencies using the long-txn log, I don't quite get it. Could you give an example of it?

ekexium · 2023-03-02T10:13:24Z

How to diagnose tail latencies using the long-txn log, I don't quite get it. Could you give an example of it?

For example we see high tail latencies for transactions and high max idle durations in metrics. But we cannot guarantee that the tail latency is caused by idle duration.
With slow txn log like

...,\"{event=\\\"stmt end\\\",gap=18.89µs}\",\"{event=\\\"insert bs_accum_lmt_detail (haveAccumCnt,haveAccumLmt,lastLmtDt,lmtNo,lmtObj,lmtPeriodType,lmtSubSeqNo,rgstBrc,rgstDt,rgstOperr,rgstTm,transSrlNo) values (?,?,?,?,?,?,?,?,?,?,?,?)\\\",gap=218.345562ms}\",...

We can tell that there is an idle duration of 218ms before the INSERT stmt comes. And it might help further diagnosis in client side.

cfzjywxk · 2023-03-03T07:31:02Z

session/session.go

@@ -2175,6 +2175,7 @@ func (s *session) ExecuteStmt(ctx context.Context, stmtNode ast.StmtNode) (sqlex
 	cmd32 := atomic.LoadUint32(&s.GetSessionVars().CommandValue)
 	s.SetProcessInfo(stmtNode.Text(), time.Now(), byte(cmd32), 0)
 	s.txn.onStmtStart(digest.String())
+	defer sessiontxn.GetTxnManager(s).OnStmtEnd()


I tried to merge the two OnStmtEnd into one #41122 but it looks difficult..

cfzjywxk · 2023-03-03T07:33:17Z

util/logutil/log.go

@@ -38,6 +38,8 @@ const (
 	DefaultLogFormat = "text"
 	// DefaultSlowThreshold is the default slow log threshold in millisecond.
 	DefaultSlowThreshold = 300
+	// DefaultSlowTxnThreshold is the default slow txn log threshold in ms.
+	DefaultSlowTxnThreshold = 0


How to choose a default-enabled value?

Default to 0. It's totally dependent on the application logic to determine what is "slow". And defaulting to 0 will prevent noisy logs from inner transactions.
And that's why this should be a SESSION-scoped variable.

session/txnmanager.go

zyguan

Note that query_dur > stmt_dur, that is {event="select ...",gap=100ms} may be caused by slow parsing, we cannot confirm that it's caused by client idle time without the slow query log of that query.

session/txnmanager.go

zyguan · 2023-03-03T09:06:36Z

session/txnmanager.go

+	// used for slow transaction logs
+	events          []event
+	lastInstant     time.Time
+	enterTxnInstant time.Time


Maybe lastInstant is unnecessary, we can record the start instant and the duration (since the start instant) of each event, then the gaps can be inferred from these info.

Yeah I've considered the alternative. I think they are basically equivalent and either is fine. If you prefer this style I can change it

I think it’s fine. A field of type time.Time here is not expensive at all.

Signed-off-by: ekexium <eke@fastmail.com>

ekexium · 2023-03-03T10:10:48Z

Note that query_dur > stmt_dur, that is {event="select ...",gap=100ms} may be caused by slow parsing, we cannot confirm that it's caused by client idle time without the slow query log of that query.

That's true. And the stat doesn't count the time spent in TiDB after OnTxnEnd. Precisely it's counting from the "txn manager's view". But that helps, too. It's better than nothing. What do you think?

In real cases we should use it together with slow query logs and stmt info. For things like {event="select ...",gap=100ms} we can almost assure it's an idle duration since long parsing/compilation is kinda rare.

cfzjywxk · 2023-03-03T10:39:59Z

BTW I think we've added some "event tracking" things in the consistency check enhancement, should we also include the inconsistency events and merge them into a single event tracking framework?

cfzjywxk · 2023-03-04T04:36:17Z

@ekexium
Need to resolve the conflicts.

Signed-off-by: ekexium <eke@fastmail.com>

ekexium · 2023-03-06T03:39:36Z

/retest

ekexium · 2023-03-06T03:39:47Z

/merge

ti-chi-bot · 2023-03-06T03:39:51Z

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

Commit hash: af9d4df

ekexium added 4 commits March 1, 2023 16:58

add slow txn log

6982eef

Signed-off-by: ekexium <eke@fastmail.com>

default to 0

d111793

Signed-off-by: ekexium <eke@fastmail.com>

calc the start of txn in EnterNewTxn

730de85

Signed-off-by: ekexium <eke@fastmail.com>

refactor

56d59e7

Signed-off-by: ekexium <eke@fastmail.com>

ekexium requested a review from a team as a code owner March 2, 2023 07:31

ti-chi-bot added release-note Denotes a PR that will be considered when it comes time to generate release notes. size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Mar 2, 2023

ekexium added 2 commits March 2, 2023 15:39

redact

de9e862

Signed-off-by: ekexium <eke@fastmail.com>

adjust log content

568b10f

Signed-off-by: ekexium <eke@fastmail.com>

ti-chi-bot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Mar 2, 2023

ekexium requested review from zyguan and cfzjywxk March 2, 2023 08:13

ekexium added 2 commits March 2, 2023 16:19

Merge branch 'master' of github.com:pingcap/tidb into slow-txn-log

d9578d5

fix bazel

d00cec6

Signed-off-by: ekexium <eke@fastmail.com>

ti-chi-bot added size/M Denotes a PR that changes 30-99 lines, ignoring generated files. and removed size/L Denotes a PR that changes 100-499 lines, ignoring generated files. labels Mar 2, 2023

ti-chi-bot added size/L Denotes a PR that changes 100-499 lines, ignoring generated files. and removed size/M Denotes a PR that changes 30-99 lines, ignoring generated files. labels Mar 2, 2023

ekexium force-pushed the slow-txn-log branch from 1cc5364 to fb619cf Compare March 2, 2023 09:42

tolerate nil pointers

3be6c30

Signed-off-by: ekexium <eke@fastmail.com>

ekexium force-pushed the slow-txn-log branch from fb619cf to 3be6c30 Compare March 2, 2023 09:48

cfzjywxk reviewed Mar 3, 2023

View reviewed changes

zyguan reviewed Mar 3, 2023

View reviewed changes

fix: incorrect resetEvents

238dc0b

Signed-off-by: ekexium <eke@fastmail.com>

zyguan approved these changes Mar 3, 2023

View reviewed changes

ti-chi-bot added the status/LGT1 Indicates that a PR has LGTM 1. label Mar 3, 2023

cfzjywxk approved these changes Mar 4, 2023

View reviewed changes

ti-chi-bot added status/LGT2 Indicates that a PR has LGTM 2. needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. and removed status/LGT1 Indicates that a PR has LGTM 1. labels Mar 4, 2023

Merge branch 'master' into slow-txn-log

62f862e

ti-chi-bot removed the needs-rebase Indicates a PR cannot be merged because it has merge conflicts with HEAD. label Mar 6, 2023

fix format

af9d4df

Signed-off-by: ekexium <eke@fastmail.com>

ti-chi-bot added the status/can-merge Indicates a PR has been approved by a committer. label Mar 6, 2023

ti-chi-bot merged commit 9e27518 into pingcap:master Mar 6, 2023

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

txn: Slow txn log #41864

txn: Slow txn log #41864

ekexium commented Mar 2, 2023 •

edited

Loading

ti-chi-bot commented Mar 2, 2023 •

edited

Loading

cfzjywxk commented Mar 2, 2023

ekexium commented Mar 2, 2023 •

edited

Loading

cfzjywxk commented Mar 2, 2023

ekexium commented Mar 2, 2023 •

edited

Loading

cfzjywxk Mar 3, 2023

cfzjywxk Mar 3, 2023

ekexium Mar 3, 2023 •

edited

Loading

zyguan left a comment •

edited

Loading

zyguan Mar 3, 2023

ekexium Mar 3, 2023

zyguan Mar 3, 2023

ekexium commented Mar 3, 2023

cfzjywxk commented Mar 3, 2023 •

edited

Loading

cfzjywxk commented Mar 4, 2023

ekexium commented Mar 6, 2023

ekexium commented Mar 6, 2023

ti-chi-bot commented Mar 6, 2023

txn: Slow txn log #41864

txn: Slow txn log #41864

Conversation

ekexium commented Mar 2, 2023 • edited Loading

What problem does this PR solve?

What is changed and how it works?

Check List

Release note

ti-chi-bot commented Mar 2, 2023 • edited Loading

cfzjywxk commented Mar 2, 2023

ekexium commented Mar 2, 2023 • edited Loading

cfzjywxk commented Mar 2, 2023

ekexium commented Mar 2, 2023 • edited Loading

cfzjywxk Mar 3, 2023

Choose a reason for hiding this comment

cfzjywxk Mar 3, 2023

Choose a reason for hiding this comment

ekexium Mar 3, 2023 • edited Loading

Choose a reason for hiding this comment

zyguan left a comment • edited Loading

Choose a reason for hiding this comment

zyguan Mar 3, 2023

Choose a reason for hiding this comment

ekexium Mar 3, 2023

Choose a reason for hiding this comment

zyguan Mar 3, 2023

Choose a reason for hiding this comment

ekexium commented Mar 3, 2023

cfzjywxk commented Mar 3, 2023 • edited Loading

cfzjywxk commented Mar 4, 2023

ekexium commented Mar 6, 2023

ekexium commented Mar 6, 2023

ti-chi-bot commented Mar 6, 2023

ekexium commented Mar 2, 2023 •

edited

Loading

ti-chi-bot commented Mar 2, 2023 •

edited

Loading

ekexium commented Mar 2, 2023 •

edited

Loading

ekexium commented Mar 2, 2023 •

edited

Loading

ekexium Mar 3, 2023 •

edited

Loading

zyguan left a comment •

edited

Loading

cfzjywxk commented Mar 3, 2023 •

edited

Loading