1818
1919package org .apache .cassandra .tcm ;
2020
21+ import java .util .concurrent .locks .ReentrantLock ;
2122import java .util .function .Supplier ;
2223
2324import org .slf4j .Logger ;
@@ -41,6 +42,44 @@ public abstract class AbstractLocalProcessor implements Processor
4142
4243 protected final LocalLog log ;
4344
45+ /**
46+ * Serialises the read-execute-propose cycle for commits originating on this node, i.e.
47+ * {@link LocalLog#waitForHighestConsecutive}, execution of the transformation, the {@link #tryCommitOne} proposal
48+ * and, when that proposal wins its epoch, the subsequent {@link LocalLog#append}.
49+ *
50+ * Invariants:
51+ * <ul>
52+ * <li>acquisition waits at most the caller's remaining {@link Retry} deadline, so being queued consumes only
53+ * the waiter's own budget and can never push it past its own deadline;</li>
54+ * <li>every successful acquisition is matched by exactly one unlock;</li>
55+ * <li>it is held across one whole cycle, including the blocking and remote work that cycle needs, and is
56+ * released before everything which is not part of deriving and proposing an epoch: local enactment via
57+ * {@link LocalLog#awaitAtLeast}, the uninterruptible retry backoff, and any log fetch performed after a
58+ * rejection or a lost epoch;</li>
59+ * <li>admission is fair, hence FIFO, and does not prioritise by {@link Transformation.Kind}: a topology
60+ * change can queue behind schema DDL which arrived first.</li>
61+ * </ul>
62+ *
63+ * This does not, and cannot, address races between separate CMS members; those remain the distributed log's job.
64+ */
65+ private final ReentrantLock proposalLock = new ReentrantLock (true );
66+
67+ /**
68+ * What a single read-execute-propose cycle concluded, so that the cycle can hand off to the code which acts on it
69+ * after {@link #proposalLock} has been released.
70+ */
71+ private enum Outcome
72+ {
73+ /** The proposal won its epoch and has been appended to the local log. */
74+ APPLIED ,
75+ /** Execution against the latest local metadata was rejected; nothing was proposed. */
76+ REJECTED ,
77+ /** The proposal did not win its epoch, or its outcome is unknown. */
78+ NOT_APPLIED ,
79+ /** The proposal threw; the throwable is reported and inspected once the lock has been released. */
80+ FAILED
81+ }
82+
4483 public AbstractLocalProcessor (LocalLog log )
4584 {
4685 this .log = log ;
@@ -57,35 +96,99 @@ public final Commit.Result commit(Entry.Id entryId, Transformation transform, fi
5796 String transformStr = transform .toString (); // convert once as idempotent and used in multiple logs
5897 logger .debug ("Starting local commit of {} with policy {}" , transformStr , retryPolicy );
5998 long commitStart = nanoTime ();
99+ // History, not per-iteration state: set immediately before the first tryCommitOne call and never cleared, so
100+ // that the failure message below can only claim nothing was proposed while it is still false.
101+ boolean proposalAttempted = false ;
60102 while (!retryPolicy .hasExpired ())
61103 {
62- ClusterMetadata previous = log .waitForHighestConsecutive ();
63- if (!acceptCommit (previous ))
64- {
65- String msg = String .format ("Node %s is not a CMS member in epoch %s; members=%s" ,
66- FBUtilities .getBroadcastAddressAndPort (),
67- previous .epoch .getEpoch (),
68- previous .fullCMSMembers ());
69- logger .warn (msg );
70- throw new NotCMSException (msg );
71- }
104+ // Serialise the read-execute-propose cycle for locally originating commits. Acquisition consumes this
105+ // caller's own deadline, so a request which cannot be admitted in time gives up here rather than proposing.
106+ if (!acquireProposalLock (retryPolicy ))
107+ return notAdmitted (transformStr , commitStart , retryPolicy , proposalAttempted );
72108
109+ ClusterMetadata previous ;
73110 Transformation .Result result ;
74- if (!transform .eligibleToCommit (previous ))
111+ Outcome outcome ;
112+ Throwable failure = null ;
113+ // The one critical section: read the highest consecutive metadata, execute against it, propose the derived
114+ // epoch and, if the proposal won, append it locally. Nothing else belongs here, and the lock is dropped in
115+ // the single finally below before any of the outcomes are acted on.
116+ try
75117 {
76- result = new Transformation .Rejected (INVALID , "Transformation rejected, can't commit " + transformStr +
77- " it not supported with cluster common serialization version " + previous .directory .commonSerializationVersion +
78- " and min/max serialization versions " + previous .directory .clusterMinVersion + "/" + previous .directory .clusterMaxVersion );
118+ previous = log .waitForHighestConsecutive ();
119+ if (!acceptCommit (previous ))
120+ {
121+ String msg = String .format ("Node %s is not a CMS member in epoch %s; members=%s" ,
122+ FBUtilities .getBroadcastAddressAndPort (),
123+ previous .epoch .getEpoch (),
124+ previous .fullCMSMembers ());
125+ logger .warn (msg );
126+ throw new NotCMSException (msg );
127+ }
128+
129+ if (!transform .eligibleToCommit (previous ))
130+ {
131+ result = new Transformation .Rejected (INVALID , "Transformation rejected, can't commit " + transformStr +
132+ " it not supported with cluster common serialization version " + previous .directory .commonSerializationVersion +
133+ " and min/max serialization versions " + previous .directory .clusterMinVersion + "/" + previous .directory .clusterMaxVersion );
134+ }
135+ else
136+ {
137+ result = executeStrictly (previous , transform );
138+ }
139+
140+ if (result .isRejected ())
141+ {
142+ // Nothing to propose; the catch-up which decides whether this rejection is final happens after the
143+ // lock is released, as it may involve remote peers.
144+ outcome = Outcome .REJECTED ;
145+ }
146+ else
147+ {
148+ try
149+ {
150+ Epoch nextEpoch = result .success ().metadata .epoch ;
151+ // If metadata applies, try committing it to the log
152+ long casStart = nanoTime ();
153+ proposalAttempted = true ;
154+ boolean applied = tryCommitOne (entryId , transform , previous .epoch , nextEpoch );
155+ long casElapsedUs = NANOSECONDS .toMicros (nanoTime () - casStart );
156+ logger .debug ("tryCommitOne for {} epoch {}->{}: applied={}, took {}us" ,
157+ transform .kind (), previous .epoch , nextEpoch , applied , casElapsedUs );
158+
159+ // Application here semantially means "succeeded in committing to the distributed log".
160+ if (applied )
161+ {
162+ logger .info ("Committed {}. New epoch is {}. Took {} attempts in {}us total." ,
163+ transformStr , nextEpoch , retryPolicy .attempts (),
164+ NANOSECONDS .toMicros (nanoTime () - commitStart ));
165+ log .append (new Entry (entryId , nextEpoch , new Transformation .Executed (transform , result )));
166+ outcome = Outcome .APPLIED ;
167+ }
168+ else
169+ {
170+ outcome = Outcome .NOT_APPLIED ;
171+ }
172+ }
173+ catch (Throwable e )
174+ {
175+ // Reported and inspected outside the lock, so that neither is done while holding it.
176+ failure = e ;
177+ outcome = Outcome .FAILED ;
178+ }
179+ }
79180 }
80- else
181+ finally
81182 {
82- result = executeStrictly ( previous , transform );
183+ proposalLock . unlock ( );
83184 }
84185
85- // If we got a rejection, it could be that _we_ are not aware of the highest epoch.
86- // Just try to catch up to the latest distributed state .
87- if (result . isRejected () )
186+ // Everything from here on runs without the lock: it is either remote, uninterruptible, or waits on the
187+ // local log being caught up, and none of it is part of deriving and proposing an epoch .
188+ if (outcome == Outcome . REJECTED )
88189 {
190+ // If we got a rejection, it could be that _we_ are not aware of the highest epoch.
191+ // Just try to catch up to the latest distributed state.
89192 // Use a dedicated retry policy here as the one for the commit itself may not be appropriate.
90193 // It uses the wrong metric and for STARTUP transformations will retry indefinitely, which is not
91194 // what we want here.
@@ -107,43 +210,43 @@ public final Commit.Result commit(Entry.Id entryId, Transformation transform, fi
107210 continue ;
108211 }
109212
213+ if (outcome == Outcome .FAILED )
214+ {
215+ logger .error ("Caught error while trying to perform a local commit" , failure );
216+ JVMStabilityInspector .inspectThrowable (failure );
217+ if (!retryPolicy .maybeSleep ())
218+ break ;
219+ continue ;
220+ }
221+
110222 try
111223 {
112- Epoch nextEpoch = result .success ().metadata .epoch ;
113- // If metadata applies, try committing it to the log
114- long casStart = nanoTime ();
115- boolean applied = tryCommitOne (entryId , transform , previous .epoch , nextEpoch );
116- long casElapsedUs = NANOSECONDS .toMicros (nanoTime () - casStart );
117- logger .debug ("tryCommitOne for {} epoch {}->{}: applied={}, took {}us" ,
118- transform .kind (), previous .epoch , nextEpoch , applied , casElapsedUs );
119-
120- // Application here semantially means "succeeded in committing to the distributed log".
121- if (applied )
224+ if (outcome == Outcome .APPLIED )
122225 {
123- logger . info ( "Committed {}. New epoch is {}. Took {} attempts in {}us total." ,
124- transformStr , nextEpoch , retryPolicy . attempts (),
125- NANOSECONDS . toMicros ( nanoTime () - commitStart ));
126- log . append ( new Entry ( entryId , nextEpoch , new Transformation . Executed ( transform , result ))) ;
226+ // The proposal is durable in the distributed log and appended locally, so the next proposer can
227+ // already derive its epoch from it. Holding the lock across this wait would serialise the local
228+ // enactment latency of this commit onto unrelated ones.
229+ Epoch nextEpoch = result . success (). metadata . epoch ;
127230 log .awaitAtLeast (nextEpoch );
128231
129- return new Commit .Result .Success (result . success (). metadata . epoch ,
232+ return new Commit .Result .Success (nextEpoch ,
130233 toLogState (result .success (), entryId , lastKnown , transform ));
131234 }
132- else
133- {
134- if (! retryPolicy . maybeSleep ())
135- break ;
136-
137- logger . info ( "Backed off after failure to commit to log, fetching latest log entries before retry" );
138- // TODO: could also add epoch from mis-application from [applied].
139- // Use a dedicated retry policy here as the one for the commit itself may not be appropriate .
140- // It uses the wrong metric and for STARTUP transformations will retry indefinitely, which is not
141- // what we want here.
142- Retry fetchLogRetry = Retry . until ( retryPolicy . deadlineNanos , TCMMetrics . instance . fetchLogRetries );
143- fetchLogAndWait ( null , fetchLogRetry );
144- logger . info ( "Fetched latest log entries, re-entering commit retry loop with {}ms remaining until deadline" ,
145- NANOSECONDS . toMillis ( retryPolicy . remainingNanos ()));
146- }
235+
236+ // Lost the epoch, or the outcome is unknown. Back off, then refetch: the sleep is uninterruptible and
237+ // the fetch may be remote, neither of which should block another local proposer.
238+ if (! retryPolicy . maybeSleep ())
239+ break ;
240+
241+ logger . info ( "Backed off after failure to commit to log, fetching latest log entries before retry" );
242+ // TODO: could also add epoch from mis-application from [applied] .
243+ // Use a dedicated retry policy here as the one for the commit itself may not be appropriate.
244+ // It uses the wrong metric and for STARTUP transformations will retry indefinitely, which is not
245+ // what we want here.
246+ Retry fetchLogRetry = Retry . until ( retryPolicy . deadlineNanos , TCMMetrics . instance . fetchLogRetries );
247+ fetchLogAndWait ( null , fetchLogRetry );
248+ logger . info ( "Fetched latest log entries, re-entering commit retry loop with {}ms remaining until deadline" ,
249+ NANOSECONDS . toMillis ( retryPolicy . remainingNanos ()));
147250 }
148251 catch (Throwable e )
149252 {
@@ -153,14 +256,73 @@ public final Commit.Result commit(Entry.Id entryId, Transformation transform, fi
153256 break ;
154257 }
155258 }
156- long remainingMillis = NANOSECONDS .toMillis (retryPolicy .remainingNanos ());
157259 String failureMsg = String .format ("Could not perform commit after %d attempts. Time remaining: %dms" ,
158- retryPolicy .attempts (), remainingMillis );
260+ retryPolicy .attempts (), NANOSECONDS .toMillis (retryPolicy .remainingNanos ()));
261+ return failed (transformStr , commitStart , failureMsg );
262+ }
263+
264+ /**
265+ * Builds the failure for a commit which could not be admitted to {@link #proposalLock} within its deadline. Either
266+ * shutdown or a cancelled request, or simply too many local commits queued ahead of this one.
267+ *
268+ * @param proposalAttempted whether any earlier iteration already reached {@link #tryCommitOne}. If it did, its
269+ * outcome may be genuinely unknown, as losing the epoch and an ambiguous Paxos result are indistinguishable
270+ * to us, so the message states only what happened and promises nothing about whether the transformation
271+ * applied. If it did not, retrying is unambiguously safe, and reporting an attempt count would imply CAS
272+ * activity which did not happen.
273+ */
274+ private Commit .Result notAdmitted (String transformStr , long commitStart , Retry retryPolicy , boolean proposalAttempted )
275+ {
276+ String cause = Thread .currentThread ().isInterrupted ()
277+ ? "Interrupted while waiting to submit commit"
278+ : String .format ("Timed out after %dms waiting to submit commit" ,
279+ NANOSECONDS .toMillis (nanoTime () - commitStart ));
280+ long remainingMillis = NANOSECONDS .toMillis (retryPolicy .remainingNanos ());
281+ String failureMsg = proposalAttempted
282+ ? String .format ("%s. A proposal was made during one of the preceding %d attempts, so " +
283+ "whether the transformation was committed to the log is unknown. " +
284+ "Time remaining: %dms" ,
285+ cause , retryPolicy .attempts (), remainingMillis )
286+ : String .format ("%s. No proposal was made. Time remaining: %dms" , cause , remainingMillis );
287+ return failed (transformStr , commitStart , failureMsg );
288+ }
289+
290+ private Commit .Result failed (String transformStr , long commitStart , String failureMsg )
291+ {
159292 logger .debug ("Commit {} failed in {}us total. {}" ,
160293 transformStr , NANOSECONDS .toMicros (nanoTime () - commitStart ), failureMsg );
161294 return Commit .Result .failed (SERVER_ERROR , failureMsg );
162295 }
163296
297+ /**
298+ * Acquires {@link #proposalLock}, waiting no longer than the caller's remaining deadline. Every successful
299+ * acquisition is matched by exactly one unlock in the {@code finally} which closes the critical section, so
300+ * hold-count accounting is safe on a thread which is already mid-cycle: a nested acquisition only raises the
301+ * count, and releasing it cannot free the lock out from under the outer cycle. That is an accounting invariant
302+ * only; it does not assert that a nested commit is semantically safe, as a synchronous pre-commit listener could
303+ * recursively encounter the same pending entry. No current production listener does this.
304+ *
305+ * @return true if the lock is held by the calling thread on return, false if the deadline expired first or the
306+ * thread was interrupted while waiting, in which case this attempt proposed nothing.
307+ */
308+ private boolean acquireProposalLock (Retry retryPolicy )
309+ {
310+ long remainingNanos = retryPolicy .remainingNanos ();
311+ if (remainingNanos <= 0 )
312+ return false ;
313+
314+ try
315+ {
316+ return proposalLock .tryLock (remainingNanos , NANOSECONDS );
317+ }
318+ catch (InterruptedException e )
319+ {
320+ // Preserve the interrupt for the caller (e.g. so shutdown is not swallowed) and give up on this attempt.
321+ Thread .currentThread ().interrupt ();
322+ return false ;
323+ }
324+ }
325+
164326 public Commit .Result maybeFailure (Entry .Id entryId , Epoch lastKnown , Supplier <Commit .Result .Failure > orElse )
165327 {
166328 LogState logState = toLogState (lastKnown );
0 commit comments