diff options
author | William Schultz <william.schultz@mongodb.com> | 2018-10-02 21:54:58 -0400 |
---|---|---|
committer | William Schultz <william.schultz@mongodb.com> | 2018-10-02 21:57:52 -0400 |
commit | 982ba21e0ffbdaaf766dc8fa060728ba9b5f4914 (patch) | |
tree | efc760c482e30bd70bfbaf5854779a89acf00ef3 /src/mongo/db/single_transaction_stats.cpp | |
parent | 23d7c89e501d221a41f350b0b10a52a4f05bb2e2 (diff) | |
download | mongo-982ba21e0ffbdaaf766dc8fa060728ba9b5f4914.tar.gz |
SERVER-36697 Utilize TickSource for transactions timing metrics
This patch converts the existing transactions diagnostics timing related
metrics to use a TickSource to record transaction durations. The
TickSource is a high precision, mock-able time source for measuring
the passage of time. This patch also converts the existing unit tests
to use a mock TickSource, which allows the tests to fully virtualize
time, making them much faster and less flaky.
Diffstat (limited to 'src/mongo/db/single_transaction_stats.cpp')
-rw-r--r-- | src/mongo/db/single_transaction_stats.cpp | 57 |
1 files changed, 28 insertions, 29 deletions
diff --git a/src/mongo/db/single_transaction_stats.cpp b/src/mongo/db/single_transaction_stats.cpp index 5057d2e356e..5d0da69dffb 100644 --- a/src/mongo/db/single_transaction_stats.cpp +++ b/src/mongo/db/single_transaction_stats.cpp @@ -32,68 +32,67 @@ namespace mongo { -unsigned long long SingleTransactionStats::getStartTime() const { - invariant(_startTime > 0); - - return _startTime; -} - -void SingleTransactionStats::setStartTime(unsigned long long time) { +void SingleTransactionStats::setStartTime(TickSource::Tick curTick, Date_t curWallClockTime) { invariant(_startTime == 0); - _startTime = time; + _startTime = curTick; + _startWallClockTime = curWallClockTime; } -unsigned long long SingleTransactionStats::getDuration(unsigned long long curTime) const { +Microseconds SingleTransactionStats::getDuration(TickSource* tickSource, + TickSource::Tick curTick) const { invariant(_startTime > 0); // The transaction hasn't ended yet, so we return how long it has currently been running for. if (_endTime == 0) { - return curTime - _startTime; + return tickSource->ticksTo<Microseconds>(curTick - _startTime); } - return _endTime - _startTime; + return tickSource->ticksTo<Microseconds>(_endTime - _startTime); } -void SingleTransactionStats::setEndTime(unsigned long long time) { +void SingleTransactionStats::setEndTime(TickSource::Tick time) { invariant(_startTime > 0); _endTime = time; } -Microseconds SingleTransactionStats::getTimeActiveMicros(unsigned long long curTime) const { +Microseconds SingleTransactionStats::getTimeActiveMicros(TickSource* tickSource, + TickSource::Tick curTick) const { invariant(_startTime > 0); // The transaction is currently active, so we return the recorded active time so far plus the // time since _timeActiveStart. if (isActive()) { return _timeActiveMicros + - Microseconds{static_cast<long long>(curTime - _lastTimeActiveStart)}; + tickSource->ticksTo<Microseconds>(curTick - _lastTimeActiveStart); } return _timeActiveMicros; } -Microseconds SingleTransactionStats::getTimeInactiveMicros(unsigned long long curTime) const { +Microseconds SingleTransactionStats::getTimeInactiveMicros(TickSource* tickSource, + TickSource::Tick curTick) const { invariant(_startTime > 0); - return Microseconds{static_cast<long long>(getDuration(curTime))} - - getTimeActiveMicros(curTime); + return getDuration(tickSource, curTick) - getTimeActiveMicros(tickSource, curTick); } -void SingleTransactionStats::setActive(unsigned long long time) { +void SingleTransactionStats::setActive(TickSource::Tick curTick) { invariant(!isActive()); - _lastTimeActiveStart = time; + _lastTimeActiveStart = curTick; } -void SingleTransactionStats::setInactive(unsigned long long time) { +void SingleTransactionStats::setInactive(TickSource* tickSource, TickSource::Tick curTick) { invariant(isActive()); - _timeActiveMicros += Microseconds{static_cast<long long>(time - _lastTimeActiveStart)}; + _timeActiveMicros += tickSource->ticksTo<Microseconds>(curTick - _lastTimeActiveStart); _lastTimeActiveStart = 0; } void SingleTransactionStats::report(BSONObjBuilder* builder, - const repl::ReadConcernArgs& readConcernArgs) const { + const repl::ReadConcernArgs& readConcernArgs, + TickSource* tickSource, + TickSource::Tick curTick) const { BSONObjBuilder parametersBuilder(builder->subobjStart("parameters")); parametersBuilder.append("txnNumber", _txnNumber); @@ -108,15 +107,15 @@ void SingleTransactionStats::report(BSONObjBuilder* builder, parametersBuilder.done(); builder->append("readTimestamp", _readTimestamp); - builder->append("startWallClockTime", - dateToISOStringLocal(Date_t::fromMillisSinceEpoch(getStartTime() / 1000))); + builder->append("startWallClockTime", dateToISOStringLocal(_startWallClockTime)); - // We use the same "now" time so that the following time metrics are consistent with each other. - auto curTime = curTimeMicros64(); - builder->append("timeOpenMicros", static_cast<long long>(getDuration(curTime))); + // The same "now" time must be used so that the following time metrics are consistent with each + // other. + builder->append("timeOpenMicros", + durationCount<Microseconds>(getDuration(tickSource, curTick))); - auto timeActive = durationCount<Microseconds>(getTimeActiveMicros(curTime)); - auto timeInactive = durationCount<Microseconds>(getTimeInactiveMicros(curTime)); + auto timeActive = durationCount<Microseconds>(getTimeActiveMicros(tickSource, curTick)); + auto timeInactive = durationCount<Microseconds>(getTimeInactiveMicros(tickSource, curTick)); builder->append("timeActiveMicros", timeActive); builder->append("timeInactiveMicros", timeInactive); |