add more detailed edit timing to entity server

This commit is contained in:
ZappoMan 2015-07-01 16:11:08 -07:00
parent 5001c9af4b
commit 24b4614703
4 changed files with 89 additions and 6 deletions

View file

@ -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();

View file

@ -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;
}

View file

@ -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

View file

@ -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);