SERVER-35433 Log slow transactions when they finish

(cherry picked from commit 70550cf9e211611c396020f0027bd64a6e5b99c0)

3 files changed, 173 insertions, 47 deletions

diff --git a/src/mongo/db/session.cpp b/src/mongo/db/session.cpp
index 80663b88a55..c66d99ea214 100644
--- a/src/mongo/db/session.cpp
+++ b/src/mongo/db/session.cpp
@@ -36,6 +36,7 @@
 #include "mongo/db/commands/feature_compatibility_version_documentation.h"
 #include "mongo/db/commands/test_commands_enabled.h"
 #include "mongo/db/concurrency/lock_state.h"
+#include "mongo/db/concurrency/locker.h"
 #include "mongo/db/concurrency/write_conflict_exception.h"
 #include "mongo/db/db_raii.h"
 #include "mongo/db/dbdirectclient.h"
@@ -856,6 +857,7 @@ void Session::abortActiveTransaction(OperationContext* opCtx) {
     stdx::unique_lock<Client> clientLock(*opCtx->getClient());
     stdx::lock_guard<stdx::mutex> lock(_mutex);
 
+    invariant(!_txnResourceStash);
     if (_txnState != MultiDocumentTransactionState::kInProgress) {
         return;
     }
@@ -880,6 +882,11 @@ void Session::abortActiveTransaction(OperationContext* opCtx) {
     // Update the LastClientInfo object stored in the SingleTransactionStats instance on the Session
     // with this Client's information.
     _singleTransactionStats->updateLastClientInfo(opCtx->getClient());
+
+    // Log the transaction if its duration is longer than the slowMS command threshold.
+    _logSlowTransaction(lock,
+                        &(opCtx->lockState()->getLockerInfo())->stats,
+                        MultiDocumentTransactionState::kAborted);
 }
 
 void Session::_abortTransaction(WithLock wl) {
@@ -890,10 +897,20 @@ void Session::_abortTransaction(WithLock wl) {
         _txnState == MultiDocumentTransactionState::kCommitted) {
         return;
     }
-    const bool isMultiDocumentTransaction = _txnState == MultiDocumentTransactionState::kInProgress;
+
+    if (_txnState == MultiDocumentTransactionState::kInProgress) {
+        auto curTime = curTimeMicros64();
+        _singleTransactionStats->setEndTime(curTime);
+        if (_singleTransactionStats->isActive()) {
+            _singleTransactionStats->setInactive(curTime);
+        }
+    }
 
     // If the transaction is stashed, then we have aborted an inactive transaction.
     if (_txnResourceStash) {
+        _logSlowTransaction(wl,
+                            &(_txnResourceStash->locker()->getLockerInfo())->stats,
+                            MultiDocumentTransactionState::kAborted);
         ServerTransactionsMetrics::get(getGlobalServiceContext())->decrementCurrentInactive();
     } else {
         ServerTransactionsMetrics::get(getGlobalServiceContext())->decrementCurrentActive();
@@ -904,13 +921,6 @@ void Session::_abortTransaction(WithLock wl) {
     _txnState = MultiDocumentTransactionState::kAborted;
     _speculativeTransactionReadOpTime = repl::OpTime();
     ServerTransactionsMetrics::get(getGlobalServiceContext())->incrementTotalAborted();
-    if (isMultiDocumentTransaction) {
-        auto curTime = curTimeMicros64();
-        _singleTransactionStats->setEndTime(curTime);
-        if (_singleTransactionStats->isActive()) {
-            _singleTransactionStats->setInactive(curTime);
-        }
-    }
     ServerTransactionsMetrics::get(getGlobalServiceContext())->decrementCurrentOpen();
 }
 
@@ -1076,6 +1086,11 @@ void Session::_commitTransaction(stdx::unique_lock<stdx::mutex> lk, OperationCon
     // Update the LastClientInfo object stored in the SingleTransactionStats instance on the Session
     // with this Client's information.
     _singleTransactionStats->updateLastClientInfo(opCtx->getClient());
+
+    // Log the transaction if its duration is longer than the slowMS command threshold.
+    _logSlowTransaction(lk,
+                        &(opCtx->lockState()->getLockerInfo())->stats,
+                        MultiDocumentTransactionState::kCommitted);
 }
 
 BSONObj Session::reportStashedState() const {
@@ -1158,12 +1173,11 @@ void Session::_reportTransactionStats(WithLock wl,
     }
 }
 
-std::string Session::transactionInfoForLog(const SingleThreadedLockStats* lockStats) {
-    // Need to lock because this function checks the state of _txnState.
-    stdx::lock_guard<stdx::mutex> lg(_mutex);
-
+std::string Session::_transactionInfoForLog(const SingleThreadedLockStats* lockStats,
+                                            MultiDocumentTransactionState terminationCause) {
     invariant(lockStats);
-    invariant(_txnState.isCommitted(lg) || _txnState.isAborted(lg));
+    invariant(terminationCause == MultiDocumentTransactionState::kCommitted ||
+              terminationCause == MultiDocumentTransactionState::kAborted);
 
     StringBuilder s;
 
@@ -1181,8 +1195,9 @@ std::string Session::transactionInfoForLog(const SingleThreadedLockStats* lockSt
 
     s << _singleTransactionStats->getOpDebug()->additiveMetrics.report();
 
-    std::string terminationCause = _txnState.isCommitted(lg) ? "committed" : "aborted";
-    s << " terminationCause:" << terminationCause;
+    std::string terminationCauseString =
+        terminationCause == MultiDocumentTransactionState::kCommitted ? "committed" : "aborted";
+    s << " terminationCause:" << terminationCauseString;
 
     auto curTime = curTimeMicros64();
     s << " timeActiveMicros:"
@@ -1206,6 +1221,20 @@ std::string Session::transactionInfoForLog(const SingleThreadedLockStats* lockSt
     return s.str();
 }
 
+void Session::_logSlowTransaction(WithLock wl,
+                                  const SingleThreadedLockStats* lockStats,
+                                  MultiDocumentTransactionState terminationCause) {
+    // Only log multi-document transactions.
+    if (_txnState != MultiDocumentTransactionState::kNone) {
+        // Log the transaction if its duration is longer than the slowMS command threshold.
+        if (_singleTransactionStats->getDuration(curTimeMicros64()) >
+            serverGlobalParams.slowMS * 1000ULL) {
+            log(logger::LogComponent::kCommand)
+                << _transactionInfoForLog(lockStats, terminationCause);
+        }
+    }
+}
+
 void Session::_checkValid(WithLock) const {
     uassert(ErrorCodes::ConflictingOperationInProgress,
             str::stream() << "Session " << getSessionId()
diff --git a/src/mongo/db/session.h b/src/mongo/db/session.h
index 7cbfcff92f7..7ae41455d49 100644
--- a/src/mongo/db/session.h
+++ b/src/mongo/db/session.h
@@ -334,6 +334,12 @@ public:
         return _speculativeTransactionReadOpTime;
     }
 
+    const Locker* getTxnResourceStashLockerForTest() const {
+        stdx::lock_guard<stdx::mutex> lk(_mutex);
+        invariant(_txnResourceStash);
+        return _txnResourceStash->locker();
+    }
+
     /**
      * 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.
@@ -353,13 +359,14 @@ public:
      */
     BSONObj reportStashedState() const;
 
-    /**
-     * This method returns a string with information about a slow transaction. The format of the
-     * logging string produced should match the format used for slow operation logging. A
-     * transaction must be completed (committed or aborted) and a valid LockStats reference must be
-     * passed in order for this method to be called.
-     */
-    std::string transactionInfoForLog(const SingleThreadedLockStats* lockStats);
+    std::string transactionInfoForLogForTest(const SingleThreadedLockStats* lockStats,
+                                             bool committed) {
+        stdx::lock_guard<stdx::mutex> lk(_mutex);
+        MultiDocumentTransactionState terminationCause = committed
+            ? MultiDocumentTransactionState::kCommitted
+            : MultiDocumentTransactionState::kAborted;
+        return _transactionInfoForLog(lockStats, terminationCause);
+    }
 
     void addMultikeyPathInfo(MultikeyPathInfo info) {
         _multikeyPathInfo.push_back(std::move(info));
@@ -460,6 +467,29 @@ private:
     // truncated because it was too old.
     bool _hasIncompleteHistory{false};
 
+    // Indicates the state of the current multi-document transaction or snapshot read, if any.  If
+    // the transaction is in any state but kInProgress, no more operations can be collected.
+    enum class MultiDocumentTransactionState {
+        kNone,
+        kInProgress,
+        kCommitting,
+        kCommitted,
+        kAborted
+    } _txnState = MultiDocumentTransactionState::kNone;
+
+    // Logs the transaction information if it has run slower than the global parameter slowMS. The
+    // transaction must be committed or aborted when this function is called.
+    void _logSlowTransaction(WithLock wl,
+                             const SingleThreadedLockStats* lockStats,
+                             MultiDocumentTransactionState terminationCause);
+
+    // This method returns a string with information about a slow transaction. The format of the
+    // logging string produced should match the format used for slow operation logging. A
+    // transaction must be completed (committed or aborted) and a valid LockStats reference must be
+    // passed in order for this method to be called.
+    std::string _transactionInfoForLog(const SingleThreadedLockStats* lockStats,
+                                       MultiDocumentTransactionState terminationCause);
+
     // Reports transaction stats for both active and inactive transactions using the provided
     // builder.
     void _reportTransactionStats(WithLock wl,
@@ -477,16 +507,6 @@ private:
     // Holds transaction resources between network operations.
     boost::optional<TxnResources> _txnResourceStash;
 
-    // Indicates the state of the current multi-document transaction or snapshot read, if any.  If
-    // the transaction is in any state but kInProgress, no more operations can be collected.
-    enum class MultiDocumentTransactionState {
-        kNone,
-        kInProgress,
-        kCommitting,
-        kCommitted,
-        kAborted
-    } _txnState = MultiDocumentTransactionState::kNone;
-
     // Holds oplog data for operations which have been applied in the current multi-document
     // transaction.  Not used for retryable writes.
     std::vector<repl::ReplOperation> _transactionOperations;
diff --git a/src/mongo/db/session_test.cpp b/src/mongo/db/session_test.cpp
index ec5175cbdf1..8d976fa9251 100644
--- a/src/mongo/db/session_test.cpp
+++ b/src/mongo/db/session_test.cpp
@@ -36,6 +36,7 @@
 #include "mongo/db/repl/oplog.h"
 #include "mongo/db/repl/oplog_entry.h"
 #include "mongo/db/repl/optime.h"
+#include "mongo/db/server_options.h"
 #include "mongo/db/server_transactions_metrics.h"
 #include "mongo/db/service_context.h"
 #include "mongo/db/session_catalog.h"
@@ -2301,9 +2302,8 @@ void buildTimeActiveInactiveString(StringBuilder* sb,
 
     // Add time inactive micros to string.
     (*sb) << " timeInactiveMicros:"
-          << session->getSingleTransactionStats()->getDuration(curTime) -
-            durationCount<Microseconds>(
-                 session->getSingleTransactionStats()->getTimeActiveMicros(curTime));
+          << durationCount<Microseconds>(
+                 session->getSingleTransactionStats()->getTimeInactiveMicros(curTime));
 }
 
 
@@ -2364,7 +2364,7 @@ std::string buildTransactionInfoString(OperationContext* opCtx,
 }
 }  // namespace
 
-TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterCommit) {
+TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterCommit) {
     const auto sessionId = makeLogicalSessionIdForTest();
     Session session(sessionId);
     session.refreshFromStorageIfNeeded(opCtx());
@@ -2379,18 +2379,19 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterCommit) {
     setupAdditiveMetrics(metricValue, opCtx());
 
     session.unstashTransactionResources(opCtx(), "commitTransaction");
-    session.commitTransaction(opCtx(), boost::none);
+    session.commitTransaction(opCtx());
 
     const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
     ASSERT(lockerInfo);
-    std::string testTransactionInfo = session.transactionInfoForLog(&lockerInfo->stats);
+    std::string testTransactionInfo =
+        session.transactionInfoForLogForTest(&lockerInfo->stats, true);
 
     std::string expectedTransactionInfo =
         buildTransactionInfoString(opCtx(), &session, "committed", sessionId, txnNum, metricValue);
     ASSERT_EQ(testTransactionInfo, expectedTransactionInfo);
 }
 
-TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterAbort) {
+TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogAfterAbort) {
     const auto sessionId = makeLogicalSessionIdForTest();
     Session session(sessionId);
     session.refreshFromStorageIfNeeded(opCtx());
@@ -2409,14 +2410,15 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterAbort) {
 
     const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
     ASSERT(lockerInfo);
-    std::string testTransactionInfo = session.transactionInfoForLog(&lockerInfo->stats);
+    std::string testTransactionInfo =
+        session.transactionInfoForLogForTest(&lockerInfo->stats, false);
 
     std::string expectedTransactionInfo =
         buildTransactionInfoString(opCtx(), &session, "aborted", sessionId, txnNum, metricValue);
     ASSERT_EQ(testTransactionInfo, expectedTransactionInfo);
 }
 
-DEATH_TEST_F(TransactionsMetricsTest, UnterminatedLogTransactionInfoFails, "invariant") {
+DEATH_TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogWithNoLockerInfoStats, "invariant") {
     const auto sessionId = makeLogicalSessionIdForTest();
     Session session(sessionId);
     session.refreshFromStorageIfNeeded(opCtx());
@@ -2426,12 +2428,42 @@ DEATH_TEST_F(TransactionsMetricsTest, UnterminatedLogTransactionInfoFails, "inva
     opCtx()->setTxnNumber(txnNum);
     session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
 
+    session.unstashTransactionResources(opCtx(), "commitTransaction");
+    session.commitTransaction(opCtx());
+
+    session.transactionInfoForLogForTest(nullptr, true);
+}
+
+TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) {
+    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");
+    // Initialize SingleTransactionStats AdditiveMetrics objects.
+    const int metricValue = 1;
+    setupAdditiveMetrics(metricValue, opCtx());
+
+    session.unstashTransactionResources(opCtx(), "commitTransaction");
+
+    serverGlobalParams.slowMS = 10;
+    sleepmillis(serverGlobalParams.slowMS + 1);
+
+    startCapturingLogMessages();
+    session.commitTransaction(opCtx());
+    stopCapturingLogMessages();
+
     const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
     ASSERT(lockerInfo);
-    session.transactionInfoForLog(&lockerInfo->stats);
+    std::string expectedTransactionInfo =
+        session.transactionInfoForLogForTest(&lockerInfo->stats, true);
+    ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
 }
 
-DEATH_TEST_F(TransactionsMetricsTest, noLockerInfoStatsFails, "invariant") {
+TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) {
     const auto sessionId = makeLogicalSessionIdForTest();
     Session session(sessionId);
     session.refreshFromStorageIfNeeded(opCtx());
@@ -2439,12 +2471,57 @@ DEATH_TEST_F(TransactionsMetricsTest, noLockerInfoStatsFails, "invariant") {
     const TxnNumber txnNum = 1;
     opCtx()->setLogicalSessionId(sessionId);
     opCtx()->setTxnNumber(txnNum);
-    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "testDB", "insert");
+    session.beginOrContinueTxn(opCtx(), txnNum, false, true, "admin", "abortTransaction");
+    // Initialize SingleTransactionStats AdditiveMetrics objects.
+    const int metricValue = 1;
+    setupAdditiveMetrics(metricValue, opCtx());
 
-    session.unstashTransactionResources(opCtx(), "commitTransaction");
-    session.commitTransaction(opCtx(), boost::none);
+    session.unstashTransactionResources(opCtx(), "abortTransaction");
+
+    serverGlobalParams.slowMS = 10;
+    sleepmillis(serverGlobalParams.slowMS + 1);
+
+    startCapturingLogMessages();
+    session.abortActiveTransaction(opCtx());
+    stopCapturingLogMessages();
+
+    const auto lockerInfo = opCtx()->lockState()->getLockerInfo();
+    ASSERT(lockerInfo);
+    std::string expectedTransactionInfo =
+        session.transactionInfoForLogForTest(&lockerInfo->stats, false);
+    ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
+}
+
+TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) {
+    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", "abortTransaction");
+    // Initialize SingleTransactionStats AdditiveMetrics objects.
+    const int metricValue = 1;
+    setupAdditiveMetrics(metricValue, opCtx());
 
-    session.transactionInfoForLog(nullptr);
+    session.unstashTransactionResources(opCtx(), "insert");
+    { Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); }
+    session.stashTransactionResources(opCtx());
+    const auto txnResourceStashLocker = session.getTxnResourceStashLockerForTest();
+    ASSERT(txnResourceStashLocker);
+    const auto lockerInfo = txnResourceStashLocker->getLockerInfo();
+
+    serverGlobalParams.slowMS = 10;
+    sleepmillis(serverGlobalParams.slowMS + 1);
+
+    startCapturingLogMessages();
+    session.abortArbitraryTransaction();
+    stopCapturingLogMessages();
+
+    std::string expectedTransactionInfo =
+        session.transactionInfoForLogForTest(&lockerInfo->stats, false);
+    ASSERT_EQUALS(1, countLogLinesContaining(expectedTransactionInfo));
 }
 
 }  // namespace