summaryrefslogtreecommitdiff
path: root/src
diff options
context:
space:
mode:
authorWilliam Schultz <william.schultz@mongodb.com>2018-10-02 21:54:58 -0400
committerWilliam Schultz <william.schultz@mongodb.com>2018-10-02 21:57:52 -0400
commit982ba21e0ffbdaaf766dc8fa060728ba9b5f4914 (patch)
treeefc760c482e30bd70bfbaf5854779a89acf00ef3 /src
parent23d7c89e501d221a41f350b0b10a52a4f05bb2e2 (diff)
downloadmongo-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')
-rw-r--r--src/mongo/db/SConscript1
-rw-r--r--src/mongo/db/ftdc/ftdc_test.cpp2
-rw-r--r--src/mongo/db/operation_context_test.cpp2
-rw-r--r--src/mongo/db/s/namespace_metadata_change_notifications_test.cpp2
-rw-r--r--src/mongo/db/single_transaction_stats.cpp57
-rw-r--r--src/mongo/db/single_transaction_stats.h54
-rw-r--r--src/mongo/db/transaction_metrics_observer.cpp45
-rw-r--r--src/mongo/db/transaction_metrics_observer.h17
-rw-r--r--src/mongo/db/transaction_participant.cpp53
-rw-r--r--src/mongo/db/transaction_participant_test.cpp824
-rw-r--r--src/mongo/s/catalog/replset_dist_lock_manager_test.cpp6
-rw-r--r--src/mongo/s/sharding_router_test_fixture.cpp2
-rw-r--r--src/mongo/transport/service_executor_adaptive.cpp3
-rw-r--r--src/mongo/transport/service_state_machine_test.cpp2
-rw-r--r--src/mongo/util/SConscript11
-rw-r--r--src/mongo/util/tick_source.h13
-rw-r--r--src/mongo/util/tick_source_mock.h28
-rw-r--r--src/mongo/util/tick_source_test.cpp (renamed from src/mongo/util/tick_source_mock.cpp)40
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