From fbdd5712f9ff6714f5ce9804eb4e9decb25dd88b Mon Sep 17 00:00:00 2001 From: Haley Connelly Date: Wed, 16 Oct 2019 17:15:00 +0000 Subject: SERVER-43871 Use a monotonic clock source in prepare conflict tracker --- src/mongo/db/curop.cpp | 9 ++++--- src/mongo/db/curop.h | 2 +- src/mongo/db/prepare_conflict_tracker.cpp | 28 +++++++++++++--------- src/mongo/db/prepare_conflict_tracker.h | 20 ++++++++++++---- .../wiredtiger/wiredtiger_prepare_conflict.h | 4 ++-- 5 files changed, 41 insertions(+), 22 deletions(-) (limited to 'src') 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(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(_prepareConflictStartTime) + << ") is somehow greater than current time (" + << tickSource->ticksTo(curTick) << ")"); + + auto curConflictDuration = + tickSource->ticksTo(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 _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 -- cgit v1.2.1