diff options
Diffstat (limited to 'src/mongo/s')
-rw-r--r-- | src/mongo/s/session_catalog_router.cpp | 7 | ||||
-rw-r--r-- | src/mongo/s/session_catalog_router.h | 1 | ||||
-rw-r--r-- | src/mongo/s/transaction_router.cpp | 102 | ||||
-rw-r--r-- | src/mongo/s/transaction_router.h | 52 | ||||
-rw-r--r-- | src/mongo/s/transaction_router_test.cpp | 306 |
5 files changed, 448 insertions, 20 deletions
diff --git a/src/mongo/s/session_catalog_router.cpp b/src/mongo/s/session_catalog_router.cpp index aa4f770bec7..5c35434fe25 100644 --- a/src/mongo/s/session_catalog_router.cpp +++ b/src/mongo/s/session_catalog_router.cpp @@ -34,6 +34,7 @@ #include "mongo/s/session_catalog_router.h" #include "mongo/db/sessions_collection.h" +#include "mongo/s/transaction_router.h" namespace mongo { @@ -68,8 +69,10 @@ int RouterSessionCatalog::reapSessionsOlderThan(OperationContext* opCtx, } RouterOperationContextSession::RouterOperationContextSession(OperationContext* opCtx) - : _operationContextSession(opCtx) {} + : _opCtx(opCtx), _operationContextSession(opCtx) {} -RouterOperationContextSession::~RouterOperationContextSession() = default; +RouterOperationContextSession::~RouterOperationContextSession() { + TransactionRouter::get(_opCtx).stash(_opCtx); +}; } // namespace mongo diff --git a/src/mongo/s/session_catalog_router.h b/src/mongo/s/session_catalog_router.h index 057f9632593..ff54747aeed 100644 --- a/src/mongo/s/session_catalog_router.h +++ b/src/mongo/s/session_catalog_router.h @@ -62,6 +62,7 @@ public: ~RouterOperationContextSession(); private: + OperationContext* _opCtx; OperationContextSession _operationContextSession; }; diff --git a/src/mongo/s/transaction_router.cpp b/src/mongo/s/transaction_router.cpp index 9de327e0d45..4df0158d3dd 100644 --- a/src/mongo/s/transaction_router.cpp +++ b/src/mongo/s/transaction_router.cpp @@ -851,10 +851,12 @@ void TransactionRouter::Router::beginOrContinueTxn(OperationContext* opCtx, repl::ReadConcernArgs::get(opCtx) = o().readConcernArgs; ++p().latestStmtId; + _onContinue(opCtx); break; } case TransactionActions::kCommit: ++p().latestStmtId; + _onContinue(opCtx); break; } } else if (txnNumber > o().txnNumber) { @@ -908,6 +910,12 @@ void TransactionRouter::Router::beginOrContinueTxn(OperationContext* opCtx, _updateLastClientInfo(opCtx->getClient()); } +void TransactionRouter::Router::stash(OperationContext* opCtx) { + auto tickSource = opCtx->getServiceContext()->getTickSource(); + stdx::lock_guard<Client> lk(*opCtx->getClient()); + o(lk).timingStats.trySetInactive(tickSource, tickSource->getTicks()); +} + BSONObj TransactionRouter::Router::_handOffCommitToCoordinator(OperationContext* opCtx) { invariant(o().coordinatorId); auto coordinatorIter = o().participants.find(*o().coordinatorId); @@ -1080,7 +1088,9 @@ BSONObj TransactionRouter::Router::_commitTransaction( } BSONObj TransactionRouter::Router::abortTransaction(OperationContext* opCtx) { - _onExplicitAbort(opCtx); + // Update stats on scope exit so the transaction is considered "active" while waiting on abort + // responses. + auto updateStatsGuard = makeGuard([&] { _onExplicitAbort(opCtx); }); // The router has yet to send any commands to a remote shard for this transaction. // Return the same error that would have been returned by a shard. @@ -1140,7 +1150,9 @@ void TransactionRouter::Router::implicitlyAbortTransaction(OperationContext* opC return; } - _onImplicitAbort(opCtx, errorStatus); + // Update stats on scope exit so the transaction is considered "active" while waiting on abort + // responses. + auto updateStatsGuard = makeGuard([&] { _onImplicitAbort(opCtx, errorStatus); }); if (o().participants.empty()) { return; @@ -1208,9 +1220,8 @@ void TransactionRouter::Router::_resetRouterState(OperationContext* opCtx, p().terminationInitiated = false; auto tickSource = opCtx->getServiceContext()->getTickSource(); - o(lk).timingStats.startTime = tickSource->getTicks(); - o(lk).timingStats.startWallClockTime = - opCtx->getServiceContext()->getPreciseClockSource()->now(); + auto curTicks = tickSource->getTicks(); + o(lk).timingStats.trySetActive(opCtx, curTicks); // TODO SERVER-37115: Parse statement ids from the client and remember the statement id // of the command that started the transaction, if one was included. @@ -1300,8 +1311,6 @@ std::string TransactionRouter::Router::_transactionInfoForLog( invariant(!o().abortCause.empty()); sb << " abortCause:" << o().abortCause << ","; - - // TODO SERVER-40985: Log abortSource } if (o().commitType != CommitType::kNotInitiated) { @@ -1312,9 +1321,13 @@ std::string TransactionRouter::Router::_transactionInfoForLog( << ","; } - // TODO SERVER-41376: Log timeActiveMicros + sb << " timeActiveMicros:" + << durationCount<Microseconds>(o().timingStats.getTimeActiveMicros(tickSource, curTicks)) + << ","; - // TODO SERVER-41376: Log timeInactiveMicros + sb << " timeInactiveMicros:" + << durationCount<Microseconds>(o().timingStats.getTimeInactiveMicros(tickSource, curTicks)) + << ","; // Total duration of the transaction. Logged at the end of the line for consistency with slow // command logging. @@ -1398,6 +1411,13 @@ void TransactionRouter::Router::_onNonRetryableCommitError(OperationContext* opC _endTransactionTrackingIfNecessary(opCtx, TerminationCause::kAborted); } +void TransactionRouter::Router::_onContinue(OperationContext* opCtx) { + auto tickSource = opCtx->getServiceContext()->getTickSource(); + + stdx::lock_guard<Client> lk(*opCtx->getClient()); + o(lk).timingStats.trySetActive(opCtx, tickSource->getTicks()); +} + void TransactionRouter::Router::_onSuccessfulCommit(OperationContext* opCtx) { _endTransactionTrackingIfNecessary(opCtx, TerminationCause::kCommitted); } @@ -1414,13 +1434,14 @@ void TransactionRouter::Router::_endTransactionTrackingIfNecessary( { stdx::lock_guard<Client> lk(*opCtx->getClient()); - o(lk).timingStats.endTime = curTicks; - // If startTime hasn't been set yet, that probably means it run into an error and is - // getting aborted. - if (o().timingStats.startTime == 0) { - o(lk).timingStats.startTime = curTicks; - } + // In some error contexts, the transaction may not have been started yet, so try setting the + // transaction's timing stats to active before ending it below. This is a no-op for already + // active transactions. + o(lk).timingStats.trySetActive(opCtx, curTicks); + + o(lk).timingStats.trySetInactive(tickSource, curTicks); + o(lk).timingStats.endTime = curTicks; } if (shouldLog(logger::LogComponent::kTransaction, logger::LogSeverity::Debug(1)) || @@ -1467,4 +1488,55 @@ Microseconds TransactionRouter::TimingStats::getCommitDuration(TickSource* tickS return tickSource->ticksTo<Microseconds>(endTime - commitStartTime); } +Microseconds TransactionRouter::TimingStats::getTimeActiveMicros(TickSource* tickSource, + TickSource::Tick curTicks) const { + invariant(startTime > 0); + + if (lastTimeActiveStart != 0) { + // The transaction is currently active, so return the active time so far plus the time since + // the transaction became active. + return timeActiveMicros + tickSource->ticksTo<Microseconds>(curTicks - lastTimeActiveStart); + } + return timeActiveMicros; +} + +Microseconds TransactionRouter::TimingStats::getTimeInactiveMicros( + TickSource* tickSource, TickSource::Tick curTicks) const { + invariant(startTime > 0); + + auto micros = getDuration(tickSource, curTicks) - getTimeActiveMicros(tickSource, curTicks); + dassert(micros >= Microseconds(0), + str::stream() << "timeInactiveMicros should never be negative, was: " << micros); + return micros; +} + +void TransactionRouter::TimingStats::trySetActive(OperationContext* opCtx, + TickSource::Tick curTicks) { + if (endTime != 0 || lastTimeActiveStart != 0) { + // A transaction can't become active if it has already ended or is already active. + return; + } + + if (startTime == 0) { + // If the transaction is becoming active for the first time, also set the transaction's + // start time. + startTime = curTicks; + startWallClockTime = opCtx->getServiceContext()->getPreciseClockSource()->now(); + } + lastTimeActiveStart = curTicks; +} + +void TransactionRouter::TimingStats::trySetInactive(TickSource* tickSource, + TickSource::Tick curTicks) { + if (endTime != 0 || lastTimeActiveStart == 0) { + // If the transaction is already over or the router has already been stashed, the relevant + // stats should have been updated earlier. In certain error scenarios, it's possible for a + // transaction to be stashed twice in a row. + return; + } + + timeActiveMicros += tickSource->ticksTo<Microseconds>(curTicks - lastTimeActiveStart); + lastTimeActiveStart = 0; +} + } // namespace mongo diff --git a/src/mongo/s/transaction_router.h b/src/mongo/s/transaction_router.h index 3f1e45d5fa3..10879068894 100644 --- a/src/mongo/s/transaction_router.h +++ b/src/mongo/s/transaction_router.h @@ -134,23 +134,59 @@ public: */ Microseconds getCommitDuration(TickSource* tickSource, TickSource::Tick curTicks) const; + /** + * Returns the total active time of the transaction, given the current time value. A + * transaction is active when there is a running operation that is part of the transaction. + */ + Microseconds getTimeActiveMicros(TickSource* tickSource, TickSource::Tick curTicks) const; + + /** + * Returns the total inactive time of the transaction, given the current time value. A + * transaction is inactive when it is idly waiting for a new operation to occur. + */ + Microseconds getTimeInactiveMicros(TickSource* tickSource, TickSource::Tick curTicks) const; + + /** + * Marks the transaction as active and sets the start of the transaction's active time and + * overall start time the first time it is called. + * + * This method is a no-op if the transaction is currently active or has already ended. + */ + void trySetActive(OperationContext* opCtx, TickSource::Tick curTicks); + + /** + * Marks the transaction as inactive and sets the total active time of the transaction. The + * total active time will only be set if the transaction was active prior to this call. + * + * This method is a no-op if the transaction is not currently active or has already ended. + */ + void trySetInactive(TickSource* tickSource, TickSource::Tick curTicks); + // The start time of the transaction in millisecond resolution. Used only for diagnostics // reporting. Date_t startWallClockTime; // The start time of the transaction. Note that tick values should only ever be used to - // measure distance from other tick values, not for reporting absolute wall clock time. + // measure distance from other tick values, not for reporting absolute wall clock time. A + // value of zero means the transaction hasn't started yet. TickSource::Tick startTime{0}; // The start time of the transaction commit in millisecond resolution. Used only for // diagnostics reporting. Date_t commitStartWallClockTime; - // When commit was started. + // When commit was started. A value of zero means the commit hasn't started yet. TickSource::Tick commitStartTime{0}; - // The end time of the transaction. + // The end time of the transaction. A value of zero means the transaction hasn't ended yet. TickSource::Tick endTime{0}; + + // The total amount of active time spent by the transaction. + Microseconds timeActiveMicros = Microseconds{0}; + + // The time at which the transaction was last marked as active. The transaction is + // considered active if this value is not equal to 0. + TickSource::Tick lastTimeActiveStart{0}; }; enum class TransactionActions { kStart, kContinue, kCommit }; @@ -260,6 +296,11 @@ public: TransactionActions action); /** + * Updates transaction diagnostics when the transaction's session is checked in. + */ + void stash(OperationContext* opCtx); + + /** * Attaches the required transaction related fields for a request to be sent to the given * shard. * @@ -517,6 +558,11 @@ public: void _onNonRetryableCommitError(OperationContext* opCtx, Status commitStatus); /** + * Updates relevent metrics when a transaction is continued. + */ + void _onContinue(OperationContext* opCtx); + + /** * The first time this method is called it marks the transaction as over in the router's * diagnostics and will log transaction information if its duration is over the global * slowMS threshold or the transaction log componenet verbosity >= 1. Only meant to be diff --git a/src/mongo/s/transaction_router_test.cpp b/src/mongo/s/transaction_router_test.cpp index db099d84789..e95252553e5 100644 --- a/src/mongo/s/transaction_router_test.cpp +++ b/src/mongo/s/transaction_router_test.cpp @@ -2794,6 +2794,9 @@ protected: const TxnNumber kTxnNumber = 10; const TxnRecoveryToken kDummyRecoveryToken; + static constexpr auto kDefaultTimeActive = Microseconds(50); + static constexpr auto kDefaultTimeInactive = Microseconds(100); + void setUp() override { TransactionRouterTestWithDefaultSession::setUp(); repl::ReadConcernArgs::get(operationContext()) = repl::ReadConcernArgs(); @@ -2856,6 +2859,16 @@ protected: return guard->hasReadyRequests(); } + void assertTimeActiveIs(Microseconds micros) { + auto stats = txnRouter().getTimingStats(); + ASSERT_EQ(stats.getTimeActiveMicros(tickSource(), tickSource()->getTicks()), micros); + } + + void assertTimeInactiveIs(Microseconds micros) { + auto stats = txnRouter().getTimingStats(); + ASSERT_EQ(stats.getTimeInactiveMicros(tickSource(), tickSource()->getTicks()), micros); + } + // // Helpers for each way a router's transaction may terminate. Meant to be used where the // particular commit type is not being tested. @@ -3051,6 +3064,31 @@ protected: auto routerTxnMetrics() { return RouterTransactionsMetrics::get(operationContext()); } + + void assertTimeActiveAndInactiveCannotAdvance(Microseconds timeActive, + Microseconds timeInactive) { + tickSource()->advance(Microseconds(150)); + assertTimeActiveIs(Microseconds(timeActive)); + assertTimeInactiveIs(Microseconds(timeInactive)); + + txnRouter().stash(operationContext()); + + tickSource()->advance(Microseconds(150)); + assertTimeActiveIs(Microseconds(timeActive)); + assertTimeInactiveIs(Microseconds(timeInactive)); + } + + void setUpDefaultTimeActiveAndInactive() { + tickSource()->advance(kDefaultTimeActive); + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(Microseconds(0)); + + txnRouter().stash(operationContext()); + + tickSource()->advance(kDefaultTimeInactive); + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive); + } }; // @@ -3132,6 +3170,23 @@ TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsDurationAtEnd) { ASSERT_EQUALS(1, countLogLinesContaining(" 111ms\n") + countLogLinesContaining(" 111ms\r\n")); } +TEST_F(TransactionRouterMetricsTest, SlowLoggingPrintsTimeActiveAndInactive) { + beginTxnWithDefaultTxnNumber(); + tickSource()->advance(Microseconds(111)); + assertTimeActiveIs(Microseconds(111)); + + txnRouter().stash(operationContext()); + tickSource()->advance(Microseconds(222)); + assertTimeInactiveIs(Microseconds(222)); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); + runCommit(kDummyOkRes); + + ASSERT_EQUALS(1, countLogLinesContaining("timeActiveMicros:111,")); + ASSERT_EQUALS(1, countLogLinesContaining("timeInactiveMicros:222,")); +} + // // Slow transaction logging tests for the parameters that depend on the read concern level. // @@ -3511,6 +3566,14 @@ TEST_F(TransactionRouterMetricsTest, DurationDoesNotAdvanceAfterImplicitAbort) { assertDurationIs(Microseconds(100)); } +TEST_F(TransactionRouterMetricsTest, DurationIsZeroForAbortedUnstartedTxn) { + // It's possible a transaction that has not been started can be implicitly aborted at server + // shutdown. The duration for such a transaction should be 0. + txnRouter().implicitlyAbortTransaction(operationContext(), kDummyStatus); + + assertDurationIs(Microseconds(0)); +} + TEST_F(TransactionRouterMetricsTest, CommitDurationAdvancesDuringCommit) { beginTxnWithDefaultTxnNumber(); @@ -3615,6 +3678,249 @@ TEST_F(TransactionRouterMetricsTest, DurationsAdvanceAfterUnknownCommitResult) { assertCommitDurationIs(Microseconds(200)); } +TEST_F(TransactionRouterMetricsTest, TimeActiveAndInactiveAdvanceSeparatelyAndSumToDuration) { + beginTxnWithDefaultTxnNumber(); + + // Both timeActive and timeInactive start at 0. + assertTimeActiveIs(Microseconds(0)); + assertTimeInactiveIs(Microseconds(0)); + assertDurationIs(Microseconds(0)); + + // Only timeActive will advance while a txn is active. + tickSource()->advance(Microseconds(50)); + assertTimeActiveIs(Microseconds(50)); + assertTimeInactiveIs(Microseconds(0)); + assertDurationIs(Microseconds(50)); + + // Only timeInactive will advance while a txn is stashed. + txnRouter().stash(operationContext()); + tickSource()->advance(Microseconds(100)); + assertTimeActiveIs(Microseconds(50)); + assertTimeInactiveIs(Microseconds(100)); + assertDurationIs(Microseconds(150)); + + // Will not advance after commit. + // Neither can advance after a successful commit. + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); + runCommit(kDummyOkRes); + + tickSource()->advance(Microseconds(150)); + assertTimeActiveIs(Microseconds(50)); + assertTimeInactiveIs(Microseconds(100)); + assertDurationIs(Microseconds(150)); +} + +TEST_F(TransactionRouterMetricsTest, StashIsIdempotent) { + // An error after checking out a session and before continuing a transaction can lead to + // back-to-back calls to TransactionRouter::stash(), so a repeated call to stash() shouldn't + // toggle the transaction back to the active state. + + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive); + + txnRouter().stash(operationContext()); + + // Only timeInactive can advance. + tickSource()->advance(Microseconds(100)); + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive + Microseconds(100)); + + txnRouter().stash(operationContext()); + + // Still only timeInactive can advance. + tickSource()->advance(Microseconds(100)); + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive + Microseconds(200)); +} + +TEST_F(TransactionRouterMetricsTest, TimeActiveAndInactiveAreZeroForAbortedUnstartedTxn) { + // It's possible a transaction that has not been started can be implicitly aborted at server + // shutdown. The time active and inactive for such a transaction should be 0. + txnRouter().implicitlyAbortTransaction(operationContext(), kDummyStatus); + + assertTimeActiveIs(Microseconds(0)); + assertTimeInactiveIs(Microseconds(0)); +} + +TEST_F(TransactionRouterMetricsTest, DurationsForImplicitlyAbortedStashedTxn) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive); + assertDurationIs(kDefaultTimeActive + kDefaultTimeInactive); + + txnRouter().stash(operationContext()); + + // At shutdown transactions are implicitly aborted without being continued so a transaction may + // be stashed when aborting, which should still lead to durations in a consistent state. + txnRouter().implicitlyAbortTransaction(operationContext(), kDummyStatus); + + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive); + assertDurationIs(kDefaultTimeActive + kDefaultTimeInactive); +} + +TEST_F(TransactionRouterMetricsTest, DurationsForImplicitlyAbortedActiveTxn) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive); + assertDurationIs(kDefaultTimeActive + kDefaultTimeInactive); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kContinue); + tickSource()->advance(Microseconds(100)); + + assertTimeActiveIs(kDefaultTimeActive + Microseconds(100)); + assertTimeInactiveIs(kDefaultTimeInactive); + assertDurationIs(kDefaultTimeActive + kDefaultTimeInactive + Microseconds(100)); + + txnRouter().implicitlyAbortTransaction(operationContext(), kDummyStatus); + + assertTimeActiveIs(kDefaultTimeActive + Microseconds(100)); + assertTimeInactiveIs(kDefaultTimeInactive); + assertDurationIs(kDefaultTimeActive + kDefaultTimeInactive + Microseconds(100)); +} + +TEST_F(TransactionRouterMetricsTest, DurationsForImplicitlyAbortedEndedTxn) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive); + assertDurationIs(kDefaultTimeActive + kDefaultTimeInactive); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); + runCommit(kDummyOkRes); + txnRouter().stash(operationContext()); + + // At shutdown transactions are implicitly aborted without being continued, so an "ended" + // transaction (i.e. committed or aborted) may be implicitly aborted again. This shouldn't + // affect any transaction durations. + auto future = launchAsync( + [&] { return txnRouter().implicitlyAbortTransaction(operationContext(), kDummyStatus); }); + expectAbortTransactions({hostAndPort1}, getSessionId(), kTxnNumber); + future.default_timed_get(); + + assertTimeActiveIs(kDefaultTimeActive); + assertTimeInactiveIs(kDefaultTimeInactive); + assertDurationIs(kDefaultTimeActive + kDefaultTimeInactive); +} + +TEST_F(TransactionRouterMetricsTest, NeitherTimeActiveNorInactiveAdvanceAfterSuccessfulCommit) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); + runCommit(kDummyOkRes); + + // Neither can advance. + assertTimeActiveAndInactiveCannotAdvance(kDefaultTimeActive /*timeActive*/, + kDefaultTimeInactive /*timeInactive*/); +} + +TEST_F(TransactionRouterMetricsTest, NeitherTimeActiveNorInactiveAdvanceAfterFailedCommit) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kContinue); + runCommit(kDummyErrorRes); + + // Neither can advance. + assertTimeActiveAndInactiveCannotAdvance(kDefaultTimeActive /*timeActive*/, + kDefaultTimeInactive /*timeInactive*/); +} + +TEST_F(TransactionRouterMetricsTest, TimeActiveAndInactiveAdvanceAfterUnknownCommitResult) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); + runCommit(Status(ErrorCodes::HostUnreachable, "dummy"), true /* expectRetries */); + + // timeActive can advance. + tickSource()->advance(Microseconds(100)); + assertTimeActiveIs(kDefaultTimeActive + Microseconds(100)); + assertTimeInactiveIs(kDefaultTimeInactive); + + // timeInactive can advance. + txnRouter().stash(operationContext()); + tickSource()->advance(Microseconds(100)); + assertTimeActiveIs(kDefaultTimeActive + Microseconds(100)); + assertTimeInactiveIs(kDefaultTimeInactive + Microseconds(100)); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); + runCommit(kDummyRetryableErrorRes, true /* expectRetries */); + + // timeActive can advance. + tickSource()->advance(Microseconds(100)); + assertTimeActiveIs(kDefaultTimeActive + Microseconds(200)); + assertTimeInactiveIs(kDefaultTimeInactive + Microseconds(100)); + + // timeInactive can advance. + txnRouter().stash(operationContext()); + tickSource()->advance(Microseconds(100)); + assertTimeActiveIs(kDefaultTimeActive + Microseconds(200)); + assertTimeInactiveIs(kDefaultTimeInactive + Microseconds(200)); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kCommit); + runCommit(kDummyOkRes); + + // The result is known, so neither can advance. + assertTimeActiveAndInactiveCannotAdvance(kDefaultTimeActive + Microseconds(200) /*timeActive*/, + kDefaultTimeInactive + + Microseconds(200) /*timeInactive*/); +} + +TEST_F(TransactionRouterMetricsTest, NeitherTimeActiveNorInactiveAdvanceAfterAbort) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kContinue); + ASSERT_THROWS_CODE(txnRouter().abortTransaction(operationContext()), + AssertionException, + ErrorCodes::NoSuchTransaction); + + // Neither can advance. + assertTimeActiveAndInactiveCannotAdvance(kDefaultTimeActive /*timeActive*/, + kDefaultTimeInactive /*timeInactive*/); +} + +TEST_F(TransactionRouterMetricsTest, NeitherTimeActiveNorInactiveAdvanceAfterImplicitAbort) { + beginTxnWithDefaultTxnNumber(); + + setUpDefaultTimeActiveAndInactive(); + + txnRouter().beginOrContinueTxn( + operationContext(), kTxnNumber, TransactionRouter::TransactionActions::kContinue); + txnRouter().implicitlyAbortTransaction(operationContext(), kDummyStatus); + + // Neither can advance. + assertTimeActiveAndInactiveCannotAdvance(kDefaultTimeActive /*timeActive*/, + kDefaultTimeInactive /*timeInactive*/); +} + TEST_F(TransactionRouterMetricsTest, RouterMetricsTotalStarted_DefaultsTo0) { ASSERT_EQUALS(0L, routerTxnMetrics()->getTotalStarted()); } |