Log packet processing time for domain server list request packets

domain-server/src/DomainGatekeeper.cpp

@@ -128,7 +128,7 @@ void DomainGatekeeper::processConnectRequestPacket(QSharedPointer<ReceivedMessag
 
         // signal that we just connected a node so the DomainServer can get it a list
         // and broadcast its presence right away
-        emit connectedNode(node);
+        emit connectedNode(node, message->getFirstPacketReceiveTime());
     } else {
         qDebug() << "Refusing connection from node at" << message->getSenderSockAddr()
             << "with hardware address" << nodeConnection.hardwareAddress
@@ -358,6 +358,7 @@ SharedNodePointer DomainGatekeeper::processAssignmentConnectRequest(const NodeCo
     nodeData->setNodeVersion(it->second.getNodeVersion());
     nodeData->setHardwareAddress(nodeConnection.hardwareAddress);
     nodeData->setMachineFingerprint(nodeConnection.machineFingerprint);
+    // client-side send time of last connect/domain list request
     nodeData->setLastDomainCheckinTimestamp(nodeConnection.lastPingTimestamp);
     nodeData->setWasAssigned(true);
 
@@ -499,7 +500,7 @@ SharedNodePointer DomainGatekeeper::processAgentConnectRequest(const NodeConnect
     // set the machine fingerprint passed in the connect request
     nodeData->setMachineFingerprint(nodeConnection.machineFingerprint);
 
-    // set the last ping timestamp passed in the connect request
+    // set client-side send time of last connect/domain list request
     nodeData->setLastDomainCheckinTimestamp(nodeConnection.lastPingTimestamp);
 
     // also add an interpolation to DomainServerNodeData so that servers can get username in stats

domain-server/src/DomainGatekeeper.h

@@ -64,7 +64,7 @@ public slots:
 
 signals:
     void killNode(SharedNodePointer node);
-    void connectedNode(SharedNodePointer node);
+    void connectedNode(SharedNodePointer node, quint64 requestReceiveTime);
 
 public slots:
     void updateNodePermissions();

domain-server/src/DomainServer.cpp

@@ -14,6 +14,7 @@
 #include <memory>
 #include <random>
 #include <iostream>
+#include <chrono>
 
 #include <QDir>
 #include <QJsonDocument>
@@ -57,6 +58,8 @@
 
 #include <OctreeDataUtils.h>
 
+using namespace std::chrono;
+
 Q_LOGGING_CATEGORY(domain_server, "hifi.domain_server")
 Q_LOGGING_CATEGORY(domain_server_ice, "hifi.domain_server.ice")
 
@@ -1068,9 +1071,10 @@ void DomainServer::processListRequestPacket(QSharedPointer<ReceivedMessage> mess
     // update the connecting hostname in case it has changed
     nodeData->setPlaceName(nodeRequestData.placeName);
 
+    // client-side send time of last connect/domain list request
     nodeData->setLastDomainCheckinTimestamp(nodeRequestData.lastPingTimestamp);
 
-    sendDomainListToNode(sendingNode, message->getSenderSockAddr());
+    sendDomainListToNode(sendingNode, message->getFirstPacketReceiveTime(), message->getSenderSockAddr());
 }
 
 bool DomainServer::isInInterestSet(const SharedNodePointer& nodeA, const SharedNodePointer& nodeB) {
@@ -1132,11 +1136,11 @@ QUrl DomainServer::oauthAuthorizationURL(const QUuid& stateUUID) {
     return authorizationURL;
 }
 
-void DomainServer::handleConnectedNode(SharedNodePointer newNode) {
+void DomainServer::handleConnectedNode(SharedNodePointer newNode, quint64 requestReceiveTime) {
     DomainServerNodeData* nodeData = static_cast<DomainServerNodeData*>(newNode->getLinkedData());
 
     // reply back to the user with a PacketType::DomainList
-    sendDomainListToNode(newNode, nodeData->getSendingSockAddr());
+    sendDomainListToNode(newNode, requestReceiveTime, nodeData->getSendingSockAddr());
 
     // if this node is a user (unassigned Agent), signal
     if (newNode->getType() == NodeType::Agent && !nodeData->wasAssigned()) {
@@ -1152,7 +1156,7 @@ void DomainServer::handleConnectedNode(SharedNodePointer newNode) {
     broadcastNewNode(newNode);
 }
 
-void DomainServer::sendDomainListToNode(const SharedNodePointer& node, const HifiSockAddr &senderSockAddr) {
+void DomainServer::sendDomainListToNode(const SharedNodePointer& node, quint64 requestPacketReceiveTime, const HifiSockAddr &senderSockAddr) {
     const int NUM_DOMAIN_LIST_EXTENDED_HEADER_BYTES = NUM_BYTES_RFC4122_UUID + NLPacket::NUM_BYTES_LOCALID +
         NUM_BYTES_RFC4122_UUID + NLPacket::NUM_BYTES_LOCALID + 4;
 
@@ -1170,7 +1174,8 @@ void DomainServer::sendDomainListToNode(const SharedNodePointer& node, const Hif
     extendedHeaderStream << node->getPermissions();
     extendedHeaderStream << limitedNodeList->getAuthenticatePackets();
     extendedHeaderStream << nodeData->getLastDomainCheckinTimestamp();
-    extendedHeaderStream << usecTimestampNow();
+    extendedHeaderStream << requestPacketReceiveTime;
+    extendedHeaderStream << duration_cast<microseconds>(p_high_resolution_clock::now().time_since_epoch()).count();
     auto domainListPackets = NLPacketList::create(PacketType::DomainList, extendedHeader);
 
     // always send the node their own UUID back

domain-server/src/DomainServer.h

@@ -111,7 +111,7 @@ private slots:
     void sendHeartbeatToMetaverse() { sendHeartbeatToMetaverse(QString()); }
     void sendHeartbeatToIceServer();
 
-    void handleConnectedNode(SharedNodePointer newNode); 
+    void handleConnectedNode(SharedNodePointer newNode, quint64 requestReceiveTime); 
     void handleTempDomainSuccess(QNetworkReply* requestReply);
     void handleTempDomainError(QNetworkReply* requestReply);
 
@@ -172,7 +172,7 @@ private:
     void handleKillNode(SharedNodePointer nodeToKill);
     void broadcastNodeDisconnect(const SharedNodePointer& disconnnectedNode);
 
-    void sendDomainListToNode(const SharedNodePointer& node, const HifiSockAddr& senderSockAddr);
+    void sendDomainListToNode(const SharedNodePointer& node, quint64 requestPacketReceiveTime, const HifiSockAddr& senderSockAddr);
 
     bool isInInterestSet(const SharedNodePointer& nodeA, const SharedNodePointer& nodeB);
 

domain-server/src/NodeConnectionData.h

@@ -22,7 +22,7 @@ public:
                                              bool isConnectRequest = true);
     
     QUuid connectUUID;
-    quint64 lastPingTimestamp{ 0 };
+    quint64 lastPingTimestamp{ 0 }; // client-side send time of last connect/domain list request
     NodeType_t nodeType;
     HifiSockAddr publicSockAddr;
     HifiSockAddr localSockAddr;

libraries/networking/src/NodeList.cpp

@@ -11,6 +11,8 @@
 
 #include "NodeList.h"
 
+#include <chrono>
+
 #include <QtCore/QDataStream>
 #include <QtCore/QDebug>
 #include <QtCore/QJsonDocument>
@@ -37,6 +39,8 @@
 #include "SharedUtil.h"
 #include <Trace.h>
 
+using namespace std::chrono;
+
 const int KEEPALIVE_PING_INTERVAL_MS = 1000;
 
 NodeList::NodeList(char newOwnerType, int socketListenPort, int dtlsListenPort) :
@@ -412,7 +416,7 @@ void NodeList::sendDomainServerCheckIn() {
             packetStream << FingerprintUtils::getMachineFingerprint();
         }
 
-        packetStream << usecTimestampNow();
+        packetStream << duration_cast<microseconds>(p_high_resolution_clock::now().time_since_epoch()).count();
 
         // pack our data to send to the domain-server including
         // the hostname information (so the domain-server can see which place name we came in on)
@@ -645,23 +649,28 @@ void NodeList::processDomainServerList(QSharedPointer<ReceivedMessage> message)
     bool isAuthenticated;
     packetStream >> isAuthenticated;
 
-    quint64 connectRequestTimestamp;
-    qint64 now = qint64(usecTimestampNow());
+    qint64 now = qint64(duration_cast<microseconds>(p_high_resolution_clock::now().time_since_epoch()).count());
 
+    quint64 connectRequestTimestamp;
     packetStream >> connectRequestTimestamp;
 
+    quint64 domainServerRequestReceiveTime;
+    packetStream >> domainServerRequestReceiveTime;
+
+    quint64 domainServerPingSendTime;
+    packetStream >> domainServerPingSendTime;
+
     qint64 pingLagTime = (now - qint64(connectRequestTimestamp)) / qint64(USECS_PER_MSEC);
-    quint64 domainServerPingReceiveTime;
 
-    packetStream >> domainServerPingReceiveTime;
-
-    qint64 domainServerRequestLag = (qint64(domainServerPingReceiveTime) - qint64(connectRequestTimestamp)) / qint64(USECS_PER_MSEC);
-    qint64 domainServerResponseLag = (now - qint64(domainServerPingReceiveTime)) / qint64(USECS_PER_MSEC);
+    qint64 domainServerRequestLag = (qint64(connectRequestTimestamp) - qint64(connectRequestTimestamp)) / qint64(USECS_PER_MSEC);
+    quint64 domainServerCheckinProcessingTime = domainServerPingSendTime - domainServerRequestReceiveTime;
+    qint64 domainServerResponseLag = (now - qint64(domainServerPingSendTime)) / qint64(USECS_PER_MSEC);
 
     if (_domainHandler.getSockAddr().isNull()) {
         qWarning(networking) << "IGNORING DomainList packet while not connected to a Domain Server: sent " << pingLagTime << " msec ago.";
-        qWarning(networking) << "DomainList request lag (with skew): " << domainServerRequestLag << "msec";
-        qWarning(networking) << "DomainList response lag (with skew): " << domainServerResponseLag << "msec";
+        qWarning(networking) << "DomainList request lag (interface->ds): " << domainServerRequestLag << "msec";
+        qWarning(networking) << "DomainList server processing time: " << domainServerCheckinProcessingTime << "usec";
+        qWarning(networking) << "DomainList response lag (ds->interface): " << domainServerResponseLag << "msec";
         // refuse to process this packet if we aren't currently connected to the DS
         return;
     }
@@ -669,8 +678,9 @@ void NodeList::processDomainServerList(QSharedPointer<ReceivedMessage> message)
     // warn if ping lag is getting long
     if (pingLagTime > qint64(MSECS_PER_SECOND)) {
         qCDebug(networking) << "DomainList ping is lagging: " << pingLagTime << "msec";
-        qCDebug(networking) << "DomainList request lag (with skew): " << domainServerRequestLag << "msec";
-        qCDebug(networking) << "DomainList response lag (with skew): " << domainServerResponseLag << "msec";
+        qCDebug(networking) << "DomainList request lag (interface->ds): " << domainServerRequestLag << "msec";
+        qCDebug(networking) << "DomainList server processing time: " << domainServerCheckinProcessingTime << "usec";
+        qCDebug(networking) << "DomainList response lag (ds->interface): " << domainServerResponseLag << "msec";
     }
 
     // this is a packet from the domain server, reset the count of un-replied check-ins
@@ -685,14 +695,12 @@ void NodeList::processDomainServerList(QSharedPointer<ReceivedMessage> message)
         // Recieved packet from different domain.
         qWarning() << "IGNORING DomainList packet from" << domainUUID << "while connected to" 
                    << _domainHandler.getUUID() << ": sent " << pingLagTime << " msec ago.";
-        qWarning(networking) << "DomainList request lag (with skew): " << domainServerRequestLag << "msec";
-        qWarning(networking) << "DomainList response lag (with skew): " << domainServerResponseLag << "msec";
+        qWarning(networking) << "DomainList request lag (interface->ds): " << domainServerRequestLag << "msec";
+        qWarning(networking) << "DomainList server processing time: " << domainServerCheckinProcessingTime << "usec";
+        qWarning(networking) << "DomainList response lag (ds->interface): " << domainServerResponseLag << "msec";
         return;
     }
 
-    setPermissions(newPermissions);
-    setAuthenticatePackets(isAuthenticated);
-
     // when connected, if the session ID or local ID were not null and changed, we should reset
     auto currentLocalID = getSessionLocalID();
     auto currentSessionID = getSessionUUID();
@@ -723,6 +731,9 @@ void NodeList::processDomainServerList(QSharedPointer<ReceivedMessage> message)
         DependencyManager::get<AddressManager>()->lookupShareableNameForDomainID(domainUUID);
     }
 
+    setPermissions(newPermissions);
+    setAuthenticatePackets(isAuthenticated);
+
     // pull each node in the packet
     while (packetStream.device()->pos() < message->getSize()) {
         parseNodeFromPacketStream(packetStream);

libraries/networking/src/ReceivedMessage.cpp

@@ -12,6 +12,7 @@
 #include "ReceivedMessage.h"
 
 #include <algorithm>
+#include <chrono>
 
 #include "QSharedPointer"
 
@@ -20,6 +21,8 @@ int sharedPtrReceivedMessageMetaTypeId = qRegisterMetaType<QSharedPointer<Receiv
 
 static const int HEAD_DATA_SIZE = 512;
 
+using namespace std::chrono;
+
 ReceivedMessage::ReceivedMessage(const NLPacketList& packetList)
     : _data(packetList.getMessage()),
       _headData(_data.mid(0, HEAD_DATA_SIZE)),
@@ -29,6 +32,7 @@ ReceivedMessage::ReceivedMessage(const NLPacketList& packetList)
       _packetVersion(packetList.getVersion()),
       _senderSockAddr(packetList.getSenderSockAddr())
 {
+    _firstPacketReceiveTime = duration_cast<microseconds>(packetList.getFirstPacketReceiveTime().time_since_epoch()).count();
 }
 
 ReceivedMessage::ReceivedMessage(NLPacket& packet)
@@ -41,12 +45,14 @@ ReceivedMessage::ReceivedMessage(NLPacket& packet)
       _senderSockAddr(packet.getSenderSockAddr()),
       _isComplete(packet.getPacketPosition() == NLPacket::ONLY)
 {
+    _firstPacketReceiveTime = duration_cast<microseconds>(packet.getReceiveTime().time_since_epoch()).count();
 }
 
 ReceivedMessage::ReceivedMessage(QByteArray byteArray, PacketType packetType, PacketVersion packetVersion,
                 const HifiSockAddr& senderSockAddr, NLPacket::LocalID sourceID) :
     _data(byteArray),
     _headData(_data.mid(0, HEAD_DATA_SIZE)),
+    _firstPacketReceiveTime(0),
     _numPackets(1),
     _sourceID(sourceID),
     _packetType(packetType),
@@ -77,7 +83,13 @@ void ReceivedMessage::appendPacket(NLPacket& packet) {
         emit progress(getSize());
     }
 
-    if (packet.getPacketPosition() == NLPacket::PacketPosition::LAST) {
+    auto packetPosition = packet.getPacketPosition();
+    if ((packetPosition == NLPacket::PacketPosition::FIRST) ||
+        (packetPosition == NLPacket::PacketPosition::ONLY)) {
+        _firstPacketReceiveTime = duration_cast<microseconds>(packet.getReceiveTime().time_since_epoch()).count();
+    }
+
+    if (packetPosition == NLPacket::PacketPosition::LAST) {
         _isComplete = true;
         emit completed();
     }

libraries/networking/src/ReceivedMessage.h

@@ -48,6 +48,8 @@ public:
     // Get the number of packets that were used to send this message
     qint64 getNumPackets() const { return _numPackets; }
 
+    qint64 getFirstPacketReceiveTime() const { return _firstPacketReceiveTime; }
+
     qint64 getSize() const { return _data.size(); }
 
     qint64 getBytesLeftToRead() const { return _data.size() -  _position; }
@@ -92,6 +94,7 @@ private:
 
     std::atomic<qint64> _position { 0 };
     std::atomic<qint64> _numPackets { 0 };
+    std::atomic<quint64> _firstPacketReceiveTime { 0 };
 
     NLPacket::LocalID _sourceID { NLPacket::NULL_LOCAL_ID };
     PacketType _packetType;

libraries/networking/src/udt/Packet.cpp

@@ -171,6 +171,7 @@ void Packet::copyMembers(const Packet& other) {
     _packetPosition = other._packetPosition;
     _messageNumber = other._messageNumber;
     _messagePartNumber = other._messagePartNumber;
+    _receiveTime = other._receiveTime;
 }
 
 void Packet::readHeader() const {

libraries/networking/src/udt/PacketList.cpp

@@ -13,6 +13,7 @@
 
 #include "../NetworkLogging.h"
 
+#include <chrono>
 #include <QDebug>
 
 using namespace udt;
@@ -261,3 +262,11 @@ qint64 PacketList::writeData(const char* data, qint64 maxSize) {
 
     return maxSize;
 }
+
+p_high_resolution_clock::time_point PacketList::getFirstPacketReceiveTime() const {
+    using namespace std::chrono;;
+    if (!_packets.empty()) {
+        return _packets.front()->getReceiveTime();
+    }
+    return p_high_resolution_clock::time_point();
+}

libraries/networking/src/udt/PacketList.h

@@ -59,6 +59,9 @@ public:
     virtual qint64 size() const override { return getDataSize(); }
     
     qint64 writeString(const QString& string);
+
+    p_high_resolution_clock::time_point getFirstPacketReceiveTime() const;
+    
     
 protected:
     PacketList(PacketType packetType, QByteArray extendedHeader = QByteArray(), bool isReliable = false, bool isOrdered = false);

libraries/networking/src/udt/Socket.cpp

@@ -334,6 +334,7 @@ void Socket::readPendingDatagrams() {
         if (system_clock::now() > abortTime) {
             // We've been running for too long, stop processing packets for now
             // Once we've processed the event queue, we'll come back to packet processing
+            qCDebug(networking) << "Socket::readPendingDatagrams() running too long, aborting to process event queue";
             break;
         }