From 006a1d60c82699612fa2d98629ba990735a3e356 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Tue, 10 Nov 2015 15:31:51 -0800 Subject: [PATCH 1/6] keep some additional erase entities history and send to viewers --- .../src/entities/EntityNodeData.h | 6 +- .../src/entities/EntityServer.cpp | 5 +- libraries/entities/src/EntityTree.cpp | 116 +++++++++--------- 3 files changed, 65 insertions(+), 62 deletions(-) diff --git a/assignment-client/src/entities/EntityNodeData.h b/assignment-client/src/entities/EntityNodeData.h index e4008fcb03..69da9ee14b 100644 --- a/assignment-client/src/entities/EntityNodeData.h +++ b/assignment-client/src/entities/EntityNodeData.h @@ -18,9 +18,7 @@ class EntityNodeData : public OctreeQueryNode { public: - EntityNodeData() : - OctreeQueryNode(), - _lastDeletedEntitiesSentAt(0) { } + EntityNodeData() : OctreeQueryNode() { } virtual PacketType getMyPacketType() const { return PacketType::EntityData; } @@ -28,7 +26,7 @@ public: void setLastDeletedEntitiesSentAt(quint64 sentAt) { _lastDeletedEntitiesSentAt = sentAt; } private: - quint64 _lastDeletedEntitiesSentAt; + quint64 _lastDeletedEntitiesSentAt { usecTimestampNow() }; }; #endif // hifi_EntityNodeData_h diff --git a/assignment-client/src/entities/EntityServer.cpp b/assignment-client/src/entities/EntityServer.cpp index f2a4c2664a..e2941541af 100644 --- a/assignment-client/src/entities/EntityServer.cpp +++ b/assignment-client/src/entities/EntityServer.cpp @@ -82,7 +82,6 @@ bool EntityServer::hasSpecialPacketsToSend(const SharedNodePointer& node) { EntityNodeData* nodeData = static_cast(node->getLinkedData()); if (nodeData) { quint64 deletedEntitiesSentAt = nodeData->getLastDeletedEntitiesSentAt(); - EntityTreePointer tree = std::static_pointer_cast(_tree); shouldSendDeletedEntities = tree->hasEntitiesDeletedSince(deletedEntitiesSentAt); } @@ -97,7 +96,6 @@ int EntityServer::sendSpecialPackets(const SharedNodePointer& node, OctreeQueryN if (nodeData) { quint64 deletedEntitiesSentAt = nodeData->getLastDeletedEntitiesSentAt(); quint64 deletePacketSentAt = usecTimestampNow(); - EntityTreePointer tree = std::static_pointer_cast(_tree); bool hasMoreToSend = true; @@ -127,7 +125,6 @@ void EntityServer::pruneDeletedEntities() { if (tree->hasAnyDeletedEntities()) { quint64 earliestLastDeletedEntitiesSent = usecTimestampNow() + 1; // in the future - DependencyManager::get()->eachNode([&earliestLastDeletedEntitiesSent](const SharedNodePointer& node) { if (node->getLinkedData()) { EntityNodeData* nodeData = static_cast(node->getLinkedData()); @@ -138,6 +135,8 @@ void EntityServer::pruneDeletedEntities() { } }); + int EXTRA_SECONDS_TO_KEEP = 4; + earliestLastDeletedEntitiesSent -= USECS_PER_SECOND * EXTRA_SECONDS_TO_KEEP; tree->forgetEntitiesDeletedBefore(earliestLastDeletedEntitiesSent); } } diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index 8e32158362..c69c2daa16 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -384,16 +384,17 @@ void EntityTree::deleteEntities(QSet entityIDs, bool force, bool i } void EntityTree::processRemovedEntities(const DeleteEntityOperator& theOperator) { + quint64 deletedAt = usecTimestampNow(); const RemovedEntities& entities = theOperator.getEntities(); foreach(const EntityToDeleteDetails& details, entities) { EntityItemPointer theEntity = details.entity; if (getIsServer()) { // set up the deleted entities ID - quint64 deletedAt = usecTimestampNow(); - _recentlyDeletedEntitiesLock.lockForWrite(); - _recentlyDeletedEntityItemIDs.insert(deletedAt, theEntity->getEntityItemID()); - _recentlyDeletedEntitiesLock.unlock(); + { + QWriteLocker locker(&_recentlyDeletedEntitiesLock); + _recentlyDeletedEntityItemIDs.insert(deletedAt, theEntity->getEntityItemID()); + } } if (_simulation) { @@ -802,18 +803,23 @@ void EntityTree::update() { } bool EntityTree::hasEntitiesDeletedSince(quint64 sinceTime) { + int EXTRA_SECONDS_TO_CONSIDER = 4; + quint64 considerEntitiesSince = sinceTime - (USECS_PER_SECOND * EXTRA_SECONDS_TO_CONSIDER); + // we can probably leverage the ordered nature of QMultiMap to do this quickly... bool hasSomethingNewer = false; + { + QReadLocker locker(&_recentlyDeletedEntitiesLock); - _recentlyDeletedEntitiesLock.lockForRead(); - QMultiMap::const_iterator iterator = _recentlyDeletedEntityItemIDs.constBegin(); - while (iterator != _recentlyDeletedEntityItemIDs.constEnd()) { - if (iterator.key() > sinceTime) { - hasSomethingNewer = true; + QMultiMap::const_iterator iterator = _recentlyDeletedEntityItemIDs.constBegin(); + while (iterator != _recentlyDeletedEntityItemIDs.constEnd()) { + if (iterator.key() > considerEntitiesSince) { + hasSomethingNewer = true; + } + ++iterator; } - ++iterator; } - _recentlyDeletedEntitiesLock.unlock(); + return hasSomethingNewer; } @@ -821,6 +827,8 @@ bool EntityTree::hasEntitiesDeletedSince(quint64 sinceTime) { std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_SEQUENCE sequenceNumber, quint64& sinceTime, bool& hasMore) { + int EXTRA_SECONDS_TO_CONSIDER = 4; + quint64 considerEntitiesSince = sinceTime - (USECS_PER_SECOND * EXTRA_SECONDS_TO_CONSIDER); auto deletesPacket = NLPacket::create(PacketType::EntityErase); // pack in flags @@ -841,48 +849,46 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // we keep a multi map of entity IDs to timestamps, we only want to include the entity IDs that have been // deleted since we last sent to this node - _recentlyDeletedEntitiesLock.lockForRead(); + { + QReadLocker locker(&_recentlyDeletedEntitiesLock); - bool hasFilledPacket = false; + bool hasFilledPacket = false; - auto it = _recentlyDeletedEntityItemIDs.constBegin(); - while (it != _recentlyDeletedEntityItemIDs.constEnd()) { - QList values = _recentlyDeletedEntityItemIDs.values(it.key()); - for (int valueItem = 0; valueItem < values.size(); ++valueItem) { + auto it = _recentlyDeletedEntityItemIDs.constBegin(); + while (it != _recentlyDeletedEntityItemIDs.constEnd()) { + QList values = _recentlyDeletedEntityItemIDs.values(it.key()); + for (int valueItem = 0; valueItem < values.size(); ++valueItem) { - // if the timestamp is more recent then out last sent time, include it - if (it.key() > sinceTime) { - QUuid entityID = values.at(valueItem); - deletesPacket->write(entityID.toRfc4122()); + // if the timestamp is more recent then out last sent time, include it + if (it.key() > considerEntitiesSince) { + QUuid entityID = values.at(valueItem); + deletesPacket->write(entityID.toRfc4122()); + ++numberOfIDs; - ++numberOfIDs; - - // check to make sure we have room for one more ID - if (NUM_BYTES_RFC4122_UUID > deletesPacket->bytesAvailableForWrite()) { - hasFilledPacket = true; - break; + // check to make sure we have room for one more ID + if (NUM_BYTES_RFC4122_UUID > deletesPacket->bytesAvailableForWrite()) { + hasFilledPacket = true; + break; + } } } + + // check to see if we're about to return + if (hasFilledPacket) { + // let our caller know how far we got + sinceTime = it.key(); + break; + } + + ++it; } - // check to see if we're about to return - if (hasFilledPacket) { - // let our caller know how far we got - sinceTime = it.key(); - - break; + // if we got to the end, then we're done sending + if (it == _recentlyDeletedEntityItemIDs.constEnd()) { + hasMore = false; } - - ++it; } - // if we got to the end, then we're done sending - if (it == _recentlyDeletedEntityItemIDs.constEnd()) { - hasMore = false; - } - - _recentlyDeletedEntitiesLock.unlock(); - // replace the count for the number of included IDs deletesPacket->seek(numberOfIDsPos); deletesPacket->writePrimitive(numberOfIDs); @@ -895,23 +901,23 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S void EntityTree::forgetEntitiesDeletedBefore(quint64 sinceTime) { QSet keysToRemove; - _recentlyDeletedEntitiesLock.lockForWrite(); - QMultiMap::iterator iterator = _recentlyDeletedEntityItemIDs.begin(); + { + QWriteLocker locker(&_recentlyDeletedEntitiesLock); + QMultiMap::iterator iterator = _recentlyDeletedEntityItemIDs.begin(); - // First find all the keys in the map that are older and need to be deleted - while (iterator != _recentlyDeletedEntityItemIDs.end()) { - if (iterator.key() <= sinceTime) { - keysToRemove << iterator.key(); + // First find all the keys in the map that are older and need to be deleted + while (iterator != _recentlyDeletedEntityItemIDs.end()) { + if (iterator.key() <= sinceTime) { + keysToRemove << iterator.key(); + } + ++iterator; } - ++iterator; - } - // Now run through the keysToRemove and remove them - foreach (quint64 value, keysToRemove) { - _recentlyDeletedEntityItemIDs.remove(value); + // Now run through the keysToRemove and remove them + foreach (quint64 value, keysToRemove) { + _recentlyDeletedEntityItemIDs.remove(value); + } } - - _recentlyDeletedEntitiesLock.unlock(); } From 3316b63bf6e8efb1c9a494dd5ce027983b76c026 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Tue, 10 Nov 2015 15:46:53 -0800 Subject: [PATCH 2/6] add a fixme comment --- libraries/entities/src/EntityTree.cpp | 6 ++++++ 1 file changed, 6 insertions(+) diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index c69c2daa16..34b09eb67c 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -862,6 +862,12 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // if the timestamp is more recent then out last sent time, include it if (it.key() > considerEntitiesSince) { QUuid entityID = values.at(valueItem); + + // FIXME - we still seem to see cases where incorrect EntityIDs get sent from the server + // to the client. These were causing "lost" entities like flashlights and laser pointers + // now that we keep around some additional history of the erased entities and resend that + // history for a longer time window, these entities are not "lost". But we haven't yet + // found/fixed the underlying issue that caused bad UUIDs to be sent to some users. deletesPacket->write(entityID.toRfc4122()); ++numberOfIDs; From 866116d2855baf69b25777cde78cbafe4c66741a Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 11 Nov 2015 12:13:47 -0800 Subject: [PATCH 3/6] more debugging --- .../src/entities/EntityServer.cpp | 11 +++- .../src/octree/OctreeSendThread.cpp | 2 +- libraries/entities/src/EntityTree.cpp | 65 +++++++++++-------- libraries/entities/src/EntityTree.h | 1 + 4 files changed, 49 insertions(+), 30 deletions(-) diff --git a/assignment-client/src/entities/EntityServer.cpp b/assignment-client/src/entities/EntityServer.cpp index e2941541af..81dabd4dcd 100644 --- a/assignment-client/src/entities/EntityServer.cpp +++ b/assignment-client/src/entities/EntityServer.cpp @@ -84,6 +84,10 @@ bool EntityServer::hasSpecialPacketsToSend(const SharedNodePointer& node) { quint64 deletedEntitiesSentAt = nodeData->getLastDeletedEntitiesSentAt(); EntityTreePointer tree = std::static_pointer_cast(_tree); shouldSendDeletedEntities = tree->hasEntitiesDeletedSince(deletedEntitiesSentAt); + if (shouldSendDeletedEntities) { + int elapsed = usecTimestampNow() - deletedEntitiesSentAt; + qDebug() << "shouldSendDeletedEntities to node:" << node->getUUID() << "deletedEntitiesSentAt:" << deletedEntitiesSentAt << "elapsed:" << elapsed; + } } return shouldSendDeletedEntities; @@ -116,6 +120,10 @@ int EntityServer::sendSpecialPackets(const SharedNodePointer& node, OctreeQueryN nodeData->setLastDeletedEntitiesSentAt(deletePacketSentAt); } + if (packetsSent > 0) { + qDebug() << "EntityServer::sendSpecialPackets() sent " << packetsSent << "special packets of " << totalBytes << " total bytes to node:" << node->getUUID(); + } + // TODO: caller is expecting a packetLength, what if we send more than one packet?? return totalBytes; } @@ -134,9 +142,6 @@ void EntityServer::pruneDeletedEntities() { } } }); - - int EXTRA_SECONDS_TO_KEEP = 4; - earliestLastDeletedEntitiesSent -= USECS_PER_SECOND * EXTRA_SECONDS_TO_KEEP; tree->forgetEntitiesDeletedBefore(earliestLastDeletedEntitiesSent); } } diff --git a/assignment-client/src/octree/OctreeSendThread.cpp b/assignment-client/src/octree/OctreeSendThread.cpp index 2696c92253..b94317050c 100644 --- a/assignment-client/src/octree/OctreeSendThread.cpp +++ b/assignment-client/src/octree/OctreeSendThread.cpp @@ -570,7 +570,7 @@ int OctreeSendThread::packetDistributor(OctreeQueryNode* nodeData, bool viewFrus } - if (somethingToSend) { + if (somethingToSend && _myServer->wantsVerboseDebug()) { qDebug() << "Hit PPS Limit, packetsSentThisInterval =" << packetsSentThisInterval << " maxPacketsPerInterval = " << maxPacketsPerInterval << " clientMaxPacketsPerInterval = " << clientMaxPacketsPerInterval; diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index 34b09eb67c..7f350888be 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -25,6 +25,7 @@ #include "RecurseOctreeToMapOperator.h" #include "LogHandler.h" +const quint64 EntityTree::DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER = USECS_PER_MSEC * 500; EntityTree::EntityTree(bool shouldReaverage) : Octree(shouldReaverage), @@ -803,21 +804,26 @@ void EntityTree::update() { } bool EntityTree::hasEntitiesDeletedSince(quint64 sinceTime) { - int EXTRA_SECONDS_TO_CONSIDER = 4; - quint64 considerEntitiesSince = sinceTime - (USECS_PER_SECOND * EXTRA_SECONDS_TO_CONSIDER); + quint64 considerEntitiesSince = sinceTime - DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER; // we can probably leverage the ordered nature of QMultiMap to do this quickly... bool hasSomethingNewer = false; - { - QReadLocker locker(&_recentlyDeletedEntitiesLock); - QMultiMap::const_iterator iterator = _recentlyDeletedEntityItemIDs.constBegin(); - while (iterator != _recentlyDeletedEntityItemIDs.constEnd()) { - if (iterator.key() > considerEntitiesSince) { - hasSomethingNewer = true; - } - ++iterator; + QReadLocker locker(&_recentlyDeletedEntitiesLock); + QMultiMap::const_iterator iterator = _recentlyDeletedEntityItemIDs.constBegin(); + while (iterator != _recentlyDeletedEntityItemIDs.constEnd()) { + if (iterator.key() > considerEntitiesSince) { + hasSomethingNewer = true; + break; // if we have at least one item, we don't need to keep searching } + ++iterator; + } + + if (hasSomethingNewer) { + int elapsed = usecTimestampNow() - considerEntitiesSince; + int difference = considerEntitiesSince - sinceTime; + qDebug() << "EntityTree::hasEntitiesDeletedSince() sinceTime:" << sinceTime + << "considerEntitiesSince:" << considerEntitiesSince << "elapsed:" << elapsed << "difference:" << difference; } return hasSomethingNewer; @@ -826,14 +832,16 @@ bool EntityTree::hasEntitiesDeletedSince(quint64 sinceTime) { // sinceTime is an in/out parameter - it will be side effected with the last time sent out std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_SEQUENCE sequenceNumber, quint64& sinceTime, bool& hasMore) { + qDebug() << "EntityTree::encodeEntitiesDeletedSince()"; - int EXTRA_SECONDS_TO_CONSIDER = 4; - quint64 considerEntitiesSince = sinceTime - (USECS_PER_SECOND * EXTRA_SECONDS_TO_CONSIDER); + quint64 considerEntitiesSince = sinceTime - DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER; auto deletesPacket = NLPacket::create(PacketType::EntityErase); + qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // pack in flags OCTREE_PACKET_FLAGS flags = 0; deletesPacket->writePrimitive(flags); + qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // pack in sequence number deletesPacket->writePrimitive(sequenceNumber); @@ -841,11 +849,13 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // pack in timestamp OCTREE_PACKET_SENT_TIME now = usecTimestampNow(); deletesPacket->writePrimitive(now); + qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // figure out where we are now and pack a temporary number of IDs uint16_t numberOfIDs = 0; qint64 numberOfIDsPos = deletesPacket->pos(); deletesPacket->writePrimitive(numberOfIDs); + qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // we keep a multi map of entity IDs to timestamps, we only want to include the entity IDs that have been // deleted since we last sent to this node @@ -869,6 +879,8 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // history for a longer time window, these entities are not "lost". But we haven't yet // found/fixed the underlying issue that caused bad UUIDs to be sent to some users. deletesPacket->write(entityID.toRfc4122()); + qDebug() << "EntityTree::encodeEntitiesDeletedSince() including:" << entityID; + qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); ++numberOfIDs; // check to make sure we have room for one more ID @@ -898,6 +910,9 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // replace the count for the number of included IDs deletesPacket->seek(numberOfIDsPos); deletesPacket->writePrimitive(numberOfIDs); + qDebug() << " ---- at line:" << __LINE__ <<" deletes packet size:" << deletesPacket->getDataSize(); + + qDebug() << " ---- EntityTree::encodeEntitiesDeletedSince() numberOfIDs:" << numberOfIDs; return deletesPacket; } @@ -905,24 +920,22 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // called by the server when it knows all nodes have been sent deleted packets void EntityTree::forgetEntitiesDeletedBefore(quint64 sinceTime) { + quint64 considerSinceTime = sinceTime - DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER; QSet keysToRemove; + QWriteLocker locker(&_recentlyDeletedEntitiesLock); + QMultiMap::iterator iterator = _recentlyDeletedEntityItemIDs.begin(); - { - QWriteLocker locker(&_recentlyDeletedEntitiesLock); - QMultiMap::iterator iterator = _recentlyDeletedEntityItemIDs.begin(); - - // First find all the keys in the map that are older and need to be deleted - while (iterator != _recentlyDeletedEntityItemIDs.end()) { - if (iterator.key() <= sinceTime) { - keysToRemove << iterator.key(); - } - ++iterator; + // First find all the keys in the map that are older and need to be deleted + while (iterator != _recentlyDeletedEntityItemIDs.end()) { + if (iterator.key() <= considerSinceTime) { + keysToRemove << iterator.key(); } + ++iterator; + } - // Now run through the keysToRemove and remove them - foreach (quint64 value, keysToRemove) { - _recentlyDeletedEntityItemIDs.remove(value); - } + // Now run through the keysToRemove and remove them + foreach (quint64 value, keysToRemove) { + _recentlyDeletedEntityItemIDs.remove(value); } } diff --git a/libraries/entities/src/EntityTree.h b/libraries/entities/src/EntityTree.h index c177840199..dd31901a4d 100644 --- a/libraries/entities/src/EntityTree.h +++ b/libraries/entities/src/EntityTree.h @@ -147,6 +147,7 @@ public: void addNewlyCreatedHook(NewlyCreatedEntityHook* hook); void removeNewlyCreatedHook(NewlyCreatedEntityHook* hook); + static const quint64 DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER; bool hasAnyDeletedEntities() const { return _recentlyDeletedEntityItemIDs.size() > 0; } bool hasEntitiesDeletedSince(quint64 sinceTime); std::unique_ptr encodeEntitiesDeletedSince(OCTREE_PACKET_SEQUENCE sequenceNumber, quint64& sinceTime, From 040bae60142ef9ed611510382cae777f64d77450 Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 11 Nov 2015 12:31:50 -0800 Subject: [PATCH 4/6] more debugging --- libraries/entities/src/EntityTree.cpp | 5 +++++ 1 file changed, 5 insertions(+) diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index 7f350888be..49d50b28ff 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -942,6 +942,7 @@ void EntityTree::forgetEntitiesDeletedBefore(quint64 sinceTime) { // TODO: consider consolidating processEraseMessageDetails() and processEraseMessage() int EntityTree::processEraseMessage(NLPacket& packet, const SharedNodePointer& sourceNode) { + qDebug() << "EntityTree::processEraseMessage()"; withWriteLock([&] { packet.seek(sizeof(OCTREE_PACKET_FLAGS) + sizeof(OCTREE_PACKET_SEQUENCE) + sizeof(OCTREE_PACKET_SENT_TIME)); @@ -959,6 +960,7 @@ int EntityTree::processEraseMessage(NLPacket& packet, const SharedNodePointer& s } QUuid entityID = QUuid::fromRfc4122(packet.readWithoutCopy(NUM_BYTES_RFC4122_UUID)); + qDebug() << " ---- EntityTree::processEraseMessage() contained ID:" << entityID; EntityItemID entityItemID(entityID); entityItemIDsToDelete << entityItemID; @@ -978,6 +980,7 @@ int EntityTree::processEraseMessage(NLPacket& packet, const SharedNodePointer& s // NOTE: Caller must lock the tree before calling this. // TODO: consider consolidating processEraseMessageDetails() and processEraseMessage() int EntityTree::processEraseMessageDetails(const QByteArray& dataByteArray, const SharedNodePointer& sourceNode) { + qDebug() << "EntityTree::processEraseMessageDetails()"; const unsigned char* packetData = (const unsigned char*)dataByteArray.constData(); const unsigned char* dataAt = packetData; size_t packetLength = dataByteArray.size(); @@ -1004,6 +1007,8 @@ int EntityTree::processEraseMessageDetails(const QByteArray& dataByteArray, cons dataAt += encodedID.size(); processedBytes += encodedID.size(); + qDebug() << " ---- EntityTree::processEraseMessageDetails() contains id:" << entityID; + EntityItemID entityItemID(entityID); entityItemIDsToDelete << entityItemID; From bdfe304f7aee9f8b6a8b3e6969b8146cea690aaa Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 11 Nov 2015 14:08:15 -0800 Subject: [PATCH 5/6] remove some logging --- .../src/entities/EntityServer.cpp | 20 +++++++---- libraries/entities/src/EntityTree.cpp | 35 ++++++++++--------- 2 files changed, 32 insertions(+), 23 deletions(-) diff --git a/assignment-client/src/entities/EntityServer.cpp b/assignment-client/src/entities/EntityServer.cpp index 81dabd4dcd..493a16fea4 100644 --- a/assignment-client/src/entities/EntityServer.cpp +++ b/assignment-client/src/entities/EntityServer.cpp @@ -84,10 +84,13 @@ bool EntityServer::hasSpecialPacketsToSend(const SharedNodePointer& node) { quint64 deletedEntitiesSentAt = nodeData->getLastDeletedEntitiesSentAt(); EntityTreePointer tree = std::static_pointer_cast(_tree); shouldSendDeletedEntities = tree->hasEntitiesDeletedSince(deletedEntitiesSentAt); - if (shouldSendDeletedEntities) { - int elapsed = usecTimestampNow() - deletedEntitiesSentAt; - qDebug() << "shouldSendDeletedEntities to node:" << node->getUUID() << "deletedEntitiesSentAt:" << deletedEntitiesSentAt << "elapsed:" << elapsed; - } + + #ifdef EXTRA_ERASE_DEBUGGING + if (shouldSendDeletedEntities) { + int elapsed = usecTimestampNow() - deletedEntitiesSentAt; + qDebug() << "shouldSendDeletedEntities to node:" << node->getUUID() << "deletedEntitiesSentAt:" << deletedEntitiesSentAt << "elapsed:" << elapsed; + } + #endif } return shouldSendDeletedEntities; @@ -120,9 +123,12 @@ int EntityServer::sendSpecialPackets(const SharedNodePointer& node, OctreeQueryN nodeData->setLastDeletedEntitiesSentAt(deletePacketSentAt); } - if (packetsSent > 0) { - qDebug() << "EntityServer::sendSpecialPackets() sent " << packetsSent << "special packets of " << totalBytes << " total bytes to node:" << node->getUUID(); - } + #ifdef EXTRA_ERASE_DEBUGGING + if (packetsSent > 0) { + qDebug() << "EntityServer::sendSpecialPackets() sent " << packetsSent << "special packets of " + << totalBytes << " total bytes to node:" << node->getUUID(); + } + #endif // TODO: caller is expecting a packetLength, what if we send more than one packet?? return totalBytes; diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index 49d50b28ff..077bd1b76b 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -25,7 +25,7 @@ #include "RecurseOctreeToMapOperator.h" #include "LogHandler.h" -const quint64 EntityTree::DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER = USECS_PER_MSEC * 500; +const quint64 EntityTree::DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER = USECS_PER_MSEC * 50; EntityTree::EntityTree(bool shouldReaverage) : Octree(shouldReaverage), @@ -819,12 +819,14 @@ bool EntityTree::hasEntitiesDeletedSince(quint64 sinceTime) { ++iterator; } +#ifdef EXTRA_ERASE_DEBUGGING if (hasSomethingNewer) { int elapsed = usecTimestampNow() - considerEntitiesSince; int difference = considerEntitiesSince - sinceTime; qDebug() << "EntityTree::hasEntitiesDeletedSince() sinceTime:" << sinceTime << "considerEntitiesSince:" << considerEntitiesSince << "elapsed:" << elapsed << "difference:" << difference; } +#endif return hasSomethingNewer; } @@ -832,16 +834,12 @@ bool EntityTree::hasEntitiesDeletedSince(quint64 sinceTime) { // sinceTime is an in/out parameter - it will be side effected with the last time sent out std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_SEQUENCE sequenceNumber, quint64& sinceTime, bool& hasMore) { - qDebug() << "EntityTree::encodeEntitiesDeletedSince()"; - quint64 considerEntitiesSince = sinceTime - DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER; auto deletesPacket = NLPacket::create(PacketType::EntityErase); - qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // pack in flags OCTREE_PACKET_FLAGS flags = 0; deletesPacket->writePrimitive(flags); - qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // pack in sequence number deletesPacket->writePrimitive(sequenceNumber); @@ -849,13 +847,11 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // pack in timestamp OCTREE_PACKET_SENT_TIME now = usecTimestampNow(); deletesPacket->writePrimitive(now); - qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // figure out where we are now and pack a temporary number of IDs uint16_t numberOfIDs = 0; qint64 numberOfIDsPos = deletesPacket->pos(); deletesPacket->writePrimitive(numberOfIDs); - qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); // we keep a multi map of entity IDs to timestamps, we only want to include the entity IDs that have been // deleted since we last sent to this node @@ -879,10 +875,12 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // history for a longer time window, these entities are not "lost". But we haven't yet // found/fixed the underlying issue that caused bad UUIDs to be sent to some users. deletesPacket->write(entityID.toRfc4122()); - qDebug() << "EntityTree::encodeEntitiesDeletedSince() including:" << entityID; - qDebug() << " ---- at line:" << __LINE__ << " deletes packet size:" << deletesPacket->getDataSize(); ++numberOfIDs; + #ifdef EXTRA_ERASE_DEBUGGING + qDebug() << "EntityTree::encodeEntitiesDeletedSince() including:" << entityID; + #endif + // check to make sure we have room for one more ID if (NUM_BYTES_RFC4122_UUID > deletesPacket->bytesAvailableForWrite()) { hasFilledPacket = true; @@ -910,9 +908,6 @@ std::unique_ptr EntityTree::encodeEntitiesDeletedSince(OCTREE_PACKET_S // replace the count for the number of included IDs deletesPacket->seek(numberOfIDsPos); deletesPacket->writePrimitive(numberOfIDs); - qDebug() << " ---- at line:" << __LINE__ <<" deletes packet size:" << deletesPacket->getDataSize(); - - qDebug() << " ---- EntityTree::encodeEntitiesDeletedSince() numberOfIDs:" << numberOfIDs; return deletesPacket; } @@ -942,7 +937,9 @@ void EntityTree::forgetEntitiesDeletedBefore(quint64 sinceTime) { // TODO: consider consolidating processEraseMessageDetails() and processEraseMessage() int EntityTree::processEraseMessage(NLPacket& packet, const SharedNodePointer& sourceNode) { - qDebug() << "EntityTree::processEraseMessage()"; + #ifdef EXTRA_ERASE_DEBUGGING + qDebug() << "EntityTree::processEraseMessage()"; + #endif withWriteLock([&] { packet.seek(sizeof(OCTREE_PACKET_FLAGS) + sizeof(OCTREE_PACKET_SEQUENCE) + sizeof(OCTREE_PACKET_SENT_TIME)); @@ -960,7 +957,9 @@ int EntityTree::processEraseMessage(NLPacket& packet, const SharedNodePointer& s } QUuid entityID = QUuid::fromRfc4122(packet.readWithoutCopy(NUM_BYTES_RFC4122_UUID)); - qDebug() << " ---- EntityTree::processEraseMessage() contained ID:" << entityID; + #ifdef EXTRA_ERASE_DEBUGGING + qDebug() << " ---- EntityTree::processEraseMessage() contained ID:" << entityID; + #endif EntityItemID entityItemID(entityID); entityItemIDsToDelete << entityItemID; @@ -980,7 +979,9 @@ int EntityTree::processEraseMessage(NLPacket& packet, const SharedNodePointer& s // NOTE: Caller must lock the tree before calling this. // TODO: consider consolidating processEraseMessageDetails() and processEraseMessage() int EntityTree::processEraseMessageDetails(const QByteArray& dataByteArray, const SharedNodePointer& sourceNode) { - qDebug() << "EntityTree::processEraseMessageDetails()"; + #ifdef EXTRA_ERASE_DEBUGGING + qDebug() << "EntityTree::processEraseMessageDetails()"; + #endif const unsigned char* packetData = (const unsigned char*)dataByteArray.constData(); const unsigned char* dataAt = packetData; size_t packetLength = dataByteArray.size(); @@ -1007,7 +1008,9 @@ int EntityTree::processEraseMessageDetails(const QByteArray& dataByteArray, cons dataAt += encodedID.size(); processedBytes += encodedID.size(); - qDebug() << " ---- EntityTree::processEraseMessageDetails() contains id:" << entityID; + #ifdef EXTRA_ERASE_DEBUGGING + qDebug() << " ---- EntityTree::processEraseMessageDetails() contains id:" << entityID; + #endif EntityItemID entityItemID(entityID); entityItemIDsToDelete << entityItemID; From 2f903a9513f43a7e5da301a756e4eccf082359bb Mon Sep 17 00:00:00 2001 From: Brad Hefta-Gaub Date: Wed, 11 Nov 2015 14:21:14 -0800 Subject: [PATCH 6/6] CR feedback and some cleanup --- assignment-client/src/entities/EntityNodeData.h | 2 -- libraries/entities/src/EntityTree.cpp | 8 +++----- libraries/entities/src/EntityTree.h | 1 - 3 files changed, 3 insertions(+), 8 deletions(-) diff --git a/assignment-client/src/entities/EntityNodeData.h b/assignment-client/src/entities/EntityNodeData.h index 69da9ee14b..0ca0834fef 100644 --- a/assignment-client/src/entities/EntityNodeData.h +++ b/assignment-client/src/entities/EntityNodeData.h @@ -18,8 +18,6 @@ class EntityNodeData : public OctreeQueryNode { public: - EntityNodeData() : OctreeQueryNode() { } - virtual PacketType getMyPacketType() const { return PacketType::EntityData; } quint64 getLastDeletedEntitiesSentAt() const { return _lastDeletedEntitiesSentAt; } diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index 077bd1b76b..0174dbe39b 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/libraries/entities/src/EntityTree.cpp @@ -25,7 +25,7 @@ #include "RecurseOctreeToMapOperator.h" #include "LogHandler.h" -const quint64 EntityTree::DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER = USECS_PER_MSEC * 50; +static const quint64 DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER = USECS_PER_MSEC * 50; EntityTree::EntityTree(bool shouldReaverage) : Octree(shouldReaverage), @@ -392,10 +392,8 @@ void EntityTree::processRemovedEntities(const DeleteEntityOperator& theOperator) if (getIsServer()) { // set up the deleted entities ID - { - QWriteLocker locker(&_recentlyDeletedEntitiesLock); - _recentlyDeletedEntityItemIDs.insert(deletedAt, theEntity->getEntityItemID()); - } + QWriteLocker locker(&_recentlyDeletedEntitiesLock); + _recentlyDeletedEntityItemIDs.insert(deletedAt, theEntity->getEntityItemID()); } if (_simulation) { diff --git a/libraries/entities/src/EntityTree.h b/libraries/entities/src/EntityTree.h index dd31901a4d..c177840199 100644 --- a/libraries/entities/src/EntityTree.h +++ b/libraries/entities/src/EntityTree.h @@ -147,7 +147,6 @@ public: void addNewlyCreatedHook(NewlyCreatedEntityHook* hook); void removeNewlyCreatedHook(NewlyCreatedEntityHook* hook); - static const quint64 DELETED_ENTITIES_EXTRA_USECS_TO_CONSIDER; bool hasAnyDeletedEntities() const { return _recentlyDeletedEntityItemIDs.size() > 0; } bool hasEntitiesDeletedSince(quint64 sinceTime); std::unique_ptr encodeEntitiesDeletedSince(OCTREE_PACKET_SEQUENCE sequenceNumber, quint64& sinceTime,