From 08ba535c384a62a09ca67583409405694038e9df Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 2 Dec 2015 13:43:05 -0800 Subject: [PATCH 1/3] add some basic send tracking --- .../src/entities/EntityServer.cpp | 46 +++++++++++++++++++ assignment-client/src/entities/EntityServer.h | 6 +++ .../src/octree/OctreeSendThread.cpp | 6 +++ assignment-client/src/octree/OctreeServer.cpp | 5 ++ assignment-client/src/octree/OctreeServer.h | 2 + libraries/entities/src/EntityItem.cpp | 5 ++ libraries/octree/src/Octree.h | 2 + 7 files changed, 72 insertions(+) diff --git a/assignment-client/src/entities/EntityServer.cpp b/assignment-client/src/entities/EntityServer.cpp index 6508f09f72..28e852af6a 100644 --- a/assignment-client/src/entities/EntityServer.cpp +++ b/assignment-client/src/entities/EntityServer.cpp @@ -266,3 +266,49 @@ void EntityServer::readAdditionalConfiguration(const QJsonObject& settingsSectio tree->setWantEditLogging(wantEditLogging); tree->setWantTerseEditLogging(wantTerseEditLogging); } + +void EntityServer::trackSend(const QUuid& dataID, const QUuid& viewerNode) { + QWriteLocker locker(&_viewerSendingStatsLock); + _viewerSendingStats[viewerNode] = usecTimestampNow(); +} + + +QString EntityServer::serverSubclassStats() { + QLocale locale(QLocale::English); + QString statsString; + + // display memory usage stats + statsString += "Entity Server Memory Statistics\r\n"; + statsString += QString().sprintf("EntityTreeElement size... %ld bytes\r\n", sizeof(EntityTreeElement)); + statsString += QString().sprintf(" EntityItem size... %ld bytes\r\n", sizeof(EntityItem)); + statsString += "\r\n\r\n"; + + statsString += "Entity Server Sending to Viewer Statistics\r\n"; + statsString += "----- Viewer Node ID ----------------- ---------- Last Sent To ----------\r\n"; + + int viewers = 0; + const int COLUMN_WIDTH = 24; + + { + QReadLocker locker(&_viewerSendingStatsLock); + quint64 now = usecTimestampNow(); + + for (auto key : _viewerSendingStats.keys()) { + quint64 lastSentAt = _viewerSendingStats[key]; + quint64 elapsed = now - lastSentAt; + double msecsAgo = (double)(elapsed / USECS_PER_MSEC); + statsString += key.toString(); + statsString += " "; + statsString += QString("%1 msecs ago\r\n") + .arg(locale.toString((double)msecsAgo).rightJustified(COLUMN_WIDTH, ' ')); + + viewers++; + } + } + if (viewers < 1) { + statsString += " no viewers... \r\n"; + } + statsString += "\r\n\r\n"; + + return statsString; +} diff --git a/assignment-client/src/entities/EntityServer.h b/assignment-client/src/entities/EntityServer.h index d9795316c4..ab7ca038cf 100644 --- a/assignment-client/src/entities/EntityServer.h +++ b/assignment-client/src/entities/EntityServer.h @@ -44,6 +44,9 @@ public: virtual void entityCreated(const EntityItem& newEntity, const SharedNodePointer& senderNode) override; virtual void readAdditionalConfiguration(const QJsonObject& settingsSectionObject) override; + virtual QString serverSubclassStats(); + + virtual void trackSend(const QUuid& dataID, const QUuid& viewerNode); public slots: void pruneDeletedEntities(); @@ -57,6 +60,9 @@ private slots: private: EntitySimulation* _entitySimulation; QTimer* _pruneDeletedEntitiesTimer = nullptr; + + QReadWriteLock _viewerSendingStatsLock; + QMap _viewerSendingStats; }; #endif // hifi_EntityServer_h diff --git a/assignment-client/src/octree/OctreeSendThread.cpp b/assignment-client/src/octree/OctreeSendThread.cpp index 94d82b463e..fc3731f063 100644 --- a/assignment-client/src/octree/OctreeSendThread.cpp +++ b/assignment-client/src/octree/OctreeSendThread.cpp @@ -467,6 +467,12 @@ int OctreeSendThread::packetDistributor(OctreeQueryNode* nodeData, bool viewFrus isFullScene, &nodeData->stats, _myServer->getJurisdiction(), &nodeData->extraEncodeData); + // Our trackSend() function is implemented by the server subclass, and will be called back + // during the encodeTreeBitstream() as new entities/data elements are sent + params.trackSend = [this](const QUuid& id) { + _myServer->trackSend(id, _nodeUUID); + }; + // TODO: should this include the lock time or not? This stat is sent down to the client, // it seems like it may be a good idea to include the lock time as part of the encode time // are reported to client. Since you can encode without the lock diff --git a/assignment-client/src/octree/OctreeServer.cpp b/assignment-client/src/octree/OctreeServer.cpp index 7cd3e59edf..c5072d0175 100644 --- a/assignment-client/src/octree/OctreeServer.cpp +++ b/assignment-client/src/octree/OctreeServer.cpp @@ -821,6 +821,11 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QUrl& url .arg(locale.toString((uint)checkSum).rightJustified(16, ' ')); statsString += "\r\n\r\n"; + + statsString += serverSubclassStats(); + + statsString += "\r\n\r\n"; + statsString += "\r\n"; statsString += ""; diff --git a/assignment-client/src/octree/OctreeServer.h b/assignment-client/src/octree/OctreeServer.h index 1aea9c960e..6c11a53bd2 100644 --- a/assignment-client/src/octree/OctreeServer.h +++ b/assignment-client/src/octree/OctreeServer.h @@ -79,6 +79,8 @@ public: virtual void beforeRun() { } virtual bool hasSpecialPacketsToSend(const SharedNodePointer& node) { return false; } virtual int sendSpecialPackets(const SharedNodePointer& node, OctreeQueryNode* queryNode, int& packetsSent) { return 0; } + virtual QString serverSubclassStats() { return QString(); } + virtual void trackSend(const QUuid& dataID, const QUuid& viewerNode) { } static float SKIP_TIME; // use this for trackXXXTime() calls for non-times diff --git a/libraries/entities/src/EntityItem.cpp b/libraries/entities/src/EntityItem.cpp index a70a8c0428..cde1012fb0 100644 --- a/libraries/entities/src/EntityItem.cpp +++ b/libraries/entities/src/EntityItem.cpp @@ -311,6 +311,11 @@ OctreeElement::AppendState EntityItem::appendEntityData(OctreePacketData* packet entityTreeElementExtraEncodeData->entities.insert(getEntityItemID(), propertiesDidntFit); } + // if any part of our entity was sent, call trackSend + if (appendState != OctreeElement::NONE) { + params.trackSend(getID()); + } + return appendState; } diff --git a/libraries/octree/src/Octree.h b/libraries/octree/src/Octree.h index d9cf17d7de..118ea79b6e 100644 --- a/libraries/octree/src/Octree.h +++ b/libraries/octree/src/Octree.h @@ -176,6 +176,8 @@ public: case OCCLUDED: return QString("OCCLUDED"); break; } } + + std::function trackSend { [](const QUuid&){} }; }; class ReadElementBufferToTreeArgs { From 1e51a902046304ea8f6619e79a319ef1578c440e Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 2 Dec 2015 14:37:41 -0800 Subject: [PATCH 2/3] add edit times and entity ids to the viewer stats --- .../src/entities/EntityServer.cpp | 41 ++++++++++++++----- assignment-client/src/entities/EntityServer.h | 10 ++++- .../src/octree/OctreeSendThread.cpp | 4 +- assignment-client/src/octree/OctreeServer.h | 2 +- libraries/entities/src/EntityItem.cpp | 2 +- libraries/octree/src/Octree.h | 2 +- 6 files changed, 43 insertions(+), 18 deletions(-) diff --git a/assignment-client/src/entities/EntityServer.cpp b/assignment-client/src/entities/EntityServer.cpp index 28e852af6a..2b53cc9314 100644 --- a/assignment-client/src/entities/EntityServer.cpp +++ b/assignment-client/src/entities/EntityServer.cpp @@ -267,9 +267,14 @@ void EntityServer::readAdditionalConfiguration(const QJsonObject& settingsSectio tree->setWantTerseEditLogging(wantTerseEditLogging); } -void EntityServer::trackSend(const QUuid& dataID, const QUuid& viewerNode) { + +// FIXME - this stats tracking is somewhat temporary to debug the Whiteboard issues. It's not a bad +// set of stats to have, but we'd probably want a different data-structure if we keep it very long. +// Since this version uses a single shared QMap for all senders, there can be a fair amount of lock +// contention on this QWriteLocker +void EntityServer::trackSend(const QUuid& dataID, quint64 dataLastEdited, const QUuid& viewerNode) { QWriteLocker locker(&_viewerSendingStatsLock); - _viewerSendingStats[viewerNode] = usecTimestampNow(); + _viewerSendingStats[viewerNode][dataID] = { usecTimestampNow(), dataLastEdited }; } @@ -284,7 +289,8 @@ QString EntityServer::serverSubclassStats() { statsString += "\r\n\r\n"; statsString += "Entity Server Sending to Viewer Statistics\r\n"; - statsString += "----- Viewer Node ID ----------------- ---------- Last Sent To ----------\r\n"; + statsString += "----- Viewer Node ID ----------------- ----- Entity ID ---------------------- " + "---------- Last Sent To ---------- ---------- Last Edited -----------\r\n"; int viewers = 0; const int COLUMN_WIDTH = 24; @@ -293,15 +299,28 @@ QString EntityServer::serverSubclassStats() { QReadLocker locker(&_viewerSendingStatsLock); quint64 now = usecTimestampNow(); - for (auto key : _viewerSendingStats.keys()) { - quint64 lastSentAt = _viewerSendingStats[key]; - quint64 elapsed = now - lastSentAt; - double msecsAgo = (double)(elapsed / USECS_PER_MSEC); - statsString += key.toString(); - statsString += " "; - statsString += QString("%1 msecs ago\r\n") - .arg(locale.toString((double)msecsAgo).rightJustified(COLUMN_WIDTH, ' ')); + for (auto viewerID : _viewerSendingStats.keys()) { + statsString += viewerID.toString() + "\r\n"; + auto viewerData = _viewerSendingStats[viewerID]; + for (auto entityID : viewerData.keys()) { + ViewerSendingStats stats = viewerData[entityID]; + + quint64 elapsedSinceSent = now - stats.lastSent; + double sentMsecsAgo = (double)(elapsedSinceSent / USECS_PER_MSEC); + + quint64 elapsedSinceEdit = now - stats.lastEdited; + double editMsecsAgo = (double)(elapsedSinceEdit / USECS_PER_MSEC); + + statsString += " "; // the viewerID spacing + statsString += entityID.toString(); + statsString += " "; + statsString += QString("%1 msecs ago") + .arg(locale.toString((double)sentMsecsAgo).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString("%1 msecs ago") + .arg(locale.toString((double)editMsecsAgo).rightJustified(COLUMN_WIDTH, ' ')); + statsString += "\r\n"; + } viewers++; } } diff --git a/assignment-client/src/entities/EntityServer.h b/assignment-client/src/entities/EntityServer.h index ab7ca038cf..d39e966430 100644 --- a/assignment-client/src/entities/EntityServer.h +++ b/assignment-client/src/entities/EntityServer.h @@ -21,6 +21,12 @@ #include "EntityTree.h" /// Handles assignments of type EntityServer - sending entities to various clients. + +struct ViewerSendingStats { + quint64 lastSent; + quint64 lastEdited; +}; + class EntityServer : public OctreeServer, public NewlyCreatedEntityHook { Q_OBJECT public: @@ -46,7 +52,7 @@ public: virtual void readAdditionalConfiguration(const QJsonObject& settingsSectionObject) override; virtual QString serverSubclassStats(); - virtual void trackSend(const QUuid& dataID, const QUuid& viewerNode); + virtual void trackSend(const QUuid& dataID, quint64 dataLastEdited, const QUuid& viewerNode); public slots: void pruneDeletedEntities(); @@ -62,7 +68,7 @@ private: QTimer* _pruneDeletedEntitiesTimer = nullptr; QReadWriteLock _viewerSendingStatsLock; - QMap _viewerSendingStats; + QMap> _viewerSendingStats; }; #endif // hifi_EntityServer_h diff --git a/assignment-client/src/octree/OctreeSendThread.cpp b/assignment-client/src/octree/OctreeSendThread.cpp index fc3731f063..0a32f574de 100644 --- a/assignment-client/src/octree/OctreeSendThread.cpp +++ b/assignment-client/src/octree/OctreeSendThread.cpp @@ -469,8 +469,8 @@ int OctreeSendThread::packetDistributor(OctreeQueryNode* nodeData, bool viewFrus // Our trackSend() function is implemented by the server subclass, and will be called back // during the encodeTreeBitstream() as new entities/data elements are sent - params.trackSend = [this](const QUuid& id) { - _myServer->trackSend(id, _nodeUUID); + params.trackSend = [this](const QUuid& dataID, quint64 dataEdited) { + _myServer->trackSend(dataID, dataEdited, _nodeUUID); }; // TODO: should this include the lock time or not? This stat is sent down to the client, diff --git a/assignment-client/src/octree/OctreeServer.h b/assignment-client/src/octree/OctreeServer.h index 6c11a53bd2..9876f5147c 100644 --- a/assignment-client/src/octree/OctreeServer.h +++ b/assignment-client/src/octree/OctreeServer.h @@ -80,7 +80,7 @@ public: virtual bool hasSpecialPacketsToSend(const SharedNodePointer& node) { return false; } virtual int sendSpecialPackets(const SharedNodePointer& node, OctreeQueryNode* queryNode, int& packetsSent) { return 0; } virtual QString serverSubclassStats() { return QString(); } - virtual void trackSend(const QUuid& dataID, const QUuid& viewerNode) { } + virtual void trackSend(const QUuid& dataID, quint64 dataLastEdited, const QUuid& viewerNode) { } static float SKIP_TIME; // use this for trackXXXTime() calls for non-times diff --git a/libraries/entities/src/EntityItem.cpp b/libraries/entities/src/EntityItem.cpp index cde1012fb0..0120b7c0ca 100644 --- a/libraries/entities/src/EntityItem.cpp +++ b/libraries/entities/src/EntityItem.cpp @@ -313,7 +313,7 @@ OctreeElement::AppendState EntityItem::appendEntityData(OctreePacketData* packet // if any part of our entity was sent, call trackSend if (appendState != OctreeElement::NONE) { - params.trackSend(getID()); + params.trackSend(getID(), getLastEdited()); } return appendState; diff --git a/libraries/octree/src/Octree.h b/libraries/octree/src/Octree.h index 118ea79b6e..514a9b391b 100644 --- a/libraries/octree/src/Octree.h +++ b/libraries/octree/src/Octree.h @@ -177,7 +177,7 @@ public: } } - std::function trackSend { [](const QUuid&){} }; + std::function trackSend { [](const QUuid&, quint64){} }; }; class ReadElementBufferToTreeArgs { From 4497d21aecde9b69babd1434252c599ed76f1f56 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 2 Dec 2015 14:49:04 -0800 Subject: [PATCH 3/3] remove nodes that disconnect from out viewer stats --- assignment-client/src/entities/EntityServer.cpp | 10 +++++++--- assignment-client/src/entities/EntityServer.h | 1 + assignment-client/src/octree/OctreeServer.cpp | 2 ++ assignment-client/src/octree/OctreeServer.h | 1 + 4 files changed, 11 insertions(+), 3 deletions(-) diff --git a/assignment-client/src/entities/EntityServer.cpp b/assignment-client/src/entities/EntityServer.cpp index 2b53cc9314..f37e8cf3f7 100644 --- a/assignment-client/src/entities/EntityServer.cpp +++ b/assignment-client/src/entities/EntityServer.cpp @@ -269,14 +269,18 @@ void EntityServer::readAdditionalConfiguration(const QJsonObject& settingsSectio // FIXME - this stats tracking is somewhat temporary to debug the Whiteboard issues. It's not a bad -// set of stats to have, but we'd probably want a different data-structure if we keep it very long. -// Since this version uses a single shared QMap for all senders, there can be a fair amount of lock -// contention on this QWriteLocker +// set of stats to have, but we'd probably want a different data structure if we keep it very long. +// Since this version uses a single shared QMap for all senders, there could be some lock contention +// on this QWriteLocker void EntityServer::trackSend(const QUuid& dataID, quint64 dataLastEdited, const QUuid& viewerNode) { QWriteLocker locker(&_viewerSendingStatsLock); _viewerSendingStats[viewerNode][dataID] = { usecTimestampNow(), dataLastEdited }; } +void EntityServer::trackViewerGone(const QUuid& viewerNode) { + QWriteLocker locker(&_viewerSendingStatsLock); + _viewerSendingStats.remove(viewerNode); +} QString EntityServer::serverSubclassStats() { QLocale locale(QLocale::English); diff --git a/assignment-client/src/entities/EntityServer.h b/assignment-client/src/entities/EntityServer.h index d39e966430..89b445c449 100644 --- a/assignment-client/src/entities/EntityServer.h +++ b/assignment-client/src/entities/EntityServer.h @@ -53,6 +53,7 @@ public: virtual QString serverSubclassStats(); virtual void trackSend(const QUuid& dataID, quint64 dataLastEdited, const QUuid& viewerNode); + virtual void trackViewerGone(const QUuid& viewerNode); public slots: void pruneDeletedEntities(); diff --git a/assignment-client/src/octree/OctreeServer.cpp b/assignment-client/src/octree/OctreeServer.cpp index c5072d0175..dead61d65a 100644 --- a/assignment-client/src/octree/OctreeServer.cpp +++ b/assignment-client/src/octree/OctreeServer.cpp @@ -1184,6 +1184,8 @@ void OctreeServer::nodeKilled(SharedNodePointer node) { if (usecsElapsed > 1000) { qDebug() << qPrintable(_safeServerName) << "server nodeKilled() took: " << usecsElapsed << " usecs for node:" << *node; } + + trackViewerGone(node->getUUID()); } void OctreeServer::forceNodeShutdown(SharedNodePointer node) { diff --git a/assignment-client/src/octree/OctreeServer.h b/assignment-client/src/octree/OctreeServer.h index 9876f5147c..f3a5191335 100644 --- a/assignment-client/src/octree/OctreeServer.h +++ b/assignment-client/src/octree/OctreeServer.h @@ -81,6 +81,7 @@ public: virtual int sendSpecialPackets(const SharedNodePointer& node, OctreeQueryNode* queryNode, int& packetsSent) { return 0; } virtual QString serverSubclassStats() { return QString(); } virtual void trackSend(const QUuid& dataID, quint64 dataLastEdited, const QUuid& viewerNode) { } + virtual void trackViewerGone(const QUuid& viewerNode) { } static float SKIP_TIME; // use this for trackXXXTime() calls for non-times