SERVER-43871 Use a monotonic clock source in prepare conflict tracker

5 files changed, 41 insertions, 22 deletions

diff --git a/src/mongo/db/curop.cpp b/src/mongo/db/curop.cpp
index fd325678ae7..4767acb9f26 100644
--- a/src/mongo/db/curop.cpp
+++ b/src/mongo/db/curop.cpp
@@ -456,8 +456,11 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx,
         }
 
         // Gets the time spent blocked on prepare conflicts.
-        _debug.prepareConflictDurationMicros =
+        auto prepareConflictDurationMicros =
             PrepareConflictTracker::get(opCtx).getPrepareConflictDuration();
+        _debug.prepareConflictDurationMillis =
+            duration_cast<Milliseconds>(prepareConflictDurationMicros);
+
         log(component) << _debug.report(opCtx, (lockerInfo ? &lockerInfo->stats : nullptr));
     }
 
@@ -689,8 +692,8 @@ string OpDebug::report(OperationContext* opCtx, const SingleThreadedLockStats* l
         s << " planSummary: " << curop.getPlanSummary().toString();
     }
 
-    if (prepareConflictDurationMicros > 0) {
-        s << " prepareConflictDuration: " << (prepareConflictDurationMicros / 1000) << "ms";
+    if (prepareConflictDurationMillis > Milliseconds::zero()) {
+        s << " prepareConflictDuration: " << prepareConflictDurationMillis;
     }
 
     OPDEBUG_TOSTRING_HELP(nShards);
diff --git a/src/mongo/db/curop.h b/src/mongo/db/curop.h
index b262898e7e7..1c1837496b2 100644
--- a/src/mongo/db/curop.h
+++ b/src/mongo/db/curop.h
@@ -227,7 +227,7 @@ public:
     int nShards{-1};
 
     // Stores the duration of time spent blocked on prepare conflicts.
-    unsigned long long prepareConflictDurationMicros{0};
+    Milliseconds prepareConflictDurationMillis{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 1a52dbf728f..ab45568f9dd 100644
--- a/src/mongo/db/prepare_conflict_tracker.cpp
+++ b/src/mongo/db/prepare_conflict_tracker.cpp
@@ -39,23 +39,29 @@ bool PrepareConflictTracker::isWaitingOnPrepareConflict() const {
     return _waitOnPrepareConflict.load();
 }
 
-void PrepareConflictTracker::beginPrepareConflict() {
+void PrepareConflictTracker::beginPrepareConflict(OperationContext* opCtx) {
     invariant(_prepareConflictStartTime == 0);
-    _prepareConflictStartTime = curTimeMicros64();
+    _prepareConflictStartTime = opCtx->getServiceContext()->getTickSource()->getTicks();
 
     // Implies that the current read operation is blocked on a prepared transaction.
     _waitOnPrepareConflict.store(true);
 }
 
-void PrepareConflictTracker::endPrepareConflict() {
+void PrepareConflictTracker::endPrepareConflict(OperationContext* opCtx) {
     // This function is called regardless whether there was a prepare conflict.
-    if (_prepareConflictStartTime > 0) {
-        auto curTimeMicros = curTimeMicros64();
-        invariant(_prepareConflictStartTime <= curTimeMicros,
-                  str::stream() << "Prepare conflict start time (" << _prepareConflictStartTime
-                                << ") is somehow greater than current time (" << curTimeMicros
-                                << ")");
-        _prepareConflictDuration += curTimeMicros - _prepareConflictStartTime;
+    if (_prepareConflictStartTime) {
+        auto tickSource = opCtx->getServiceContext()->getTickSource();
+        auto curTick = tickSource->getTicks();
+
+        invariant(_prepareConflictStartTime <= curTick,
+                  str::stream() << "Prepare conflict start time ("
+                                << tickSource->ticksTo<Microseconds>(_prepareConflictStartTime)
+                                << ") is somehow greater than current time ("
+                                << tickSource->ticksTo<Microseconds>(curTick) << ")");
+
+        auto curConflictDuration =
+            tickSource->ticksTo<Microseconds>(curTick - _prepareConflictStartTime);
+        _prepareConflictDuration += curConflictDuration;
     }
     _prepareConflictStartTime = 0;
 
@@ -63,7 +69,7 @@ void PrepareConflictTracker::endPrepareConflict() {
     _waitOnPrepareConflict.store(false);
 }
 
-unsigned long long PrepareConflictTracker::getPrepareConflictDuration() {
+Microseconds PrepareConflictTracker::getPrepareConflictDuration() {
     return _prepareConflictDuration;
 }
 
diff --git a/src/mongo/db/prepare_conflict_tracker.h b/src/mongo/db/prepare_conflict_tracker.h
index 7b2298f239c..01fc146d675 100644
--- a/src/mongo/db/prepare_conflict_tracker.h
+++ b/src/mongo/db/prepare_conflict_tracker.h
@@ -57,26 +57,36 @@ public:
      * Sets _waitOnPrepareConflict to true after a read thread hits a WT_PREPARE_CONFLICT
      * error code.
      */
-    void beginPrepareConflict();
+    void beginPrepareConflict(OperationContext* opCtx);
 
     /**
      * Sets _waitOnPrepareConflict to false after wiredTigerPrepareConflictRetry returns,
      * implying that the read thread is not blocked on a prepare conflict.
      */
-    void endPrepareConflict();
+    void endPrepareConflict(OperationContext* opCtx);
 
     /**
      * Returns the total duration of time spent blocked on prepare conflicts.
      */
-    unsigned long long getPrepareConflictDuration();
+    Microseconds getPrepareConflictDuration();
 
 private:
     /**
      * Set to true when a read operation is currently blocked on a prepare conflict.
      */
     AtomicWord<bool> _waitOnPrepareConflict{false};
-    unsigned long long _prepareConflictStartTime{0};
-    unsigned long long _prepareConflictDuration{0};
+
+    /**
+     * Multiple prepare read conflicts can be hit during the life time of the prepare conflict
+     * tracker. _prepareConflictStartTime indicates the most recent time a block started due to a
+     * prepare read conflict.
+     */
+    TickSource::Tick _prepareConflictStartTime{0};
+
+    /**
+     * Stores the total amount of time spent blocked on prepare read conflicts.
+     */
+    Microseconds _prepareConflictDuration{0};
 };
 
 }  // namespace mongo
diff --git a/src/mongo/db/storage/wiredtiger/wiredtiger_prepare_conflict.h b/src/mongo/db/storage/wiredtiger/wiredtiger_prepare_conflict.h
index 3b9cb06044a..0d8170b2999 100644
--- a/src/mongo/db/storage/wiredtiger/wiredtiger_prepare_conflict.h
+++ b/src/mongo/db/storage/wiredtiger/wiredtiger_prepare_conflict.h
@@ -70,14 +70,14 @@ int wiredTigerPrepareConflictRetry(OperationContext* opCtx, F&& f) {
     int attempts = 1;
     // If we return from this function, we have either returned successfully or we've returned an
     // error other than WT_PREPARE_CONFLICT. Reset PrepareConflictTracker accordingly.
-    ON_BLOCK_EXIT([opCtx] { PrepareConflictTracker::get(opCtx).endPrepareConflict(); });
+    ON_BLOCK_EXIT([opCtx] { PrepareConflictTracker::get(opCtx).endPrepareConflict(opCtx); });
     // If the failpoint is enabled, don't call the function, just simulate a conflict.
     int ret = MONGO_unlikely(WTPrepareConflictForReads.shouldFail()) ? WT_PREPARE_CONFLICT
                                                                      : WT_READ_CHECK(f());
     if (ret != WT_PREPARE_CONFLICT)
         return ret;
 
-    PrepareConflictTracker::get(opCtx).beginPrepareConflict();
+    PrepareConflictTracker::get(opCtx).beginPrepareConflict(opCtx);
 
     // It is contradictory to be running into a prepare conflict when we are ignoring interruptions,
     // particularly when running code inside an