Skip to content

Commit fbdd571

Browse files
haleyConnellyevergreen
authored andcommitted
SERVER-43871 Use a monotonic clock source in prepare conflict tracker
1 parent 81e1eb0 commit fbdd571

File tree

5 files changed

+41
-22
lines changed

5 files changed

+41
-22
lines changed

src/mongo/db/curop.cpp

Lines changed: 6 additions & 3 deletions
Original file line numberDiff line numberDiff line change
@@ -456,8 +456,11 @@ bool CurOp::completeAndLogOperation(OperationContext* opCtx,
456456
}
457457

458458
// Gets the time spent blocked on prepare conflicts.
459-
_debug.prepareConflictDurationMicros =
459+
auto prepareConflictDurationMicros =
460460
PrepareConflictTracker::get(opCtx).getPrepareConflictDuration();
461+
_debug.prepareConflictDurationMillis =
462+
duration_cast<Milliseconds>(prepareConflictDurationMicros);
463+
461464
log(component) << _debug.report(opCtx, (lockerInfo ? &lockerInfo->stats : nullptr));
462465
}
463466

@@ -689,8 +692,8 @@ string OpDebug::report(OperationContext* opCtx, const SingleThreadedLockStats* l
689692
s << " planSummary: " << curop.getPlanSummary().toString();
690693
}
691694

692-
if (prepareConflictDurationMicros > 0) {
693-
s << " prepareConflictDuration: " << (prepareConflictDurationMicros / 1000) << "ms";
695+
if (prepareConflictDurationMillis > Milliseconds::zero()) {
696+
s << " prepareConflictDuration: " << prepareConflictDurationMillis;
694697
}
695698

696699
OPDEBUG_TOSTRING_HELP(nShards);

src/mongo/db/curop.h

Lines changed: 1 addition & 1 deletion
Original file line numberDiff line numberDiff line change
@@ -227,7 +227,7 @@ class OpDebug {
227227
int nShards{-1};
228228

229229
// Stores the duration of time spent blocked on prepare conflicts.
230-
unsigned long long prepareConflictDurationMicros{0};
230+
Milliseconds prepareConflictDurationMillis{0};
231231

232232
// Stores additive metrics.
233233
AdditiveMetrics additiveMetrics;

src/mongo/db/prepare_conflict_tracker.cpp

Lines changed: 17 additions & 11 deletions
Original file line numberDiff line numberDiff line change
@@ -39,31 +39,37 @@ bool PrepareConflictTracker::isWaitingOnPrepareConflict() const {
3939
return _waitOnPrepareConflict.load();
4040
}
4141

42-
void PrepareConflictTracker::beginPrepareConflict() {
42+
void PrepareConflictTracker::beginPrepareConflict(OperationContext* opCtx) {
4343
invariant(_prepareConflictStartTime == 0);
44-
_prepareConflictStartTime = curTimeMicros64();
44+
_prepareConflictStartTime = opCtx->getServiceContext()->getTickSource()->getTicks();
4545

4646
// Implies that the current read operation is blocked on a prepared transaction.
4747
_waitOnPrepareConflict.store(true);
4848
}
4949

50-
void PrepareConflictTracker::endPrepareConflict() {
50+
void PrepareConflictTracker::endPrepareConflict(OperationContext* opCtx) {
5151
// This function is called regardless whether there was a prepare conflict.
52-
if (_prepareConflictStartTime > 0) {
53-
auto curTimeMicros = curTimeMicros64();
54-
invariant(_prepareConflictStartTime <= curTimeMicros,
55-
str::stream() << "Prepare conflict start time (" << _prepareConflictStartTime
56-
<< ") is somehow greater than current time (" << curTimeMicros
57-
<< ")");
58-
_prepareConflictDuration += curTimeMicros - _prepareConflictStartTime;
52+
if (_prepareConflictStartTime) {
53+
auto tickSource = opCtx->getServiceContext()->getTickSource();
54+
auto curTick = tickSource->getTicks();
55+
56+
invariant(_prepareConflictStartTime <= curTick,
57+
str::stream() << "Prepare conflict start time ("
58+
<< tickSource->ticksTo<Microseconds>(_prepareConflictStartTime)
59+
<< ") is somehow greater than current time ("
60+
<< tickSource->ticksTo<Microseconds>(curTick) << ")");
61+
62+
auto curConflictDuration =
63+
tickSource->ticksTo<Microseconds>(curTick - _prepareConflictStartTime);
64+
_prepareConflictDuration += curConflictDuration;
5965
}
6066
_prepareConflictStartTime = 0;
6167

6268
// Implies that the current read operation is not blocked on a prepared transaction.
6369
_waitOnPrepareConflict.store(false);
6470
}
6571

66-
unsigned long long PrepareConflictTracker::getPrepareConflictDuration() {
72+
Microseconds PrepareConflictTracker::getPrepareConflictDuration() {
6773
return _prepareConflictDuration;
6874
}
6975

src/mongo/db/prepare_conflict_tracker.h

Lines changed: 15 additions & 5 deletions
Original file line numberDiff line numberDiff line change
@@ -57,26 +57,36 @@ class PrepareConflictTracker {
5757
* Sets _waitOnPrepareConflict to true after a read thread hits a WT_PREPARE_CONFLICT
5858
* error code.
5959
*/
60-
void beginPrepareConflict();
60+
void beginPrepareConflict(OperationContext* opCtx);
6161

6262
/**
6363
* Sets _waitOnPrepareConflict to false after wiredTigerPrepareConflictRetry returns,
6464
* implying that the read thread is not blocked on a prepare conflict.
6565
*/
66-
void endPrepareConflict();
66+
void endPrepareConflict(OperationContext* opCtx);
6767

6868
/**
6969
* Returns the total duration of time spent blocked on prepare conflicts.
7070
*/
71-
unsigned long long getPrepareConflictDuration();
71+
Microseconds getPrepareConflictDuration();
7272

7373
private:
7474
/**
7575
* Set to true when a read operation is currently blocked on a prepare conflict.
7676
*/
7777
AtomicWord<bool> _waitOnPrepareConflict{false};
78-
unsigned long long _prepareConflictStartTime{0};
79-
unsigned long long _prepareConflictDuration{0};
78+
79+
/**
80+
* Multiple prepare read conflicts can be hit during the life time of the prepare conflict
81+
* tracker. _prepareConflictStartTime indicates the most recent time a block started due to a
82+
* prepare read conflict.
83+
*/
84+
TickSource::Tick _prepareConflictStartTime{0};
85+
86+
/**
87+
* Stores the total amount of time spent blocked on prepare read conflicts.
88+
*/
89+
Microseconds _prepareConflictDuration{0};
8090
};
8191

8292
} // namespace mongo

src/mongo/db/storage/wiredtiger/wiredtiger_prepare_conflict.h

Lines changed: 2 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -70,14 +70,14 @@ int wiredTigerPrepareConflictRetry(OperationContext* opCtx, F&& f) {
7070
int attempts = 1;
7171
// If we return from this function, we have either returned successfully or we've returned an
7272
// error other than WT_PREPARE_CONFLICT. Reset PrepareConflictTracker accordingly.
73-
ON_BLOCK_EXIT([opCtx] { PrepareConflictTracker::get(opCtx).endPrepareConflict(); });
73+
ON_BLOCK_EXIT([opCtx] { PrepareConflictTracker::get(opCtx).endPrepareConflict(opCtx); });
7474
// If the failpoint is enabled, don't call the function, just simulate a conflict.
7575
int ret = MONGO_unlikely(WTPrepareConflictForReads.shouldFail()) ? WT_PREPARE_CONFLICT
7676
: WT_READ_CHECK(f());
7777
if (ret != WT_PREPARE_CONFLICT)
7878
return ret;
7979

80-
PrepareConflictTracker::get(opCtx).beginPrepareConflict();
80+
PrepareConflictTracker::get(opCtx).beginPrepareConflict(opCtx);
8181

8282
// It is contradictory to be running into a prepare conflict when we are ignoring interruptions,
8383
// particularly when running code inside an

0 commit comments

Comments
 (0)