Merge pull request #5253 from ZappoMan/inBoundStats

add edit update stats

interface/src/Menu.cpp

@@ -531,6 +531,7 @@ Menu::Menu() {
     addCheckableActionToQMenuAndActionHash(timingMenu, MenuOption::PipelineWarnings);
     addCheckableActionToQMenuAndActionHash(timingMenu, MenuOption::LogExtraTimings);
     addCheckableActionToQMenuAndActionHash(timingMenu, MenuOption::SuppressShortTimings);
+    addCheckableActionToQMenuAndActionHash(timingMenu, MenuOption::ShowRealtimeEntityStats);
 
     auto audioIO = DependencyManager::get<AudioClient>();
     MenuWrapper* audioDebugMenu = developerMenu->addMenu("Audio");

interface/src/Menu.h

@@ -269,6 +269,7 @@ namespace MenuOption {
     const QString ShowDSConnectTable = "Show Domain Connection Timing";
     const QString ShowBordersEntityNodes = "Show Entity Nodes";
     const QString ShowIKConstraints = "Show IK Constraints";
+    const QString ShowRealtimeEntityStats = "Show Realtime Entity Stats";
     const QString SimpleShadows = "Simple";
     const QString SixenseEnabled = "Enable Hydra Support";
     const QString SixenseMouseInput = "Enable Sixense Mouse Input";

interface/src/ui/OctreeStatsDialog.cpp

@@ -25,7 +25,9 @@
 
 OctreeStatsDialog::OctreeStatsDialog(QWidget* parent, NodeToOctreeSceneStats* model) :
     QDialog(parent, Qt::Window | Qt::WindowCloseButtonHint | Qt::WindowStaysOnTopHint),
-    _model(model) {
+    _model(model),
+     _averageUpdatesPerSecond(SAMPLES_PER_SECOND)
+{
     
     _statCount = 0;
     _octreeServerLabelsCount = 0;
@@ -50,6 +52,14 @@ OctreeStatsDialog::OctreeStatsDialog(QWidget* parent, NodeToOctreeSceneStats* mo
     _localElements = AddStatItem("Local Elements");
     _localElementsMemory = AddStatItem("Elements Memory");
     _sendingMode = AddStatItem("Sending Mode");
+
+    _processedPackets = AddStatItem("Processed Packets");
+    _processedPacketsElements = AddStatItem("Processed Packets Elements");
+    _processedPacketsEntities = AddStatItem("Processed Packets Entities");
+    _processedPacketsTiming = AddStatItem("Processed Packets Timing");
+
+    _entityUpdateTime = AddStatItem("Entity Update Time");
+    _entityUpdates = AddStatItem("Entity Updates");
     
     layout()->setSizeConstraint(QLayout::SetFixedSize); 
 }
@@ -119,6 +129,34 @@ OctreeStatsDialog::~OctreeStatsDialog() {
 
 void OctreeStatsDialog::paintEvent(QPaintEvent* event) {
 
+    // Processed Entities Related stats
+    auto entities = Application::getInstance()->getEntities();
+    auto entitiesTree = entities->getTree();
+
+    // Do this ever paint event... even if we don't update
+    auto totalTrackedEdits = entitiesTree->getTotalTrackedEdits();
+    
+    // track our updated per second
+    const quint64 SAMPLING_WINDOW = USECS_PER_SECOND / SAMPLES_PER_SECOND;
+    quint64 now = usecTimestampNow();
+    quint64 sinceLastWindow = now - _lastWindowAt;
+    auto editsInLastWindow = totalTrackedEdits - _lastKnownTrackedEdits;
+    float sinceLastWindowInSeconds = (float)sinceLastWindow / (float)USECS_PER_SECOND;
+    float recentUpdatesPerSecond = (float)editsInLastWindow / sinceLastWindowInSeconds;
+    if (sinceLastWindow > SAMPLING_WINDOW) {
+        _averageUpdatesPerSecond.updateAverage(recentUpdatesPerSecond);
+        _lastWindowAt = now;
+        _lastKnownTrackedEdits = totalTrackedEdits;
+    }
+
+    // Only refresh our stats every once in a while, unless asked for realtime
+    quint64 REFRESH_AFTER = Menu::getInstance()->isOptionChecked(MenuOption::ShowRealtimeEntityStats) ? 0 : USECS_PER_SECOND;
+    quint64 sinceLastRefresh = now - _lastRefresh;
+    if (sinceLastRefresh < REFRESH_AFTER) {
+        return QDialog::paintEvent(event);
+    }
+    _lastRefresh = now;
+
     // Update labels
 
     QLabel* label;
@@ -203,9 +241,100 @@ void OctreeStatsDialog::paintEvent(QPaintEvent* event) {
         "Leaves: " << qPrintable(serversLeavesString) << "";
     label->setText(statsValue.str().c_str());
 
+    // Processed Packets Elements
+    auto averageElementsPerPacket = entities->getAverageElementsPerPacket();
+    auto averageEntitiesPerPacket = entities->getAverageEntitiesPerPacket();
+
+    auto averagePacketsPerSecond = entities->getAveragePacketsPerSecond();
+    auto averageElementsPerSecond = entities->getAverageElementsPerSecond();
+    auto averageEntitiesPerSecond = entities->getAverageEntitiesPerSecond();
+
+    auto averageWaitLockPerPacket = entities->getAverageWaitLockPerPacket();
+    auto averageUncompressPerPacket = entities->getAverageUncompressPerPacket();
+    auto averageReadBitstreamPerPacket = entities->getAverageReadBitstreamPerPacket();
+
+    QString averageElementsPerPacketString = locale.toString(averageElementsPerPacket);
+    QString averageEntitiesPerPacketString = locale.toString(averageEntitiesPerPacket);
+
+    QString averagePacketsPerSecondString = locale.toString(averagePacketsPerSecond);
+    QString averageElementsPerSecondString = locale.toString(averageElementsPerSecond);
+    QString averageEntitiesPerSecondString = locale.toString(averageEntitiesPerSecond);
+
+    QString averageWaitLockPerPacketString = locale.toString(averageWaitLockPerPacket);
+    QString averageUncompressPerPacketString = locale.toString(averageUncompressPerPacket);
+    QString averageReadBitstreamPerPacketString = locale.toString(averageReadBitstreamPerPacket);
+
+    label = _labels[_processedPackets];
+    statsValue.str("");
+    statsValue << 
+        "" << qPrintable(averagePacketsPerSecondString) << " per second";
+        
+    label->setText(statsValue.str().c_str());
+
+    label = _labels[_processedPacketsElements];
+    statsValue.str("");
+    statsValue << 
+        "" << qPrintable(averageElementsPerPacketString) << " per packet / " <<
+        "" << qPrintable(averageElementsPerSecondString) << " per second";
+        
+    label->setText(statsValue.str().c_str());
+
+    label = _labels[_processedPacketsEntities];
+    statsValue.str("");
+    statsValue << 
+        "" << qPrintable(averageEntitiesPerPacketString) << " per packet / " <<
+        "" << qPrintable(averageEntitiesPerSecondString) << " per second";
+        
+    label->setText(statsValue.str().c_str());
+
+    label = _labels[_processedPacketsTiming];
+    statsValue.str("");
+    statsValue << 
+        "Lock Wait:" << qPrintable(averageWaitLockPerPacketString) << " (usecs) / " <<
+        "Uncompress:" << qPrintable(averageUncompressPerPacketString) << " (usecs) / " <<
+        "Process:" << qPrintable(averageReadBitstreamPerPacketString) << " (usecs)";
+        
+    label->setText(statsValue.str().c_str());
+
+    // Entity Edits update time
+    label = _labels[_entityUpdateTime];
+    auto averageEditDelta = entitiesTree->getAverageEditDeltas();
+    auto maxEditDelta = entitiesTree->getMaxEditDelta();
+
+    QString averageEditDeltaString = locale.toString((uint)averageEditDelta);
+    QString maxEditDeltaString = locale.toString((uint)maxEditDelta);
+
+    statsValue.str("");
+    statsValue << 
+        "Average: " << qPrintable(averageEditDeltaString) << " (usecs) / " <<
+        "Max: " << qPrintable(maxEditDeltaString) << " (usecs)";
+        
+    label->setText(statsValue.str().c_str());
+
+    // Entity Edits
+    label = _labels[_entityUpdates];
+    auto bytesPerEdit = entitiesTree->getAverageEditBytes();
+    
+    auto updatesPerSecond = _averageUpdatesPerSecond.getAverage();
+    if (updatesPerSecond < 1) {
+        updatesPerSecond = 0; // we don't really care about small updates per second so suppress those
+    }
+
+    QString totalTrackedEditsString = locale.toString((uint)totalTrackedEdits);
+    QString updatesPerSecondString = locale.toString(updatesPerSecond);
+    QString bytesPerEditString = locale.toString(bytesPerEdit);
+
+    statsValue.str("");
+    statsValue << 
+        "" << qPrintable(updatesPerSecondString) << " updates per second / " <<
+        "" << qPrintable(totalTrackedEditsString) << " total updates / " <<
+        "Average Size: " << qPrintable(bytesPerEditString) << " bytes ";
+        
+    label->setText(statsValue.str().c_str());
+
     showAllOctreeServers();
 
-    this->QDialog::paintEvent(event);
+    QDialog::paintEvent(event);
 }
 void OctreeStatsDialog::showAllOctreeServers() {
     int serverCount = 0;

interface/src/ui/OctreeStatsDialog.h

@@ -63,6 +63,21 @@ private:
     int _serverElements;
     int _localElements;
     int _localElementsMemory;
+
+    int _entityUpdateTime;
+    int _entityUpdates;
+    int _processedPackets;
+    int _processedPacketsElements;
+    int _processedPacketsEntities;
+    int _processedPacketsTiming;
+    
+    const int SAMPLES_PER_SECOND = 10;
+    SimpleMovingAverage _averageUpdatesPerSecond;
+    quint64 _lastWindowAt = 0;
+    quint64 _lastKnownTrackedEdits = 0;
+
+    quint64 _lastRefresh = 0;
+
     int _octreeServerLables[MAX_VOXEL_SERVERS];
     int _octreeServerLabelsCount;
     details _extraServerDetails[MAX_VOXEL_SERVERS];

libraries/entities/src/EntityItem.cpp

@@ -343,6 +343,8 @@ int EntityItem::readEntityDataFromBuffer(const unsigned char* data, int bytesLef
         return 0;
     }
 
+    args.entitiesPerPacket++;
+
     // Header bytes
     //    object ID [16 bytes]
     //    ByteCountCoded(type code) [~1 byte]
@@ -423,6 +425,7 @@ int EntityItem::readEntityDataFromBuffer(const unsigned char* data, int bytesLef
     dataAt += sizeof(lastEditedFromBuffer);
     bytesRead += sizeof(lastEditedFromBuffer);
     lastEditedFromBufferAdjusted = lastEditedFromBuffer - clockSkew;
+
     if (lastEditedFromBufferAdjusted > now) {
         lastEditedFromBufferAdjusted = now;
     }
@@ -495,6 +498,7 @@ int EntityItem::readEntityDataFromBuffer(const unsigned char* data, int bytesLef
             qCDebug(entities) << "           lastEditedFromBufferAdjusted:" << debugTime(lastEditedFromBufferAdjusted, now);
         #endif
     }
+
     encodedUpdateDelta = updateDeltaCoder; // determine true length
     dataAt += encodedUpdateDelta.size();
     bytesRead += encodedUpdateDelta.size();
@@ -673,6 +677,14 @@ int EntityItem::readEntityDataFromBuffer(const unsigned char* data, int bytesLef
         }
     }
 
+    // Tracking for editing roundtrips here. We will tell our EntityTree that we just got incoming data about
+    // and entity that was edited at some time in the past. The tree will determine how it wants to track this
+    // information.
+    if (_element && _element->getTree()) {
+        _element->getTree()->trackIncomingEntityLastEdited(lastEditedFromBufferAdjusted, bytesRead);
+    }
+
+
     return bytesRead;
 }
 

libraries/entities/src/EntityTree.cpp

@@ -32,6 +32,7 @@ EntityTree::EntityTree(bool shouldReaverage) :
     _simulation(NULL)
 {
     _rootElement = createNewElement();
+    resetClientEditStats();
 }
 
 EntityTree::~EntityTree() {
@@ -58,6 +59,8 @@ void EntityTree::eraseAllOctreeElements(bool createNewRoot) {
     }
     _entityToElementMap.clear();
     Octree::eraseAllOctreeElements(createNewRoot);
+    
+    resetClientEditStats();
 }
 
 bool EntityTree::handlesEditPacketType(PacketType packetType) const {
@@ -1120,3 +1123,29 @@ bool EntityTree::readFromMap(QVariantMap& map) {
 
     return true;
 }
+
+void EntityTree::resetClientEditStats() {
+    _treeResetTime = usecTimestampNow();
+    _maxEditDelta = 0;
+    _totalEditDeltas = 0;
+    _totalTrackedEdits = 0;
+}
+
+
+
+void EntityTree::trackIncomingEntityLastEdited(quint64 lastEditedTime, int bytesRead) {
+    // we don't want to track all edit deltas, just those edits that have happend
+    // since we connected to this domain. This will filter out all previously created
+    // content and only track new edits
+    if (lastEditedTime > _treeResetTime) {
+        quint64 now = usecTimestampNow();
+        quint64 sinceEdit = now - lastEditedTime;
+
+        _totalEditDeltas += sinceEdit;
+        _totalEditBytes += bytesRead;
+        _totalTrackedEdits++;
+        if (sinceEdit > _maxEditDelta) {
+            _maxEditDelta = sinceEdit;
+        }
+    }
+}

libraries/entities/src/EntityTree.h

@@ -185,6 +185,14 @@ public:
     virtual quint64 getAverageCreateTime() const { return _totalCreates == 0 ? 0 : _totalCreateTime / _totalCreates; }
     virtual quint64 getAverageLoggingTime() const { return _totalEditMessages == 0 ? 0 : _totalLoggingTime / _totalEditMessages; }
 
+    void trackIncomingEntityLastEdited(quint64 lastEditedTime, int bytesRead);
+    quint64 getAverageEditDeltas() const 
+        { return _totalTrackedEdits == 0 ? 0 : _totalEditDeltas / _totalTrackedEdits; }
+    quint64 getAverageEditBytes() const 
+        { return _totalTrackedEdits == 0 ? 0 : _totalEditBytes / _totalTrackedEdits; }
+    quint64 getMaxEditDelta() const { return _maxEditDelta; }
+    quint64 getTotalTrackedEdits() const { return _totalTrackedEdits; }
+
 signals:
     void deletingEntity(const EntityItemID& entityID);
     void addingEntity(const EntityItemID& entityID);
@@ -230,6 +238,14 @@ private:
     quint64 _totalUpdateTime = 0;
     quint64 _totalCreateTime = 0;
     quint64 _totalLoggingTime = 0;
+
+    // these performance statistics are only used in the client
+    void resetClientEditStats();
+    int _totalTrackedEdits = 0;
+    quint64 _totalEditBytes = 0;
+    quint64 _totalEditDeltas = 0;
+    quint64 _maxEditDelta = 0;
+    quint64 _treeResetTime = 0;
 };
 
 #endif // hifi_EntityTree_h

libraries/entities/src/EntityTreeElement.cpp

@@ -702,6 +702,8 @@ int EntityTreeElement::readElementDataFromBuffer(const unsigned char* data, int
     int bytesRead = 0;
     uint16_t numberOfEntities = 0;
     int expectedBytesPerEntity = EntityItem::expectedBytes();
+    
+    args.elementsPerPacket++;
 
     if (bytesLeftToRead >= (int)sizeof(numberOfEntities)) {
         // read our entities in....

libraries/octree/src/Octree.h

@@ -195,6 +195,8 @@ public:
     SharedNodePointer sourceNode;
     bool wantImportProgress;
     PacketVersion bitstreamVersion;
+    int elementsPerPacket = 0;
+    int entitiesPerPacket = 0;
 
     ReadBitstreamToTreeParams(
         bool includeColor = WANT_COLOR,

libraries/octree/src/OctreeRenderer.cpp

@@ -12,9 +12,11 @@
 #include <glm/glm.hpp>
 #include <stdint.h>
 
-#include <SharedUtil.h>
+#include <NumericalConstants.h>
 #include <PerfStat.h>
 #include <RenderArgs.h>
+#include <SharedUtil.h>
+
 #include "OctreeLogging.h"
 #include "OctreeRenderer.h"
 
@@ -101,6 +103,15 @@ void OctreeRenderer::processDatagram(const QByteArray& dataByteArray, const Shar
                    sequence, flightTime, packetLength, dataBytes);
         }
         
+        _packetsInLastWindow++;
+        
+        int elementsPerPacket = 0;
+        int entitiesPerPacket = 0;
+        
+        quint64 totalWaitingForLock = 0;
+        quint64 totalUncompress = 0;
+        quint64 totalReadBitsteam = 0;
+        
         int subsection = 1;
         while (dataBytes > 0) {
             if (packetIsCompressed) {
@@ -120,7 +131,12 @@ void OctreeRenderer::processDatagram(const QByteArray& dataByteArray, const Shar
                 // ask the VoxelTree to read the bitstream into the tree
                 ReadBitstreamToTreeParams args(packetIsColored ? WANT_COLOR : NO_COLOR, WANT_EXISTS_BITS, NULL, 
                                                 sourceUUID, sourceNode, false, packetVersion);
+                quint64 startLock = usecTimestampNow();
+
+                // FIXME STUTTER - there may be an opportunity to bump this lock outside of the
+                // loop to reduce the amount of locking/unlocking we're doing
                 _tree->lockForWrite();
+                quint64 startUncompress = usecTimestampNow();
                 OctreePacketData packetData(packetIsCompressed);
                 packetData.loadFinalizedContent(dataAt, sectionLength);
                 if (extraDebugging) {
@@ -134,17 +150,56 @@ void OctreeRenderer::processDatagram(const QByteArray& dataByteArray, const Shar
                 if (extraDebugging) {
                     qCDebug(octree) << "OctreeRenderer::processDatagram() ******* START _tree->readBitstreamToTree()...";
                 }
+                quint64 startReadBitsteam = usecTimestampNow();
                 _tree->readBitstreamToTree(packetData.getUncompressedData(), packetData.getUncompressedSize(), args);
+                quint64 endReadBitsteam = usecTimestampNow();
                 if (extraDebugging) {
                     qCDebug(octree) << "OctreeRenderer::processDatagram() ******* END _tree->readBitstreamToTree()...";
                 }
                 _tree->unlock();
-            
+                
                 dataBytes -= sectionLength;
                 dataAt += sectionLength;
+
+                elementsPerPacket += args.elementsPerPacket;
+                entitiesPerPacket += args.entitiesPerPacket;
+
+                _elementsInLastWindow += args.elementsPerPacket;
+                _entitiesInLastWindow += args.entitiesPerPacket;
+
+                totalWaitingForLock += (startUncompress - startLock);
+                totalUncompress += (startReadBitsteam - startUncompress);
+                totalReadBitsteam += (endReadBitsteam - startReadBitsteam);
+
             }
+            subsection++;
+        }
+        _elementsPerPacket.updateAverage(elementsPerPacket);
+        _entitiesPerPacket.updateAverage(entitiesPerPacket);
+
+        _waitLockPerPacket.updateAverage(totalWaitingForLock);
+        _uncompressPerPacket.updateAverage(totalUncompress);
+        _readBitstreamPerPacket.updateAverage(totalReadBitsteam);
+        
+        quint64 now = usecTimestampNow();
+        if (_lastWindowAt == 0) {
+            _lastWindowAt = now;
+        }
+        quint64 sinceLastWindow = now - _lastWindowAt;
+        
+        if (sinceLastWindow > USECS_PER_SECOND) {
+            float packetsPerSecondInWindow = (float)_packetsInLastWindow / (float)(sinceLastWindow / USECS_PER_SECOND);
+            float elementsPerSecondInWindow = (float)_elementsInLastWindow / (float)(sinceLastWindow / USECS_PER_SECOND);
+            float entitiesPerSecondInWindow = (float)_entitiesInLastWindow / (float)(sinceLastWindow / USECS_PER_SECOND);
+            _packetsPerSecond.updateAverage(packetsPerSecondInWindow);
+            _elementsPerSecond.updateAverage(elementsPerSecondInWindow);
+            _entitiesPerSecond.updateAverage(entitiesPerSecondInWindow);
+
+            _lastWindowAt = now;
+            _packetsInLastWindow = 0;
+            _elementsInLastWindow = 0;
+            _entitiesInLastWindow = 0;
         }
-        subsection++;
     }
 }
 

libraries/octree/src/OctreeRenderer.h

@@ -61,12 +61,40 @@ public:
     /// clears the tree
     virtual void clear();
 
+    float getAverageElementsPerPacket() const { return _elementsPerPacket.getAverage(); }
+    float getAverageEntitiesPerPacket() const { return _entitiesPerPacket.getAverage(); }
+
+    float getAveragePacketsPerSecond() const { return _packetsPerSecond.getAverage(); }
+    float getAverageElementsPerSecond() const { return _elementsPerSecond.getAverage(); }
+    float getAverageEntitiesPerSecond() const { return _entitiesPerSecond.getAverage(); }
+
+    float getAverageWaitLockPerPacket() const { return _waitLockPerPacket.getAverage(); }
+    float getAverageUncompressPerPacket() const { return _uncompressPerPacket.getAverage(); }
+    float getAverageReadBitstreamPerPacket() const { return _readBitstreamPerPacket.getAverage(); }
+    
 protected:
     virtual Octree* createTree() = 0;
 
     Octree* _tree;
     bool _managedTree;
     ViewFrustum* _viewFrustum;
+
+    SimpleMovingAverage _elementsPerPacket;
+    SimpleMovingAverage _entitiesPerPacket;
+
+    SimpleMovingAverage _packetsPerSecond;
+    SimpleMovingAverage _elementsPerSecond;
+    SimpleMovingAverage _entitiesPerSecond;
+
+    SimpleMovingAverage _waitLockPerPacket;
+    SimpleMovingAverage _uncompressPerPacket;
+    SimpleMovingAverage _readBitstreamPerPacket;
+
+    quint64 _lastWindowAt = 0;
+    int _packetsInLastWindow = 0;
+    int _elementsInLastWindow = 0;
+    int _entitiesInLastWindow = 0;
+
 };
 
 #endif // hifi_OctreeRenderer_h