From c6de86a80c16fae6246582d426c5a9bc4bc55072 Mon Sep 17 00:00:00 2001 From: Roxanne Skelly Date: Fri, 24 May 2019 14:52:55 -0700 Subject: [PATCH] Log packet processing time for domain server list request packets --- domain-server/src/DomainGatekeeper.cpp | 5 ++- domain-server/src/DomainGatekeeper.h | 2 +- domain-server/src/DomainServer.cpp | 15 ++++--- domain-server/src/DomainServer.h | 4 +- domain-server/src/NodeConnectionData.h | 2 +- libraries/networking/src/NodeList.cpp | 45 ++++++++++++-------- libraries/networking/src/ReceivedMessage.cpp | 14 +++++- libraries/networking/src/ReceivedMessage.h | 3 ++ libraries/networking/src/udt/Packet.cpp | 1 + libraries/networking/src/udt/PacketList.cpp | 9 ++++ libraries/networking/src/udt/PacketList.h | 3 ++ libraries/networking/src/udt/Socket.cpp | 1 + 12 files changed, 75 insertions(+), 29 deletions(-) diff --git a/domain-server/src/DomainGatekeeper.cpp b/domain-server/src/DomainGatekeeper.cpp index 75399d1a9b..f5705a570b 100644 --- a/domain-server/src/DomainGatekeeper.cpp +++ b/domain-server/src/DomainGatekeeper.cpp @@ -128,7 +128,7 @@ void DomainGatekeeper::processConnectRequestPacket(QSharedPointergetFirstPacketReceiveTime()); } 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 diff --git a/domain-server/src/DomainGatekeeper.h b/domain-server/src/DomainGatekeeper.h index f8d79179d6..92b400882e 100644 --- a/domain-server/src/DomainGatekeeper.h +++ b/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(); diff --git a/domain-server/src/DomainServer.cpp b/domain-server/src/DomainServer.cpp index 028bfdb9aa..e8401c64c7 100644 --- a/domain-server/src/DomainServer.cpp +++ b/domain-server/src/DomainServer.cpp @@ -14,6 +14,7 @@ #include #include #include +#include #include #include @@ -57,6 +58,8 @@ #include +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 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(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(p_high_resolution_clock::now().time_since_epoch()).count(); auto domainListPackets = NLPacketList::create(PacketType::DomainList, extendedHeader); // always send the node their own UUID back diff --git a/domain-server/src/DomainServer.h b/domain-server/src/DomainServer.h index 8276566233..704650e594 100644 --- a/domain-server/src/DomainServer.h +++ b/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); diff --git a/domain-server/src/NodeConnectionData.h b/domain-server/src/NodeConnectionData.h index 779411d11e..43661f9caf 100644 --- a/domain-server/src/NodeConnectionData.h +++ b/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; diff --git a/libraries/networking/src/NodeList.cpp b/libraries/networking/src/NodeList.cpp index d858711e33..aabeabbbf5 100644 --- a/libraries/networking/src/NodeList.cpp +++ b/libraries/networking/src/NodeList.cpp @@ -11,6 +11,8 @@ #include "NodeList.h" +#include + #include #include #include @@ -37,6 +39,8 @@ #include "SharedUtil.h" #include +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(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 message) bool isAuthenticated; packetStream >> isAuthenticated; - quint64 connectRequestTimestamp; - qint64 now = qint64(usecTimestampNow()); + qint64 now = qint64(duration_cast(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 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 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 message) DependencyManager::get()->lookupShareableNameForDomainID(domainUUID); } + setPermissions(newPermissions); + setAuthenticatePackets(isAuthenticated); + // pull each node in the packet while (packetStream.device()->pos() < message->getSize()) { parseNodeFromPacketStream(packetStream); diff --git a/libraries/networking/src/ReceivedMessage.cpp b/libraries/networking/src/ReceivedMessage.cpp index e70301dab1..86fd3da9ad 100644 --- a/libraries/networking/src/ReceivedMessage.cpp +++ b/libraries/networking/src/ReceivedMessage.cpp @@ -12,6 +12,7 @@ #include "ReceivedMessage.h" #include +#include #include "QSharedPointer" @@ -20,6 +21,8 @@ int sharedPtrReceivedMessageMetaTypeId = qRegisterMetaType(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(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(packet.getReceiveTime().time_since_epoch()).count(); + } + + if (packetPosition == NLPacket::PacketPosition::LAST) { _isComplete = true; emit completed(); } diff --git a/libraries/networking/src/ReceivedMessage.h b/libraries/networking/src/ReceivedMessage.h index af87ef75af..c864616635 100644 --- a/libraries/networking/src/ReceivedMessage.h +++ b/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 _position { 0 }; std::atomic _numPackets { 0 }; + std::atomic _firstPacketReceiveTime { 0 }; NLPacket::LocalID _sourceID { NLPacket::NULL_LOCAL_ID }; PacketType _packetType; diff --git a/libraries/networking/src/udt/Packet.cpp b/libraries/networking/src/udt/Packet.cpp index 0456fa1223..f8b74cea37 100644 --- a/libraries/networking/src/udt/Packet.cpp +++ b/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 { diff --git a/libraries/networking/src/udt/PacketList.cpp b/libraries/networking/src/udt/PacketList.cpp index d69ff39197..f6ea12242e 100644 --- a/libraries/networking/src/udt/PacketList.cpp +++ b/libraries/networking/src/udt/PacketList.cpp @@ -13,6 +13,7 @@ #include "../NetworkLogging.h" +#include #include 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(); +} \ No newline at end of file diff --git a/libraries/networking/src/udt/PacketList.h b/libraries/networking/src/udt/PacketList.h index b9bd6a8c15..8d3ffb2783 100644 --- a/libraries/networking/src/udt/PacketList.h +++ b/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); diff --git a/libraries/networking/src/udt/Socket.cpp b/libraries/networking/src/udt/Socket.cpp index 7829e3727c..6f93281b2a 100644 --- a/libraries/networking/src/udt/Socket.cpp +++ b/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; }