SERVER-35300 Added startTime field to TxnStats to store the start time of a transaction

4 files changed, 226 insertions, 2 deletions

diff --git a/src/mongo/db/session.cpp b/src/mongo/db/session.cpp
index 144c1dd2b10..4f3afc8b8ae 100644
--- a/src/mongo/db/session.cpp
+++ b/src/mongo/db/session.cpp
@@ -600,8 +600,12 @@ void Session::_beginOrContinueTxn(WithLock wl,
         _setActiveTxn(wl, txnNumber);
         _autocommit = false;
         _txnState = MultiDocumentTransactionState::kInProgress;
+        // Tracks various transactions metrics.
+        _singleTransactionStats = SingleTransactionStats();
+        _singleTransactionStats->setStartTime(curTimeMicros64());
         _transactionExpireDate =
-            Date_t::now() + stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()};
+            Date_t::fromMillisSinceEpoch(_singleTransactionStats->getStartTime() / 1000) +
+            stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()};
         ServerTransactionsMetrics::get(getGlobalServiceContext())->incrementTotalStarted();
     } else {
         // Execute a retryable write or snapshot read.
@@ -609,6 +613,7 @@ void Session::_beginOrContinueTxn(WithLock wl,
         _setActiveTxn(wl, txnNumber);
         _autocommit = true;
         _txnState = MultiDocumentTransactionState::kNone;
+        // SingleTransactionStats are only for multi-document transactions.
         _singleTransactionStats = boost::none;
     }
 
@@ -899,12 +904,16 @@ void Session::_abortTransaction(WithLock wl) {
         _txnState == MultiDocumentTransactionState::kCommitted) {
         return;
     }
+    const bool isMultiDocumentTransaction = _txnState == MultiDocumentTransactionState::kInProgress;
     _txnResourceStash = boost::none;
     _transactionOperationBytes = 0;
     _transactionOperations.clear();
     _txnState = MultiDocumentTransactionState::kAborted;
     _speculativeTransactionReadOpTime = repl::OpTime();
     ServerTransactionsMetrics::get(getGlobalServiceContext())->incrementTotalAborted();
+    if (isMultiDocumentTransaction) {
+        _singleTransactionStats->setEndTime(curTimeMicros64());
+    }
 }
 
 void Session::_beginOrContinueTxnOnMigration(WithLock wl, TxnNumber txnNumber) {
@@ -1036,6 +1045,10 @@ void Session::_commitTransaction(stdx::unique_lock<stdx::mutex> lk, OperationCon
     }
     _txnState = MultiDocumentTransactionState::kCommitted;
     ServerTransactionsMetrics::get(opCtx)->incrementTotalCommitted();
+    // After the transaction has been committed, we must update the end time.
+    if (isMultiDocumentTransaction) {
+        _singleTransactionStats->setEndTime(curTimeMicros64());
+    }
 }
 
 BSONObj Session::reportStashedState() const {
diff --git a/src/mongo/db/session.h b/src/mongo/db/session.h
index e6e41083249..a6eee891625 100644
--- a/src/mongo/db/session.h
+++ b/src/mongo/db/session.h
@@ -358,6 +358,10 @@ public:
         return _activeTxnNumber;
     }
 
+    boost::optional<SingleTransactionStats> getSingleTransactionStats() const {
+        return _singleTransactionStats;
+    }
+
     /**
      * If this session is holding stashed locks in _txnResourceStash, reports the current state of
      * the session using the provided builder. Locks the session object's mutex while running.
diff --git a/src/mongo/db/session_test.cpp b/src/mongo/db/session_test.cpp
index 29466f9b1a5..a29ffb11c69 100644
--- a/src/mongo/db/session_test.cpp
+++ b/src/mongo/db/session_test.cpp
@@ -1235,5 +1235,151 @@ TEST_F(SessionTest, IncrementTotalAbortedUponAbort) {
     ASSERT_EQ(ServerTransactionsMetrics::get(opCtx())->getTotalAborted(), beforeAbortCount + 1U);
 }
 
+/**
+ * Test fixture for transactions metrics.
+ */
+class TransactionsMetricsTest : public SessionTest {};
+
+TEST_F(TransactionsMetricsTest, SingleTransactionStatsStartTimeShouldBeSetUponTransactionStart) {
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+
+    // Save the time before the transaction is created.
+    unsigned long long timeBeforeTxn = curTimeMicros64();
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
+    unsigned long long timeAfterTxn = curTimeMicros64();
+
+    // Start time should be greater than or equal to the time before the transaction was created.
+    ASSERT_GTE(session.getSingleTransactionStats()->getStartTime(), timeBeforeTxn);
+
+    // Start time should be less than or equal to the time after the transaction was started.
+    ASSERT_LTE(session.getSingleTransactionStats()->getStartTime(), timeAfterTxn);
+}
+
+TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldBeSetUponCommit) {
+    Session::registerCursorExistsFunction(noopCursorExistsFunction);
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+
+    unsigned long long timeBeforeTxnStart = curTimeMicros64();
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "commitTransaction");
+    unsigned long long timeAfterTxnStart = curTimeMicros64();
+    session.unstashTransactionResources(opCtx(), "commitTransaction");
+    // The transaction machinery cannot store an empty locker.
+    Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow);
+
+    // Sleep here to allow enough time to elapse.
+    sleepmillis(10);
+
+    unsigned long long timeBeforeTxnCommit = curTimeMicros64();
+    session.commitTransaction(opCtx());
+    unsigned long long timeAfterTxnCommit = curTimeMicros64();
+
+    ASSERT_GTE(session.getSingleTransactionStats()->getDuration(),
+               timeBeforeTxnCommit - timeAfterTxnStart);
+
+    ASSERT_LTE(session.getSingleTransactionStats()->getDuration(),
+               timeAfterTxnCommit - timeBeforeTxnStart);
+}
+
+TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldBeSetUponAbort) {
+    Session::registerCursorExistsFunction(noopCursorExistsFunction);
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+
+    unsigned long long timeBeforeTxnStart = curTimeMicros64();
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
+    unsigned long long timeAfterTxnStart = curTimeMicros64();
+    session.unstashTransactionResources(opCtx(), "insert");
+
+    // Sleep here to allow enough time to elapse.
+    sleepmillis(10);
+
+    unsigned long long timeBeforeTxnAbort = curTimeMicros64();
+    session.abortArbitraryTransaction();
+    unsigned long long timeAfterTxnAbort = curTimeMicros64();
+
+    ASSERT_GTE(session.getSingleTransactionStats()->getDuration(),
+               timeBeforeTxnAbort - timeAfterTxnStart);
+
+    ASSERT_LTE(session.getSingleTransactionStats()->getDuration(),
+               timeAfterTxnAbort - timeBeforeTxnStart);
+}
+
+TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasingUntilCommit) {
+    Session::registerCursorExistsFunction(noopCursorExistsFunction);
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "commitTransaction");
+    session.unstashTransactionResources(opCtx(), "commitTransaction");
+    // The transaction machinery cannot store an empty locker.
+    Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow);
+
+    // Save the transaction's duration at this point.
+    unsigned long long txnDurationAfterStart = session.getSingleTransactionStats()->getDuration();
+    sleepmillis(10);
+
+    // The transaction's duration should have increased.
+    ASSERT_GT(session.getSingleTransactionStats()->getDuration(), txnDurationAfterStart);
+    sleepmillis(10);
+    session.commitTransaction(opCtx());
+    unsigned long long txnDurationAfterCommit = session.getSingleTransactionStats()->getDuration();
+
+    // The transaction has committed, so the duration should have not increased.
+    ASSERT_EQ(session.getSingleTransactionStats()->getDuration(), txnDurationAfterCommit);
+
+    ASSERT_GT(txnDurationAfterCommit, txnDurationAfterStart);
+}
+
+TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasingUntilAbort) {
+    Session::registerCursorExistsFunction(noopCursorExistsFunction);
+    const auto sessionId = makeLogicalSessionIdForTest();
+    Session session(sessionId);
+    session.refreshFromStorageIfNeeded(opCtx());
+
+    const TxnNumber txnNum = 1;
+    opCtx()->setLogicalSessionId(sessionId);
+    opCtx()->setTxnNumber(txnNum);
+
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
+    session.unstashTransactionResources(opCtx(), "insert");
+    // The transaction machinery cannot store an empty locker.
+    Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow);
+
+    // Save the transaction's duration at this point.
+    unsigned long long txnDurationAfterStart = session.getSingleTransactionStats()->getDuration();
+    sleepmillis(10);
+
+    // The transaction's duration should have increased.
+    ASSERT_GT(session.getSingleTransactionStats()->getDuration(), txnDurationAfterStart);
+    sleepmillis(10);
+    session.abortArbitraryTransaction();
+    unsigned long long txnDurationAfterAbort = session.getSingleTransactionStats()->getDuration();
+
+    // The transaction has aborted, so the duration should have not increased.
+    ASSERT_EQ(session.getSingleTransactionStats()->getDuration(), txnDurationAfterAbort);
+
+    ASSERT_GT(txnDurationAfterAbort, txnDurationAfterStart);
+}
+
 }  // namespace
 }  // namespace mongo
diff --git a/src/mongo/db/single_transaction_stats.h b/src/mongo/db/single_transaction_stats.h
index 300afb99007..0bcae54d07f 100644
--- a/src/mongo/db/single_transaction_stats.h
+++ b/src/mongo/db/single_transaction_stats.h
@@ -33,6 +33,67 @@ namespace mongo {
 /**
  * Tracks metrics for a single multi-document transaction.
  */
-class SingleTransactionStats {};
+class SingleTransactionStats {
+public:
+    /**
+     * Returns the start time of the transaction in microseconds.
+     *
+     * This method cannot be called until setStartTime() has been called.
+     */
+    unsigned long long getStartTime() const {
+        invariant(_startTime > 0);
+
+        return _startTime;
+    }
+
+    /**
+     * Sets the transaction's start time, only if it hasn't already been set.
+     *
+     * This method must only be called once.
+     */
+    void setStartTime(unsigned long long time) {
+        invariant(_startTime == 0);
+
+        _startTime = time;
+    }
+
+    /**
+     * If the transaction is currently in progress, this method returns the duration
+     * the transaction has been running for in microseconds.
+     *
+     * For a completed transaction, this method returns the total duration of the
+     * transaction in microseconds.
+     *
+     * This method cannot be called until setStartTime() has been called.
+     */
+    unsigned long long getDuration() const {
+        invariant(_startTime > 0);
+
+        // The transaction hasn't ended yet, so we return how long it has currently
+        // been running for.
+        if (_endTime == 0) {
+            return curTimeMicros64() - _startTime;
+        }
+        return _endTime - _startTime;
+    }
+
+    /**
+     * 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.
+     */
+    void setEndTime(unsigned long long time) {
+        invariant(_startTime > 0);
+
+        _endTime = time;
+    }
+
+private:
+    // The start time of the transaction in microseconds.
+    unsigned long long _startTime{0};
+
+    // The end time of the transaction in microseconds.
+    unsigned long long _endTime{0};
+};
 
 }  // namespace mongo