SERVER-36501 Add getPreparedDuration metric reporting

4 files changed, 179 insertions, 1 deletions

diff --git a/src/mongo/db/single_transaction_stats.cpp b/src/mongo/db/single_transaction_stats.cpp
index 134879d7b60..0660752e41e 100644
--- a/src/mongo/db/single_transaction_stats.cpp
+++ b/src/mongo/db/single_transaction_stats.cpp
@@ -52,6 +52,24 @@ Microseconds SingleTransactionStats::getDuration(TickSource* tickSource,
     return tickSource->ticksTo<Microseconds>(_endTime - _startTime);
 }
 
+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);
+    }
+    return tickSource->ticksTo<Microseconds>(_endTime - _preparedStartTime);
+}
+
+void SingleTransactionStats::setPreparedStartTime(TickSource::Tick time) {
+    invariant(_startTime > 0);
+
+    _preparedStartTime = time;
+}
+
 void SingleTransactionStats::setEndTime(TickSource::Tick time) {
     invariant(_startTime > 0);
 
@@ -122,6 +140,11 @@ void SingleTransactionStats::report(BSONObjBuilder* builder,
     builder->append("timeActiveMicros", timeActive);
     builder->append("timeInactiveMicros", timeInactive);
 
+    if (_preparedStartTime > 0) {
+        auto timePrepared = durationCount<Microseconds>(getPreparedDuration(tickSource, curTick));
+        builder->append("timePreparedMicros", timePrepared);
+    }
+
     if (_expireDate != Date_t::max()) {
         builder->append("expiryTime", dateToISOStringLocal(_expireDate));
     }
diff --git a/src/mongo/db/single_transaction_stats.h b/src/mongo/db/single_transaction_stats.h
index 54de9bdd2a0..6c5bbe860c2 100644
--- a/src/mongo/db/single_transaction_stats.h
+++ b/src/mongo/db/single_transaction_stats.h
@@ -94,6 +94,26 @@ public:
     Microseconds getDuration(TickSource* tickSource, TickSource::Tick curTick) const;
 
     /**
+     * If the transaction is currently in progress, this method returns the duration
+     * the transaction has been in the prepared state for in microseconds, given the
+     * current time value.
+     *
+     * For a completed transaction, this method returns the total duration the transaction
+     * has been in the prepared state in microseconds.
+     *
+     * This method cannot be called until setStartTime() and setPreparedStartTime() have been
+     * called.
+     */
+    Microseconds getPreparedDuration(TickSource* tickSource, TickSource::Tick curTick) const;
+
+    /**
+     * Sets the time at which a transaction enters the prepared state.
+     *
+     * This method cannot be called until setStartTime() has been called.
+     */
+    void setPreparedStartTime(TickSource::Tick time);
+
+    /**
      * Sets the transaction's end time, only if the start time has already been set.
      *
      * This method cannot be called until setStartTime() has been called.
@@ -238,6 +258,9 @@ 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};
 };
 
 }  // namespace mongo
diff --git a/src/mongo/db/transaction_metrics_observer.cpp b/src/mongo/db/transaction_metrics_observer.cpp
index 28a6f26e696..ec960f69265 100644
--- a/src/mongo/db/transaction_metrics_observer.cpp
+++ b/src/mongo/db/transaction_metrics_observer.cpp
@@ -227,6 +227,12 @@ void TransactionMetricsObserver::_onAbort(ServerTransactionsMetrics* serverTrans
 void TransactionMetricsObserver::onPrepare(ServerTransactionsMetrics* serverTransactionsMetrics,
                                            repl::OpTime prepareOpTime,
                                            TickSource::Tick curTick) {
+
+    //
+    // Per transaction metrics.
+    //
+    _singleTransactionStats.setPreparedStartTime(curTick);
+
     // Since we currently only write an oplog entry for an in progress transaction when it is in
     // the prepare state, the prepareOpTime is currently the oldest OpTime written to the
     // oplog for this transaction.
diff --git a/src/mongo/db/transaction_participant_test.cpp b/src/mongo/db/transaction_participant_test.cpp
index 8330d1dc187..876edf6df1a 100644
--- a/src/mongo/db/transaction_participant_test.cpp
+++ b/src/mongo/db/transaction_participant_test.cpp
@@ -2001,6 +2001,28 @@ TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldBeSetUponCom
         Microseconds(100));
 }
 
+TEST_F(TransactionsMetricsTest, SingleTranasactionStatsPreparedDurationShouldBeSetUponCommit) {
+    auto tickSource = initMockTickSource();
+
+    OperationContextSessionMongod opCtxSession(opCtx(), true, makeSessionInfo());
+    auto txnParticipant = TransactionParticipant::get(opCtx());
+    txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction");
+    // The transaction machinery cannot store an empty locker.
+    Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow);
+
+    // Advance the clock.
+    tickSource->advance(Microseconds(10));
+
+    // Prepare the transaction and extend the duration in the prepared state.
+    const auto preparedTimestamp = txnParticipant->prepareTransaction(opCtx(), {});
+    tickSource->advance(Microseconds(100));
+
+    txnParticipant->commitPreparedTransaction(opCtx(), preparedTimestamp);
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(100));
+}
+
 TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldBeSetUponAbort) {
     auto tickSource = initMockTickSource();
 
@@ -2017,6 +2039,26 @@ TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldBeSetUponAbo
         Microseconds(100));
 }
 
+TEST_F(TransactionsMetricsTest, SingleTransactionStatsPreparedDurationShouldBeSetUponAbort) {
+    auto tickSource = initMockTickSource();
+
+    OperationContextSessionMongod opCtxSession(opCtx(), true, makeSessionInfo());
+    auto txnParticipant = TransactionParticipant::get(opCtx());
+    txnParticipant->unstashTransactionResources(opCtx(), "abortTransaction");
+
+    // Advance the clock.
+    tickSource->advance(Microseconds(10));
+
+    // Prepare the transaction and extend the duration in the prepared state.
+    const auto prepareTimestamp = txnParticipant->prepareTransaction(opCtx(), {});
+    tickSource->advance(Microseconds(100));
+
+    txnParticipant->abortActiveTransaction(opCtx());
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(100));
+}
+
 TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasingUntilCommit) {
     auto tickSource = initMockTickSource();
 
@@ -2048,6 +2090,41 @@ TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasi
         Microseconds(200));
 }
 
+TEST_F(TransactionsMetricsTest,
+       SingleTransactionStatsPreparedDurationShouldKeepIncreasingUntilCommit) {
+    auto tickSource = initMockTickSource();
+
+    OperationContextSessionMongod opCtxSession(opCtx(), true, makeSessionInfo());
+    auto txnParticipant = TransactionParticipant::get(opCtx());
+    txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction");
+    // The transaction machinery cannot store an empty locker.
+    Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow);
+
+    // Prepare the transaction and extend the duration in the prepared state.
+    const auto prepareTimestamp = txnParticipant->prepareTransaction(opCtx(), {});
+    tickSource->advance(Microseconds(100));
+
+    // The prepared transaction's duration should have increased.
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(100));
+
+    tickSource->advance(Microseconds(100));
+
+    // Commit the prepared transaction and check the prepared duration.
+    txnParticipant->commitPreparedTransaction(opCtx(), prepareTimestamp);
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(200));
+
+    // The prepared transaction committed, so the prepared duration shouldn't have increased even if
+    // more time passed.
+    tickSource->advance(Microseconds(100));
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(200));
+}
+
 TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasingUntilAbort) {
     auto tickSource = initMockTickSource();
 
@@ -2079,6 +2156,41 @@ TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasi
         Microseconds(200));
 }
 
+TEST_F(TransactionsMetricsTest,
+       SingleTransactionStatsPreparedDurationShouldKeepIncreasingUntilAbort) {
+    auto tickSource = initMockTickSource();
+
+    OperationContextSessionMongod opCtxSession(opCtx(), true, makeSessionInfo());
+    auto txnParticipant = TransactionParticipant::get(opCtx());
+    txnParticipant->unstashTransactionResources(opCtx(), "abortTransaction");
+    // The transaction machinery cannot store an empty locker.
+    Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow);
+
+    // Prepare the transaction and extend the duration in the prepared state.
+    txnParticipant->prepareTransaction(opCtx(), {});
+    tickSource->advance(Microseconds(100));
+
+    // The prepared transaction's duration should have increased.
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(100));
+
+    tickSource->advance(Microseconds(100));
+
+    // Abort the prepared transaction and check the prepared duration.
+    txnParticipant->abortActiveTransaction(opCtx());
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(200));
+
+    // The prepared transaction aborted, so the prepared duration shouldn't have increased even if
+    // more time passed.
+    tickSource->advance(Microseconds(100));
+    ASSERT_EQ(txnParticipant->getSingleTransactionStats().getPreparedDuration(
+                  tickSource, tickSource->getTicks()),
+              Microseconds(200));
+}
+
 TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldBeSetUponUnstashAndStash) {
     auto tickSource = initMockTickSource();
 
@@ -2499,6 +2611,7 @@ TEST_F(TransactionsMetricsTest, TimeInactiveMicrosShouldIncreaseUntilCommit) {
 
 
 TEST_F(TransactionsMetricsTest, ReportStashedResources) {
+    auto tickSource = initMockTickSource();
     auto clockSource = initMockPreciseClockSource();
     auto startTime = Date_t::now();
     clockSource->reset(startTime);
@@ -2540,6 +2653,11 @@ TEST_F(TransactionsMetricsTest, ReportStashedResources) {
     ASSERT(opCtx()->getWriteUnitOfWork());
     ASSERT(opCtx()->lockState()->isLocked());
 
+    // Prepare the transaction and extend the duration in the prepared state.
+    const auto prepareTimestamp = txnParticipant->prepareTransaction(opCtx(), {});
+    const long preparedDuration = 10;
+    tickSource->advance(Microseconds(preparedDuration));
+
     // Stash resources. The original Locker and RecoveryUnit now belong to the stash.
     txnParticipant->stashTransactionResources(opCtx());
     ASSERT(!opCtx()->getWriteUnitOfWork());
@@ -2565,6 +2683,7 @@ TEST_F(TransactionsMetricsTest, ReportStashedResources) {
     ASSERT_EQ(
         dateFromISOString(transactionDocument.getField("expiryTime").valueStringData()).getValue(),
         startTime + stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()});
+    ASSERT_EQ(transactionDocument.getField("timePreparedMicros").numberLong(), preparedDuration);
 
     ASSERT_EQ(stashedState.getField("client").valueStringData().toString(), "");
     ASSERT_EQ(stashedState.getField("connectionId").numberLong(), 0);
@@ -2592,10 +2711,11 @@ TEST_F(TransactionsMetricsTest, ReportStashedResources) {
     ASSERT(txnParticipant->reportStashedState().isEmpty());
 
     // Commit the transaction. This allows us to release locks.
-    txnParticipant->commitUnpreparedTransaction(opCtx());
+    txnParticipant->commitPreparedTransaction(opCtx(), prepareTimestamp);
 }
 
 TEST_F(TransactionsMetricsTest, ReportUnstashedResources) {
+    auto tickSource = initMockTickSource();
     auto clockSource = initMockPreciseClockSource();
     auto startTime = Date_t::now();
     clockSource->reset(startTime);
@@ -2620,6 +2740,11 @@ TEST_F(TransactionsMetricsTest, ReportUnstashedResources) {
     ASSERT(opCtx()->getWriteUnitOfWork());
     ASSERT(opCtx()->lockState()->isLocked());
 
+    // Prepare transaction and extend duration in the prepared state.
+    const auto prepareTimestamp = txnParticipant->prepareTransaction(opCtx(), {});
+    const long prepareDuration = 10;
+    tickSource->advance(Microseconds(prepareDuration));
+
     // Verify that the Session's report of its own unstashed state aligns with our expectations.
     BSONObjBuilder unstashedStateBuilder;
     txnParticipant->reportUnstashedState(repl::ReadConcernArgs::get(opCtx()),
@@ -2640,6 +2765,7 @@ TEST_F(TransactionsMetricsTest, ReportUnstashedResources) {
     ASSERT_EQ(
         dateFromISOString(transactionDocument.getField("expiryTime").valueStringData()).getValue(),
         startTime + stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()});
+    ASSERT_EQ(transactionDocument.getField("timePreparedMicros").numberLong(), prepareDuration);
 
     // For the following time metrics, we are only verifying that the transaction sub-document is
     // being constructed correctly with proper types because we have other tests to verify that