From cdb0aeb153abffbde1f921ac1eadce0eea41faf8 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Thu, 27 Feb 2014 10:47:17 -0800 Subject: [PATCH 1/3] some hacking on server performance --- .../src/octree/OctreeSendThread.cpp | 26 ++++++++++++++++--- assignment-client/src/octree/OctreeServer.cpp | 16 ++++++++++++ assignment-client/src/octree/OctreeServer.h | 5 ++++ libraries/octree/src/OctreePersistThread.cpp | 2 -- libraries/particles/src/ParticleTree.cpp | 2 ++ 5 files changed, 46 insertions(+), 5 deletions(-) diff --git a/assignment-client/src/octree/OctreeSendThread.cpp b/assignment-client/src/octree/OctreeSendThread.cpp index 121e80b808..b1f693725a 100644 --- a/assignment-client/src/octree/OctreeSendThread.cpp +++ b/assignment-client/src/octree/OctreeSendThread.cpp @@ -52,6 +52,8 @@ bool OctreeSendThread::process() { } node->getMutex().unlock(); // we're done with this node for now. + } else { + qDebug("OctreeSendThread::process() failed to get node lock"); } } } else { @@ -70,8 +72,8 @@ bool OctreeSendThread::process() { PerformanceWarning warn(false,"OctreeSendThread... usleep()",false,&_usleepTime,&_usleepCalls); usleep(usecToSleep); } else { - if (_myServer->wantsDebugSending() && _myServer->wantsVerboseDebug()) { - std::cout << "Last send took too much time, not sleeping!\n"; + if (true || (_myServer->wantsDebugSending() && _myServer->wantsVerboseDebug())) { + qDebug() << "Last send took too much time (" << (elapsed / USECS_PER_MSEC) <<" msecs), not sleeping!\n"; } } } @@ -420,9 +422,23 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue isFullScene, &nodeData->stats, _myServer->getJurisdiction()); + quint64 lockWaitStart = usecTimestampNow(); _myServer->getOctree()->lockForRead(); + quint64 lockWaitEnd = usecTimestampNow(); + int lockWaitElapsedMsec = (lockWaitEnd - lockWaitStart)/USECS_PER_MSEC; + if (lockWaitElapsedMsec > 0) { + qDebug() << "lockWaitElapsedMsec=" << lockWaitElapsedMsec; + } + nodeData->stats.encodeStarted(); + + quint64 encodeStart = usecTimestampNow(); bytesWritten = _myServer->getOctree()->encodeTreeBitstream(subTree, &_packetData, nodeData->nodeBag, params); + quint64 encodeEnd = usecTimestampNow(); + int encodeElapsedMsec = (encodeEnd - encodeStart)/USECS_PER_MSEC; + if (encodeElapsedMsec > 0) { + qDebug() << "encodeElapsedMsec=" << encodeElapsedMsec; + } // If after calling encodeTreeBitstream() there are no nodes left to send, then we know we've // sent the entire scene. We want to know this below so we'll actually write this content into @@ -543,7 +559,11 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue quint64 endCompressTimeMsecs = OctreePacketData::getCompressContentTime() / 1000; int elapsedCompressTimeMsecs = endCompressTimeMsecs - startCompressTimeMsecs; - + if (elapsedmsec > 0) { + qDebug() << "elapsedmsec=" << elapsedmsec; + } + OctreeServer::trackLoopTime((float)elapsedmsec); + if (elapsedmsec > 100) { if (elapsedmsec > 1000) { int elapsedsec = (end - start)/1000000; diff --git a/assignment-client/src/octree/OctreeServer.cpp b/assignment-client/src/octree/OctreeServer.cpp index 1fb858c884..c1dd5a69ec 100644 --- a/assignment-client/src/octree/OctreeServer.cpp +++ b/assignment-client/src/octree/OctreeServer.cpp @@ -19,6 +19,8 @@ #include "OctreeServerConsts.h" OctreeServer* OctreeServer::_instance = NULL; +int OctreeServer::_clientCount = 0; +SimpleMovingAverage OctreeServer::_averageLoopTime(1000); void OctreeServer::attachQueryNodeToNode(Node* newNode) { if (newNode->getLinkedData() == NULL) { @@ -48,6 +50,7 @@ OctreeServer::OctreeServer(const QByteArray& packet) : _startedUSecs(usecTimestampNow()) { _instance = this; + _averageLoopTime.updateAverage(0); } OctreeServer::~OctreeServer() { @@ -234,6 +237,19 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QString& quint64 totalBytesOfColor = OctreePacketData::getTotalBytesOfColor(); const int COLUMN_WIDTH = 10; + statsString += QString(" Configured Max PPS/Client: %1 pps/client\r\n") + .arg(locale.toString((uint)getPacketsPerClientPerSecond()).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString(" Configured Max PPS/Server: %1 pps/server\r\n\r\n") + .arg(locale.toString((uint)getPacketsTotalPerSecond()).rightJustified(COLUMN_WIDTH, ' ')); + statsString += QString(" Total Clients Connected: %1 clients\r\n\r\n") + .arg(locale.toString((uint)getCurrentClientCount()).rightJustified(COLUMN_WIDTH, ' ')); + + float averageLoopTime = _averageLoopTime.getAverage(); + statsString += QString().sprintf(" Average packetLoop() time: %5.2f msecs\r\n", averageLoopTime); + + qDebug() << "_averageLoopTime.getAverage()=" << averageLoopTime; + + statsString += QString(" Total Outbound Packets: %1 packets\r\n") .arg(locale.toString((uint)totalOutboundPackets).rightJustified(COLUMN_WIDTH, ' ')); statsString += QString(" Total Outbound Bytes: %1 bytes\r\n") diff --git a/assignment-client/src/octree/OctreeServer.h b/assignment-client/src/octree/OctreeServer.h index e221011b76..5315934d6a 100644 --- a/assignment-client/src/octree/OctreeServer.h +++ b/assignment-client/src/octree/OctreeServer.h @@ -63,6 +63,8 @@ public: static void attachQueryNodeToNode(Node* newNode); + static void trackLoopTime(float time) { _averageLoopTime.updateAverage(time); } + bool handleHTTPRequest(HTTPConnection* connection, const QString& path); public slots: /// runs the voxel server assignment @@ -95,6 +97,9 @@ protected: time_t _started; quint64 _startedUSecs; + + static int _clientCount; + static SimpleMovingAverage _averageLoopTime; }; #endif // __octree_server__OctreeServer__ diff --git a/libraries/octree/src/OctreePersistThread.cpp b/libraries/octree/src/OctreePersistThread.cpp index c6c3ce2a6a..3de3085a36 100644 --- a/libraries/octree/src/OctreePersistThread.cpp +++ b/libraries/octree/src/OctreePersistThread.cpp @@ -68,9 +68,7 @@ bool OctreePersistThread::process() { usleep(USECS_TO_SLEEP); // do our updates then check to save... - _tree->lockForWrite(); _tree->update(); - _tree->unlock(); quint64 now = usecTimestampNow(); quint64 sinceLastSave = now - _lastCheck; diff --git a/libraries/particles/src/ParticleTree.cpp b/libraries/particles/src/ParticleTree.cpp index afffe7943c..b422b8e4e8 100644 --- a/libraries/particles/src/ParticleTree.cpp +++ b/libraries/particles/src/ParticleTree.cpp @@ -474,7 +474,9 @@ void ParticleTree::update() { AABox treeBounds = getRoot()->getAABox(); if (!shouldDie && treeBounds.contains(args._movingParticles[i].getPosition())) { + lockForWrite(); storeParticle(args._movingParticles[i]); + unlock(); } else { uint32_t particleID = args._movingParticles[i].getID(); quint64 deletedAt = usecTimestampNow(); From d2faca97670d699df3a602fd4f7d08139fa40b73 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Fri, 28 Feb 2014 16:17:30 -0800 Subject: [PATCH 2/3] fixed some warnings --- SvoViewer/src/AABoundingVolume.h | 2 +- SvoViewer/src/Render.cpp | 1 - libraries/shared/src/ResourceCache.cpp | 4 ++-- 3 files changed, 3 insertions(+), 4 deletions(-) diff --git a/SvoViewer/src/AABoundingVolume.h b/SvoViewer/src/AABoundingVolume.h index 399c2fa68c..d6f73ba510 100644 --- a/SvoViewer/src/AABoundingVolume.h +++ b/SvoViewer/src/AABoundingVolume.h @@ -20,7 +20,7 @@ class AABoundingVolume { public: - AABoundingVolume() : _isSingleDirectionSet(false), _numPointsInSet(0) { memset(_bounds,0,sizeof(_bounds)); } + AABoundingVolume() : _numPointsInSet(0), _isSingleDirectionSet(false) { memset(_bounds,0,sizeof(_bounds)); } ~AABoundingVolume(){} void AddToSet(const glm::vec3 newPt) diff --git a/SvoViewer/src/Render.cpp b/SvoViewer/src/Render.cpp index 2b1064aa49..cb6ddd25c9 100755 --- a/SvoViewer/src/Render.cpp +++ b/SvoViewer/src/Render.cpp @@ -28,7 +28,6 @@ GLubyte SvoViewer::SetupGlVBO(GLuint * id, int sizeInBytes, GLenum target, GLenu bool SvoViewer::FindNumLeaves(OctreeElement* node, void* extraData) { - VoxelTreeElement* voxel = (VoxelTreeElement*)node; FindNumLeavesData* args = (FindNumLeavesData*)extraData; if (node->isLeaf()) args->numLeaves++; return true; diff --git a/libraries/shared/src/ResourceCache.cpp b/libraries/shared/src/ResourceCache.cpp index 24350794bc..eacce71e98 100644 --- a/libraries/shared/src/ResourceCache.cpp +++ b/libraries/shared/src/ResourceCache.cpp @@ -77,8 +77,8 @@ Resource::Resource(const QUrl& url, bool delayLoad) : _request(url), _startedLoading(false), _failedToLoad(false), - _attempts(0), - _reply(NULL) { + _reply(NULL), + _attempts(0) { if (!url.isValid()) { _startedLoading = _failedToLoad = true; From c1c41ea2ca7fdab1eec7de225802662609eb55a7 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Fri, 28 Feb 2014 16:18:02 -0800 Subject: [PATCH 3/3] handle some shutdown cases and reduce time of locking in octree server --- .../src/octree/OctreeSendThread.cpp | 67 +++++++++---------- assignment-client/src/octree/OctreeServer.cpp | 44 ++++++++++-- assignment-client/src/octree/OctreeServer.h | 14 ++++ libraries/shared/src/GenericThread.cpp | 1 - 4 files changed, 84 insertions(+), 42 deletions(-) diff --git a/assignment-client/src/octree/OctreeSendThread.cpp b/assignment-client/src/octree/OctreeSendThread.cpp index 334fabf5a4..751583960e 100644 --- a/assignment-client/src/octree/OctreeSendThread.cpp +++ b/assignment-client/src/octree/OctreeSendThread.cpp @@ -23,13 +23,13 @@ OctreeSendThread::OctreeSendThread(const QUuid& nodeUUID, OctreeServer* myServer _packetData(), _nodeMissingCount(0) { - qDebug() << "client connected"; - _myServer->clientConnected(); + qDebug() << "client connected - starting sending thread"; + OctreeServer::clientConnected(); } OctreeSendThread::~OctreeSendThread() { - qDebug() << "client disconnected"; - _myServer->clientDisconnected(); + qDebug() << "client disconnected - ending sending thread"; + OctreeServer::clientDisconnected(); } @@ -43,7 +43,6 @@ bool OctreeSendThread::process() { } quint64 start = usecTimestampNow(); - bool gotLock = false; // don't do any send processing until the initial load of the octree is complete... if (_myServer->isInitialLoadComplete()) { @@ -51,27 +50,19 @@ bool OctreeSendThread::process() { if (node) { _nodeMissingCount = 0; - // make sure the node list doesn't kill our node while we're using it - if (node->getMutex().tryLock()) { - gotLock = true; - OctreeQueryNode* nodeData = NULL; + OctreeQueryNode* nodeData = NULL; - nodeData = (OctreeQueryNode*) node->getLinkedData(); + nodeData = (OctreeQueryNode*) node->getLinkedData(); - int packetsSent = 0; + int packetsSent = 0; - // Sometimes the node data has not yet been linked, in which case we can't really do anything - if (nodeData) { - bool viewFrustumChanged = nodeData->updateCurrentViewFrustum(); - if (_myServer->wantsDebugSending() && _myServer->wantsVerboseDebug()) { - printf("nodeData->updateCurrentViewFrustum() changed=%s\n", debug::valueOf(viewFrustumChanged)); - } - packetsSent = packetDistributor(node, nodeData, viewFrustumChanged); + // Sometimes the node data has not yet been linked, in which case we can't really do anything + if (nodeData) { + bool viewFrustumChanged = nodeData->updateCurrentViewFrustum(); + if (_myServer->wantsDebugSending() && _myServer->wantsVerboseDebug()) { + printf("nodeData->updateCurrentViewFrustum() changed=%s\n", debug::valueOf(viewFrustumChanged)); } - - node->getMutex().unlock(); // we're done with this node for now. - } else { - qDebug("OctreeSendThread::process() failed to get node lock"); + packetsSent = packetDistributor(node, nodeData, viewFrustumChanged); } } else { _nodeMissingCount++; @@ -83,7 +74,7 @@ bool OctreeSendThread::process() { } // Only sleep if we're still running and we got the lock last time we tried, otherwise try to get the lock asap - if (isStillRunning() && gotLock) { + if (isStillRunning()) { // dynamically sleep until we need to fire off the next set of octree elements int elapsed = (usecTimestampNow() - start); int usecToSleep = OCTREE_SEND_INTERVAL_USECS - elapsed; @@ -93,8 +84,11 @@ bool OctreeSendThread::process() { usleep(usecToSleep); } else { if (true || (_myServer->wantsDebugSending() && _myServer->wantsVerboseDebug())) { - qDebug() << "Last send took too much time (" << (elapsed / USECS_PER_MSEC) <<" msecs), not sleeping!\n"; + qDebug() << "Last send took too much time (" << (elapsed / USECS_PER_MSEC) + <<" msecs), barely sleeping 1 usec!\n"; } + const int MIN_USEC_TO_SLEEP = 1; + usleep(MIN_USEC_TO_SLEEP); } } @@ -116,6 +110,13 @@ int OctreeSendThread::handlePacketSend(const SharedNodePointer& node, OctreeQuer int packetsSent = 0; // double check that the node has an active socket, otherwise, don't send... + + quint64 lockWaitStart = usecTimestampNow(); + QMutexLocker locker(&node->getMutex()); + quint64 lockWaitEnd = usecTimestampNow(); + float lockWaitElapsedUsec = (float)(lockWaitEnd - lockWaitStart); + OctreeServer::trackNodeWaitTime(lockWaitElapsedUsec); + const HifiSockAddr* nodeAddress = node->getActiveSocket(); if (!nodeAddress) { return packetsSent; // without sending... @@ -445,10 +446,8 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue quint64 lockWaitStart = usecTimestampNow(); _myServer->getOctree()->lockForRead(); quint64 lockWaitEnd = usecTimestampNow(); - int lockWaitElapsedMsec = (lockWaitEnd - lockWaitStart)/USECS_PER_MSEC; - if (lockWaitElapsedMsec > 0) { - qDebug() << "lockWaitElapsedMsec=" << lockWaitElapsedMsec; - } + float lockWaitElapsedUsec = (float)(lockWaitEnd - lockWaitStart); + OctreeServer::trackTreeWaitTime(lockWaitElapsedUsec); nodeData->stats.encodeStarted(); @@ -456,9 +455,7 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue bytesWritten = _myServer->getOctree()->encodeTreeBitstream(subTree, &_packetData, nodeData->nodeBag, params); quint64 encodeEnd = usecTimestampNow(); int encodeElapsedMsec = (encodeEnd - encodeStart)/USECS_PER_MSEC; - if (encodeElapsedMsec > 0) { - qDebug() << "encodeElapsedMsec=" << encodeElapsedMsec; - } + OctreeServer::trackEncodeTime(encodeElapsedMsec); // If after calling encodeTreeBitstream() there are no nodes left to send, then we know we've // sent the entire scene. We want to know this below so we'll actually write this content into @@ -571,7 +568,8 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue quint64 end = usecTimestampNow(); - int elapsedmsec = (end - start)/1000; + int elapsedmsec = (end - start)/USECS_PER_MSEC; + OctreeServer::trackLoopTime(elapsedmsec); quint64 endCompressCalls = OctreePacketData::getCompressContentCalls(); int elapsedCompressCalls = endCompressCalls - startCompressCalls; @@ -579,11 +577,6 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue quint64 endCompressTimeMsecs = OctreePacketData::getCompressContentTime() / 1000; int elapsedCompressTimeMsecs = endCompressTimeMsecs - startCompressTimeMsecs; - if (elapsedmsec > 0) { - qDebug() << "elapsedmsec=" << elapsedmsec; - } - OctreeServer::trackLoopTime((float)elapsedmsec); - if (elapsedmsec > 100) { if (elapsedmsec > 1000) { int elapsedsec = (end - start)/1000000; diff --git a/assignment-client/src/octree/OctreeServer.cpp b/assignment-client/src/octree/OctreeServer.cpp index 83713f8ae8..c384c95176 100644 --- a/assignment-client/src/octree/OctreeServer.cpp +++ b/assignment-client/src/octree/OctreeServer.cpp @@ -20,7 +20,10 @@ OctreeServer* OctreeServer::_instance = NULL; int OctreeServer::_clientCount = 0; -SimpleMovingAverage OctreeServer::_averageLoopTime(1000); +SimpleMovingAverage OctreeServer::_averageLoopTime(10000); +SimpleMovingAverage OctreeServer::_averageEncodeTime(10000); +SimpleMovingAverage OctreeServer::_averageTreeWaitTime(10000); +SimpleMovingAverage OctreeServer::_averageNodeWaitTime(10000); void OctreeServer::attachQueryNodeToNode(Node* newNode) { if (newNode->getLinkedData() == NULL) { @@ -268,11 +271,25 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QString& statsString += QString(" Total Clients Connected: %1 clients\r\n\r\n") .arg(locale.toString((uint)getCurrentClientCount()).rightJustified(COLUMN_WIDTH, ' ')); - float averageLoopTime = _averageLoopTime.getAverage(); + float averageLoopTime = getAverageLoopTime(); statsString += QString().sprintf(" Average packetLoop() time: %5.2f msecs\r\n", averageLoopTime); - - qDebug() << "_averageLoopTime.getAverage()=" << averageLoopTime; + qDebug() << "averageLoopTime=" << averageLoopTime; + float averageEncodeTime = getAverageEncodeTime(); + statsString += QString().sprintf(" Average encode time: %5.2f msecs\r\n", averageEncodeTime); + qDebug() << "averageEncodeTime=" << averageEncodeTime; + + + float averageTreeWaitTime = getAverageTreeWaitTime(); + statsString += QString().sprintf(" Average tree lock wait time: %7.2f usecs\r\n", averageTreeWaitTime); + qDebug() << "averageTreeWaitTime=" << averageTreeWaitTime; + + float averageNodeWaitTime = getAverageNodeWaitTime(); + statsString += QString().sprintf(" Average node lock wait time: %7.2f usecs\r\n", averageNodeWaitTime); + qDebug() << "averageNodeWaitTime=" << averageNodeWaitTime; + + + statsString += QString("\r\n"); statsString += QString(" Total Outbound Packets: %1 packets\r\n") .arg(locale.toString((uint)totalOutboundPackets).rightJustified(COLUMN_WIDTH, ' ')); @@ -591,6 +608,9 @@ void OctreeServer::run() { NodeList* nodeList = NodeList::getInstance(); nodeList->setOwnerType(getMyNodeType()); + connect(nodeList, SIGNAL(nodeAdded(SharedNodePointer)), SLOT(nodeAdded(SharedNodePointer))); + connect(nodeList, SIGNAL(nodeKilled(SharedNodePointer)),SLOT(nodeKilled(SharedNodePointer))); + // we need to ask the DS about agents so we can ping/reply with them nodeList->addNodeTypeToInterestSet(NodeType::Agent); @@ -710,3 +730,19 @@ void OctreeServer::run() { silentNodeTimer->start(NODE_SILENCE_THRESHOLD_USECS / 1000); } +void OctreeServer::nodeAdded(SharedNodePointer node) { + // we might choose to use this notifier to track clients in a pending state +} + +void OctreeServer::nodeKilled(SharedNodePointer node) { + OctreeQueryNode* nodeData = static_cast(node->getLinkedData()); + if (nodeData) { + // Note: It should be safe to do this without locking the node, because if any other threads + // are using the SharedNodePointer, then they have a reference to the SharedNodePointer and the deleteLater() + // won't actually delete it until all threads have released their references to the pointer. + // But we can and should clear the linked data so that no one else tries to access it. + nodeData->deleteLater(); + node->setLinkedData(NULL); + } +} + diff --git a/assignment-client/src/octree/OctreeServer.h b/assignment-client/src/octree/OctreeServer.h index 95b0720a8b..94dcf18dc8 100644 --- a/assignment-client/src/octree/OctreeServer.h +++ b/assignment-client/src/octree/OctreeServer.h @@ -75,12 +75,23 @@ public: static void attachQueryNodeToNode(Node* newNode); static void trackLoopTime(float time) { _averageLoopTime.updateAverage(time); } + static float getAverageLoopTime() { return _averageLoopTime.getAverage(); } + + static void trackEncodeTime(float time) { _averageEncodeTime.updateAverage(time); } + static float getAverageEncodeTime() { return _averageEncodeTime.getAverage(); } + + static void trackTreeWaitTime(float time) { _averageTreeWaitTime.updateAverage(time); } + static float getAverageTreeWaitTime() { return _averageTreeWaitTime.getAverage(); } + static void trackNodeWaitTime(float time) { _averageNodeWaitTime.updateAverage(time); } + static float getAverageNodeWaitTime() { return _averageNodeWaitTime.getAverage(); } bool handleHTTPRequest(HTTPConnection* connection, const QString& path); public slots: /// runs the voxel server assignment void run(); void readPendingDatagrams(); + void nodeAdded(SharedNodePointer node); + void nodeKilled(SharedNodePointer node); protected: void parsePayload(); @@ -112,6 +123,9 @@ protected: static int _clientCount; static SimpleMovingAverage _averageLoopTime; + static SimpleMovingAverage _averageEncodeTime; + static SimpleMovingAverage _averageTreeWaitTime; + static SimpleMovingAverage _averageNodeWaitTime; }; #endif // __octree_server__OctreeServer__ diff --git a/libraries/shared/src/GenericThread.cpp b/libraries/shared/src/GenericThread.cpp index 186366c606..ff371e0f32 100644 --- a/libraries/shared/src/GenericThread.cpp +++ b/libraries/shared/src/GenericThread.cpp @@ -72,6 +72,5 @@ void GenericThread::threadRoutine() { if (_isThreaded && _thread) { _thread->quit(); } - emit finished(); }