From 24b4614703418600bacee900034e3e059e9b6f90 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Wed, 1 Jul 2015 16:11:08 -0700 Subject: [PATCH] add more detailed edit timing to entity server --- assignment-client/src/octree/OctreeServer.cpp | 19 ++++++++++ libraries/entities/src/EntityTree.cpp | 36 ++++++++++++++++--- libraries/entities/src/EntityTree.h | 28 +++++++++++++++ libraries/octree/src/Octree.h | 12 +++++-- 4 files changed, 89 insertions(+), 6 deletions(-) diff --git a/assignment-client/src/octree/OctreeServer.cpp b/assignment-client/src/octree/OctreeServer.cpp index 8efe1c39a0..06fb5c4f47 100644 --- a/assignment-client/src/octree/OctreeServer.cpp +++ b/assignment-client/src/octree/OctreeServer.cpp @@ -327,6 +327,7 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QUrl& url showStats = true; } else if (url.path() == "/resetStats") { _octreeInboundPacketProcessor->resetStats(); + _tree->resetEditStats(); resetSendingStats(); showStats = true; } @@ -636,6 +637,13 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QUrl& url quint64 totalElementsProcessed = _octreeInboundPacketProcessor->getTotalElementsProcessed(); quint64 totalPacketsProcessed = _octreeInboundPacketProcessor->getTotalPacketsProcessed(); + quint64 averageDecodeTime = _tree->getAverageDecodeTime(); + quint64 averageLookupTime = _tree->getAverageLookupTime(); + quint64 averageUpdateTime = _tree->getAverageUpdateTime(); + quint64 averageCreateTime = _tree->getAverageCreateTime(); + quint64 averageLoggingTime = _tree->getAverageLoggingTime(); + + float averageElementsPerPacket = totalPacketsProcessed == 0 ? 0 : totalElementsProcessed / totalPacketsProcessed; statsString += QString(" Current Inbound Packets Queue: %1 packets\r\n") @@ -658,6 +666,17 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QUrl& url statsString += QString(" Average Wait Lock Time/Element: %1 usecs\r\n") .arg(locale.toString((uint)averageLockWaitTimePerElement).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString(" Average Decode Time: %1 usecs\r\n") + .arg(locale.toString((uint)averageDecodeTime).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString(" Average Lookup Time: %1 usecs\r\n") + .arg(locale.toString((uint)averageLookupTime).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString(" Average Update Time: %1 usecs\r\n") + .arg(locale.toString((uint)averageUpdateTime).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString(" Average Create Time: %1 usecs\r\n") + .arg(locale.toString((uint)averageCreateTime).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString(" Average Logging Time: %1 usecs\r\n") + .arg(locale.toString((uint)averageLoggingTime).rightJustified(COLUMN_WIDTH, ' ')); + int senderNumber = 0; NodeToSenderStatsMap& allSenderStats = _octreeInboundPacketProcessor->getSingleSenderStats(); diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index 752082932b..6a652d609b 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -574,41 +574,61 @@ int EntityTree::processEditPacketData(PacketType packetType, const unsigned char case PacketTypeEntityAdd: case PacketTypeEntityEdit: { + quint64 startDecode = 0, endDecode = 0; + quint64 startLookup = 0, endLookup = 0; + quint64 startUpdate = 0, endUpdate = 0; + quint64 startCreate = 0, endCreate = 0; + quint64 startLogging = 0, endLogging = 0; + + _totalEditMessages++; + EntityItemID entityItemID; EntityItemProperties properties; + startDecode = usecTimestampNow(); bool validEditPacket = EntityItemProperties::decodeEntityEditPacket(editData, maxLength, processedBytes, entityItemID, properties); + endDecode = usecTimestampNow(); // If we got a valid edit packet, then it could be a new entity or it could be an update to // an existing entity... handle appropriately if (validEditPacket) { // search for the entity by EntityItemID + startLookup = usecTimestampNow(); EntityItemPointer existingEntity = findEntityByEntityItemID(entityItemID); + endLookup = usecTimestampNow(); if (existingEntity && packetType == PacketTypeEntityEdit) { // if the EntityItem exists, then update it + startLogging = usecTimestampNow(); if (wantEditLogging()) { qCDebug(entities) << "User [" << senderNode->getUUID() << "] editing entity. ID:" << entityItemID; qCDebug(entities) << " properties:" << properties; } + endLogging = usecTimestampNow(); + + startUpdate = usecTimestampNow(); updateEntity(entityItemID, properties, senderNode); existingEntity->markAsChangedOnServer(); + endUpdate = usecTimestampNow(); + _totalUpdates++; } else if (packetType == PacketTypeEntityAdd) { if (senderNode->getCanRez()) { // this is a new entity... assign a new entityID - if (wantEditLogging()) { - qCDebug(entities) << "User [" << senderNode->getUUID() << "] adding entity."; - qCDebug(entities) << " properties:" << properties; - } properties.setCreated(properties.getLastEdited()); + startCreate = usecTimestampNow(); EntityItemPointer newEntity = addEntity(entityItemID, properties); + endCreate = usecTimestampNow(); + _totalCreates++; if (newEntity) { newEntity->markAsChangedOnServer(); notifyNewlyCreatedEntity(*newEntity, senderNode); + + startLogging = usecTimestampNow(); if (wantEditLogging()) { qCDebug(entities) << "User [" << senderNode->getUUID() << "] added entity. ID:" << newEntity->getEntityItemID(); qCDebug(entities) << " properties:" << properties; } + endLogging = usecTimestampNow(); } } else { @@ -619,6 +639,14 @@ int EntityTree::processEditPacketData(PacketType packetType, const unsigned char qCDebug(entities) << "Add or Edit failed." << packetType << existingEntity.get(); } } + + + _totalDecodeTime += endDecode - startDecode; + _totalLookupTime += endLookup - startLookup; + _totalUpdateTime += endUpdate - startUpdate; + _totalCreateTime += endCreate - startCreate; + _totalLoggingTime += endLogging - startLogging; + break; } diff --git a/libraries/entities/src/EntityTree.h b/libraries/entities/src/EntityTree.h index 9c4be9a86f..fa72cc7691 100644 --- a/libraries/entities/src/EntityTree.h +++ b/libraries/entities/src/EntityTree.h @@ -168,6 +168,23 @@ public: float getContentsLargestDimension(); + virtual void resetEditStats() { + _totalEditMessages = 0; + _totalUpdates = 0; + _totalCreates = 0; + _totalDecodeTime = 0; + _totalLookupTime = 0; + _totalUpdateTime = 0; + _totalCreateTime = 0; + _totalLoggingTime = 0; + } + + virtual quint64 getAverageDecodeTime() const { return _totalEditMessages == 0 ? 0 : _totalDecodeTime / _totalEditMessages; } + virtual quint64 getAverageLookupTime() const { return _totalEditMessages == 0 ? 0 : _totalLookupTime / _totalEditMessages; } + virtual quint64 getAverageUpdateTime() const { return _totalUpdates == 0 ? 0 : _totalUpdateTime / _totalUpdates; } + virtual quint64 getAverageCreateTime() const { return _totalCreates == 0 ? 0 : _totalCreateTime / _totalCreates; } + virtual quint64 getAverageLoggingTime() const { return _totalEditMessages == 0 ? 0 : _totalLoggingTime / _totalEditMessages; } + signals: void deletingEntity(const EntityItemID& entityID); void addingEntity(const EntityItemID& entityID); @@ -202,6 +219,17 @@ private: bool _wantEditLogging = false; void maybeNotifyNewCollisionSoundURL(const QString& oldCollisionSoundURL, const QString& newCollisionSoundURL); + + + // some performance tracking properties - only used in server trees + int _totalEditMessages = 0; + int _totalUpdates = 0; + int _totalCreates = 0; + quint64 _totalDecodeTime = 0; + quint64 _totalLookupTime = 0; + quint64 _totalUpdateTime = 0; + quint64 _totalCreateTime = 0; + quint64 _totalLoggingTime = 0; }; #endif // hifi_EntityTree_h diff --git a/libraries/octree/src/Octree.h b/libraries/octree/src/Octree.h index d7fc58699f..6eeb423ddd 100644 --- a/libraries/octree/src/Octree.h +++ b/libraries/octree/src/Octree.h @@ -367,8 +367,16 @@ public: bool getIsClient() const { return !_isServer; } /// Is this a client based tree. Allows guards for certain operations void setIsClient(bool isClient) { _isServer = !isClient; } - virtual void dumpTree() { }; - virtual void pruneTree() { }; + virtual void dumpTree() { } + virtual void pruneTree() { } + + virtual void resetEditStats() { } + virtual quint64 getAverageDecodeTime() const { return 0; } + virtual quint64 getAverageLookupTime() const { return 0; } + virtual quint64 getAverageUpdateTime() const { return 0; } + virtual quint64 getAverageCreateTime() const { return 0; } + virtual quint64 getAverageLoggingTime() const { return 0; } + signals: void importSize(float x, float y, float z);