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.

Author: will62794

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',
     ],
 )

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

src/mongo/db/operation_context_test.cpp

@@ -225,7 +225,7 @@ class OperationDeadlineTests : public unittest::Test {
         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");
     }
 

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<>>());
     }
 };
 

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);

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:
@@ -64,19 +66,19 @@ class SingleTransactionStats {
     SingleTransactionStats() : _txnNumber(kUninitializedTxnNumber){};
     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,42 +89,42 @@ class SingleTransactionStats {
      *
      * 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.
      *
      * 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
      * total active time will only be set if the transaction was active prior to this call.
      *
      * 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 @@ class SingleTransactionStats {
     /**
      * 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 @@ class SingleTransactionStats {
     // 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();