From e9684c0ee537d86e889834f84cd4fba47bc2f01f Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Mon, 17 Mar 2014 16:11:00 -0700 Subject: [PATCH] added more stats to octree server stats page --- .../src/octree/OctreeSendThread.cpp | 6 +- assignment-client/src/octree/OctreeServer.cpp | 104 ++++++++++++++---- assignment-client/src/octree/OctreeServer.h | 11 +- 3 files changed, 97 insertions(+), 24 deletions(-) diff --git a/assignment-client/src/octree/OctreeSendThread.cpp b/assignment-client/src/octree/OctreeSendThread.cpp index fd4bbbd7a9..dc8cd64ebe 100644 --- a/assignment-client/src/octree/OctreeSendThread.cpp +++ b/assignment-client/src/octree/OctreeSendThread.cpp @@ -117,7 +117,7 @@ int OctreeSendThread::handlePacketSend(const SharedNodePointer& node, OctreeQuer quint64 lockWaitEnd = usecTimestampNow(); float lockWaitElapsedUsec = (float)(lockWaitEnd - lockWaitStart); OctreeServer::trackNodeWaitTime(lockWaitElapsedUsec); - + const HifiSockAddr* nodeAddress = node->getActiveSocket(); if (!nodeAddress) { return packetsSent; // without sending... @@ -452,15 +452,13 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue _myServer->getOctree()->lockForRead(); quint64 lockWaitEnd = usecTimestampNow(); lockWaitElapsedUsec = (float)(lockWaitEnd - lockWaitStart); - OctreeServer::trackTreeWaitTime(lockWaitElapsedUsec); - + nodeData->stats.encodeStarted(); quint64 encodeStart = usecTimestampNow(); bytesWritten = _myServer->getOctree()->encodeTreeBitstream(subTree, &_packetData, nodeData->nodeBag, params); quint64 encodeEnd = usecTimestampNow(); encodeElapsedUsec = (float)(encodeEnd - encodeStart); - OctreeServer::trackEncodeTime(encodeElapsedUsec); // 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 diff --git a/assignment-client/src/octree/OctreeServer.cpp b/assignment-client/src/octree/OctreeServer.cpp index 4d55455f76..22bdae16d8 100644 --- a/assignment-client/src/octree/OctreeServer.cpp +++ b/assignment-client/src/octree/OctreeServer.cpp @@ -20,13 +20,54 @@ OctreeServer* OctreeServer::_instance = NULL; int OctreeServer::_clientCount = 0; -SimpleMovingAverage OctreeServer::_averageLoopTime(100000); -SimpleMovingAverage OctreeServer::_averageEncodeTime(100000); -SimpleMovingAverage OctreeServer::_averageInsideTime(100000); -SimpleMovingAverage OctreeServer::_averageTreeWaitTime(100000); -SimpleMovingAverage OctreeServer::_averageNodeWaitTime(100000); -SimpleMovingAverage OctreeServer::_averageCompressAndWriteTime(100000); -SimpleMovingAverage OctreeServer::_averagePacketSendingTime(100000); +const int MOVING_AVERAGE_SAMPLE_COUNTS = 1000000; +SimpleMovingAverage OctreeServer::_averageLoopTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageEncodeTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageInsideTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageTreeWaitTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageTreeShortWaitTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageTreeLongWaitTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageTreeExtraLongWaitTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageNodeWaitTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averageCompressAndWriteTime(MOVING_AVERAGE_SAMPLE_COUNTS); +SimpleMovingAverage OctreeServer::_averagePacketSendingTime(MOVING_AVERAGE_SAMPLE_COUNTS); +int OctreeServer::_extraLongTreeWait = 0; +int OctreeServer::_longTreeWait = 0; +int OctreeServer::_shortTreeWait = 0; + + +void OctreeServer::resetSendingStats() { + _averageLoopTime.reset(); + _averageEncodeTime.reset(); + _averageInsideTime.reset(); + _averageTreeWaitTime.reset(); + _averageTreeShortWaitTime.reset(); + _averageTreeLongWaitTime.reset(); + _averageTreeExtraLongWaitTime.reset(); + _averageNodeWaitTime.reset(); + _averageCompressAndWriteTime.reset(); + _averagePacketSendingTime.reset(); + _extraLongTreeWait = 0; + _longTreeWait = 0; + _shortTreeWait = 0; +} + +void OctreeServer::trackTreeWaitTime(float time) { + _averageTreeWaitTime.updateAverage(time); + const float MAX_SHORT_TIME = 10.0f; + const float MAX_LONG_TIME = 100.0f; + if (time <= MAX_SHORT_TIME) { + _shortTreeWait++; + _averageTreeShortWaitTime.updateAverage(time); + } else if (time <= MAX_LONG_TIME) { + _longTreeWait++; + _averageTreeLongWaitTime.updateAverage(time); + } else { + _extraLongTreeWait++; + _averageTreeExtraLongWaitTime.updateAverage(time); + } +} + void OctreeServer::attachQueryNodeToNode(Node* newNode) { if (!newNode->getLinkedData()) { @@ -124,6 +165,7 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QString& showStats = true; } else if (path == "/resetStats") { _octreeInboundPacketProcessor->resetStats(); + resetSendingStats(); showStats = true; } } @@ -258,7 +300,9 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QString& statsString += "\r\n"; // display outbound packet stats - statsString += QString("%1 Outbound Packet Statistics...\r\n").arg(getMyServerName()); + statsString += QString("%1 Outbound Packet Statistics... " + "[RESET]\r\n").arg(getMyServerName()); + quint64 totalOutboundPackets = OctreeSendThread::_totalPackets; quint64 totalOutboundBytes = OctreeSendThread::_totalBytes; quint64 totalWastedBytes = OctreeSendThread::_totalWastedBytes; @@ -266,7 +310,7 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QString& quint64 totalBytesOfBitMasks = OctreePacketData::getTotalBytesOfBitMasks(); quint64 totalBytesOfColor = OctreePacketData::getTotalBytesOfColor(); - const int COLUMN_WIDTH = 10; + const int COLUMN_WIDTH = 19; 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") @@ -275,45 +319,66 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QString& .arg(locale.toString((uint)getCurrentClientCount()).rightJustified(COLUMN_WIDTH, ' ')); float averageLoopTime = getAverageLoopTime(); - statsString += QString().sprintf(" Average packetLoop() time: %5.2f msecs\r\n", averageLoopTime); + statsString += QString().sprintf(" Average packetLoop() time: %5.2f msecs\r\n", averageLoopTime); qDebug() << "averageLoopTime=" << averageLoopTime; float averageInsideTime = getAverageInsideTime(); - statsString += QString().sprintf(" Average 'inside' time: %7.2f usecs\r\n", averageInsideTime); + statsString += QString().sprintf(" Average 'inside' time: %7.2f usecs\r\n", averageInsideTime); qDebug() << "averageInsideTime=" << averageInsideTime; + int allWaitTimes = _extraLongTreeWait +_longTreeWait + _shortTreeWait; + float averageTreeWaitTime = getAverageTreeWaitTime(); - statsString += QString().sprintf(" Average tree lock wait time: %7.2f usecs\r\n", averageTreeWaitTime); + statsString += QString().sprintf(" Average tree lock wait time: %7.2f usecs samples: %12d \r\n", + averageTreeWaitTime, allWaitTimes); qDebug() << "averageTreeWaitTime=" << averageTreeWaitTime; + float shortVsTotal = (allWaitTimes > 0) ? ((float)_shortTreeWait / (float)allWaitTimes) : 0.0f; + statsString += QString().sprintf(" Avg tree lock short wait time: %7.2f usecs (%6.2f%%) samples: %12d \r\n", + _averageTreeShortWaitTime.getAverage(), + shortVsTotal * AS_PERCENT, _shortTreeWait); + qDebug() << "averageTreeShortWaitTime=" << _averageTreeShortWaitTime.getAverage(); + + float longVsTotal = (allWaitTimes > 0) ? ((float)_longTreeWait / (float)allWaitTimes) : 0.0f; + statsString += QString().sprintf(" Avg tree lock long wait time: %7.2f usecs (%6.2f%%) samples: %12d \r\n", + _averageTreeLongWaitTime.getAverage(), + longVsTotal * AS_PERCENT, _longTreeWait); + qDebug() << "averageTreeLongWaitTime=" << _averageTreeLongWaitTime.getAverage(); + + float extraLongVsTotal = (allWaitTimes > 0) ? ((float)_extraLongTreeWait / (float)allWaitTimes) : 0.0f; + statsString += QString().sprintf("Avg tree lock extra long wait time: %7.2f usecs (%6.2f%%) samples: %12d \r\n", + _averageTreeExtraLongWaitTime.getAverage(), + extraLongVsTotal * AS_PERCENT, _extraLongTreeWait); + qDebug() << "averageTreeExtraLongWaitTime=" << _averageTreeExtraLongWaitTime.getAverage(); + float averageEncodeTime = getAverageEncodeTime(); - statsString += QString().sprintf(" Average encode time: %7.2f usecs\r\n", averageEncodeTime); + statsString += QString().sprintf(" Average encode time: %7.2f usecs\r\n", averageEncodeTime); qDebug() << "averageEncodeTime=" << averageEncodeTime; float averageCompressAndWriteTime = getAverageCompressAndWriteTime(); - statsString += QString().sprintf(" Average compress and write time: %7.2f usecs\r\n", averageCompressAndWriteTime); + statsString += QString().sprintf(" Average compress and write time: %7.2f usecs\r\n", averageCompressAndWriteTime); qDebug() << "averageCompressAndWriteTime=" << averageCompressAndWriteTime; float averagePacketSendingTime = getAveragePacketSendingTime(); - statsString += QString().sprintf(" Average packet sending time: %7.2f usecs (includes node lock)\r\n", + statsString += QString().sprintf(" Average packet sending time: %7.2f usecs (includes node lock)\r\n", averagePacketSendingTime); qDebug() << "averagePacketSendingTime=" << averagePacketSendingTime; float averageNodeWaitTime = getAverageNodeWaitTime(); - statsString += QString().sprintf(" Average node lock wait time: %7.2f usecs\r\n", averageNodeWaitTime); + statsString += QString().sprintf(" Average node lock wait time: %7.2f usecs\r\n", averageNodeWaitTime); qDebug() << "averageNodeWaitTime=" << averageNodeWaitTime; - statsString += QString().sprintf("---------------------------------------------------\r\n"); + statsString += QString().sprintf("----------------------------------------------------\r\n"); float encodeToInsidePercent = averageInsideTime == 0.0f ? 0.0f : (averageEncodeTime / averageInsideTime) * AS_PERCENT; - statsString += QString().sprintf(" encode ratio: %5.2f%%\r\n", + statsString += QString().sprintf(" encode ratio: %5.2f%%\r\n", encodeToInsidePercent); qDebug() << "encodeToInsidePercent=" << encodeToInsidePercent; float waitToInsidePercent = averageInsideTime == 0.0f ? 0.0f : ((averageTreeWaitTime + averageNodeWaitTime) / averageInsideTime) * AS_PERCENT; - statsString += QString().sprintf(" waiting ratio: %5.2f%%\r\n", waitToInsidePercent); + statsString += QString().sprintf(" waiting ratio: %5.2f%%\r\n", waitToInsidePercent); qDebug() << "waitToInsidePercent=" << waitToInsidePercent; @@ -761,6 +826,7 @@ void OctreeServer::run() { void OctreeServer::nodeAdded(SharedNodePointer node) { // we might choose to use this notifier to track clients in a pending state + qDebug() << "OctreeServer::nodeAdded() node:" << *node; } void OctreeServer::nodeKilled(SharedNodePointer node) { diff --git a/assignment-client/src/octree/OctreeServer.h b/assignment-client/src/octree/OctreeServer.h index 022da9d658..636ecb8365 100644 --- a/assignment-client/src/octree/OctreeServer.h +++ b/assignment-client/src/octree/OctreeServer.h @@ -83,8 +83,9 @@ public: static void trackInsideTime(float time) { _averageInsideTime.updateAverage(time); } static float getAverageInsideTime() { return _averageInsideTime.getAverage(); } - static void trackTreeWaitTime(float time) { _averageTreeWaitTime.updateAverage(time); } + static void trackTreeWaitTime(float time); static float getAverageTreeWaitTime() { return _averageTreeWaitTime.getAverage(); } + static void trackNodeWaitTime(float time) { _averageNodeWaitTime.updateAverage(time); } static float getAverageNodeWaitTime() { return _averageNodeWaitTime.getAverage(); } @@ -95,6 +96,7 @@ public: static float getAveragePacketSendingTime() { return _averagePacketSendingTime.getAverage(); } bool handleHTTPRequest(HTTPConnection* connection, const QString& path); + public slots: /// runs the voxel server assignment void run(); @@ -105,6 +107,7 @@ public slots: protected: void parsePayload(); void initHTTPManager(int port); + void resetSendingStats(); int _argc; const char** _argv; @@ -135,9 +138,15 @@ protected: static SimpleMovingAverage _averageEncodeTime; static SimpleMovingAverage _averageInsideTime; static SimpleMovingAverage _averageTreeWaitTime; + static SimpleMovingAverage _averageTreeShortWaitTime; + static SimpleMovingAverage _averageTreeLongWaitTime; + static SimpleMovingAverage _averageTreeExtraLongWaitTime; static SimpleMovingAverage _averageNodeWaitTime; static SimpleMovingAverage _averageCompressAndWriteTime; static SimpleMovingAverage _averagePacketSendingTime; + static int _extraLongTreeWait; + static int _longTreeWait; + static int _shortTreeWait; }; #endif // __octree_server__OctreeServer__