SERVER-37756 add logging for the amount of time spent blocked on a prepare conflict

6 files changed, 59 insertions, 9 deletions

diff --git a/jstests/core/txns/prepare_conflict.js b/jstests/core/txns/prepare_conflict.js
index 7eb4212c5c3..2abb942ff75 100644
--- a/jstests/core/txns/prepare_conflict.js
+++ b/jstests/core/txns/prepare_conflict.js
@@ -6,20 +6,24 @@
 (function() {
 "use strict";
 load("jstests/core/txns/libs/prepare_helpers.js");
+load("jstests/libs/check_log.js");
 
 const dbName = "test";
 const collName = "prepare_conflict";
 const testDB = db.getSiblingDB(dbName);
 const testColl = testDB.getCollection(collName);
 
+// Logs must be cleared each run.
+assert.commandWorked(testDB.adminCommand({clearLog: "global"}));
+
 testColl.drop({writeConcern: {w: "majority"}});
 assert.commandWorked(testDB.runCommand({create: collName, writeConcern: {w: "majority"}}));
 
-function assertPrepareConflict(filter, clusterTime) {
-    // Use a 5 second timeout so that there is enough time for the prepared transaction to
+function assertPrepareConflict(filter, clusterTime, count) {
+    // Uses a 5 second timeout so that there is enough time for the prepared transaction to
     // release its locks and for the command to obtain those locks.
     assert.commandFailedWithCode(
-        // Use afterClusterTime read to make sure that it will block on a prepare conflict.
+        // Uses afterClusterTime read to make sure that it will block on a prepare conflict.
         testDB.runCommand({
             find: collName,
             filter: filter,
@@ -28,6 +32,9 @@ function assertPrepareConflict(filter, clusterTime) {
         }),
         ErrorCodes.MaxTimeMSExpired);
 
+    // Ensures prepareConflictDuration is logged each time a prepare conflict is encountered.
+    checkLog.containsWithCount(testDB, "prepareConflictDuration", count);
+
     let prepareConflicted = false;
     const cur =
         testDB.system.profile.find({"ns": testColl.getFullName(), "command.filter": filter});
@@ -41,14 +48,13 @@ function assertPrepareConflict(filter, clusterTime) {
     assert(prepareConflicted);
 }
 
-// Insert a document modified by the transaction.
+// Inserts a document modified by the transaction.
 const txnDoc = {
     _id: 1,
     x: 1
 };
 assert.commandWorked(testColl.insert(txnDoc));
-
-// Insert a document unmodified by the transaction.
+// Inserts a document unmodified by the transaction.
 const otherDoc = {
     _id: 2,
     y: 2
@@ -69,14 +75,16 @@ assert.commandWorked(sessionDB.runCommand({
     update: collName,
     updates: [{q: txnDoc, u: {$inc: {x: 1}}}],
 }));
-
 const prepareTimestamp = PrepareHelpers.prepareTransaction(session);
 
+// Stores the number of times prepareConflictDuration should appear in the log.
+let conflictCount = 1;
+
 // Conflict on _id of prepared document.
-assertPrepareConflict({_id: txnDoc._id}, prepareTimestamp);
+assertPrepareConflict({_id: txnDoc._id}, prepareTimestamp, conflictCount);
 
 // Conflict on field that could be added to a prepared document.
-assertPrepareConflict({randomField: "random"}, prepareTimestamp);
+assertPrepareConflict({randomField: "random"}, prepareTimestamp, ++conflictCount);
 
 // No conflict on _id of a non-prepared document.
 assert.commandWorked(testDB.runCommand({find: collName, filter: {_id: otherDoc._id}}));
@@ -84,6 +92,10 @@ assert.commandWorked(testDB.runCommand({find: collName, filter: {_id: otherDoc._
 // No conflict on indexed field of a non-prepared document.
 assert.commandWorked(testDB.runCommand({find: collName, filter: {y: otherDoc.y}}));
 
+// Ensures that prepareConflictDuration is only logged when a prepare conflict is encountered. We
+// expect conflictCount to be 2.
+checkLog.containsWithCount(testDB, "prepareConflictDuration", conflictCount);
+
 // At this point, we can guarantee all subsequent reads will conflict. Do a read in a parallel
 // shell, abort the transaction, then ensure the read succeeded with the old document.
 TestData.collName = collName;
diff --git a/src/mongo/db/SConscript b/src/mongo/db/SConscript
index 0f8bc475563..08aa289e870 100644
--- a/src/mongo/db/SConscript
+++ b/src/mongo/db/SConscript
@@ -128,6 +128,9 @@ env.Library(
         'server_options',
         'generic_cursor',
     ],
+    LIBDEPS_PRIVATE=[
+        'prepare_conflict_tracker',
+    ],
 )
 
 env.Library(
diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index de804da0983..6fcb94b2938 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -45,6 +45,7 @@
 #include "mongo/db/concurrency/d_concurrency.h"
 #include "mongo/db/concurrency/locker.h"
 #include "mongo/db/json.h"
+#include "mongo/db/prepare_conflict_tracker.h"
 #include "mongo/db/query/getmore_request.h"
 #include "mongo/db/query/plan_summary_stats.h"
 #include "mongo/platform/mutex.h"
@@ -475,6 +476,11 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx,
                                       "operation due to interrupt";
             }
         }
+
+        // Gets the time spent blocked on prepare conflicts.
+        _debug.prepareConflictDurationMicros = durationCount<Microseconds>(
+            PrepareConflictTracker::get(opCtx).getPrepareConflictDuration());
+
         log(component) << _debug.report(client,
                                         *this,
                                         (lockerInfo ? &lockerInfo->stats : nullptr),
@@ -702,6 +708,10 @@ string OpDebug::report(Client* client,
         s << " planSummary: " << curop.getPlanSummary().toString();
     }
 
+    if (prepareConflictDurationMicros > 0) {
+        s << " prepareConflictDuration: " << (prepareConflictDurationMicros / 1000) << "ms";
+    }
+
     OPDEBUG_TOSTRING_HELP(nShards);
     OPDEBUG_TOSTRING_HELP(cursorid);
     if (mongotCursorId) {
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index 37985a76865..0019bbb85ad 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -229,6 +229,9 @@ public:
     // Shard targeting info.
     int nShards{-1};
 
+    // Stores the duration of time spent blocked on prepare conflicts.
+    long long prepareConflictDurationMicros{0};
+
     // Stores additive metrics.
     AdditiveMetrics additiveMetrics;
 
diff --git a/src/mongo/db/prepare_conflict_tracker.cpp b/src/mongo/db/prepare_conflict_tracker.cpp
index 25120459408..1ec1bb9c89a 100644
--- a/src/mongo/db/prepare_conflict_tracker.cpp
+++ b/src/mongo/db/prepare_conflict_tracker.cpp
@@ -40,13 +40,28 @@ bool PrepareConflictTracker::isWaitingOnPrepareConflict() const {
 }
 
 void PrepareConflictTracker::beginPrepareConflict() {
+    invariant(_prepareConflictStartTime == 0);
+    _prepareConflictStartTime = curTimeMicros64();
+
     // Implies that the current read operation is blocked on a prepared transaction.
     _waitOnPrepareConflict.store(true);
 }
 
 void PrepareConflictTracker::endPrepareConflict() {
+    // This function is called regardless whether there was a prepare conflict.
+    if (_prepareConflictStartTime > 0) {
+        invariant(_prepareConflictStartTime <= static_cast<long long>(curTimeMicros64()));
+        _prepareConflictDuration +=
+            Microseconds{static_cast<long long>(curTimeMicros64()) - _prepareConflictStartTime};
+    }
+    _prepareConflictStartTime = 0;
+
     // Implies that the current read operation is not blocked on a prepared transaction.
     _waitOnPrepareConflict.store(false);
 }
 
+Microseconds PrepareConflictTracker::getPrepareConflictDuration() {
+    return _prepareConflictDuration;
+}
+
 }  // namespace mongo
diff --git a/src/mongo/db/prepare_conflict_tracker.h b/src/mongo/db/prepare_conflict_tracker.h
index 48e4fa1a063..e488af59fe0 100644
--- a/src/mongo/db/prepare_conflict_tracker.h
+++ b/src/mongo/db/prepare_conflict_tracker.h
@@ -65,11 +65,18 @@ public:
      */
     void endPrepareConflict();
 
+    /**
+     * Returns the total duration of time spent blocked on prepare conflicts.
+     */
+    Microseconds getPrepareConflictDuration();
+
 private:
     /**
      * Set to true when a read operation is currently blocked on a prepare conflict.
      */
     AtomicWord<bool> _waitOnPrepareConflict{false};
+    long long _prepareConflictStartTime{0};
+    Microseconds _prepareConflictDuration{0};
 };
 
 }  // namespace mongo