From af8438b098b8eeb7e11241406f4751735c1f9d80 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Mon, 11 Nov 2013 16:31:36 -0800 Subject: [PATCH] add stats to voxel server to show average voxel edit packet statistics --- .../voxel-server-library/src/VoxelServer.cpp | 110 +++++++++++++----- .../src/VoxelServerPacketProcessor.cpp | 59 +++++++++- .../src/VoxelServerPacketProcessor.h | 22 ++++ libraries/voxels/src/JurisdictionMap.cpp | 2 +- libraries/voxels/src/JurisdictionMap.h | 2 +- .../voxels/src/VoxelEditPacketSender.cpp | 2 +- 6 files changed, 159 insertions(+), 38 deletions(-) diff --git a/libraries/voxel-server-library/src/VoxelServer.cpp b/libraries/voxel-server-library/src/VoxelServer.cpp index 1ce0bcd59d..320e2c7de0 100644 --- a/libraries/voxel-server-library/src/VoxelServer.cpp +++ b/libraries/voxel-server-library/src/VoxelServer.cpp @@ -128,15 +128,26 @@ int VoxelServer::civetwebRequestHandler(struct mg_connection* connection) { return 1; } #endif - + + bool showStats = false; if (strcmp(ri->uri, "/") == 0 && strcmp(ri->request_method, "GET") == 0) { + showStats = true; + } + + if (strcmp(ri->uri, "/resetStats") == 0 && strcmp(ri->request_method, "GET") == 0) { + GetInstance()->_voxelServerPacketProcessor->resetStats(); + showStats = true; + } + + if (showStats) { uint64_t checkSum; // return a 200 - mg_printf(connection, "%s", "HTTP/1.0 200 OK\r\n\r\n"); - mg_printf(connection, "%s", "Your Voxel Server is running.\r\n"); + mg_printf(connection, "%s", "HTTP/1.0 200 OK\r\n"); + mg_printf(connection, "%s", "Content-Type: text/html\r\n\r\n"); + mg_printf(connection, "%s", "\r\n"); + mg_printf(connection, "%s", "
\r\n");
+        mg_printf(connection, "%s", "Your Voxel Server is running... [RELOAD]\r\n");
 
-
-        mg_printf(connection, "%s", "\r\n");
         tm* localtm = localtime(&GetInstance()->_started);
         const int MAX_TIME_LENGTH = 128;
         char buffer[MAX_TIME_LENGTH];
@@ -206,7 +217,7 @@ int VoxelServer::civetwebRequestHandler(struct mg_connection* connection) {
             if (minutes > 0) {
                 mg_printf(connection, "%d minute%s ", minutes, (minutes > 1) ? "s" : "");
             }
-            if (seconds > 0) {
+            if (seconds >= 0) {
                 mg_printf(connection, "%.3f seconds", seconds);
             }
             mg_printf(connection, "%s", "\r\n");
@@ -218,15 +229,70 @@ int VoxelServer::civetwebRequestHandler(struct mg_connection* connection) {
         mg_printf(connection, "%s", "\r\n");
 
         mg_printf(connection, "%s", "\r\n");
-        mg_printf(connection, "%s", "Configuration: \r\n     ");
+
+        mg_printf(connection, "%s", "Configuration:\r\n");
+
         for (int i = 1; i < GetInstance()->_argc; i++) {
             mg_printf(connection, "%s ", GetInstance()->_argv[i]);
         }
+        mg_printf(connection, "%s", "\r\n"); // one to end the config line
+        mg_printf(connection, "%s", "\r\n"); // two more for spacing
+        mg_printf(connection, "%s", "\r\n");
+
+        // display scene stats
+        unsigned long nodeCount = VoxelNode::getNodeCount();
+        unsigned long internalNodeCount = VoxelNode::getInternalNodeCount();
+        unsigned long leafNodeCount = VoxelNode::getLeafNodeCount();
+        
+        QLocale locale(QLocale::English);
+        const float AS_PERCENT = 100.0;
+        mg_printf(connection, "%s", "Current Nodes in scene:\r\n");
+        mg_printf(connection, "       Total Nodes: %s nodes\r\n",
+                    locale.toString((uint)nodeCount).rightJustified(16, ' ').toLocal8Bit().constData());
+        mg_printf(connection, "    Internal Nodes: %s nodes (%5.2f%%)\r\n",
+            locale.toString((uint)internalNodeCount).rightJustified(16, ' ').toLocal8Bit().constData(),
+            ((float)internalNodeCount/(float)nodeCount) * AS_PERCENT);
+        mg_printf(connection, "        Leaf Nodes: %s nodes (%5.2f%%)\r\n", 
+            locale.toString((uint)leafNodeCount).rightJustified(16, ' ').toLocal8Bit().constData(),
+            ((float)leafNodeCount/(float)nodeCount) * AS_PERCENT);
         mg_printf(connection, "%s", "\r\n");
         mg_printf(connection, "%s", "\r\n");
 
+        // display inbound packet stats
+        mg_printf(connection, "%s", "Voxel Edit Statistics... [RESET]\r\n");
+        uint64_t averageTransitTimePerPacket = GetInstance()->_voxelServerPacketProcessor->getAverateTransitTimePerPacket();
+        uint64_t averageProcessTimePerPacket = GetInstance()->_voxelServerPacketProcessor->getAverageProcessTimePerPacket();
+        uint64_t averageLockWaitTimePerPacket = GetInstance()->_voxelServerPacketProcessor->getAverageLockWaitTimePerPacket();
+        uint64_t averageProcessTimePerVoxel = GetInstance()->_voxelServerPacketProcessor->getAverageProcessTimePerVoxel();
+        uint64_t averageLockWaitTimePerVoxel = GetInstance()->_voxelServerPacketProcessor->getAverageLockWaitTimePerVoxel();
+        uint64_t totalVoxelsProcessed = GetInstance()->_voxelServerPacketProcessor->getTotalVoxelsProcessed();
+        uint64_t totalPacketsProcessed = GetInstance()->_voxelServerPacketProcessor->getTotalPacketsProcessed();
 
-        mg_printf(connection, "%s", "Current Statistics\r\n");
+        float averageVoxelsPerPacket = totalPacketsProcessed == 0 ? 0 : totalVoxelsProcessed / totalPacketsProcessed;
+
+        const int COLUMN_WIDTH = 10;
+        mg_printf(connection, "           Total Inbound Packets: %s packets\r\n",
+            locale.toString((uint)totalPacketsProcessed).rightJustified(COLUMN_WIDTH, ' ').toLocal8Bit().constData());
+        mg_printf(connection, "            Total Inbound Voxels: %s voxels\r\n",
+            locale.toString((uint)totalVoxelsProcessed).rightJustified(COLUMN_WIDTH, ' ').toLocal8Bit().constData());
+        mg_printf(connection, "   Average Inbound Voxels/Packet: %f voxels/packet\r\n", averageVoxelsPerPacket);
+        mg_printf(connection, "     Average Transit Time/Packet: %s usecs\r\n", 
+            locale.toString((uint)averageTransitTimePerPacket).rightJustified(COLUMN_WIDTH, ' ').toLocal8Bit().constData());
+        mg_printf(connection, "     Average Process Time/Packet: %s usecs\r\n",
+            locale.toString((uint)averageProcessTimePerPacket).rightJustified(COLUMN_WIDTH, ' ').toLocal8Bit().constData());
+        mg_printf(connection, "   Average Wait Lock Time/Packet: %s usecs\r\n", 
+            locale.toString((uint)averageLockWaitTimePerPacket).rightJustified(COLUMN_WIDTH, ' ').toLocal8Bit().constData());
+        mg_printf(connection, "      Average Process Time/Voxel: %s usecs\r\n",
+            locale.toString((uint)averageProcessTimePerVoxel).rightJustified(COLUMN_WIDTH, ' ').toLocal8Bit().constData());
+        mg_printf(connection, "    Average Wait Lock Time/Voxel: %s usecs\r\n", 
+            locale.toString((uint)averageLockWaitTimePerVoxel).rightJustified(COLUMN_WIDTH, ' ').toLocal8Bit().constData());
+
+        mg_printf(connection, "%s", "\r\n");
+        mg_printf(connection, "%s", "\r\n");
+
+        // display memory usage stats
+        mg_printf(connection, "%s", "Current Memory Usage Statistics\r\n");
+        mg_printf(connection, "\r\nVoxelNode size... %ld bytes\r\n", sizeof(VoxelNode));
         mg_printf(connection, "%s", "\r\n");
 
         const char* memoryScaleLabel;
@@ -251,28 +317,6 @@ int VoxelServer::civetwebRequestHandler(struct mg_connection* connection) {
         mg_printf(connection, "                         Total:  %8.2f %s\r\n", 
             VoxelNode::getTotalMemoryUsage() / memoryScale, memoryScaleLabel);
 
-        mg_printf(connection, "\r\nVoxelNode size... %ld bytes\r\n", sizeof(VoxelNode));
-
-        unsigned long nodeCount = VoxelNode::getNodeCount();
-        unsigned long internalNodeCount = VoxelNode::getInternalNodeCount();
-        unsigned long leafNodeCount = VoxelNode::getLeafNodeCount();
-        
-        
-        QLocale locale(QLocale::English);
-
-        const float AS_PERCENT = 100.0;
-
-        mg_printf(connection, "%s", "\r\n");
-        mg_printf(connection, "%s", "Current Nodes in scene\r\n");
-        mg_printf(connection, "       Total Nodes: %s nodes\r\n",
-                    locale.toString((uint)nodeCount).rightJustified(16, ' ').toLocal8Bit().constData());
-        mg_printf(connection, "    Internal Nodes: %s nodes (%5.2f%%)\r\n",
-            locale.toString((uint)internalNodeCount).rightJustified(16, ' ').toLocal8Bit().constData(),
-            ((float)internalNodeCount/(float)nodeCount) * AS_PERCENT);
-        mg_printf(connection, "        Leaf Nodes: %s nodes (%5.2f%%)\r\n", 
-            locale.toString((uint)leafNodeCount).rightJustified(16, ' ').toLocal8Bit().constData(),
-            ((float)leafNodeCount/(float)nodeCount) * AS_PERCENT);
-
         mg_printf(connection, "%s", "\r\n");
         mg_printf(connection, "%s", "VoxelNode Children Population Statistics...\r\n");
         checkSum = 0;
@@ -325,6 +369,12 @@ int VoxelServer::civetwebRequestHandler(struct mg_connection* connection) {
             VoxelNode::getCouldNotStoreFourChildrenInternally());
 #endif
 
+        mg_printf(connection, "%s", "\r\n");
+        mg_printf(connection, "%s", "\r\n");
+        mg_printf(connection, "%s", "
\r\n"); + + mg_printf(connection, "%s", ""); + return 1; } else { // have mongoose process this request from the document_root diff --git a/libraries/voxel-server-library/src/VoxelServerPacketProcessor.cpp b/libraries/voxel-server-library/src/VoxelServerPacketProcessor.cpp index eb96706f12..9d3ffcdc51 100644 --- a/libraries/voxel-server-library/src/VoxelServerPacketProcessor.cpp +++ b/libraries/voxel-server-library/src/VoxelServerPacketProcessor.cpp @@ -15,10 +15,25 @@ #include "VoxelServerConsts.h" #include "VoxelServerPacketProcessor.h" +static QUuid DEFAULT_NODE_ID_REF; VoxelServerPacketProcessor::VoxelServerPacketProcessor(VoxelServer* myServer) : _myServer(myServer), - _receivedPacketCount(0) { + _receivedPacketCount(0), + _totalTransitTime(0), + _totalProcessTime(0), + _totalLockWaitTime(0), + _totalVoxelsInPacket(0), + _totalPackets(0) +{ +} + +void VoxelServerPacketProcessor::resetStats() { + _totalTransitTime = 0; + _totalProcessTime = 0; + _totalLockWaitTime = 0; + _totalVoxelsInPacket = 0; + _totalPackets = 0; } @@ -37,13 +52,16 @@ void VoxelServerPacketProcessor::processPacket(sockaddr& senderAddress, unsigned PerformanceWarning warn(_myServer->wantShowAnimationDebug(), destructive ? "PACKET_TYPE_SET_VOXEL_DESTRUCTIVE" : "PACKET_TYPE_SET_VOXEL", _myServer->wantShowAnimationDebug()); - + _receivedPacketCount++; unsigned short int sequence = (*((unsigned short int*)(packetData + numBytesPacketHeader))); uint64_t sentAt = (*((uint64_t*)(packetData + numBytesPacketHeader + sizeof(sequence)))); uint64_t arrivedAt = usecTimestampNow(); uint64_t transitTime = arrivedAt - sentAt; + int voxelsInPacket = 0; + uint64_t processTime = 0; + uint64_t lockWaitTime = 0; if (_myServer->wantShowAnimationDebug() || _myServer->wantsDebugVoxelReceiving()) { printf("PROCESSING THREAD: got %s - %d command from client receivedBytes=%ld sequence=%d transitTime=%llu usecs\n", @@ -84,9 +102,20 @@ void VoxelServerPacketProcessor::processPacket(sockaddr& senderAddress, unsigned delete[] vertices; } + uint64_t startLock = usecTimestampNow(); _myServer->getServerTree().lockForWrite(); + uint64_t startProcess = usecTimestampNow(); _myServer->getServerTree().readCodeColorBufferToTree(voxelData, destructive); _myServer->getServerTree().unlock(); + uint64_t endProcess = usecTimestampNow(); + + voxelsInPacket++; + + uint64_t thisProcessTime = endProcess - startProcess; + uint64_t thisLockWaitTime = startProcess - startLock; + + processTime += thisProcessTime; + lockWaitTime += thisLockWaitTime; // skip to next voxel edit record in the packet voxelData += voxelDataSize; @@ -104,10 +133,20 @@ void VoxelServerPacketProcessor::processPacket(sockaddr& senderAddress, unsigned } // Make sure our Node and NodeList knows we've heard from this node. - Node* node = NodeList::getInstance()->nodeWithAddress(&senderAddress); - if (node) { - node->setLastHeardMicrostamp(usecTimestampNow()); + Node* senderNode = NodeList::getInstance()->nodeWithAddress(&senderAddress); + QUuid& nodeUUID = DEFAULT_NODE_ID_REF; + if (senderNode) { + senderNode->setLastHeardMicrostamp(usecTimestampNow()); + nodeUUID = senderNode->getUUID(); + if (debugProcessPacket) { + qDebug() << "sender has uuid=" << nodeUUID << "\n"; + } + } else { + if (debugProcessPacket) { + qDebug() << "sender has no known nodeUUID.\n"; + } } + trackInboudPackets(nodeUUID, sequence, transitTime, voxelsInPacket, processTime, lockWaitTime); } else if (packetData[0] == PACKET_TYPE_ERASE_VOXEL) { @@ -167,3 +206,13 @@ void VoxelServerPacketProcessor::processPacket(sockaddr& senderAddress, unsigned } } +void VoxelServerPacketProcessor::trackInboudPackets(const QUuid& nodeUUID, int sequence, uint64_t transitTime, + int voxelsInPacket, uint64_t processTime, uint64_t lockWaitTime) { + + _totalTransitTime += transitTime; + _totalProcessTime += processTime; + _totalLockWaitTime += lockWaitTime; + _totalVoxelsInPacket += voxelsInPacket; + _totalPackets++; +} + diff --git a/libraries/voxel-server-library/src/VoxelServerPacketProcessor.h b/libraries/voxel-server-library/src/VoxelServerPacketProcessor.h index 8ef316bd23..b461c5a664 100644 --- a/libraries/voxel-server-library/src/VoxelServerPacketProcessor.h +++ b/libraries/voxel-server-library/src/VoxelServerPacketProcessor.h @@ -21,11 +21,33 @@ class VoxelServerPacketProcessor : public ReceivedPacketProcessor { public: VoxelServerPacketProcessor(VoxelServer* myServer); + uint64_t getAverateTransitTimePerPacket() const { return _totalPackets == 0 ? 0 : _totalTransitTime / _totalPackets; } + uint64_t getAverageProcessTimePerPacket() const { return _totalPackets == 0 ? 0 : _totalProcessTime / _totalPackets; } + uint64_t getAverageLockWaitTimePerPacket() const { return _totalPackets == 0 ? 0 : _totalLockWaitTime / _totalPackets; } + uint64_t getTotalVoxelsProcessed() const { return _totalVoxelsInPacket; } + uint64_t getTotalPacketsProcessed() const { return _totalPackets; } + uint64_t getAverageProcessTimePerVoxel() const + { return _totalVoxelsInPacket == 0 ? 0 : _totalProcessTime / _totalVoxelsInPacket; } + uint64_t getAverageLockWaitTimePerVoxel() const + { return _totalVoxelsInPacket == 0 ? 0 : _totalLockWaitTime / _totalVoxelsInPacket; } + + void resetStats(); + protected: virtual void processPacket(sockaddr& senderAddress, unsigned char* packetData, ssize_t packetLength); private: + void trackInboudPackets(const QUuid& nodeUUID, int sequence, uint64_t transitTime, + int voxelsInPacket, uint64_t processTime, uint64_t lockWaitTime); + VoxelServer* _myServer; int _receivedPacketCount; + + uint64_t _totalTransitTime; + uint64_t _totalProcessTime; + uint64_t _totalLockWaitTime; + uint64_t _totalVoxelsInPacket; + uint64_t _totalPackets; + }; #endif // __voxel_server__VoxelServerPacketProcessor__ diff --git a/libraries/voxels/src/JurisdictionMap.cpp b/libraries/voxels/src/JurisdictionMap.cpp index c95a71ac75..00e469b03f 100644 --- a/libraries/voxels/src/JurisdictionMap.cpp +++ b/libraries/voxels/src/JurisdictionMap.cpp @@ -229,7 +229,7 @@ bool JurisdictionMap::readFromFile(const char* filename) { return true; } -void JurisdictionMap::displayDebugDetails() { +void JurisdictionMap::displayDebugDetails() const { QString rootNodeValue = octalCodeToHexString(_rootOctalCode); qDebug() << "root:" << rootNodeValue << "\n"; diff --git a/libraries/voxels/src/JurisdictionMap.h b/libraries/voxels/src/JurisdictionMap.h index aafc029253..d412373faf 100644 --- a/libraries/voxels/src/JurisdictionMap.h +++ b/libraries/voxels/src/JurisdictionMap.h @@ -60,7 +60,7 @@ public: /// Available to pack an empty or unknown jurisdiction into a network packet, used when no JurisdictionMap is available static int packEmptyJurisdictionIntoMessage(unsigned char* destinationBuffer, int availableBytes); - void displayDebugDetails(); + void displayDebugDetails() const; private: void copyContents(const JurisdictionMap& other); // use assignment instead diff --git a/libraries/voxels/src/VoxelEditPacketSender.cpp b/libraries/voxels/src/VoxelEditPacketSender.cpp index 1652e22dc5..8ac2b37833 100644 --- a/libraries/voxels/src/VoxelEditPacketSender.cpp +++ b/libraries/voxels/src/VoxelEditPacketSender.cpp @@ -191,7 +191,7 @@ void VoxelEditPacketSender::queuePacketToNodes(unsigned char* buffer, ssize_t le assert(voxelServersExist()); // we must have jurisdictions to be here!! - int headerBytes = numBytesForPacketHeader(buffer) + sizeof(short); + int headerBytes = numBytesForPacketHeader(buffer) + sizeof(short) + sizeof(uint64_t); unsigned char* octCode = buffer + headerBytes; // skip the packet header to get to the octcode // We want to filter out edit messages for voxel servers based on the server's Jurisdiction