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 | |
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')
18 files changed, 633 insertions, 529 deletions
diff --git a/src/mongo/db/SConscript b/src/mongo/db/SConscript index 27e96498768..dc86b4e0ac2 100644 --- a/src/mongo/db/SConscript +++ b/src/mongo/db/SConscript @@ -1950,6 +1950,7 @@ env.CppUnitTest( '$BUILD_DIR/mongo/client/read_preference', '$BUILD_DIR/mongo/db/auth/authmocks', '$BUILD_DIR/mongo/db/repl/mock_repl_coord_server_fixture', + '$BUILD_DIR/mongo/util/clock_source_mock', 'query_exec', ], ) diff --git a/src/mongo/db/ftdc/ftdc_test.cpp b/src/mongo/db/ftdc/ftdc_test.cpp index 631ca23397e..f35644e0505 100644 --- a/src/mongo/db/ftdc/ftdc_test.cpp +++ b/src/mongo/db/ftdc/ftdc_test.cpp @@ -142,7 +142,7 @@ FTDCTest::FTDCTest() { auto service = getServiceContext(); service->setFastClockSource(stdx::make_unique<ClockSourceMock>()); service->setPreciseClockSource(stdx::make_unique<ClockSourceMock>()); - service->setTickSource(stdx::make_unique<TickSourceMock>()); + service->setTickSource(stdx::make_unique<TickSourceMock<>>()); } } // namespace mongo diff --git a/src/mongo/db/operation_context_test.cpp b/src/mongo/db/operation_context_test.cpp index 524e19d47e0..d524d9b34e8 100644 --- a/src/mongo/db/operation_context_test.cpp +++ b/src/mongo/db/operation_context_test.cpp @@ -225,7 +225,7 @@ public: service = ServiceContext::make(); service->setFastClockSource(stdx::make_unique<SharedClockSourceAdapter>(mockClock)); service->setPreciseClockSource(stdx::make_unique<SharedClockSourceAdapter>(mockClock)); - service->setTickSource(stdx::make_unique<TickSourceMock>()); + service->setTickSource(stdx::make_unique<TickSourceMock<>>()); client = service->makeClient("OperationDeadlineTest"); } diff --git a/src/mongo/db/s/namespace_metadata_change_notifications_test.cpp b/src/mongo/db/s/namespace_metadata_change_notifications_test.cpp index 4d8dcad43a1..88007210bfb 100644 --- a/src/mongo/db/s/namespace_metadata_change_notifications_test.cpp +++ b/src/mongo/db/s/namespace_metadata_change_notifications_test.cpp @@ -45,7 +45,7 @@ const NamespaceString kNss("foo.bar"); class NamespaceMetadataChangeNotificationsTest : public ServiceContextMongoDTest { protected: NamespaceMetadataChangeNotificationsTest() { - getServiceContext()->setTickSource(stdx::make_unique<TickSourceMock>()); + getServiceContext()->setTickSource(stdx::make_unique<TickSourceMock<>>()); } }; 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); diff --git a/src/mongo/db/single_transaction_stats.h b/src/mongo/db/single_transaction_stats.h index 42be4ae8a17..14d4cac4bb6 100644 --- a/src/mongo/db/single_transaction_stats.h +++ b/src/mongo/db/single_transaction_stats.h @@ -36,6 +36,8 @@ namespace mongo { /** * Tracks metrics for a single multi-document transaction. + * + * For all timing related stats, a TickSource with at least microsecond resolution must be used. */ class SingleTransactionStats { public: @@ -65,18 +67,18 @@ public: SingleTransactionStats(TxnNumber txnNumber) : _txnNumber(txnNumber){}; /** - * Returns the start time of the transaction in microseconds. - * - * This method cannot be called until setStartTime() has been called. - */ - unsigned long long getStartTime() const; - - /** * Sets the transaction's start time, only if it hasn't already been set. * + * This method takes two sources of input for the current time. The 'curTick' argument should be + * the current time as measured by a TickSource, which is a high precision interface for + * measuring the passage of time that should provide at least microsecond resolution. The given + * 'curWallClockTime' need only be a millisecond resolution time point that serves as a close + * approximation to the true start time. This millisecond resolution time point is not used for + * measuring transaction durations. The given tick value, however, is. + * * This method must only be called once. */ - void setStartTime(unsigned long long time); + void setStartTime(TickSource::Tick curTick, Date_t curWallClockTime); /** * If the transaction is currently in progress, this method returns the duration @@ -87,26 +89,26 @@ public: * * This method cannot be called until setStartTime() has been called. */ - unsigned long long getDuration(unsigned long long curTime) const; + Microseconds getDuration(TickSource* tickSource, TickSource::Tick curTick) const; /** * Sets the transaction's end time, only if the start time has already been set. * * This method cannot be called until setStartTime() has been called. */ - void setEndTime(unsigned long long time); + void setEndTime(TickSource::Tick time); /** * Returns the total active time of the transaction, given the current time value. A transaction * is active when there is a running operation that is part of the transaction. */ - Microseconds getTimeActiveMicros(unsigned long long curTime) const; + Microseconds getTimeActiveMicros(TickSource* tickSource, TickSource::Tick curTick) const; /** * Returns the total inactive time of the transaction, given the current time value. A * transaction is inactive when it is idly waiting for a new operation to occur. */ - Microseconds getTimeInactiveMicros(unsigned long long curTime) const; + Microseconds getTimeInactiveMicros(TickSource* tickSource, TickSource::Tick curTick) const; /** * Marks the transaction as active and sets the start of the transaction's active time. @@ -114,7 +116,7 @@ public: * This method cannot be called if the transaction is currently active. A call to setActive() * must be followed by a call to setInactive() before calling setActive() again. */ - void setActive(unsigned long long time); + void setActive(TickSource::Tick curTick); /** * Marks the transaction as inactive and sets the total active time of the transaction. The @@ -122,7 +124,7 @@ public: * * This method cannot be called if the transaction is currently not active. */ - void setInactive(unsigned long long time); + void setInactive(TickSource* tickSource, TickSource::Tick curTick); /** * Returns whether or not the transaction is currently active. @@ -192,7 +194,10 @@ public: /** * Append the stats to the builder. */ - void report(BSONObjBuilder* builder, const repl::ReadConcernArgs& readConcernArgs) const; + void report(BSONObjBuilder* builder, + const repl::ReadConcernArgs& readConcernArgs, + TickSource* tickSource, + TickSource::Tick curTick) const; private: // The transaction number of the transaction. @@ -202,18 +207,23 @@ private: // for future use. boost::optional<bool> _autoCommit; - // The start time of the transaction in microseconds. - unsigned long long _startTime{0}; + // The start time of the transaction in millisecond resolution. Used only for diagnostics + // reporting. Not used for measuring transaction durations. + Date_t _startWallClockTime; + + // The start time of the transaction. Note that tick values should only ever be used to measure + // distance from other tick values, not for reporting absolute wall clock time. + TickSource::Tick _startTime{0}; - // The end time of the transaction in microseconds. - unsigned long long _endTime{0}; + // The end time of the transaction. + TickSource::Tick _endTime{0}; // The total amount of active time spent by the transaction. Microseconds _timeActiveMicros = Microseconds{0}; - // The time at which the transaction was last marked as active in microseconds. The transaction - // is considered active if this value is not equal to 0. - unsigned long long _lastTimeActiveStart{0}; + // The time at which the transaction was last marked as active. The transaction is considered + // active if this value is not equal to 0. + TickSource::Tick _lastTimeActiveStart{0}; // The expiration date of the transaction. Date_t _expireDate = Date_t::max(); diff --git a/src/mongo/db/transaction_metrics_observer.cpp b/src/mongo/db/transaction_metrics_observer.cpp index 0eec2a3d1a7..2010c2fd6fc 100644 --- a/src/mongo/db/transaction_metrics_observer.cpp +++ b/src/mongo/db/transaction_metrics_observer.cpp @@ -37,12 +37,13 @@ namespace mongo { void TransactionMetricsObserver::onStart(ServerTransactionsMetrics* serverTransactionsMetrics, bool isAutoCommit, - unsigned long long curTime, + TickSource* tickSource, + Date_t curWallClockTime, Date_t expireDate) { // // Per transaction metrics. // - _singleTransactionStats.setStartTime(curTime); + _singleTransactionStats.setStartTime(tickSource->getTicks(), curWallClockTime); _singleTransactionStats.setAutoCommit(isAutoCommit); _singleTransactionStats.setExpireDate(expireDate); @@ -59,7 +60,7 @@ void TransactionMetricsObserver::onChooseReadTimestamp(Timestamp readTimestamp) } void TransactionMetricsObserver::onStash(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime) { + TickSource* tickSource) { // // Per transaction metrics. // @@ -67,7 +68,7 @@ void TransactionMetricsObserver::onStash(ServerTransactionsMetrics* serverTransa // aborted by another thread, so we check that the transaction is active before setting it as // inactive. if (_singleTransactionStats.isActive()) { - _singleTransactionStats.setInactive(curTime); + _singleTransactionStats.setInactive(tickSource, tickSource->getTicks()); } // @@ -79,11 +80,11 @@ void TransactionMetricsObserver::onStash(ServerTransactionsMetrics* serverTransa } void TransactionMetricsObserver::onUnstash(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime) { + TickSource* tickSource) { // // Per transaction metrics. // - _singleTransactionStats.setActive(curTime); + _singleTransactionStats.setActive(tickSource->getTicks()); // // Server wide transactions metrics. @@ -94,7 +95,7 @@ void TransactionMetricsObserver::onUnstash(ServerTransactionsMetrics* serverTran } void TransactionMetricsObserver::onCommit(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource* tickSource, boost::optional<Timestamp> oldestOplogEntryTS, Top* top) { // @@ -102,11 +103,12 @@ void TransactionMetricsObserver::onCommit(ServerTransactionsMetrics* serverTrans // // After the transaction has been committed, we must update the end time and mark it as // inactive. We use the same "now" time to prevent skew in the time-related metrics. - _singleTransactionStats.setEndTime(curTime); + auto curTick = tickSource->getTicks(); + _singleTransactionStats.setEndTime(curTick); // The transaction operation may have already been aborted by another thread, so we check that // the transaction is active before setting it as inactive. if (_singleTransactionStats.isActive()) { - _singleTransactionStats.setInactive(curTime); + _singleTransactionStats.setInactive(tickSource, curTick); } // @@ -116,7 +118,9 @@ void TransactionMetricsObserver::onCommit(ServerTransactionsMetrics* serverTrans serverTransactionsMetrics->decrementCurrentOpen(); serverTransactionsMetrics->decrementCurrentActive(); - top->incrementGlobalTransactionLatencyStats(_singleTransactionStats.getDuration(curTime)); + auto duration = + durationCount<Microseconds>(_singleTransactionStats.getDuration(tickSource, curTick)); + top->incrementGlobalTransactionLatencyStats(static_cast<uint64_t>(duration)); // Remove this transaction's oldest oplog entry Timestamp if one was written. if (oldestOplogEntryTS) { @@ -125,17 +129,18 @@ void TransactionMetricsObserver::onCommit(ServerTransactionsMetrics* serverTrans } void TransactionMetricsObserver::onAbortActive(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource* tickSource, boost::optional<Timestamp> oldestOplogEntryTS, Top* top) { - _onAbort(serverTransactionsMetrics, curTime, top); + auto curTick = tickSource->getTicks(); + _onAbort(serverTransactionsMetrics, curTick, tickSource, top); // // Per transaction metrics. // // The transaction operation may have already been aborted by another thread, so we check that // the transaction is active before setting it as inactive. if (_singleTransactionStats.isActive()) { - _singleTransactionStats.setInactive(curTime); + _singleTransactionStats.setInactive(tickSource, curTick); } // @@ -151,10 +156,11 @@ void TransactionMetricsObserver::onAbortActive(ServerTransactionsMetrics* server void TransactionMetricsObserver::onAbortInactive( ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource* tickSource, boost::optional<Timestamp> oldestOplogEntryTS, Top* top) { - _onAbort(serverTransactionsMetrics, curTime, top); + auto curTick = tickSource->getTicks(); + _onAbort(serverTransactionsMetrics, curTick, tickSource, top); // // Server wide transactions metrics. @@ -180,12 +186,13 @@ void TransactionMetricsObserver::onTransactionOperation(Client* client, } void TransactionMetricsObserver::_onAbort(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource::Tick curTick, + TickSource* tickSource, Top* top) { // // Per transaction metrics. // - _singleTransactionStats.setEndTime(curTime); + _singleTransactionStats.setEndTime(curTick); // // Server wide transactions metrics. @@ -193,7 +200,9 @@ void TransactionMetricsObserver::_onAbort(ServerTransactionsMetrics* serverTrans serverTransactionsMetrics->incrementTotalAborted(); serverTransactionsMetrics->decrementCurrentOpen(); - top->incrementGlobalTransactionLatencyStats(_singleTransactionStats.getDuration(curTime)); + auto latency = + durationCount<Microseconds>(_singleTransactionStats.getDuration(tickSource, curTick)); + top->incrementGlobalTransactionLatencyStats(static_cast<uint64_t>(latency)); } void TransactionMetricsObserver::onPrepare(ServerTransactionsMetrics* serverTransactionsMetrics, diff --git a/src/mongo/db/transaction_metrics_observer.h b/src/mongo/db/transaction_metrics_observer.h index 1ec30bedfff..72b5c89788e 100644 --- a/src/mongo/db/transaction_metrics_observer.h +++ b/src/mongo/db/transaction_metrics_observer.h @@ -47,7 +47,8 @@ public: */ void onStart(ServerTransactionsMetrics* serverTransactionMetrics, bool isAutoCommit, - unsigned long long curTime, + TickSource* tickSource, + Date_t curWallClockTime, Date_t expireDate); /** @@ -58,20 +59,19 @@ public: /** * Updates relevant metrics when a transaction stashes its resources. */ - void onStash(ServerTransactionsMetrics* serverTransactionMetrics, unsigned long long curTime); + void onStash(ServerTransactionsMetrics* serverTransactionMetrics, TickSource* tickSource); /** * Updates relevant metrics when a transaction unstashes its resources. */ - void onUnstash(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime); + void onUnstash(ServerTransactionsMetrics* serverTransactionsMetrics, TickSource* tickSource); /** * Updates relevant metrics when a transaction commits. Also removes this transaction's oldest * oplog entry Timestamp from the oldestActiveOplogEntryTS set if it is not boost::none. */ void onCommit(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource* tickSource, boost::optional<Timestamp> oldestOplogEntryTS, Top* top); @@ -80,7 +80,7 @@ public: * oldest oplog entry Timestamp from the oldestActiveOplogEntryTS set if it is not boost::none. */ void onAbortActive(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource* tickSource, boost::optional<Timestamp> oldestOplogEntryTS, Top* top); @@ -89,7 +89,7 @@ public: * oldest oplog entry Timestamp from the oldestActiveOplogEntryTS set if it is not boost::none. */ void onAbortInactive(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource* tickSource, boost::optional<Timestamp> oldestOplogEntryTS, Top* top); @@ -125,7 +125,8 @@ public: private: // Updates relevant metrics for any generic transaction abort. void _onAbort(ServerTransactionsMetrics* serverTransactionsMetrics, - unsigned long long curTime, + TickSource::Tick curTick, + TickSource* tickSource, Top* top); // Tracks metrics for a single multi-document transaction. diff --git a/src/mongo/db/transaction_participant.cpp b/src/mongo/db/transaction_participant.cpp index 144dec8c0cc..e4423d4f3d9 100644 --- a/src/mongo/db/transaction_participant.cpp +++ b/src/mongo/db/transaction_participant.cpp @@ -152,16 +152,22 @@ void TransactionParticipant::_beginMultiDocumentTransaction(WithLock wl, TxnNumb _txnState.transitionTo(wl, TransactionState::kInProgress); // Start tracking various transactions metrics. - auto curTime = curTimeMicros64(); - _transactionExpireDate = Date_t::fromMillisSinceEpoch(curTime / 1000) + - stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()}; + // + // We measure the start time in both microsecond and millisecond resolution. The TickSource + // provides microsecond resolution to record the duration of the transaction. The start "wall + // clock" time can be considered an approximation to the microsecond measurement. + auto now = getGlobalServiceContext()->getPreciseClockSource()->now(); + auto tickSource = getGlobalServiceContext()->getTickSource(); + + _transactionExpireDate = now + stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()}; { stdx::lock_guard<stdx::mutex> lm(_metricsMutex); _transactionMetricsObserver.onStart( ServerTransactionsMetrics::get(getGlobalServiceContext()), *_autoCommit, - curTime, + tickSource, + now, *_transactionExpireDate); } invariant(_transactionOperations.empty()); @@ -398,8 +404,8 @@ void TransactionParticipant::_stashActiveTransaction(WithLock, OperationContext* invariant(_activeTxnNumber == opCtx->getTxnNumber()); { stdx::lock_guard<stdx::mutex> lm(_metricsMutex); - _transactionMetricsObserver.onStash(ServerTransactionsMetrics::get(opCtx), - curTimeMicros64()); + auto tickSource = opCtx->getServiceContext()->getTickSource(); + _transactionMetricsObserver.onStash(ServerTransactionsMetrics::get(opCtx), tickSource); _transactionMetricsObserver.onTransactionOperation( opCtx->getClient(), CurOp::get(opCtx)->debug().additiveMetrics); } @@ -463,7 +469,7 @@ void TransactionParticipant::unstashTransactionResources(OperationContext* opCtx _txnResourceStash = boost::none; stdx::lock_guard<stdx::mutex> lm(_metricsMutex); _transactionMetricsObserver.onUnstash(ServerTransactionsMetrics::get(opCtx), - curTimeMicros64()); + opCtx->getServiceContext()->getTickSource()); return; } @@ -494,7 +500,7 @@ void TransactionParticipant::unstashTransactionResources(OperationContext* opCtx stdx::lock_guard<stdx::mutex> lm(_metricsMutex); _transactionMetricsObserver.onUnstash(ServerTransactionsMetrics::get(opCtx), - curTimeMicros64()); + opCtx->getServiceContext()->getTickSource()); } // Storage engine transactions may be started in a lazy manner. By explicitly @@ -767,11 +773,11 @@ void TransactionParticipant::_finishCommitTransaction(WithLock lk, OperationCont _txnState.transitionTo(lk, TransactionState::kCommitted); - const auto curTime = curTimeMicros64(); { stdx::lock_guard<stdx::mutex> lm(_metricsMutex); + auto tickSource = opCtx->getServiceContext()->getTickSource(); _transactionMetricsObserver.onCommit(ServerTransactionsMetrics::get(opCtx), - curTime, + tickSource, _oldestOplogEntryTS, &Top::get(getGlobalServiceContext())); _transactionMetricsObserver.onTransactionOperation( @@ -940,7 +946,7 @@ void TransactionParticipant::_abortActiveTransaction(stdx::unique_lock<stdx::mut } void TransactionParticipant::_abortTransactionOnSession(WithLock wl) { - const auto curTime = curTimeMicros64(); + const auto tickSource = getGlobalServiceContext()->getTickSource(); // If the transaction is stashed, then we have aborted an inactive transaction. if (_txnResourceStash) { // The transaction is stashed, so we abort the inactive transaction on session. @@ -948,7 +954,7 @@ void TransactionParticipant::_abortTransactionOnSession(WithLock wl) { stdx::lock_guard<stdx::mutex> lm(_metricsMutex); _transactionMetricsObserver.onAbortInactive( ServerTransactionsMetrics::get(getGlobalServiceContext()), - curTime, + tickSource, _oldestOplogEntryTS, &Top::get(getGlobalServiceContext())); } @@ -961,7 +967,7 @@ void TransactionParticipant::_abortTransactionOnSession(WithLock wl) { stdx::lock_guard<stdx::mutex> lm(_metricsMutex); _transactionMetricsObserver.onAbortActive( ServerTransactionsMetrics::get(getGlobalServiceContext()), - curTime, + tickSource, _oldestOplogEntryTS, &Top::get(getGlobalServiceContext())); } @@ -1208,7 +1214,9 @@ void TransactionParticipant::TransactionState::transitionTo(WithLock, void TransactionParticipant::_reportTransactionStats(WithLock wl, BSONObjBuilder* builder, repl::ReadConcernArgs readConcernArgs) const { - _transactionMetricsObserver.getSingleTransactionStats().report(builder, readConcernArgs); + auto tickSource = getGlobalServiceContext()->getTickSource(); + _transactionMetricsObserver.getSingleTransactionStats().report( + builder, readConcernArgs, tickSource, tickSource->getTicks()); } void TransactionParticipant::_updateState(WithLock wl, const Session::RefreshState& newState) { @@ -1259,11 +1267,15 @@ std::string TransactionParticipant::_transactionInfoForLog( terminationCause == TransactionState::kCommitted ? "committed" : "aborted"; s << " terminationCause:" << terminationCauseString; - auto curTime = curTimeMicros64(); + auto tickSource = getGlobalServiceContext()->getTickSource(); + auto curTick = tickSource->getTicks(); + s << " timeActiveMicros:" - << durationCount<Microseconds>(singleTransactionStats.getTimeActiveMicros(curTime)); + << durationCount<Microseconds>( + singleTransactionStats.getTimeActiveMicros(tickSource, curTick)); s << " timeInactiveMicros:" - << durationCount<Microseconds>(singleTransactionStats.getTimeInactiveMicros(curTime)); + << durationCount<Microseconds>( + singleTransactionStats.getTimeInactiveMicros(tickSource, curTick)); // Number of yields is always 0 in multi-document transactions, but it is included mainly to // match the format with other slow operation logging messages. @@ -1276,7 +1288,7 @@ std::string TransactionParticipant::_transactionInfoForLog( // Total duration of the transaction. s << " " - << Milliseconds{static_cast<long long>(singleTransactionStats.getDuration(curTime)) / 1000}; + << duration_cast<Milliseconds>(singleTransactionStats.getDuration(tickSource, curTick)); return s.str(); } @@ -1287,9 +1299,10 @@ void TransactionParticipant::_logSlowTransaction(WithLock wl, repl::ReadConcernArgs readConcernArgs) { // Only log multi-document transactions. if (!_txnState.isNone(wl)) { + auto tickSource = getGlobalServiceContext()->getTickSource(); // Log the transaction if its duration is longer than the slowMS command threshold. - if (_transactionMetricsObserver.getSingleTransactionStats().getDuration(curTimeMicros64()) > - serverGlobalParams.slowMS * 1000ULL) { + if (_transactionMetricsObserver.getSingleTransactionStats().getDuration( + tickSource, tickSource->getTicks()) > Milliseconds(serverGlobalParams.slowMS)) { log(logger::LogComponent::kTransaction) << "transaction " << _transactionInfoForLog(lockStats, terminationCause, readConcernArgs); diff --git a/src/mongo/db/transaction_participant_test.cpp b/src/mongo/db/transaction_participant_test.cpp index f43b1149c49..dac0f16ce4a 100644 --- a/src/mongo/db/transaction_participant_test.cpp +++ b/src/mongo/db/transaction_participant_test.cpp @@ -48,7 +48,9 @@ #include "mongo/stdx/memory.h" #include "mongo/unittest/death_test.h" #include "mongo/unittest/unittest.h" +#include "mongo/util/clock_source_mock.h" #include "mongo/util/net/socket_utils.h" +#include "mongo/util/tick_source_mock.h" namespace mongo { namespace { @@ -353,188 +355,6 @@ TEST_F(TxnParticipantTest, StashAndUnstashResources) { txnParticipant->commitUnpreparedTransaction(opCtx()); } -TEST_F(TxnParticipantTest, ReportStashedResources) { - Date_t startTime = Date_t::now(); - const bool autocommit = false; - - ASSERT(opCtx()->lockState()); - ASSERT(opCtx()->recoveryUnit()); - - OperationContextSessionMongod opCtxSession(opCtx(), true, autocommit, true); - - // Create a ClientMetadata object and set it on ClientMetadataIsMasterState. - BSONObjBuilder builder; - ASSERT_OK(ClientMetadata::serializePrivate("driverName", - "driverVersion", - "osType", - "osName", - "osArchitecture", - "osVersion", - "appName", - &builder)); - auto obj = builder.obj(); - auto clientMetadata = ClientMetadata::parse(obj["client"]); - auto& clientMetadataIsMasterState = ClientMetadataIsMasterState::get(opCtx()->getClient()); - clientMetadataIsMasterState.setClientMetadata(opCtx()->getClient(), - std::move(clientMetadata.getValue())); - - repl::ReadConcernArgs readConcernArgs; - ASSERT_OK(readConcernArgs.initialize(BSON("find" - << "test" - << repl::ReadConcernArgs::kReadConcernFieldName - << BSON(repl::ReadConcernArgs::kLevelFieldName - << "snapshot")))); - repl::ReadConcernArgs::get(opCtx()) = readConcernArgs; - - // Perform initial unstash which sets up a WriteUnitOfWork. - auto txnParticipant = TransactionParticipant::get(opCtx()); - txnParticipant->unstashTransactionResources(opCtx(), "find"); - ASSERT(opCtx()->getWriteUnitOfWork()); - ASSERT(opCtx()->lockState()->isLocked()); - - // Stash resources. The original Locker and RecoveryUnit now belong to the stash. - txnParticipant->stashTransactionResources(opCtx()); - ASSERT(!opCtx()->getWriteUnitOfWork()); - - // Verify that the Session's report of its own stashed state aligns with our expectations. - auto stashedState = txnParticipant->reportStashedState(); - auto transactionDocument = stashedState.getObjectField("transaction"); - auto parametersDocument = transactionDocument.getObjectField("parameters"); - - ASSERT_EQ(stashedState.getField("host").valueStringData().toString(), - getHostNameCachedAndPort()); - ASSERT_EQ(stashedState.getField("desc").valueStringData().toString(), "inactive transaction"); - ASSERT_BSONOBJ_EQ(stashedState.getField("lsid").Obj(), _sessionId.toBSON()); - ASSERT_EQ(parametersDocument.getField("txnNumber").numberLong(), *opCtx()->getTxnNumber()); - ASSERT_EQ(parametersDocument.getField("autocommit").boolean(), autocommit); - ASSERT_BSONELT_EQ(parametersDocument.getField("readConcern"), - readConcernArgs.toBSON().getField("readConcern")); - ASSERT_GTE(transactionDocument.getField("readTimestamp").timestamp(), Timestamp(0, 0)); - ASSERT_GTE( - dateFromISOString(transactionDocument.getField("startWallClockTime").valueStringData()) - .getValue(), - startTime); - ASSERT_EQ( - dateFromISOString(transactionDocument.getField("expiryTime").valueStringData()).getValue(), - Date_t::fromMillisSinceEpoch(txnParticipant->getSingleTransactionStats().getStartTime() / - 1000) + - stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()}); - - ASSERT_EQ(stashedState.getField("client").valueStringData().toString(), ""); - ASSERT_EQ(stashedState.getField("connectionId").numberLong(), 0); - ASSERT_EQ(stashedState.getField("appName").valueStringData().toString(), "appName"); - ASSERT_BSONOBJ_EQ(stashedState.getField("clientMetadata").Obj(), obj.getField("client").Obj()); - ASSERT_EQ(stashedState.getField("waitingForLock").boolean(), false); - ASSERT_EQ(stashedState.getField("active").boolean(), false); - - // For the following time metrics, we are only verifying that the transaction sub-document is - // being constructed correctly with proper types because we have other tests to verify that the - // values are being tracked correctly. - ASSERT_GTE(transactionDocument.getField("timeOpenMicros").numberLong(), 0); - ASSERT_GTE(transactionDocument.getField("timeActiveMicros").numberLong(), 0); - ASSERT_GTE(transactionDocument.getField("timeInactiveMicros").numberLong(), 0); - - // Unset the read concern on the OperationContext. This is needed to unstash. - repl::ReadConcernArgs::get(opCtx()) = repl::ReadConcernArgs(); - - // Unstash the stashed resources. This restores the original Locker and RecoveryUnit to the - // OperationContext. - txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction"); - ASSERT(opCtx()->getWriteUnitOfWork()); - - // With the resources unstashed, verify that the Session reports an empty stashed state. - ASSERT(txnParticipant->reportStashedState().isEmpty()); - - // Commit the transaction. This allows us to release locks. - txnParticipant->commitUnpreparedTransaction(opCtx()); -} - -TEST_F(TxnParticipantTest, ReportUnstashedResources) { - Date_t startTime = Date_t::now(); - ASSERT(opCtx()->lockState()); - ASSERT(opCtx()->recoveryUnit()); - - const auto autocommit = false; - OperationContextSessionMongod opCtxSession(opCtx(), true, autocommit, true); - - repl::ReadConcernArgs readConcernArgs; - ASSERT_OK(readConcernArgs.initialize(BSON("find" - << "test" - << repl::ReadConcernArgs::kReadConcernFieldName - << BSON(repl::ReadConcernArgs::kLevelFieldName - << "snapshot")))); - repl::ReadConcernArgs::get(opCtx()) = readConcernArgs; - - // Perform initial unstash which sets up a WriteUnitOfWork. - auto txnParticipant = TransactionParticipant::get(opCtx()); - txnParticipant->unstashTransactionResources(opCtx(), "find"); - ASSERT(opCtx()->getWriteUnitOfWork()); - ASSERT(opCtx()->lockState()->isLocked()); - - // Verify that the Session's report of its own unstashed state aligns with our expectations. - BSONObjBuilder unstashedStateBuilder; - txnParticipant->reportUnstashedState(repl::ReadConcernArgs::get(opCtx()), - &unstashedStateBuilder); - auto unstashedState = unstashedStateBuilder.obj(); - auto transactionDocument = unstashedState.getObjectField("transaction"); - auto parametersDocument = transactionDocument.getObjectField("parameters"); - - ASSERT_EQ(parametersDocument.getField("txnNumber").numberLong(), *opCtx()->getTxnNumber()); - ASSERT_EQ(parametersDocument.getField("autocommit").boolean(), autocommit); - ASSERT_BSONELT_EQ(parametersDocument.getField("readConcern"), - readConcernArgs.toBSON().getField("readConcern")); - ASSERT_GTE(transactionDocument.getField("readTimestamp").timestamp(), Timestamp(0, 0)); - ASSERT_GTE( - dateFromISOString(transactionDocument.getField("startWallClockTime").valueStringData()) - .getValue(), - startTime); - ASSERT_EQ( - dateFromISOString(transactionDocument.getField("expiryTime").valueStringData()).getValue(), - Date_t::fromMillisSinceEpoch(txnParticipant->getSingleTransactionStats().getStartTime() / - 1000) + - stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()}); - - // For the following time metrics, we are only verifying that the transaction sub-document is - // being constructed correctly with proper types because we have other tests to verify that the - // values are being tracked correctly. - ASSERT_GTE(transactionDocument.getField("timeOpenMicros").numberLong(), 0); - ASSERT_GTE(transactionDocument.getField("timeActiveMicros").numberLong(), 0); - ASSERT_GTE(transactionDocument.getField("timeInactiveMicros").numberLong(), 0); - - // Stash resources. The original Locker and RecoveryUnit now belong to the stash. - txnParticipant->stashTransactionResources(opCtx()); - ASSERT(!opCtx()->getWriteUnitOfWork()); - - // With the resources stashed, verify that the Session reports an empty unstashed state. - BSONObjBuilder builder; - txnParticipant->reportUnstashedState(repl::ReadConcernArgs::get(opCtx()), &builder); - ASSERT(builder.obj().isEmpty()); -} - -TEST_F(TxnParticipantTest, ReportUnstashedResourcesForARetryableWrite) { - ASSERT(opCtx()->lockState()); - ASSERT(opCtx()->recoveryUnit()); - - OperationContextSessionMongod opCtxSession(opCtx(), true, boost::none, boost::none); - auto txnParticipant = TransactionParticipant::get(opCtx()); - txnParticipant->unstashTransactionResources(opCtx(), "find"); - - // Build a BSONObj containing the details which we expect to see reported when we call - // Session::reportUnstashedState. For a retryable write, we should only include the txnNumber. - BSONObjBuilder reportBuilder; - BSONObjBuilder transactionBuilder(reportBuilder.subobjStart("transaction")); - BSONObjBuilder parametersBuilder(transactionBuilder.subobjStart("parameters")); - parametersBuilder.append("txnNumber", *opCtx()->getTxnNumber()); - parametersBuilder.done(); - transactionBuilder.done(); - - // Verify that the Session's report of its own unstashed state aligns with our expectations. - BSONObjBuilder unstashedStateBuilder; - txnParticipant->reportUnstashedState(repl::ReadConcernArgs::get(opCtx()), - &unstashedStateBuilder); - ASSERT_BSONOBJ_EQ(unstashedStateBuilder.obj(), reportBuilder.obj()); -} - TEST_F(TxnParticipantTest, CannotSpecifyStartTransactionOnInProgressTxn) { // Must specify startTransaction=true and autocommit=false to start a transaction. OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); @@ -1788,7 +1608,31 @@ TEST_F(TxnParticipantTest, ThrowDuringPreparedOnTransactionAbortIsFatal) { /** * Test fixture for transactions metrics. */ -class TransactionsMetricsTest : public TxnParticipantTest {}; +class TransactionsMetricsTest : public TxnParticipantTest { + +public: + using TickSourceMicrosecondMock = TickSourceMock<Microseconds>; + + /** + * Set up and return a mock clock source. + */ + ClockSourceMock* initMockPreciseClockSource() { + getServiceContext()->setPreciseClockSource(stdx::make_unique<ClockSourceMock>()); + return dynamic_cast<ClockSourceMock*>(getServiceContext()->getPreciseClockSource()); + } + + /** + * Set up and return a mock tick source. + */ + TickSourceMicrosecondMock* initMockTickSource() { + getServiceContext()->setTickSource(stdx::make_unique<TickSourceMicrosecondMock>()); + auto tickSource = + dynamic_cast<TickSourceMicrosecondMock*>(getServiceContext()->getTickSource()); + // Ensure that the tick source is not initialized to zero. + tickSource->reset(1); + return tickSource; + } +}; TEST_F(TransactionsMetricsTest, IncrementTotalStartedUponStartTransaction) { unsigned long long beforeTransactionStart = @@ -1974,268 +1818,275 @@ TEST_F(TransactionsMetricsTest, TrackTotalActiveAndInactiveTransactionsWithUnsta ASSERT_EQ(ServerTransactionsMetrics::get(opCtx())->getCurrentInactive(), beforeInactiveCounter); } -TEST_F(TransactionsMetricsTest, SingleTransactionStatsStartTimeShouldBeSetUponTransactionStart) { - // Save the time before the transaction is created. - unsigned long long timeBeforeTxn = curTimeMicros64(); - OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); - - unsigned long long timeAfterTxn = curTimeMicros64(); - - // Start time should be greater than or equal to the time before the transaction was created. - auto txnParticipant = TransactionParticipant::get(opCtx()); - ASSERT_GTE(txnParticipant->getSingleTransactionStats().getStartTime(), timeBeforeTxn); - - // Start time should be less than or equal to the time after the transaction was started. - ASSERT_LTE(txnParticipant->getSingleTransactionStats().getStartTime(), timeAfterTxn); -} - TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldBeSetUponCommit) { - unsigned long long timeBeforeTxnStart = curTimeMicros64(); + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); - unsigned long long timeAfterTxnStart = curTimeMicros64(); txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction"); // The transaction machinery cannot store an empty locker. Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); - // Sleep here to allow enough time to elapse. - sleepmillis(10); + // Advance the clock. + tickSource->advance(Microseconds(100)); - unsigned long long timeBeforeTxnCommit = curTimeMicros64(); txnParticipant->commitUnpreparedTransaction(opCtx()); - unsigned long long timeAfterTxnCommit = curTimeMicros64(); - - ASSERT_GTE(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - timeBeforeTxnCommit - timeAfterTxnStart); - ASSERT_LTE(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - timeAfterTxnCommit - timeBeforeTxnStart); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(100)); } TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldBeSetUponAbort) { - unsigned long long timeBeforeTxnStart = curTimeMicros64(); + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); - unsigned long long timeAfterTxnStart = curTimeMicros64(); txnParticipant->unstashTransactionResources(opCtx(), "insert"); - // Sleep here to allow enough time to elapse. - sleepmillis(10); + // Advance the clock. + tickSource->advance(Microseconds(100)); - unsigned long long timeBeforeTxnAbort = curTimeMicros64(); txnParticipant->abortArbitraryTransaction(); - unsigned long long timeAfterTxnAbort = curTimeMicros64(); - - ASSERT_GTE(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - timeBeforeTxnAbort - timeAfterTxnStart); - ASSERT_LTE(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - timeAfterTxnAbort - timeBeforeTxnStart); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(100)); } TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasingUntilCommit) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction"); // The transaction machinery cannot store an empty locker. Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); - // Save the transaction's duration at this point. - unsigned long long txnDurationAfterStart = - txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()); - sleepmillis(10); + tickSource->advance(Microseconds(100)); // The transaction's duration should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - txnDurationAfterStart); - sleepmillis(10); - txnParticipant->commitUnpreparedTransaction(opCtx()); - unsigned long long txnDurationAfterCommit = - txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(100)); - // The transaction has committed, so the duration should have not increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - txnDurationAfterCommit); + tickSource->advance(Microseconds(100)); - ASSERT_GT(txnDurationAfterCommit, txnDurationAfterStart); + // Commit the transaction and check duration. + txnParticipant->commitUnpreparedTransaction(opCtx()); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(200)); + + // The transaction committed, so the duration shouldn't have increased even if more time passed. + tickSource->advance(Microseconds(100)); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(200)); } TEST_F(TransactionsMetricsTest, SingleTransactionStatsDurationShouldKeepIncreasingUntilAbort) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); txnParticipant->unstashTransactionResources(opCtx(), "insert"); // The transaction machinery cannot store an empty locker. Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); - // Save the transaction's duration at this point. - unsigned long long txnDurationAfterStart = - txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()); - sleepmillis(10); + tickSource->advance(Microseconds(100)); // The transaction's duration should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - txnDurationAfterStart); - sleepmillis(10); - txnParticipant->abortArbitraryTransaction(); - unsigned long long txnDurationAfterAbort = - txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(100)); - // The transaction has aborted, so the duration should have not increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getDuration(curTimeMicros64()), - txnDurationAfterAbort); + tickSource->advance(Microseconds(100)); - ASSERT_GT(txnDurationAfterAbort, txnDurationAfterStart); + // Abort the transaction and check duration. + txnParticipant->abortArbitraryTransaction(); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(200)); + + // The transaction aborted, so the duration shouldn't have increased even if more time passed. + tickSource->advance(Microseconds(100)); + ASSERT_EQ( + txnParticipant->getSingleTransactionStats().getDuration(tickSource, tickSource->getTicks()), + Microseconds(200)); } TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldBeSetUponUnstashAndStash) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); // Time active should be zero. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), Microseconds{0}); txnParticipant->unstashTransactionResources(opCtx(), "insert"); - - // Sleep a bit to make sure time active is nonzero. - sleepmillis(1); - + tickSource->advance(Microseconds(100)); // The transaction machinery cannot store an empty locker. { Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); } txnParticipant->stashTransactionResources(opCtx()); - // Time active should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - Microseconds{0}); + // Advance clock during inactive period. + tickSource->advance(Microseconds(100)); - // Save time active at this point. - auto timeActiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()); + // Time active should have increased only during active period. + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); txnParticipant->unstashTransactionResources(opCtx(), "insert"); - // Sleep here to allow enough time to elapse. - sleepmillis(10); + tickSource->advance(Microseconds(100)); txnParticipant->stashTransactionResources(opCtx()); + // Advance clock during inactive period. + tickSource->advance(Microseconds(100)); + // Time active should have increased again. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - timeActiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{200}); // Start a new transaction. const auto higherTxnNum = *opCtx()->getTxnNumber() + 1; txnParticipant->beginOrContinue(higherTxnNum, false, true); // Time active should be zero for a new transaction. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), Microseconds{0}); } TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldBeSetUponUnstashAndAbort) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); // Time active should be zero. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), Microseconds{0}); txnParticipant->unstashTransactionResources(opCtx(), "insert"); - // Sleep here to allow enough time to elapse. - sleepmillis(10); + tickSource->advance(Microseconds(100)); txnParticipant->abortArbitraryTransaction(); // Time active should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - Microseconds{0}); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); - // Save time active at this point. - auto timeActiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()); + tickSource->advance(Microseconds(100)); - // The transaction is no longer active, so time active should not have increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - timeActiveSoFar); + // The transaction is not active after abort, so time active should not have increased. + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); } TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldNotBeSetUponAbortOnly) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); // Time active should be zero. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), Microseconds{0}); + // Advance clock during inactive period. + tickSource->advance(Microseconds(100)); + txnParticipant->abortArbitraryTransaction(); - // Time active should not have increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), + // Time active should still be zero. + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), Microseconds{0}); } TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldIncreaseUntilStash) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); // Time active should be zero. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), Microseconds{0}); txnParticipant->unstashTransactionResources(opCtx(), "insert"); - sleepmillis(1); + tickSource->advance(Microseconds(100)); // Time active should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - Microseconds{0}); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds(100)); - // Save time active at this point. - auto timeActiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()); - sleepmillis(1); + tickSource->advance(Microseconds(100)); // Time active should have increased again. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - timeActiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds(200)); + // The transaction machinery cannot store an empty locker. { Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); } txnParticipant->stashTransactionResources(opCtx()); - // The transaction is no longer active, so time active should not have increased. - timeActiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()); - sleepmillis(1); - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - timeActiveSoFar); + tickSource->advance(Microseconds(100)); + + // The transaction is no longer active, so time active should have stopped increasing. + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds(200)); } TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldIncreaseUntilCommit) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); // Time active should be zero. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), Microseconds{0}); txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction"); - sleepmillis(1); + + tickSource->advance(Microseconds(100)); // Time active should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - Microseconds{0}); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); - // Save time active at this point. - auto timeActiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()); - sleepmillis(1); + tickSource->advance(Microseconds(100)); // Time active should have increased again. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - timeActiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{200}); + txnParticipant->commitUnpreparedTransaction(opCtx()); - // The transaction is no longer active, so time active should not have increased. - timeActiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()); - sleepmillis(1); - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - timeActiveSoFar); + tickSource->advance(Microseconds(100)); + + // The transaction is no longer active, so time active should have stopped increasing. + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds(200)); } TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldNotBeSetIfUnstashHasBadReadConcernArgs) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); @@ -2246,20 +2097,16 @@ TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldNotBeSetIfUnstashHasBadRea // Transaction resources do not exist yet. txnParticipant->unstashTransactionResources(opCtx(), "find"); - // Sleep a bit to make sure time active is nonzero. - sleepmillis(1); + tickSource->advance(Microseconds(100)); // The transaction machinery cannot store an empty locker. { Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); } txnParticipant->stashTransactionResources(opCtx()); // Time active should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - Microseconds{0}); - - // Save time active at this point. - auto timeActiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); // Transaction resources already exist here and should throw an exception due to bad read // concern arguments. @@ -2267,9 +2114,12 @@ TEST_F(TransactionsMetricsTest, TimeActiveMicrosShouldNotBeSetIfUnstashHasBadRea AssertionException, ErrorCodes::InvalidOptions); + tickSource->advance(Microseconds(100)); + // Time active should not have increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTimeMicros64()), - timeActiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeActiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); } TEST_F(TransactionsMetricsTest, AdditiveMetricsObjectsShouldBeAddedTogetherUponStash) { @@ -2380,114 +2230,291 @@ TEST_F(TransactionsMetricsTest, AdditiveMetricsObjectsShouldBeAddedTogetherUponA } TEST_F(TransactionsMetricsTest, TimeInactiveMicrosShouldBeSetUponUnstashAndStash) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); - // Time inactive should be greater than or equal to zero. - ASSERT_GTE(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - Microseconds{0}); - - // Save time inactive at this point. - auto timeInactiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()); - // Sleep here to allow enough time to elapse. - sleepmillis(1); - // Time inactive should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + tickSource->advance(Microseconds(100)); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); - timeInactiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()); - // Sleep here to allow enough time to elapse. - sleepmillis(1); - - // The transaction is still inactive, so time inactive should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + // Time inactive should have increased again. + tickSource->advance(Microseconds(100)); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{200}); txnParticipant->unstashTransactionResources(opCtx(), "insert"); - timeInactiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()); - // Sleep here to allow enough time to elapse. - sleepmillis(1); + tickSource->advance(Microseconds(100)); // The transaction is currently active, so time inactive should not have increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{200}); // The transaction machinery cannot store an empty locker. { Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); } txnParticipant->stashTransactionResources(opCtx()); + tickSource->advance(Microseconds(100)); + // The transaction is inactive again, so time inactive should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{300}); } TEST_F(TransactionsMetricsTest, TimeInactiveMicrosShouldBeSetUponUnstashAndAbort) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); // Time inactive should be greater than or equal to zero. - ASSERT_GTE(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - Microseconds{0}); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{0}); - // Save time inactive at this point. - auto timeInactiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()); - // Sleep here to allow enough time to elapse. - sleepmillis(1); + tickSource->advance(Microseconds(100)); // Time inactive should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); txnParticipant->unstashTransactionResources(opCtx(), "insert"); txnParticipant->abortArbitraryTransaction(); - timeInactiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()); - // Sleep here to allow enough time to elapse. - sleepmillis(1); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); + + tickSource->advance(Microseconds(100)); // The transaction has aborted, so time inactive should not have increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); } TEST_F(TransactionsMetricsTest, TimeInactiveMicrosShouldIncreaseUntilCommit) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); auto txnParticipant = TransactionParticipant::get(opCtx()); // Time inactive should be greater than or equal to zero. - ASSERT_GTE(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - Microseconds{0}); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{0}); - // Save time inactive at this point. - auto timeInactiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()); - // Sleep here to allow enough time to elapse. - sleepmillis(1); + tickSource->advance(Microseconds(100)); // Time inactive should have increased. - ASSERT_GT(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); txnParticipant->unstashTransactionResources(opCtx(), "insert"); // The transaction machinery cannot store an empty locker. { Lock::GlobalLock lk(opCtx(), MODE_IX, Date_t::now(), Lock::InterruptBehavior::kThrow); } txnParticipant->commitUnpreparedTransaction(opCtx()); - timeInactiveSoFar = - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()); - // Sleep here to allow enough time to elapse. - sleepmillis(1); + tickSource->advance(Microseconds(100)); // The transaction has committed, so time inactive should not have increased. - ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTimeMicros64()), - timeInactiveSoFar); + ASSERT_EQ(txnParticipant->getSingleTransactionStats().getTimeInactiveMicros( + tickSource, tickSource->getTicks()), + Microseconds{100}); +} + + +TEST_F(TransactionsMetricsTest, ReportStashedResources) { + auto clockSource = initMockPreciseClockSource(); + auto startTime = Date_t::now(); + clockSource->reset(startTime); + + const bool autocommit = false; + + ASSERT(opCtx()->lockState()); + ASSERT(opCtx()->recoveryUnit()); + + OperationContextSessionMongod opCtxSession(opCtx(), true, autocommit, true); + + // Create a ClientMetadata object and set it on ClientMetadataIsMasterState. + BSONObjBuilder builder; + ASSERT_OK(ClientMetadata::serializePrivate("driverName", + "driverVersion", + "osType", + "osName", + "osArchitecture", + "osVersion", + "appName", + &builder)); + auto obj = builder.obj(); + auto clientMetadata = ClientMetadata::parse(obj["client"]); + auto& clientMetadataIsMasterState = ClientMetadataIsMasterState::get(opCtx()->getClient()); + clientMetadataIsMasterState.setClientMetadata(opCtx()->getClient(), + std::move(clientMetadata.getValue())); + + repl::ReadConcernArgs readConcernArgs; + ASSERT_OK(readConcernArgs.initialize(BSON("find" + << "test" + << repl::ReadConcernArgs::kReadConcernFieldName + << BSON(repl::ReadConcernArgs::kLevelFieldName + << "snapshot")))); + repl::ReadConcernArgs::get(opCtx()) = readConcernArgs; + + // Perform initial unstash which sets up a WriteUnitOfWork. + auto txnParticipant = TransactionParticipant::get(opCtx()); + txnParticipant->unstashTransactionResources(opCtx(), "find"); + ASSERT(opCtx()->getWriteUnitOfWork()); + ASSERT(opCtx()->lockState()->isLocked()); + + // Stash resources. The original Locker and RecoveryUnit now belong to the stash. + txnParticipant->stashTransactionResources(opCtx()); + ASSERT(!opCtx()->getWriteUnitOfWork()); + + // Verify that the Session's report of its own stashed state aligns with our expectations. + auto stashedState = txnParticipant->reportStashedState(); + auto transactionDocument = stashedState.getObjectField("transaction"); + auto parametersDocument = transactionDocument.getObjectField("parameters"); + + ASSERT_EQ(stashedState.getField("host").valueStringData().toString(), + getHostNameCachedAndPort()); + ASSERT_EQ(stashedState.getField("desc").valueStringData().toString(), "inactive transaction"); + ASSERT_BSONOBJ_EQ(stashedState.getField("lsid").Obj(), _sessionId.toBSON()); + ASSERT_EQ(parametersDocument.getField("txnNumber").numberLong(), *opCtx()->getTxnNumber()); + ASSERT_EQ(parametersDocument.getField("autocommit").boolean(), autocommit); + ASSERT_BSONELT_EQ(parametersDocument.getField("readConcern"), + readConcernArgs.toBSON().getField("readConcern")); + ASSERT_GTE(transactionDocument.getField("readTimestamp").timestamp(), Timestamp(0, 0)); + ASSERT_EQ( + dateFromISOString(transactionDocument.getField("startWallClockTime").valueStringData()) + .getValue(), + startTime); + ASSERT_EQ( + dateFromISOString(transactionDocument.getField("expiryTime").valueStringData()).getValue(), + startTime + stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()}); + + ASSERT_EQ(stashedState.getField("client").valueStringData().toString(), ""); + ASSERT_EQ(stashedState.getField("connectionId").numberLong(), 0); + ASSERT_EQ(stashedState.getField("appName").valueStringData().toString(), "appName"); + ASSERT_BSONOBJ_EQ(stashedState.getField("clientMetadata").Obj(), obj.getField("client").Obj()); + ASSERT_EQ(stashedState.getField("waitingForLock").boolean(), false); + ASSERT_EQ(stashedState.getField("active").boolean(), false); + + // For the following time metrics, we are only verifying that the transaction sub-document is + // being constructed correctly with proper types because we have other tests to verify that the + // values are being tracked correctly. + ASSERT_GTE(transactionDocument.getField("timeOpenMicros").numberLong(), 0); + ASSERT_GTE(transactionDocument.getField("timeActiveMicros").numberLong(), 0); + ASSERT_GTE(transactionDocument.getField("timeInactiveMicros").numberLong(), 0); + + // Unset the read concern on the OperationContext. This is needed to unstash. + repl::ReadConcernArgs::get(opCtx()) = repl::ReadConcernArgs(); + + // Unstash the stashed resources. This restores the original Locker and RecoveryUnit to the + // OperationContext. + txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction"); + ASSERT(opCtx()->getWriteUnitOfWork()); + + // With the resources unstashed, verify that the Session reports an empty stashed state. + ASSERT(txnParticipant->reportStashedState().isEmpty()); + + // Commit the transaction. This allows us to release locks. + txnParticipant->commitUnpreparedTransaction(opCtx()); +} + +TEST_F(TransactionsMetricsTest, ReportUnstashedResources) { + auto clockSource = initMockPreciseClockSource(); + auto startTime = Date_t::now(); + clockSource->reset(startTime); + + ASSERT(opCtx()->lockState()); + ASSERT(opCtx()->recoveryUnit()); + + const auto autocommit = false; + OperationContextSessionMongod opCtxSession(opCtx(), true, autocommit, true); + + repl::ReadConcernArgs readConcernArgs; + ASSERT_OK(readConcernArgs.initialize(BSON("find" + << "test" + << repl::ReadConcernArgs::kReadConcernFieldName + << BSON(repl::ReadConcernArgs::kLevelFieldName + << "snapshot")))); + repl::ReadConcernArgs::get(opCtx()) = readConcernArgs; + + // Perform initial unstash which sets up a WriteUnitOfWork. + auto txnParticipant = TransactionParticipant::get(opCtx()); + txnParticipant->unstashTransactionResources(opCtx(), "find"); + ASSERT(opCtx()->getWriteUnitOfWork()); + ASSERT(opCtx()->lockState()->isLocked()); + + // Verify that the Session's report of its own unstashed state aligns with our expectations. + BSONObjBuilder unstashedStateBuilder; + txnParticipant->reportUnstashedState(repl::ReadConcernArgs::get(opCtx()), + &unstashedStateBuilder); + auto unstashedState = unstashedStateBuilder.obj(); + auto transactionDocument = unstashedState.getObjectField("transaction"); + auto parametersDocument = transactionDocument.getObjectField("parameters"); + + ASSERT_EQ(parametersDocument.getField("txnNumber").numberLong(), *opCtx()->getTxnNumber()); + ASSERT_EQ(parametersDocument.getField("autocommit").boolean(), autocommit); + ASSERT_BSONELT_EQ(parametersDocument.getField("readConcern"), + readConcernArgs.toBSON().getField("readConcern")); + ASSERT_GTE(transactionDocument.getField("readTimestamp").timestamp(), Timestamp(0, 0)); + ASSERT_EQ( + dateFromISOString(transactionDocument.getField("startWallClockTime").valueStringData()) + .getValue(), + startTime); + ASSERT_EQ( + dateFromISOString(transactionDocument.getField("expiryTime").valueStringData()).getValue(), + startTime + stdx::chrono::seconds{transactionLifetimeLimitSeconds.load()}); + + // For the following time metrics, we are only verifying that the transaction sub-document is + // being constructed correctly with proper types because we have other tests to verify that + // the values are being tracked correctly. + ASSERT_GTE(transactionDocument.getField("timeOpenMicros").numberLong(), 0); + ASSERT_GTE(transactionDocument.getField("timeActiveMicros").numberLong(), 0); + ASSERT_GTE(transactionDocument.getField("timeInactiveMicros").numberLong(), 0); + + // Stash resources. The original Locker and RecoveryUnit now belong to the stash. + txnParticipant->stashTransactionResources(opCtx()); + ASSERT(!opCtx()->getWriteUnitOfWork()); + + // With the resources stashed, verify that the Session reports an empty unstashed state. + BSONObjBuilder builder; + txnParticipant->reportUnstashedState(repl::ReadConcernArgs::get(opCtx()), &builder); + ASSERT(builder.obj().isEmpty()); +} + +TEST_F(TransactionsMetricsTest, ReportUnstashedResourcesForARetryableWrite) { + ASSERT(opCtx()->lockState()); + ASSERT(opCtx()->recoveryUnit()); + + OperationContextSessionMongod opCtxSession(opCtx(), true, boost::none, boost::none); + auto txnParticipant = TransactionParticipant::get(opCtx()); + txnParticipant->unstashTransactionResources(opCtx(), "find"); + + // Build a BSONObj containing the details which we expect to see reported when we call + // Session::reportUnstashedState. For a retryable write, we should only include the txnNumber. + BSONObjBuilder reportBuilder; + BSONObjBuilder transactionBuilder(reportBuilder.subobjStart("transaction")); + BSONObjBuilder parametersBuilder(transactionBuilder.subobjStart("parameters")); + parametersBuilder.append("txnNumber", *opCtx()->getTxnNumber()); + parametersBuilder.done(); + transactionBuilder.done(); + + // Verify that the Session's report of its own unstashed state aligns with our expectations. + BSONObjBuilder unstashedStateBuilder; + txnParticipant->reportUnstashedState(repl::ReadConcernArgs::get(opCtx()), + &unstashedStateBuilder); + ASSERT_BSONOBJ_EQ(unstashedStateBuilder.obj(), reportBuilder.obj()); } namespace { @@ -2639,16 +2666,19 @@ void buildSingleTransactionStatsString(StringBuilder* sb, const int metricValue) */ void buildTimeActiveInactiveString(StringBuilder* sb, TransactionParticipant* txnParticipant, - unsigned long long curTime) { + TickSource* tickSource, + TickSource::Tick curTick) { // Add time active micros to string. (*sb) << " timeActiveMicros:" << durationCount<Microseconds>( - txnParticipant->getSingleTransactionStats().getTimeActiveMicros(curTime)); + txnParticipant->getSingleTransactionStats().getTimeActiveMicros(tickSource, + curTick)); // Add time inactive micros to string. (*sb) << " timeInactiveMicros:" << durationCount<Microseconds>( - txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(curTime)); + txnParticipant->getSingleTransactionStats().getTimeInactiveMicros(tickSource, + curTick)); } /* @@ -2677,9 +2707,10 @@ std::string buildTransactionInfoString(OperationContext* opCtx, StringBuilder singleTransactionStatsInfo; buildSingleTransactionStatsString(&singleTransactionStatsInfo, metricValue); - auto curTime = curTimeMicros64(); + auto tickSource = opCtx->getServiceContext()->getTickSource(); StringBuilder timeActiveAndInactiveInfo; - buildTimeActiveInactiveString(&timeActiveAndInactiveInfo, txnParticipant, curTime); + buildTimeActiveInactiveString( + &timeActiveAndInactiveInfo, txnParticipant, tickSource, tickSource->getTicks()); BSONObjBuilder locks; if (lockerInfo) { @@ -2697,13 +2728,14 @@ std::string buildTransactionInfoString(OperationContext* opCtx, // { acquireCount: { r: 1, w: 1, W: 2 } }, Collection: { acquireCount: { R: 1 } }, oplog: { // acquireCount: { W: 1 } } } 0ms StringBuilder expectedTransactionInfo; - expectedTransactionInfo - << parametersInfo.str() << readTimestampInfo.str() << singleTransactionStatsInfo.str() - << " terminationCause:" << terminationCause << timeActiveAndInactiveInfo.str() - << " numYields:" << 0 << " locks:" << locks.done().toString() << " " - << Milliseconds{static_cast<long long>( - txnParticipant->getSingleTransactionStats().getDuration(curTime)) / - 1000}; + expectedTransactionInfo << parametersInfo.str() << readTimestampInfo.str() + << singleTransactionStatsInfo.str() + << " terminationCause:" << terminationCause + << timeActiveAndInactiveInfo.str() << " numYields:" << 0 + << " locks:" << locks.done().toString() << " " + << duration_cast<Milliseconds>( + txnParticipant->getSingleTransactionStats().getDuration( + tickSource, tickSource->getTicks())); return expectedTransactionInfo.str(); } @@ -2804,6 +2836,8 @@ DEATH_TEST_F(TransactionsMetricsTest, TestTransactionInfoForLogWithNoLockerInfoS } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); repl::ReadConcernArgs readConcernArgs; @@ -2823,7 +2857,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) { txnParticipant->unstashTransactionResources(opCtx(), "commitTransaction"); serverGlobalParams.slowMS = 10; - sleepmillis(serverGlobalParams.slowMS + 1); + tickSource->advance(Microseconds(11 * 1000)); startCapturingLogMessages(); txnParticipant->commitUnpreparedTransaction(opCtx()); @@ -2837,6 +2871,8 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowCommit) { } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); repl::ReadConcernArgs readConcernArgs; @@ -2856,7 +2892,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) { txnParticipant->unstashTransactionResources(opCtx(), "abortTransaction"); serverGlobalParams.slowMS = 10; - sleepmillis(serverGlobalParams.slowMS + 1); + tickSource->advance(Microseconds(11 * 1000)); startCapturingLogMessages(); txnParticipant->abortActiveTransaction(opCtx()); @@ -2870,6 +2906,8 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowAbort) { } TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) { + auto tickSource = initMockTickSource(); + OperationContextSessionMongod opCtxSession(opCtx(), true, false, true); repl::ReadConcernArgs readConcernArgs; @@ -2896,7 +2934,7 @@ TEST_F(TransactionsMetricsTest, LogTransactionInfoAfterSlowStashedAbort) { const auto lockerInfo = txnResourceStashLocker->getLockerInfo(boost::none); serverGlobalParams.slowMS = 10; - sleepmillis(serverGlobalParams.slowMS + 1); + tickSource->advance(Microseconds(11 * 1000)); startCapturingLogMessages(); txnParticipant->abortArbitraryTransaction(); diff --git a/src/mongo/s/catalog/replset_dist_lock_manager_test.cpp b/src/mongo/s/catalog/replset_dist_lock_manager_test.cpp index e6527b548c3..231a3d62b2c 100644 --- a/src/mongo/s/catalog/replset_dist_lock_manager_test.cpp +++ b/src/mongo/s/catalog/replset_dist_lock_manager_test.cpp @@ -118,14 +118,14 @@ private: class RSDistLockMgrWithMockTickSource : public ReplSetDistLockManagerFixture { protected: RSDistLockMgrWithMockTickSource() { - getServiceContext()->setTickSource(stdx::make_unique<TickSourceMock>()); + getServiceContext()->setTickSource(stdx::make_unique<TickSourceMock<>>()); } /** * Returns the mock tick source. */ - TickSourceMock* getMockTickSource() { - return dynamic_cast<TickSourceMock*>(getServiceContext()->getTickSource()); + TickSourceMock<>* getMockTickSource() { + return dynamic_cast<TickSourceMock<>*>(getServiceContext()->getTickSource()); } }; diff --git a/src/mongo/s/sharding_router_test_fixture.cpp b/src/mongo/s/sharding_router_test_fixture.cpp index 264bd25240b..cc4fc863246 100644 --- a/src/mongo/s/sharding_router_test_fixture.cpp +++ b/src/mongo/s/sharding_router_test_fixture.cpp @@ -99,7 +99,7 @@ ShardingTestFixture::ShardingTestFixture() { // Configure the service context service->setFastClockSource(stdx::make_unique<ClockSourceMock>()); service->setPreciseClockSource(stdx::make_unique<ClockSourceMock>()); - service->setTickSource(stdx::make_unique<TickSourceMock>()); + service->setTickSource(stdx::make_unique<TickSourceMock<>>()); CollatorFactoryInterface::set(service, stdx::make_unique<CollatorFactoryMock>()); _transportSession = transport::MockSession::create(nullptr); diff --git a/src/mongo/transport/service_executor_adaptive.cpp b/src/mongo/transport/service_executor_adaptive.cpp index 5d928bd0520..710f49cb317 100644 --- a/src/mongo/transport/service_executor_adaptive.cpp +++ b/src/mongo/transport/service_executor_adaptive.cpp @@ -96,8 +96,7 @@ constexpr auto kThreadReasons = "threadCreationCauses"_sd; int64_t ticksToMicros(TickSource::Tick ticks, TickSource* tickSource) { invariant(tickSource->getTicksPerSecond() >= 1000000); - static const auto ticksPerMicro = tickSource->getTicksPerSecond() / 1000000; - return ticks / ticksPerMicro; + return tickSource->ticksTo<Microseconds>(ticks).count(); } struct ServerParameterOptions : public ServiceExecutorAdaptive::Options { diff --git a/src/mongo/transport/service_state_machine_test.cpp b/src/mongo/transport/service_state_machine_test.cpp index 37e4dcb251d..d530719ee48 100644 --- a/src/mongo/transport/service_state_machine_test.cpp +++ b/src/mongo/transport/service_state_machine_test.cpp @@ -295,7 +295,7 @@ protected: auto sc = scOwned.get(); setGlobalServiceContext(std::move(scOwned)); - sc->setTickSource(stdx::make_unique<TickSourceMock>()); + sc->setTickSource(stdx::make_unique<TickSourceMock<>>()); sc->setFastClockSource(stdx::make_unique<ClockSourceMock>()); auto sep = stdx::make_unique<MockSEP>(); diff --git a/src/mongo/util/SConscript b/src/mongo/util/SConscript index 5e29f17fe61..d31c2d90536 100644 --- a/src/mongo/util/SConscript +++ b/src/mongo/util/SConscript @@ -174,8 +174,7 @@ env.CppUnitTest( env.Library( target='clock_source_mock', source=[ - 'clock_source_mock.cpp', - 'tick_source_mock.cpp', + 'clock_source_mock.cpp' ], LIBDEPS=[ '$BUILD_DIR/mongo/base', @@ -193,6 +192,14 @@ env.CppUnitTest( ) env.CppUnitTest( + target='tick_source_test', + source=[ + 'tick_source_test.cpp', + ], + LIBDEPS=[], +) + +env.CppUnitTest( target='text_test', source=[ 'text_test.cpp' diff --git a/src/mongo/util/tick_source.h b/src/mongo/util/tick_source.h index 134f4d05737..1aef0e478dc 100644 --- a/src/mongo/util/tick_source.h +++ b/src/mongo/util/tick_source.h @@ -50,5 +50,18 @@ public: * Returns the conversion ratio from ticks to seconds. */ virtual Tick getTicksPerSecond() = 0; + + /** + * Convert the given tick count into a duration, specified by the type parameter. + * + * e.g. tickSource->ticksTo<Milliseconds>(ticks); + */ + template <typename D> + D ticksTo(Tick ticks) { + // The number of ticks per 1 duration unit. + double ticksPerD = + static_cast<double>(getTicksPerSecond()) * D::period::num / D::period::den; + return D(static_cast<int64_t>(ticks / ticksPerD)); + } }; } // namespace mongo diff --git a/src/mongo/util/tick_source_mock.h b/src/mongo/util/tick_source_mock.h index 066bd3c9dcc..d0d16189e84 100644 --- a/src/mongo/util/tick_source_mock.h +++ b/src/mongo/util/tick_source_mock.h @@ -34,24 +34,38 @@ namespace mongo { /** - * Mock tick source with millisecond resolution that doesn't gives a fixed tick count - * until the advance method is called. + * Mock tick source that can be parameterized on a duration type. + * + * Its internal tick count will be tracked in the unit of the duration type parameter. For example, + * for TickSourceMock<Milliseconds>, 1 tick = 1 millisecond. It gives a fixed tick count until the + * advance method is called. */ +template <typename D = Milliseconds> class TickSourceMock final : public TickSource { public: - TickSource::Tick getTicks() override; + TickSource::Tick getTicks() override { + return _currentTicks; + }; - TickSource::Tick getTicksPerSecond() override; + TickSource::Tick getTicksPerSecond() override { + static_assert(D::period::num == 1, + "Cannot measure ticks per second for duration types larger than 1 second."); + return D::period::den; + }; /** * Advance the ticks by the given amount of milliseconds. */ - void advance(const Milliseconds& ms); + void advance(const D& duration) { + _currentTicks += duration.count(); + } /** - * Resets the tick count to the give value. + * Resets the tick count to the given value. */ - void reset(TickSource::Tick tick); + void reset(TickSource::Tick tick) { + _currentTicks = std::move(tick); + } private: TickSource::Tick _currentTicks = 0; diff --git a/src/mongo/util/tick_source_mock.cpp b/src/mongo/util/tick_source_test.cpp index c5a5596ee94..2b26221910c 100644 --- a/src/mongo/util/tick_source_mock.cpp +++ b/src/mongo/util/tick_source_test.cpp @@ -1,5 +1,5 @@ /** - * Copyright (C) 2015 MongoDB Inc. + * Copyright (C) 2016 MongoDB Inc. * * This program is free software: you can redistribute it and/or modify * it under the terms of the GNU Affero General Public License, version 3, @@ -26,30 +26,30 @@ * it in the license file. */ -#include "mongo/util/tick_source_mock.h" +#include "mongo/platform/basic.h" -#include <utility> +#include "mongo/unittest/unittest.h" +#include "mongo/util/tick_source.h" +#include "mongo/util/tick_source_mock.h" namespace mongo { - namespace { -const TickSource::Tick kTicksPerSecond = 1000; -} // unnamed namespace -TickSource::Tick TickSourceMock::getTicks() { - return _currentTicks; +TEST(TickSourceTest, TicksToDurationConversion) { + TickSourceMock<Seconds> tsSecs; + tsSecs.reset(1); + ASSERT_EQ(tsSecs.ticksTo<Seconds>(tsSecs.getTicks()).count(), 1); + ASSERT_EQ(tsSecs.ticksTo<Milliseconds>(tsSecs.getTicks()).count(), 1000); + ASSERT_EQ(tsSecs.ticksTo<Microseconds>(tsSecs.getTicks()).count(), 1000 * 1000); + + TickSourceMock<Milliseconds> tsMillis; + tsMillis.reset(1); + ASSERT_EQ(tsMillis.ticksTo<Milliseconds>(tsMillis.getTicks()).count(), 1); + ASSERT_EQ(tsMillis.ticksTo<Microseconds>(tsMillis.getTicks()).count(), 1000); + + TickSourceMock<Microseconds> tsMicros; + tsMicros.reset(1); + ASSERT_EQ(tsMicros.ticksTo<Microseconds>(tsMicros.getTicks()).count(), 1); } - -TickSource::Tick TickSourceMock::getTicksPerSecond() { - return kTicksPerSecond; } - -void TickSourceMock::advance(const Milliseconds& ms) { - _currentTicks += ms.count(); -} - -void TickSourceMock::reset(TickSource::Tick tick) { - _currentTicks = std::move(tick); -} - } // namespace mongo |