SERVER-49694: fix latency measurement in RSM; change latency measurement for command responses to Microseconds

12 files changed, 61 insertions, 38 deletions

diff --git a/src/mongo/client/async_client.cpp b/src/mongo/client/async_client.cpp
index d3df41d9705..692f38191f5 100644
--- a/src/mongo/client/async_client.cpp
+++ b/src/mongo/client/async_client.cpp
@@ -226,18 +226,14 @@ Future<void> AsyncDBClient::initWireVersion(const std::string& appName,
     // have to communicate with servers that do not support other protocols.
     auto requestMsg =
         rpc::legacyRequestFromOpMsgRequest(OpMsgRequest::fromDBAndBody("admin", requestObj));
-    auto clkSource = _svcCtx->getFastClockSource();
-    auto start = clkSource->now();
-
     auto msgId = nextMessageId();
     return _call(requestMsg, msgId)
         .then([msgId, this]() { return _waitForResponse(msgId); })
-        .then([this, requestObj, hook, clkSource, start](Message response) {
+        .then([this, requestObj, hook, timer = Timer{}](Message response) {
             auto cmdReply = rpc::makeReply(&response);
             _parseIsMasterResponse(requestObj, cmdReply);
             if (hook) {
-                auto millis = duration_cast<Milliseconds>(clkSource->now() - start);
-                executor::RemoteCommandResponse cmdResp(*cmdReply, millis);
+                executor::RemoteCommandResponse cmdResp(*cmdReply, timer.elapsed());
                 uassertStatusOK(hook->validateHost(_peer, requestObj, std::move(cmdResp)));
             }
         });
@@ -310,16 +306,14 @@ Future<rpc::UniqueReply> AsyncDBClient::runCommand(OpMsgRequest request,
 
 Future<executor::RemoteCommandResponse> AsyncDBClient::runCommandRequest(
     executor::RemoteCommandRequest request, const BatonHandle& baton) {
-    auto clkSource = _svcCtx->getPreciseClockSource();
-    auto start = clkSource->now();
+    auto startTimer = Timer();
     auto opMsgRequest = OpMsgRequest::fromDBAndBody(
         std::move(request.dbname), std::move(request.cmdObj), std::move(request.metadata));
     auto fireAndForget =
         request.fireAndForgetMode == executor::RemoteCommandRequest::FireAndForgetMode::kOn;
     return runCommand(std::move(opMsgRequest), baton, fireAndForget)
-        .then([start, clkSource, this](rpc::UniqueReply response) {
-            auto duration = duration_cast<Milliseconds>(clkSource->now() - start);
-            return executor::RemoteCommandResponse(*response, duration);
+        .then([this, startTimer = std::move(startTimer)](rpc::UniqueReply response) {
+            return executor::RemoteCommandResponse(*response, startTimer.elapsed());
         });
 }
 
diff --git a/src/mongo/client/fetcher.cpp b/src/mongo/client/fetcher.cpp
index ae04a7c4c5c..d8c78fd25c0 100644
--- a/src/mongo/client/fetcher.cpp
+++ b/src/mongo/client/fetcher.cpp
@@ -345,7 +345,7 @@ void Fetcher::_callback(const RemoteCommandCallbackArgs& rcbd, const char* batch
     }
 
     batchData.otherFields.metadata = std::move(rcbd.response.data);
-    batchData.elapsedMillis = rcbd.response.elapsedMillis.value_or(Milliseconds{0});
+    batchData.elapsed = rcbd.response.elapsed.value_or(Microseconds{0});
     {
         stdx::lock_guard<Latch> lk(_mutex);
         batchData.first = _first;
diff --git a/src/mongo/client/fetcher.h b/src/mongo/client/fetcher.h
index bd4556d0ee4..3d0d10abec8 100644
--- a/src/mongo/client/fetcher.h
+++ b/src/mongo/client/fetcher.h
@@ -70,7 +70,7 @@ public:
         struct OtherFields {
             BSONObj metadata;
         } otherFields;
-        Milliseconds elapsedMillis = Milliseconds(0);
+        Microseconds elapsed = Microseconds(0);
         bool first = false;
     };
 
diff --git a/src/mongo/client/fetcher_test.cpp b/src/mongo/client/fetcher_test.cpp
index e8283d1a4a6..c958d860e9c 100644
--- a/src/mongo/client/fetcher_test.cpp
+++ b/src/mongo/client/fetcher_test.cpp
@@ -175,7 +175,7 @@ void FetcherTest::_callback(const StatusWith<Fetcher::QueryResponse>& result,
         cursorId = batchData.cursorId;
         nss = batchData.nss;
         documents = batchData.documents;
-        elapsedMillis = batchData.elapsedMillis;
+        elapsedMillis = duration_cast<Milliseconds>(batchData.elapsed);
         first = batchData.first;
     }
 
diff --git a/src/mongo/client/replica_set_monitor_manager.cpp b/src/mongo/client/replica_set_monitor_manager.cpp
index 56ac55234c2..3f8bffe62dd 100644
--- a/src/mongo/client/replica_set_monitor_manager.cpp
+++ b/src/mongo/client/replica_set_monitor_manager.cpp
@@ -51,6 +51,7 @@
 #include "mongo/logv2/log.h"
 #include "mongo/platform/mutex.h"
 #include "mongo/rpc/metadata/egress_metadata_hook_list.h"
+#include "mongo/util/duration.h"
 
 namespace mongo {
 
@@ -89,7 +90,7 @@ Status ReplicaSetMonitorManagerNetworkConnectionHook::validateHost(
                 try {
                     if (isMasterReply.status.isOK()) {
                         publisher->onServerHandshakeCompleteEvent(
-                            isMasterReply.elapsedMillis.get(), remoteHost, isMasterReply.data);
+                            *isMasterReply.elapsed, remoteHost, isMasterReply.data);
                     } else {
                         publisher->onServerHandshakeFailedEvent(
                             remoteHost, isMasterReply.status, isMasterReply.data);
diff --git a/src/mongo/client/sdam/sdam_datatypes.h b/src/mongo/client/sdam/sdam_datatypes.h
index 4e59dd5a6b7..87a107db7ad 100644
--- a/src/mongo/client/sdam/sdam_datatypes.h
+++ b/src/mongo/client/sdam/sdam_datatypes.h
@@ -73,7 +73,7 @@ std::string toString(const ServerType serverType);
 StatusWith<ServerType> parseServerType(StringData strServerType);
 std::ostream& operator<<(std::ostream& os, const ServerType serverType);
 
-using IsMasterRTT = mongo::Nanoseconds;
+using IsMasterRTT = mongo::Microseconds;
 
 // The result of an attempt to call the "ismaster" command on a server.
 class IsMasterOutcome {
diff --git a/src/mongo/client/sdam/server_description.cpp b/src/mongo/client/sdam/server_description.cpp
index 08500bbe2db..93138d222a6 100644
--- a/src/mongo/client/sdam/server_description.cpp
+++ b/src/mongo/client/sdam/server_description.cpp
@@ -171,8 +171,10 @@ void ServerDescription::calculateRtt(const boost::optional<IsMasterRTT> currentR
         _rtt = currentRtt;
     } else {
         // new_rtt = alpha * x + (1 - alpha) * old_rtt
-        _rtt = IsMasterRTT(static_cast<IsMasterRTT::rep>(kRttAlpha * currentRtt.get().count() +
-                                                         (1 - kRttAlpha) * lastRtt.get().count()));
+        auto currentMicros = durationCount<Microseconds>(*currentRtt);
+        auto lastMicros = durationCount<Microseconds>(*lastRtt);
+        _rtt = Microseconds(static_cast<Microseconds::rep>(kRttAlpha * currentMicros +
+                                                           (1 - kRttAlpha) * lastMicros));
     }
 }
 
diff --git a/src/mongo/client/sdam/server_description_test.cpp b/src/mongo/client/sdam/server_description_test.cpp
index 9949ddec9ee..3c335201281 100644
--- a/src/mongo/client/sdam/server_description_test.cpp
+++ b/src/mongo/client/sdam/server_description_test.cpp
@@ -37,6 +37,8 @@
 #include "mongo/client/sdam/server_description_builder.h"
 #include "mongo/db/jsobj.h"
 #include "mongo/db/repl/optime.h"
+#include "mongo/platform/random.h"
+#include "mongo/unittest/unittest.h"
 #include "mongo/util/system_clock_source.h"
 
 namespace mongo::sdam {
@@ -231,6 +233,8 @@ protected:
         return std::move(BSONObjBuilder().append("ok", 1));
     }
 
+    static inline auto rand = PseudoRandom(SecureRandom().nextInt64());
+
     static inline const auto clockSource = SystemClockSource::get();
 
     static inline const auto kBsonOk = okBuilder().obj();
@@ -383,6 +387,28 @@ TEST_F(ServerDescriptionTestFixture,
     ASSERT_EQUALS(20, durationCount<mongo::Milliseconds>(*description2.getRtt()));
 }
 
+TEST_F(ServerDescriptionTestFixture, ShouldPreserveRTTPrecisionForMicroseconds) {
+    const int numIterations = 100;
+    const int minRttMicros = 100;
+
+    const auto randMicroseconds = [](int m) { return Microseconds(rand.nextInt64(m) + m); };
+    auto lastServerDescription = ServerDescriptionBuilder()
+                                     .withType(ServerType::kRSPrimary)
+                                     .withRtt(randMicroseconds(minRttMicros))
+                                     .instance();
+
+    for (int i = 0; i < numIterations; ++i) {
+        auto lastRtt = *lastServerDescription->getRtt();
+        auto response = IsMasterOutcome(
+            HostAndPort("foo:1234"), kBsonRsPrimary, randMicroseconds(minRttMicros));
+        lastServerDescription = std::make_shared<ServerDescription>(clockSource, response, lastRtt);
+    }
+
+    // assert the value does not decay to zero
+    ASSERT_GT(durationCount<Microseconds>(*lastServerDescription->getRtt()), minRttMicros);
+    ASSERT_LT(durationCount<Microseconds>(*lastServerDescription->getRtt()), 2 * minRttMicros);
+}
+
 TEST_F(ServerDescriptionTestFixture, ShouldStoreLastWriteDate) {
     auto response = IsMasterOutcome(HostAndPort("foo:1234"),
                                     kBsonLastWrite,
diff --git a/src/mongo/client/sdam/topology_listener.cpp b/src/mongo/client/sdam/topology_listener.cpp
index b4d6be361e8..d91f444c033 100644
--- a/src/mongo/client/sdam/topology_listener.cpp
+++ b/src/mongo/client/sdam/topology_listener.cpp
@@ -59,14 +59,14 @@ void TopologyEventsPublisher::onTopologyDescriptionChangedEvent(
     _scheduleNextDelivery();
 }
 
-void TopologyEventsPublisher::onServerHandshakeCompleteEvent(IsMasterRTT durationMs,
+void TopologyEventsPublisher::onServerHandshakeCompleteEvent(IsMasterRTT duration,
                                                              const HostAndPort& address,
                                                              const BSONObj reply) {
     {
         stdx::lock_guard<Mutex> lock(_eventQueueMutex);
         EventPtr event = std::make_unique<Event>();
         event->type = EventType::HANDSHAKE_COMPLETE;
-        event->duration = duration_cast<IsMasterRTT>(durationMs);
+        event->duration = duration;
         event->hostAndPort = address;
         event->reply = reply;
         _eventQueue.push_back(std::move(event));
@@ -136,13 +136,13 @@ void TopologyEventsPublisher::onServerPingFailedEvent(const HostAndPort& hostAnd
     _scheduleNextDelivery();
 }
 
-void TopologyEventsPublisher::onServerPingSucceededEvent(IsMasterRTT durationMS,
+void TopologyEventsPublisher::onServerPingSucceededEvent(IsMasterRTT duration,
                                                          const HostAndPort& hostAndPort) {
     {
         stdx::lock_guard lock(_eventQueueMutex);
         EventPtr event = std::make_unique<Event>();
         event->type = EventType::PING_SUCCESS;
-        event->duration = duration_cast<IsMasterRTT>(durationMS);
+        event->duration = duration;
         event->hostAndPort = hostAndPort;
         _eventQueue.push_back(std::move(event));
     }
@@ -193,13 +193,10 @@ void TopologyEventsPublisher::_sendEvent(TopologyListenerPtr listener, const Eve
             break;
         case EventType::HANDSHAKE_COMPLETE:
             listener->onServerHandshakeCompleteEvent(
-                sdam::IsMasterRTT(duration_cast<Milliseconds>(event.duration)),
-                event.hostAndPort,
-                event.reply);
+                event.duration, event.hostAndPort, event.reply);
             break;
         case EventType::PING_SUCCESS:
-            listener->onServerPingSucceededEvent(duration_cast<IsMasterRTT>(event.duration),
-                                                 event.hostAndPort);
+            listener->onServerPingSucceededEvent(event.duration, event.hostAndPort);
             break;
         case EventType::PING_FAILURE:
             listener->onServerPingFailedEvent(event.hostAndPort, event.status);
diff --git a/src/mongo/client/sdam/topology_listener.h b/src/mongo/client/sdam/topology_listener.h
index a503193ff5c..c7824912b92 100644
--- a/src/mongo/client/sdam/topology_listener.h
+++ b/src/mongo/client/sdam/topology_listener.h
@@ -55,9 +55,9 @@ public:
                                                const BSONObj reply){};
     /**
      * Called when a ServerHandshakeCompleteEvent is published - The initial handshake to the server
-     * at hostAndPort was successful. durationMS is the measured RTT (Round Trip Time).
+     * at hostAndPort was successful. duration is the measured RTT (Round Trip Time).
      */
-    virtual void onServerHandshakeCompleteEvent(IsMasterRTT durationMs,
+    virtual void onServerHandshakeCompleteEvent(IsMasterRTT duration,
                                                 const HostAndPort& address,
                                                 const BSONObj reply = BSONObj()){};
 
@@ -67,7 +67,7 @@ public:
 
     /**
      * Called when a ServerHeartBeatSucceededEvent is published - A heartbeat sent to the server at
-     * hostAndPort succeeded. durationMS is the execution time of the event, including the time it
+     * hostAndPort succeeded. duration is the execution time of the event, including the time it
      * took to send the message and recieve the reply from the server.
      */
     virtual void onServerHeartbeatSucceededEvent(const HostAndPort& hostAndPort,
@@ -81,10 +81,9 @@ public:
 
     /**
      * Called when a ServerPingSucceededEvent is published - A monitoring ping to the server at
-     * hostAndPort was successful. durationMS is the measured RTT (Round Trip Time).
+     * hostAndPort was successful. duration is the measured RTT (Round Trip Time).
      */
-    virtual void onServerPingSucceededEvent(IsMasterRTT durationMS,
-                                            const HostAndPort& hostAndPort){};
+    virtual void onServerPingSucceededEvent(IsMasterRTT duration, const HostAndPort& hostAndPort){};
 };
 
 /**
@@ -104,7 +103,7 @@ public:
 
     void onTopologyDescriptionChangedEvent(TopologyDescriptionPtr previousDescription,
                                            TopologyDescriptionPtr newDescription) override;
-    virtual void onServerHandshakeCompleteEvent(IsMasterRTT durationMs,
+    virtual void onServerHandshakeCompleteEvent(IsMasterRTT duration,
                                                 const HostAndPort& address,
                                                 const BSONObj reply = BSONObj()) override;
 
@@ -118,8 +117,7 @@ public:
                                        const HostAndPort& hostAndPort,
                                        const BSONObj reply) override;
     void onServerPingFailedEvent(const HostAndPort& hostAndPort, const Status& status) override;
-    void onServerPingSucceededEvent(IsMasterRTT durationMS,
-                                    const HostAndPort& hostAndPort) override;
+    void onServerPingSucceededEvent(IsMasterRTT duration, const HostAndPort& hostAndPort) override;
 
 private:
     enum class EventType {
diff --git a/src/mongo/client/server_ping_monitor.cpp b/src/mongo/client/server_ping_monitor.cpp
index 478dd037670..30ad5806e0d 100644
--- a/src/mongo/client/server_ping_monitor.cpp
+++ b/src/mongo/client/server_ping_monitor.cpp
@@ -167,7 +167,7 @@ void SingleServerPingMonitor::_doServerPing() {
                     anchor->_rttListener->onServerPingFailedEvent(anchor->_hostAndPort,
                                                                   result.response.status);
                 } else {
-                    auto rtt = sdam::IsMasterRTT(timer.micros());
+                    auto rtt = Microseconds(timer.micros());
                     anchor->_rttListener->onServerPingSucceededEvent(rtt, anchor->_hostAndPort);
                 }
             }
diff --git a/src/mongo/client/server_ping_monitor_test.cpp b/src/mongo/client/server_ping_monitor_test.cpp
index 6851f672cc9..2a86b31615e 100644
--- a/src/mongo/client/server_ping_monitor_test.cpp
+++ b/src/mongo/client/server_ping_monitor_test.cpp
@@ -153,11 +153,11 @@ protected:
                          const HostAndPort& hostAndPort,
                          MockReplicaSet* replSet) {
         processPingRequest(hostAndPort, replSet);
-
         auto deadline = elapsed() + pingFrequency;
         while (elapsed() < deadline && !_topologyListener->hasPingResponse(hostAndPort)) {
             advanceTime(Milliseconds(100));
         }
+
         ASSERT_TRUE(_topologyListener->hasPingResponse(hostAndPort));
         ASSERT_LT(elapsed(), deadline);
         auto pingResponse = _topologyListener->getPingResponse(hostAndPort);
@@ -165,6 +165,11 @@ protected:
         // There should only be one isMaster response queued up.
         ASSERT_EQ(pingResponse.size(), 1);
         ASSERT(pingResponse[0].isOK());
+
+        // The latency is from the ping monitor's local timer; not from the mocked clock.
+        // Just assert that we receive a signal.
+        ASSERT_GTE(durationCount<Microseconds>(pingResponse[0].getValue()), 1);
+
         checkNoActivityBefore(deadline, hostAndPort);
     }