From 4c39a891be141c305861c2a67f15ee75cb3e13af Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Fri, 14 Mar 2014 10:23:07 -0700 Subject: [PATCH] add more packet sending statistics to server --- .../src/octree/OctreeSendThread.cpp | 44 +++++++++++++++++-- assignment-client/src/octree/OctreeServer.cpp | 2 +- 2 files changed, 42 insertions(+), 4 deletions(-) diff --git a/assignment-client/src/octree/OctreeSendThread.cpp b/assignment-client/src/octree/OctreeSendThread.cpp index ef69771607..7f75f17252 100644 --- a/assignment-client/src/octree/OctreeSendThread.cpp +++ b/assignment-client/src/octree/OctreeSendThread.cpp @@ -414,6 +414,13 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue int extraPackingAttempts = 0; bool completedScene = false; while (somethingToSend && packetsSentThisInterval < maxPacketsPerInterval) { + float lockWaitElapsedUsec = 0.0f; + float encodeElapsedUsec = 0.0f; + float compressAndWriteElapsedUsec = 0.0f; + float packetSendingElapsedUsec = 0.0f; + + quint64 startInside = usecTimestampNow(); + if (_myServer->wantsDebugSending() && _myServer->wantsVerboseDebug()) { qDebug("truePacketsSent=%d packetsSentThisInterval=%d maxPacketsPerInterval=%d server PPI=%d nodePPS=%d nodePPI=%d", truePacketsSent, packetsSentThisInterval, maxPacketsPerInterval, _myServer->getPacketsPerClientPerInterval(), @@ -442,7 +449,7 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue quint64 lockWaitStart = usecTimestampNow(); _myServer->getOctree()->lockForRead(); quint64 lockWaitEnd = usecTimestampNow(); - float lockWaitElapsedUsec = (float)(lockWaitEnd - lockWaitStart); + lockWaitElapsedUsec = (float)(lockWaitEnd - lockWaitStart); OctreeServer::trackTreeWaitTime(lockWaitElapsedUsec); nodeData->stats.encodeStarted(); @@ -450,8 +457,8 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue quint64 encodeStart = usecTimestampNow(); bytesWritten = _myServer->getOctree()->encodeTreeBitstream(subTree, &_packetData, nodeData->nodeBag, params); quint64 encodeEnd = usecTimestampNow(); - int encodeElapsedMsec = (encodeEnd - encodeStart)/USECS_PER_MSEC; - OctreeServer::trackEncodeTime(encodeElapsedMsec); + encodeElapsedUsec = (encodeEnd - encodeStart)/USECS_PER_MSEC; + 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 @@ -491,6 +498,9 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue // mean we should send the previous packet contents and reset it. if (completedScene || lastNodeDidntFit) { if (_packetData.hasContent()) { + + quint64 compressAndWriteStart = usecTimestampNow(); + // if for some reason the finalized size is greater than our available size, then probably the "compressed" // form actually inflated beyond our padding, and in this case we will send the current packet, then // write to out new packet... @@ -514,11 +524,15 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue } nodeData->writeToPacket(_packetData.getFinalizedData(), _packetData.getFinalizedSize()); extraPackingAttempts = 0; + quint64 compressAndWriteEnd = usecTimestampNow(); + compressAndWriteElapsedUsec = (float)(compressAndWriteEnd - compressAndWriteStart); } // If we're not running compressed, then we know we can just send now. Or if we're running compressed, but // the packet doesn't have enough space to bother attempting to pack more... bool sendNow = true; + + quint64 packetSendingStart = usecTimestampNow(); if (nodeData->getCurrentPacketIsCompressed() && nodeData->getAvailable() >= MINIMUM_ATTEMPT_MORE_PACKING && @@ -549,7 +563,27 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue debug::valueOf(nodeData->getWantCompression()), targetSize); } _packetData.changeSettings(nodeData->getWantCompression(), targetSize); // will do reset + + quint64 packetSendingEnd = usecTimestampNow(); + packetSendingElapsedUsec = (float)(packetSendingEnd - packetSendingStart); } + OctreeServer::trackTreeWaitTime(lockWaitElapsedUsec); + OctreeServer::trackEncodeTime(encodeElapsedUsec); + OctreeServer::trackCompressAndWriteTime(compressAndWriteElapsedUsec); + OctreeServer::trackPacketSendingTime(packetSendingElapsedUsec); + + quint64 endInside = usecTimestampNow(); + quint64 elapsedInsideUsecs = endInside - startInside; + OctreeServer::trackInsideTime((float)elapsedInsideUsecs); + + float insideMsecs = (float)elapsedInsideUsecs / (float)USECS_PER_MSEC; + if (insideMsecs > 1.0f) { + qDebug()<< "inside msecs=" << insideMsecs + << "lockWait usec=" << lockWaitElapsedUsec + << "encode usec=" << encodeElapsedUsec + << "compress usec=" << compressAndWriteElapsedUsec + << "sending usec=" << packetSendingElapsedUsec; + } } @@ -614,6 +648,10 @@ int OctreeSendThread::packetDistributor(const SharedNodePointer& node, OctreeQue } // end if bag wasn't empty, and so we sent stuff... + if (truePacketsSent > 0 || packetsSentThisInterval > 0) { + qDebug() << "truePacketsSent=" << truePacketsSent << "packetsSentThisInterval=" << packetsSentThisInterval; + } + return truePacketsSent; } diff --git a/assignment-client/src/octree/OctreeServer.cpp b/assignment-client/src/octree/OctreeServer.cpp index 6c9e5cf70c..04467c87e6 100644 --- a/assignment-client/src/octree/OctreeServer.cpp +++ b/assignment-client/src/octree/OctreeServer.cpp @@ -302,7 +302,7 @@ bool OctreeServer::handleHTTPRequest(HTTPConnection* connection, const QString& statsString += QString().sprintf(" Average node lock wait time: %7.2f usecs\r\n", averageNodeWaitTime); qDebug() << "averageNodeWaitTime=" << averageNodeWaitTime; - float encodeToInsidePercent = (averageEncodeTime / averageInsideTime) * AS_PERCENT; + float encodeToInsidePercent = averageInsideTime == 0.0f ? 0.0f : (averageEncodeTime / averageInsideTime) * AS_PERCENT; statsString += QString().sprintf(" Percent 'inside' time is encode: %5.2f%%\r\n", encodeToInsidePercent); qDebug() << "averageInsideTime=" << averageInsideTime;