SERVER-39934 Fix locking for slow ops storage stats

SERVER-39654 Make slow ops storage stats work with transactions

6 files changed, 51 insertions, 27 deletions

diff --git a/src/mongo/db/concurrency/global_lock_acquisition_tracker.cpp b/src/mongo/db/concurrency/global_lock_acquisition_tracker.cpp
index c28bfb643aa..eeec12f3c1a 100644
--- a/src/mongo/db/concurrency/global_lock_acquisition_tracker.cpp
+++ b/src/mongo/db/concurrency/global_lock_acquisition_tracker.cpp
@@ -44,6 +44,10 @@ bool GlobalLockAcquisitionTracker::getGlobalSharedLockTaken() const {
     return _globalLockMode & (1 << MODE_S);
 }
 
+bool GlobalLockAcquisitionTracker::getGlobalLockTaken() const {
+    return _globalLockMode & ((1 << MODE_IX) | (1 << MODE_X) | (1 << MODE_IS) | (1 << MODE_S));
+}
+
 void GlobalLockAcquisitionTracker::setGlobalLockModeBit(LockMode mode) {
     _globalLockMode |= (1 << mode);
 }
diff --git a/src/mongo/db/concurrency/global_lock_acquisition_tracker.h b/src/mongo/db/concurrency/global_lock_acquisition_tracker.h
index 4e3e5f8bcc5..dae19eb537f 100644
--- a/src/mongo/db/concurrency/global_lock_acquisition_tracker.h
+++ b/src/mongo/db/concurrency/global_lock_acquisition_tracker.h
@@ -58,6 +58,11 @@ public:
     bool getGlobalSharedLockTaken() const;
 
     /**
+     * Returns whether we have ever taken a global lock in this operation.
+     */
+    bool getGlobalLockTaken() const;
+
+    /**
      * Sets the mode bit in _globalLockMode. Once a mode bit is set, we won't clear it.
      */
     void setGlobalLockModeBit(LockMode mode);
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index 5d5c1dd1240..5208639bc93 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -44,6 +44,7 @@
 #include "mongo/db/commands.h"
 #include "mongo/db/commands/server_status_metric.h"
 #include "mongo/db/concurrency/d_concurrency.h"
+#include "mongo/db/concurrency/global_lock_acquisition_tracker.h"
 #include "mongo/db/concurrency/locker.h"
 #include "mongo/db/json.h"
 #include "mongo/db/query/getmore_request.h"
@@ -405,15 +406,30 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx,
 
     if (shouldLogOp || (shouldSample && _debug.executionTimeMicros > slowMs * 1000LL)) {
         auto lockerInfo = opCtx->lockState()->getLockerInfo(_lockStatsBase);
-        if (opCtx->getServiceContext()->getStorageEngine()) {
-            // Take a lock before calling into the storage engine to prevent racing against
-            // a shutdown. We can get here and our lock acquisition be interrupted, log a
+        const GlobalLockAcquisitionTracker& globalLockTracker =
+            GlobalLockAcquisitionTracker::get(opCtx);
+        if (_debug.storageStats == nullptr && globalLockTracker.getGlobalLockTaken() &&
+            opCtx->getServiceContext()->getStorageEngine()) {
+            // Do not fetch operation statistics again if we have already got them (for instance,
+            // as a part of stashing the transaction).
+            // Take a lock before calling into the storage engine to prevent racing against a
+            // shutdown. Any operation that used a storage engine would have at-least held a
+            // global lock at one point, hence we limit our lock acquisition to such operations.
+            // We can get here and our lock acquisition be timed out or interrupted, log a
             // message if that happens.
             try {
-                Lock::GlobalLock lk(opCtx, MODE_IS);
-                _debug.storageStats = opCtx->recoveryUnit()->getOperationStatistics();
+                Lock::GlobalLock lk(opCtx,
+                                    MODE_IS,
+                                    Date_t::now() + Milliseconds(500),
+                                    Lock::InterruptBehavior::kLeaveUnlocked);
+                if (lk.isLocked()) {
+                    _debug.storageStats = opCtx->recoveryUnit()->getOperationStatistics();
+                } else {
+                    log(component) << "Timed out obtaining lock while trying to gather storage "
+                                      "statistics for a slow operation";
+                }
             } catch (const ExceptionForCat<ErrorCategory::Interruption>&) {
-                warning()
+                log(component)
                     << "Interrupted while trying to gather storage statistics for a slow operation";
             }
         }
diff --git a/src/mongo/db/transaction_metrics_observer.cpp b/src/mongo/db/transaction_metrics_observer.cpp
index d9e7484e529..156b6cfc091 100644
--- a/src/mongo/db/transaction_metrics_observer.cpp
+++ b/src/mongo/db/transaction_metrics_observer.cpp
@@ -193,10 +193,9 @@ void TransactionMetricsObserver::onAbortInactive(
     }
 }
 
-void TransactionMetricsObserver::onTransactionOperation(
-    Client* client,
-    OpDebug::AdditiveMetrics additiveMetrics,
-    std::shared_ptr<StorageStats> storageStats) {
+void TransactionMetricsObserver::onTransactionOperation(OperationContext* opCtx,
+                                                        OpDebug::AdditiveMetrics additiveMetrics,
+                                                        bool isPrepared) {
     // Add the latest operation stats to the aggregate OpDebug::AdditiveMetrics object stored in the
     // SingleTransactionStats instance on the TransactionMetricsObserver.
     _singleTransactionStats.getOpDebug()->additiveMetrics.add(additiveMetrics);
@@ -204,18 +203,24 @@ void TransactionMetricsObserver::onTransactionOperation(
     // If there are valid storage statistics for this operation, put those in the
     // SingleTransactionStats instance either by creating a new storageStats instance or by adding
     // into an existing storageStats instance stored in SingleTransactionStats.
-    if (storageStats) {
-        if (!_singleTransactionStats.getOpDebug()->storageStats) {
-            _singleTransactionStats.getOpDebug()->storageStats = storageStats->getCopy();
-        } else {
-            *_singleTransactionStats.getOpDebug()->storageStats += *storageStats;
+    // WiredTiger doesn't let storage statistics be collected when transaction is prepared.
+    if (!isPrepared) {
+        std::shared_ptr<StorageStats> storageStats =
+            opCtx->recoveryUnit()->getOperationStatistics();
+        if (storageStats) {
+            CurOp::get(opCtx)->debug().storageStats = storageStats;
+            if (!_singleTransactionStats.getOpDebug()->storageStats) {
+                _singleTransactionStats.getOpDebug()->storageStats = storageStats->getCopy();
+            } else {
+                *_singleTransactionStats.getOpDebug()->storageStats += *storageStats;
+            }
         }
     }
 
     // Update the LastClientInfo object stored in the SingleTransactionStats instance on the
     // TransactionMetricsObserver with this Client's information. This is the last client that ran a
     // transaction operation on the txnParticipant.
-    _singleTransactionStats.updateLastClientInfo(client);
+    _singleTransactionStats.updateLastClientInfo(opCtx->getClient());
 }
 
 void TransactionMetricsObserver::_onAbort(ServerTransactionsMetrics* serverTransactionsMetrics,
diff --git a/src/mongo/db/transaction_metrics_observer.h b/src/mongo/db/transaction_metrics_observer.h
index 7a3b7ad0ecf..71e01ce3e13 100644
--- a/src/mongo/db/transaction_metrics_observer.h
+++ b/src/mongo/db/transaction_metrics_observer.h
@@ -117,9 +117,9 @@ public:
      * Updates relevant metrics and storage statistics when an operation running on the transaction
      * completes. An operation may be a read/write operation, or an abort/commit command.
      */
-    void onTransactionOperation(Client* client,
+    void onTransactionOperation(OperationContext* opCtx,
                                 OpDebug::AdditiveMetrics additiveMetrics,
-                                std::shared_ptr<StorageStats> storageStats);
+                                bool isPrepared);
 
     /**
      * Returns a read-only reference to the SingleTransactionStats object stored in this
diff --git a/src/mongo/db/transaction_participant.cpp b/src/mongo/db/transaction_participant.cpp
index fe4789f2a33..7e5d3334b3d 100644
--- a/src/mongo/db/transaction_participant.cpp
+++ b/src/mongo/db/transaction_participant.cpp
@@ -736,9 +736,7 @@ void TransactionParticipant::Participant::_stashActiveTransaction(OperationConte
         auto tickSource = opCtx->getServiceContext()->getTickSource();
         o(lk).transactionMetricsObserver.onStash(ServerTransactionsMetrics::get(opCtx), tickSource);
         o(lk).transactionMetricsObserver.onTransactionOperation(
-            opCtx->getClient(),
-            CurOp::get(opCtx)->debug().additiveMetrics,
-            CurOp::get(opCtx)->debug().storageStats);
+            opCtx, CurOp::get(opCtx)->debug().additiveMetrics, o().txnState.isPrepared());
     }
 
     invariant(!o().txnResourceStash);
@@ -1256,9 +1254,7 @@ void TransactionParticipant::Participant::_finishCommitTransaction(OperationCont
                                                   &Top::get(getGlobalServiceContext()),
                                                   isCommittingWithPrepare);
         o(lk).transactionMetricsObserver.onTransactionOperation(
-            opCtx->getClient(),
-            CurOp::get(opCtx)->debug().additiveMetrics,
-            CurOp::get(opCtx)->debug().storageStats);
+            opCtx, CurOp::get(opCtx)->debug().additiveMetrics, o().txnState.isPrepared());
     }
     // We must clear the recovery unit and locker so any post-transaction writes can run without
     // transactional settings such as a read timestamp.
@@ -1338,9 +1334,7 @@ void TransactionParticipant::Participant::_abortActiveTransaction(
     if (!o().txnState.isNone()) {
         stdx::lock_guard<Client> lk(*opCtx->getClient());
         o(lk).transactionMetricsObserver.onTransactionOperation(
-            opCtx->getClient(),
-            CurOp::get(opCtx)->debug().additiveMetrics,
-            CurOp::get(opCtx)->debug().storageStats);
+            opCtx, CurOp::get(opCtx)->debug().additiveMetrics, o().txnState.isPrepared());
     }
 
     // We reserve an oplog slot before aborting the transaction so that no writes that are causally