From c1c41ea2ca7fdab1eec7de225802662609eb55a7 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Fri, 28 Feb 2014 16:18:02 -0800 Subject: [PATCH] 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(); }