Add trace event to recovery_transaction step in recovery #5015

kakaiu · 2021-06-18T20:42:27Z

Problem:
(1) When a recovery blocks at recovery_transaction phase and we do root cause analysis of it, it is often hard to distinguish which step in the phase blocks the recovery --- The recovery may block at the special transaction, or block at sending TxnStateStore to proxies, or block at initializing resolvers.
(2) In the root cause analysis, we may want to see which proxy is the proxy 0. Proxy 0 is the proxy that accepts special transactions that must keep serial order. However, the current way to identify the proxy 0 is somewhat tricky. We want to clearly see this information in the trace event.

Solution:
(1) Add two trace events --- SentTxnStateStoreToCommitProxies and InitializedAllResolvers to sendInitialCommitToResolvers() in masterserver.actor.cpp.
In recovery_transaction phase, the time order is:
The master sends TxnStateStore to proxies meanwhile issues the special transaction to proxy 0, then the master initializes resolvers, then the special transaction at the proxy 0 gets resolution replied from resolver.
When the recovery blocks at recovery_transaction phase, (a) if both events appear, then we can conclude that the special transaction must be blocked. (b) If only SentTxnStateStoreToCommitProxies appears, then at least initializing resolvers is blocked, and the special transaction may be blocked (at no later than when the proxy sending resolution request to resolver) (c) If none of the two events appears, then at least sending TxnStateStore to proxies is blocked, and the special transaction may be blocked (at no later than when the proxy sending resolution request to resolver).
Noting that in case (b) and (c), it is hard to determine whether the special transaction is blocked when the master issues transaction to proxy.
This is basically due to that the special transaction and initializing resolvers happen concurrently, but we have to check them in a serialized way.

(2) Add "FirstProxy" to CommitProxyReplies events in newCommitProxies().

Verified the function via simulation.
Passed Joshua 100k test: 20210619-210933-zhewang-846f7db1a7ac57e1

Code-Reviewer Section

The general guidelines can be found here.

Please check each of the following things and check all boxes before accepting a PR.

The PR has a description, explaining both the problem and the solution.
The description mentions which forms of testing were done and the testing seems reasonable.
Every function/class/actor that was touched is reasonably well documented.

For Release-Branches

If this PR is made against a release-branch, please also check the following:

This change/bugfix is a cherry-pick from the next younger branch (younger release-branch or master if this is the youngest branch)
There is a good reason why this PR needs to go into a release branch and this reason is documented (either in the description above or in a linked GitHub issue)

foundationdb-ci · 2021-06-18T21:03:50Z

AWS CodeBuild CI Report

CodeBuild project: foundationdb-pull-request-build
Commit ID: 32920f3
Result: SUCCEEDED
Build Logs (available for 7 days)

jzhou77 · 2021-06-18T23:17:11Z

fdbserver/masterserver.actor.cpp

@@ -965,6 +968,7 @@ ACTOR Future<Void> sendInitialCommitToResolvers(Reference<MasterData> self) {
 	}

 	wait(waitForAll(replies));
+	TraceEvent("SentTxnStateStoreToResolvers", self->dbgid);


Master doesn't send txnStateStore to resolvers.

Suggested change

TraceEvent("SentTxnStateStoreToResolvers", self->dbgid);

TraceEvent("InitializedAllResolvers", self->dbgid);

Yes. It sends LastEpochEnd version to resolvers.

foundationdb-ci · 2021-06-19T01:30:56Z

AWS CodeBuild CI Report

CodeBuild project: foundationdb-pull-request-build
Commit ID: 250eaf2
Result: SUCCEEDED
Build Logs (available for 7 days)

foundationdb-ci · 2021-06-19T01:32:40Z

AWS CodeBuild CI Report

CodeBuild project: foundationdb-pull-request-build
Commit ID: 80aabcc
Result: SUCCEEDED
Build Logs (available for 7 days)

foundationdb-ci · 2021-06-19T02:17:28Z

AWS CodeBuild CI Report

CodeBuild project: foundationdb-pull-request-build
Commit ID: fff0593
Result: SUCCEEDED
Build Logs (available for 7 days)

foundationdb-ci · 2021-06-19T02:18:24Z

AWS CodeBuild CI Report

CodeBuild project: foundationdb-pull-request-build
Commit ID: d00d679
Result: SUCCEEDED
Build Logs (available for 7 days)

halfprice · 2021-06-19T03:52:03Z

fdbserver/masterserver.actor.cpp

@@ -294,7 +294,9 @@ ACTOR Future<Void> newCommitProxies(Reference<MasterData> self, RecruitFromConfi
 		req.recoveryCount = self->cstate.myDBState.recoveryCount + 1;
 		req.recoveryTransactionVersion = self->recoveryTransactionVersion;
 		req.firstProxy = i == 0;
-		TraceEvent("CommitProxyReplies", self->dbgid).detail("WorkerID", recr.commitProxies[i].id());
+		TraceEvent("CommitProxyReplies", self->dbgid)


I think this is better named as "InitializeCommitProxy", since there is no reply at this point.

But if I rename this existing event name, I am afraid this may break our existing queries for others.

SG. Didn't realize that it already exists.

halfprice · 2021-06-19T03:53:43Z

fdbserver/masterserver.actor.cpp

@@ -953,6 +955,7 @@ ACTOR Future<Void> sendInitialCommitToResolvers(Reference<MasterData> self) {
 		wait(yield());
 	}
 	wait(waitForAll(txnReplies));
+	TraceEvent("SentTxnStateStoreToCommitProxies", self->dbgid);


This sounds too general. I think you want to add word "Recovery" in it since it is only used in recovery.

halfprice · 2021-06-19T03:54:35Z

Love your PR description!

xumengpanda · 2021-06-19T19:00:22Z

Love your PR description!
Clear and descriptive!

foundationdb-ci · 2021-06-19T21:32:59Z

AWS CodeBuild CI Report

CodeBuild project: foundationdb-pull-request-build
Commit ID: b685691
Result: SUCCEEDED
Build Logs (available for 7 days)

halfprice · 2021-06-20T23:24:07Z

fdbserver/masterserver.actor.cpp

@@ -294,7 +294,9 @@ ACTOR Future<Void> newCommitProxies(Reference<MasterData> self, RecruitFromConfi
 		req.recoveryCount = self->cstate.myDBState.recoveryCount + 1;
 		req.recoveryTransactionVersion = self->recoveryTransactionVersion;
 		req.firstProxy = i == 0;
-		TraceEvent("CommitProxyReplies", self->dbgid).detail("WorkerID", recr.commitProxies[i].id());
+		TraceEvent("CommitProxyReplies", self->dbgid)


SG. Didn't realize that it already exists.

kakaiu requested review from halfprice and RenxuanW June 18, 2021 20:42

jzhou77 reviewed Jun 18, 2021

View reviewed changes

apple deleted a comment from foundationdb-ci Jun 19, 2021

kakaiu requested a review from jzhou77 June 19, 2021 01:17

halfprice suggested changes Jun 19, 2021

View reviewed changes

add trace event to recovery_transaction step in recovery

b685691

kakaiu requested a review from halfprice June 19, 2021 21:07

kakaiu marked this pull request as ready for review June 20, 2021 02:29

halfprice approved these changes Jun 20, 2021

View reviewed changes

RenxuanW approved these changes Jun 21, 2021

View reviewed changes

kakaiu merged commit ab1404b into apple:master Jun 21, 2021

RenxuanW mentioned this pull request Jun 22, 2021

Add trace event to recovery_transaction step in recovery (release-6.3) #5038

Merged

5 tasks

kakaiu mentioned this pull request Jun 22, 2021

Add trace event to recovery_transaction step in recovery (release-7.0) #5029

Merged

5 tasks

kakaiu deleted the zhewang-add-traceevent-in-recovery branch June 26, 2021 15:42

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Add trace event to recovery_transaction step in recovery #5015

Add trace event to recovery_transaction step in recovery #5015

kakaiu commented Jun 18, 2021 •

edited

foundationdb-ci commented Jun 18, 2021

jzhou77 Jun 18, 2021

kakaiu Jun 19, 2021

foundationdb-ci commented Jun 19, 2021

foundationdb-ci commented Jun 19, 2021

foundationdb-ci commented Jun 19, 2021

foundationdb-ci commented Jun 19, 2021

halfprice Jun 19, 2021

kakaiu Jun 19, 2021 •

edited

halfprice Jun 20, 2021

halfprice Jun 19, 2021

halfprice commented Jun 19, 2021

xumengpanda commented Jun 19, 2021

foundationdb-ci commented Jun 19, 2021

halfprice Jun 20, 2021

	TraceEvent("SentTxnStateStoreToResolvers", self->dbgid);
	TraceEvent("InitializedAllResolvers", self->dbgid);

Add trace event to recovery_transaction step in recovery #5015

Add trace event to recovery_transaction step in recovery #5015

Conversation

kakaiu commented Jun 18, 2021 • edited

Code-Reviewer Section

For Release-Branches

foundationdb-ci commented Jun 18, 2021

AWS CodeBuild CI Report

jzhou77 Jun 18, 2021

Choose a reason for hiding this comment

kakaiu Jun 19, 2021

Choose a reason for hiding this comment

foundationdb-ci commented Jun 19, 2021

AWS CodeBuild CI Report

foundationdb-ci commented Jun 19, 2021

AWS CodeBuild CI Report

foundationdb-ci commented Jun 19, 2021

AWS CodeBuild CI Report

foundationdb-ci commented Jun 19, 2021

AWS CodeBuild CI Report

halfprice Jun 19, 2021

Choose a reason for hiding this comment

kakaiu Jun 19, 2021 • edited

Choose a reason for hiding this comment

halfprice Jun 20, 2021

Choose a reason for hiding this comment

halfprice Jun 19, 2021

Choose a reason for hiding this comment

halfprice commented Jun 19, 2021

xumengpanda commented Jun 19, 2021

foundationdb-ci commented Jun 19, 2021

AWS CodeBuild CI Report

halfprice Jun 20, 2021

Choose a reason for hiding this comment

kakaiu commented Jun 18, 2021 •

edited

kakaiu Jun 19, 2021 •

edited