From cddb72bbd77772374435309c03474b6120654bb7 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 15 Feb 2017 12:11:17 -0800 Subject: [PATCH] clean up stats, add slave stats --- assignment-client/src/avatars/AvatarMixer.cpp | 48 ++++++++++++------- assignment-client/src/avatars/AvatarMixer.h | 1 + .../src/avatars/AvatarMixerClientData.cpp | 7 ++- .../src/avatars/AvatarMixerClientData.h | 2 +- .../src/avatars/AvatarMixerSlave.cpp | 23 +++++++-- .../src/avatars/AvatarMixerSlave.h | 6 +++ 6 files changed, 63 insertions(+), 24 deletions(-) diff --git a/assignment-client/src/avatars/AvatarMixer.cpp b/assignment-client/src/avatars/AvatarMixer.cpp index 1405e40f1b..94e78968bb 100644 --- a/assignment-client/src/avatars/AvatarMixer.cpp +++ b/assignment-client/src/avatars/AvatarMixer.cpp @@ -102,6 +102,7 @@ void AvatarMixer::start() { //_slavePool.setNumThreads(1); // grins while (!_isFinished) { + _numTightLoopFrames++; _loopRate.increment(); // FIXME - we really should sleep for the remainder of what we haven't spent time processing @@ -754,24 +755,19 @@ void AvatarMixer::sendStatsPacket() { statsObject["timing_average_b_ignoreCalculation"] = (float)_ignoreCalculationElapsedTime / (float)_numStatFrames; statsObject["timing_average_c_avatarDataPacking"] = (float)_avatarDataPackingElapsedTime / (float)_numStatFrames; statsObject["timing_average_d_packetSending"] = (float)_packetSendingElapsedTime / (float)_numStatFrames; - statsObject["timing_average_e_total_broadcastAvatarData"] = (float)_broadcastAvatarDataElapsedTime / (float)_numStatFrames; - - statsObject["timing_average_y_processEvents"] = (float)_processEventsElapsedTime / (float)_numStatFrames; - statsObject["timing_average_y_queueIncomingPacket"] = (float)_queueIncomingPacketElapsedTime / (float)_numStatFrames; - - - statsObject["timing_average_z_handleAvatarDataPacket"] = (float)_handleAvatarDataPacketElapsedTime / (float)_numStatFrames; - statsObject["timing_average_z_handleAvatarIdentityPacket"] = (float)_handleAvatarIdentityPacketElapsedTime / (float)_numStatFrames; - statsObject["timing_average_z_handleKillAvatarPacket"] = (float)_handleKillAvatarPacketElapsedTime / (float)_numStatFrames; - statsObject["timing_average_z_handleNodeIgnoreRequestPacket"] = (float)_handleNodeIgnoreRequestPacketElapsedTime / (float)_numStatFrames; - statsObject["timing_average_z_handleRadiusIgnoreRequestPacket"] = (float)_handleRadiusIgnoreRequestPacketElapsedTime / (float)_numStatFrames; - statsObject["timing_average_z_handleRequestsDomainListDataPacket"] = (float)_handleRequestsDomainListDataPacketElapsedTime / (float)_numStatFrames; - statsObject["timing_average_z_handleViewFrustumPacket"] = (float)_handleViewFrustumPacketElapsedTime / (float)_numStatFrames; - - statsObject["timing_average_z_processQueuedAvatarDataPackets"] = (float)_processQueuedAvatarDataPacketsElapsedTime / (float)_numStatFrames; - + // this things all occur on the frequency of the tight loop + statsObject["timing_average_y_processEvents"] = (float)_processEventsElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_y_queueIncomingPacket"] = (float)_queueIncomingPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_handleAvatarDataPacket"] = (float)_handleAvatarDataPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_handleAvatarIdentityPacket"] = (float)_handleAvatarIdentityPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_handleKillAvatarPacket"] = (float)_handleKillAvatarPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_handleNodeIgnoreRequestPacket"] = (float)_handleNodeIgnoreRequestPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_handleRadiusIgnoreRequestPacket"] = (float)_handleRadiusIgnoreRequestPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_handleRequestsDomainListDataPacket"] = (float)_handleRequestsDomainListDataPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_handleViewFrustumPacket"] = (float)_handleViewFrustumPacketElapsedTime / (float)_numTightLoopFrames; + statsObject["timing_average_z_processQueuedAvatarDataPackets"] = (float)_processQueuedAvatarDataPacketsElapsedTime / (float)_numTightLoopFrames; statsObject["timing_sendStats"] = (float)_sendStatsElapsedTime; @@ -786,8 +782,24 @@ void AvatarMixer::sendStatsPacket() { _queueIncomingPacketElapsedTime = 0; _processQueuedAvatarDataPacketsElapsedTime = 0; - QJsonObject avatarsObject; + QJsonObject slavesObject; + // gather stats + int slaveNumber = 1; + _slavePool.each([&](AvatarMixerSlave& slave) { + QJsonObject slaveObject; + int nodesProcessed, packetsProcessed; + quint64 processIncomingPacketsElapsedTime; + slave.harvestStats(nodesProcessed, packetsProcessed, processIncomingPacketsElapsedTime); + slaveObject["nodesProcessed"] = nodesProcessed; + slaveObject["packetsProcessed"] = packetsProcessed; + slaveObject["timing_average_processIncomingPackets"] = (float)processIncomingPacketsElapsedTime / (float)_numTightLoopFrames; + slavesObject[QString::number(slaveNumber)] = slaveObject; + slaveNumber++; + }); + statsObject["timing_slaves"] = slavesObject; + + QJsonObject avatarsObject; auto nodeList = DependencyManager::get(); // add stats for each listerner nodeList->eachNode([&](const SharedNodePointer& node) { @@ -818,11 +830,13 @@ void AvatarMixer::sendStatsPacket() { }); statsObject["z_avatars"] = avatarsObject; + ThreadedAssignment::addPacketStatsAndSendStatsPacket(statsObject); _sumListeners = 0; _sumIdentityPackets = 0; _numStatFrames = 0; + _numTightLoopFrames = 0; _broadcastAvatarDataElapsedTime = 0; _displayNameManagementElapsedTime = 0; diff --git a/assignment-client/src/avatars/AvatarMixer.h b/assignment-client/src/avatars/AvatarMixer.h index b1d1dbef0b..c8d1516e0d 100644 --- a/assignment-client/src/avatars/AvatarMixer.h +++ b/assignment-client/src/avatars/AvatarMixer.h @@ -69,6 +69,7 @@ private: int _sumListeners { 0 }; int _numStatFrames { 0 }; + std::atomic _numTightLoopFrames; int _sumIdentityPackets { 0 }; float _maxKbpsPerNode = 0.0f; diff --git a/assignment-client/src/avatars/AvatarMixerClientData.cpp b/assignment-client/src/avatars/AvatarMixerClientData.cpp index 5ba346ade9..09e3a6a87a 100644 --- a/assignment-client/src/avatars/AvatarMixerClientData.cpp +++ b/assignment-client/src/avatars/AvatarMixerClientData.cpp @@ -34,7 +34,8 @@ void AvatarMixerClientData::queuePacket(QSharedPointer message, // packetReceiver.registerListener(PacketType::RadiusIgnoreRequest, this, "handleRadiusIgnoreRequestPacket"); // packetReceiver.registerListener(PacketType::RequestsDomainListData, this, "handleRequestsDomainListDataPacket"); -void AvatarMixerClientData::processPackets() { +int AvatarMixerClientData::processPackets() { + int packetsProcessed = 0; SharedNodePointer node = _packetQueue.node; assert(_packetQueue.empty() || node); _packetQueue.node.clear(); @@ -42,6 +43,8 @@ void AvatarMixerClientData::processPackets() { while (!_packetQueue.empty()) { auto& packet = _packetQueue.back(); + packetsProcessed++; + switch (packet->getType()) { case PacketType::AvatarData: parseData(*packet); @@ -52,6 +55,8 @@ void AvatarMixerClientData::processPackets() { _packetQueue.pop(); } assert(_packetQueue.empty()); + + return packetsProcessed; } int AvatarMixerClientData::parseData(ReceivedMessage& message) { diff --git a/assignment-client/src/avatars/AvatarMixerClientData.h b/assignment-client/src/avatars/AvatarMixerClientData.h index f43df28052..c69599cc26 100644 --- a/assignment-client/src/avatars/AvatarMixerClientData.h +++ b/assignment-client/src/avatars/AvatarMixerClientData.h @@ -120,7 +120,7 @@ public: } void queuePacket(QSharedPointer message, SharedNodePointer node); - void processPackets(); + int processPackets(); // returns number of packets processed private: struct PacketQueue : public std::queue> { diff --git a/assignment-client/src/avatars/AvatarMixerSlave.cpp b/assignment-client/src/avatars/AvatarMixerSlave.cpp index 44f2060b52..06d21b51b9 100644 --- a/assignment-client/src/avatars/AvatarMixerSlave.cpp +++ b/assignment-client/src/avatars/AvatarMixerSlave.cpp @@ -35,10 +35,23 @@ void AvatarMixerSlave::configure(ConstIter begin, ConstIter end) { _end = end; } -void AvatarMixerSlave::processIncomingPackets(const SharedNodePointer& node) { - auto nodeData = dynamic_cast(node->getLinkedData()); - if (nodeData) { - nodeData->processPackets(); - } +void AvatarMixerSlave::harvestStats(int& nodesProcessed, int& packetsProcessed, quint64& processIncomingPacketsElapsedTime) { + nodesProcessed = _nodesProcessed; + packetsProcessed = _packetsProcessed; + processIncomingPacketsElapsedTime = _processIncomingPacketsElapsedTime; + _packetsProcessed = _nodesProcessed = 0; + _processIncomingPacketsElapsedTime = 0; +} + + +void AvatarMixerSlave::processIncomingPackets(const SharedNodePointer& node) { + auto start = usecTimestampNow(); + auto nodeData = dynamic_cast(node->getLinkedData()); + if (nodeData) { + _nodesProcessed++; + _packetsProcessed += nodeData->processPackets(); + } + auto end = usecTimestampNow(); + _processIncomingPacketsElapsedTime += (end - start); } diff --git a/assignment-client/src/avatars/AvatarMixerSlave.h b/assignment-client/src/avatars/AvatarMixerSlave.h index 6bd2f5acd4..1abba8d46c 100644 --- a/assignment-client/src/avatars/AvatarMixerSlave.h +++ b/assignment-client/src/avatars/AvatarMixerSlave.h @@ -29,10 +29,16 @@ public: void processIncomingPackets(const SharedNodePointer& node); + void harvestStats(int& nodesProcessed, int& packetsProcessed, quint64& processIncomingPacketsElapsedTime); + private: // frame state ConstIter _begin; ConstIter _end; + + int _nodesProcessed { 0 }; + int _packetsProcessed { 0 }; + quint64 _processIncomingPacketsElapsedTime { 0 }; }; #endif // hifi_AvatarMixerSlave_h