summaryrefslogtreecommitdiff
diff options
context:
space:
mode:
Diffstat
-rw-r--r--src/mongo/db/single_transaction_stats.cpp17
-rw-r--r--src/mongo/db/single_transaction_stats.h6
-rw-r--r--src/mongo/db/transaction_participant.cpp21
-rw-r--r--src/mongo/db/transaction_participant.h8
-rw-r--r--src/mongo/db/transaction_participant_test.cpp72
5 files changed, 81 insertions, 43 deletions
diff --git a/src/mongo/db/single_transaction_stats.cpp b/src/mongo/db/single_transaction_stats.cpp
index 0660752e41e..e0137d63148 100644
--- a/src/mongo/db/single_transaction_stats.cpp
+++ b/src/mongo/db/single_transaction_stats.cpp
@@ -55,13 +55,16 @@ Microseconds SingleTransactionStats::getDuration(TickSource* tickSource,
Microseconds SingleTransactionStats::getPreparedDuration(TickSource* tickSource,
TickSource::Tick curTick) const {
invariant(_startTime > 0);
- invariant(_preparedStartTime > 0);
-
- // If the transaction hasn't ended yet, we return how long it has currently been running for.
- if (_endTime == 0) {
- return tickSource->ticksTo<Microseconds>(curTick - _preparedStartTime);
+ if (_preparedStartTime != boost::none) {
+ // If the transaction hasn't ended yet, we return how long it has currently been running
+ // for.
+ invariant(_preparedStartTime.get() > 0);
+ if (_endTime == 0) {
+ return tickSource->ticksTo<Microseconds>(curTick - _preparedStartTime.get());
+ }
+ return tickSource->ticksTo<Microseconds>(_endTime - _preparedStartTime.get());
}
- return tickSource->ticksTo<Microseconds>(_endTime - _preparedStartTime);
+ return Microseconds(0);
}
void SingleTransactionStats::setPreparedStartTime(TickSource::Tick time) {
@@ -140,7 +143,7 @@ void SingleTransactionStats::report(BSONObjBuilder* builder,
builder->append("timeActiveMicros", timeActive);
builder->append("timeInactiveMicros", timeInactive);
- if (_preparedStartTime > 0) {
+ if (_preparedStartTime != boost::none) {
auto timePrepared = durationCount<Microseconds>(getPreparedDuration(tickSource, curTick));
builder->append("timePreparedMicros", timePrepared);
}
diff --git a/src/mongo/db/single_transaction_stats.h b/src/mongo/db/single_transaction_stats.h
index 6c5bbe860c2..e13bdd8635c 100644
--- a/src/mongo/db/single_transaction_stats.h
+++ b/src/mongo/db/single_transaction_stats.h
@@ -259,8 +259,10 @@ private:
// Holds information about the last client to run a transaction operation.
LastClientInfo _lastClientInfo;
- // The time at which a transaction enters the prepared state.
- TickSource::Tick _preparedStartTime{0};
+ // The time at which a transaction becomes prepared. It is possible for _preparedStartTime to
+ // not be set in a transaction that is in state kPrepared if an exception is thrown after the
+ // transaction transitions to the prepared state but before setPreparedStartTime is called.
+ boost::optional<TickSource::Tick> _preparedStartTime{boost::none};
};
} // namespace mongo
diff --git a/src/mongo/db/transaction_participant.cpp b/src/mongo/db/transaction_participant.cpp
index b8b76d1864d..c45caef9ed8 100644
--- a/src/mongo/db/transaction_participant.cpp
+++ b/src/mongo/db/transaction_participant.cpp
@@ -1434,8 +1434,7 @@ void TransactionParticipant::_reportTransactionStats(WithLock wl,
std::string TransactionParticipant::_transactionInfoForLog(
const SingleThreadedLockStats* lockStats,
TransactionState::StateFlag terminationCause,
- repl::ReadConcernArgs readConcernArgs,
- bool wasPrepared) {
+ repl::ReadConcernArgs readConcernArgs) {
invariant(lockStats);
invariant(terminationCause == TransactionState::kCommitted ||
terminationCause == TransactionState::kAborted);
@@ -1488,11 +1487,14 @@ std::string TransactionParticipant::_transactionInfoForLog(
s << " "
<< duration_cast<Milliseconds>(singleTransactionStats.getDuration(tickSource, curTick));
- s << " wasPrepared:" << wasPrepared;
- if (wasPrepared) {
- s << " totalPreparedDurationMicros:"
- << durationCount<Microseconds>(
- singleTransactionStats.getPreparedDuration(tickSource, curTick));
+ // It is possible for a slow transaction to have aborted in the prepared state if an
+ // exception was thrown before prepareTransaction succeeds.
+ const auto totalPreparedDuration = durationCount<Microseconds>(
+ singleTransactionStats.getPreparedDuration(tickSource, curTick));
+ const bool txnWasPrepared = totalPreparedDuration > 0;
+ s << " wasPrepared:" << txnWasPrepared;
+ if (txnWasPrepared) {
+ s << " totalPreparedDurationMicros:" << totalPreparedDuration;
}
return s.str();
@@ -1508,10 +1510,9 @@ void TransactionParticipant::_logSlowTransaction(WithLock wl,
// Log the transaction if its duration is longer than the slowMS command threshold.
if (_transactionMetricsObserver.getSingleTransactionStats().getDuration(
tickSource, tickSource->getTicks()) > Milliseconds(serverGlobalParams.slowMS)) {
- bool wasPrepared = !_prepareOpTime.isNull();
log(logger::LogComponent::kTransaction)
- << "transaction " << _transactionInfoForLog(
- lockStats, terminationCause, readConcernArgs, wasPrepared);
+ << "transaction "
+ << _transactionInfoForLog(lockStats, terminationCause, readConcernArgs);
}
}
}
diff --git a/src/mongo/db/transaction_participant.h b/src/mongo/db/transaction_participant.h
index e778de94cd3..e7c69a69c76 100644
--- a/src/mongo/db/transaction_participant.h
+++ b/src/mongo/db/transaction_participant.h
@@ -280,12 +280,11 @@ public:
std::string transactionInfoForLogForTest(const SingleThreadedLockStats* lockStats,
bool committed,
- repl::ReadConcernArgs readConcernArgs,
- bool wasPrepared) {
+ repl::ReadConcernArgs readConcernArgs) {
stdx::lock_guard<stdx::mutex> lk(_mutex);
TransactionState::StateFlag terminationCause =
committed ? TransactionState::kCommitted : TransactionState::kAborted;
- return _transactionInfoForLog(lockStats, terminationCause, readConcernArgs, wasPrepared);
+ return _transactionInfoForLog(lockStats, terminationCause, readConcernArgs);
}
/**
@@ -695,8 +694,7 @@ private:
// passed in order for this method to be called.
std::string _transactionInfoForLog(const SingleThreadedLockStats* lockStats,
TransactionState::StateFlag terminationCause,
- repl::ReadConcernArgs readConcernArgs,
- bool wasPrepared);
+ repl::ReadConcernArgs readConcernArgs);
// Reports transaction stats for both active and inactive transactions using the provided
// builder. The lock may be either a lock on _mutex or a lock on _metricsMutex.
diff --git a/src/mongo/db/transaction_participant_test.cpp b/src/mongo/db/transaction_participant_test.cpp
index 0f0eaa0c534..be01a7d2db2 100644
--- a/src/mongo/db/transaction_participant_test.cpp
+++ b/src/mongo/db/transaction_participant_test.cpp
@@ -3177,8 +3177,8 @@ TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterCommit) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
- std::string testTransactionInfo = txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, true, readConcernArgs, false);
+ std::string testTransactionInfo =
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, true, readConcernArgs);
std::string expectedTransactionInfo =
buildTransactionInfoString(opCtx(),
@@ -3223,8 +3223,8 @@ TEST_F(TransactionsMetricsTest, TestPreparedTransactionInfoForLogAfterCommit) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
- std::string testTransactionInfo = txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, true, readConcernArgs, true);
+ std::string testTransactionInfo =
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, true, readConcernArgs);
std::string expectedTransactionInfo =
buildTransactionInfoString(opCtx(),
@@ -3261,8 +3261,8 @@ TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterAbort) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
- std::string testTransactionInfo = txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, false, readConcernArgs, false);
+ std::string testTransactionInfo =
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
std::string expectedTransactionInfo =
buildTransactionInfoString(opCtx(),
@@ -3304,8 +3304,8 @@ TEST_F(TransactionsMetricsTest, TestPreparedTransactionInfoForLogAfterAbort) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
- std::string testTransactionInfo = txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, false, readConcernArgs, true);
+ std::string testTransactionInfo =
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
std::string expectedTransactionInfo =
buildTransactionInfoString(opCtx(),
@@ -3338,7 +3338,7 @@ DEATH_TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogWithNoLockerInfoS
txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction");
txnParticipant->commitUnpreparedTransaction(opCtx());
- txnParticipant->transactionInfoForLogForTest(nullptr, true, readConcernArgs, false);
+ txnParticipant->transactionInfoForLogForTest(nullptr, true, readConcernArgs);
}
TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) {
@@ -3372,8 +3372,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
std::string expectedTransactionInfo = "transaction " +
- txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, true, readConcernArgs, false);
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, true, readConcernArgs);
ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
}
@@ -3411,8 +3410,7 @@ TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowCommit) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
std::string expectedTransactionInfo = "transaction " +
- txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, true, readConcernArgs, true);
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, true, readConcernArgs);
ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
}
@@ -3447,8 +3445,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
std::string expectedTransactionInfo = "transaction " +
- txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, false, readConcernArgs, false);
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
}
@@ -3484,8 +3481,46 @@ TEST_F(TransactionsMetricsTest, LogPreparedTransactionInfoAfterSlowAbort) {
const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
ASSERT(lockerInfo);
std::string expectedTransactionInfo = "transaction " +
- txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, false, readConcernArgs, true);
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
+ ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
+}
+
+TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterExceptionInPrepare) {
+ auto tickSource = initMockTickSource();
+ auto sessionCheckout = checkOutSession();
+
+ repl::ReadConcernArgs readConcernArgs;
+ ASSERT_OK(readConcernArgs.initialize(BSON("find"
+ << "test"
+ << repl::ReadConcernArgs::kReadConcernFieldName
+ << BSON(repl::ReadConcernArgs::kLevelFieldName
+ << "snapshot"))));
+ repl::ReadConcernArgs::get(opCtx()) = readConcernArgs;
+
+ auto txnParticipant = TransactionParticipant::get(opCtx());
+
+ // Initialize SingleTransactionStats AdditiveMetrics objects.
+ const int metricValue = 1;
+ setupAdditiveMetrics(metricValue, opCtx());
+
+ txnParticipant->unstashTransactionResources(opCtx(), "prepareTransaction");
+ serverGlobalParams.slowMS = 10;
+ tickSource->advance(Microseconds(11 * 1000));
+
+ _opObserver->onTransactionPrepareThrowsException = true;
+
+ startCapturingLogMessages();
+ ASSERT_THROWS_CODE(txnParticipant->prepareTransaction(opCtx(), {}),
+ AssertionException,
+ ErrorCodes::OperationFailed);
+ ASSERT_FALSE(_opObserver->transactionPrepared);
+ ASSERT(txnParticipant->transactionIsAborted());
+ stopCapturingLogMessages();
+
+ const auto lockerInfo = opCtx()->lockState()->getLockerInfo(boost::none);
+ ASSERT(lockerInfo);
+ std::string expectedTransactionInfo = "transaction " +
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
}
@@ -3525,8 +3560,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) {
stopCapturingLogMessages();
std::string expectedTransactionInfo = "transaction " +
- txnParticipant->transactionInfoForLogForTest(
- &lockerInfo->stats, false, readConcernArgs, false);
+ txnParticipant->transactionInfoForLogForTest(&lockerInfo->stats, false, readConcernArgs);
ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
}
View Lorry Controller Status