From 485c603d4fe8dbd0bedc8ac2dec717cece2e7076 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Wed, 3 Jul 2013 12:42:34 -0700 Subject: [PATCH 1/3] added some timing debugging, and bail early if voxel server is slow --- voxel-server/src/VoxelAgentData.cpp | 3 ++- voxel-server/src/VoxelAgentData.h | 5 ++++ voxel-server/src/main.cpp | 38 +++++++++++++++++++++++++++-- 3 files changed, 43 insertions(+), 3 deletions(-) diff --git a/voxel-server/src/VoxelAgentData.cpp b/voxel-server/src/VoxelAgentData.cpp index 289b1161e6..98990011da 100644 --- a/voxel-server/src/VoxelAgentData.cpp +++ b/voxel-server/src/VoxelAgentData.cpp @@ -16,7 +16,8 @@ VoxelAgentData::VoxelAgentData(Agent* owningAgent) : _viewSent(false), _voxelPacketAvailableBytes(MAX_VOXEL_PACKET_SIZE), _maxSearchLevel(1), - _maxLevelReachedInLastSearch(1) + _maxLevelReachedInLastSearch(1), + _lastTimeBagEmpty(0) { _voxelPacket = new unsigned char[MAX_VOXEL_PACKET_SIZE]; _voxelPacketAt = _voxelPacket; diff --git a/voxel-server/src/VoxelAgentData.h b/voxel-server/src/VoxelAgentData.h index 6606530b94..e26b85151c 100644 --- a/voxel-server/src/VoxelAgentData.h +++ b/voxel-server/src/VoxelAgentData.h @@ -50,6 +50,10 @@ public: bool getViewSent() const { return _viewSent; }; void setViewSent(bool viewSent) { _viewSent = viewSent; } + long long getLastTimeBagEmpty() const { return _lastTimeBagEmpty; }; + void setLastTimeBagEmpty(long long now) { _lastTimeBagEmpty = now; }; + + private: VoxelAgentData(const VoxelAgentData &); VoxelAgentData& operator= (const VoxelAgentData&); @@ -63,6 +67,7 @@ private: int _maxLevelReachedInLastSearch; ViewFrustum _currentViewFrustum; ViewFrustum _lastKnownViewFrustum; + long long _lastTimeBagEmpty; }; diff --git a/voxel-server/src/main.cpp b/voxel-server/src/main.cpp index a73a8dd09a..e21f46f6ca 100644 --- a/voxel-server/src/main.cpp +++ b/voxel-server/src/main.cpp @@ -46,6 +46,7 @@ const float MAX_CUBE = 0.05f; const int VOXEL_SEND_INTERVAL_USECS = 100 * 1000; int PACKETS_PER_CLIENT_PER_INTERVAL = 30; +const int SENDING_TIME_TO_SPARE = 20 * 1000; // usec of sending interval to spare for calculating voxels const int MAX_VOXEL_TREE_DEPTH_LEVELS = 4; @@ -263,6 +264,23 @@ void deepestLevelVoxelDistributor(AgentList* agentList, // If the current view frustum has changed OR we have nothing to send, then search against // the current view frustum for things to send. if (viewFrustumChanged || agentData->nodeBag.isEmpty()) { + if (::debugVoxelSending) { + printf("(viewFrustumChanged=%s || agentData->nodeBag.isEmpty() =%s)...\n", + debug::valueOf(viewFrustumChanged),debug::valueOf(agentData->nodeBag.isEmpty())); + long long now = usecTimestampNow(); + if (agentData->getLastTimeBagEmpty() > 0) { + float elapsedSceneSend = (now - agentData->getLastTimeBagEmpty()) / 1000000.0f; + printf(" elapsed time to send scene = %f seconds\n", elapsedSceneSend); + } + agentData->setLastTimeBagEmpty(now); + } + + // if our view has changed, we need to reset these things... + if (viewFrustumChanged) { + agentData->nodeBag.deleteAll(); + agentData->map.erase(); + } + // For now, we're going to disable the "search for colored nodes" because that strategy doesn't work when we support // deletion of nodes. Instead if we just start at the root we get the correct behavior we want. We are keeping this @@ -310,6 +328,22 @@ void deepestLevelVoxelDistributor(AgentList* agentList, bool shouldSendEnvironments = shouldDo(ENVIRONMENT_SEND_INTERVAL_USECS, VOXEL_SEND_INTERVAL_USECS); while (packetsSentThisInterval < PACKETS_PER_CLIENT_PER_INTERVAL - (shouldSendEnvironments ? 1 : 0)) { + + // Check to see if we're taking too long, and if so bail early... + long long now = usecTimestampNow(); + long elapsedUsec = (now - start); + long elapsedUsecPerPacket = (truePacketsSent == 0) ? 0 : (elapsedUsec / truePacketsSent); + long usecRemaining = (VOXEL_SEND_INTERVAL_USECS - elapsedUsec); + + if (elapsedUsecPerPacket + SENDING_TIME_TO_SPARE > usecRemaining) { + if (::debugVoxelSending) { + printf("packetLoop() usecRemaining=%ld bailing early took %ld usecs to generate %d bytes in %d packets (%ld usec avg), %d nodes still to send\n", + usecRemaining, elapsedUsec, trueBytesSent, truePacketsSent, elapsedUsecPerPacket, + agentData->nodeBag.count()); + } + break; + } + if (!agentData->nodeBag.isEmpty()) { VoxelNode* subTree = agentData->nodeBag.extract(); @@ -322,7 +356,7 @@ void deepestLevelVoxelDistributor(AgentList* agentList, bytesWritten = serverTree.encodeTreeBitstream(subTree, &tempOutputBuffer[0], MAX_VOXEL_PACKET_SIZE - 1, agentData->nodeBag, params); - + if (agentData->getAvailable() >= bytesWritten) { agentData->writeToPacket(&tempOutputBuffer[0], bytesWritten); } else { @@ -379,7 +413,7 @@ void deepestLevelVoxelDistributor(AgentList* agentList, if (agentData->nodeBag.isEmpty()) { agentData->updateLastKnownViewFrustum(); agentData->setViewSent(true); - agentData->map.erase(); + agentData->map.erase(); // It would be nice if we could save this, and only reset it when the view frustum changes } From 2fffb15d947b7f71f61f8bf3f07ce5b27fa77637 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Wed, 3 Jul 2013 14:43:01 -0700 Subject: [PATCH 2/3] CR feedback --- voxel-server/src/VoxelAgentData.h | 4 ++-- voxel-server/src/main.cpp | 2 +- 2 files changed, 3 insertions(+), 3 deletions(-) diff --git a/voxel-server/src/VoxelAgentData.h b/voxel-server/src/VoxelAgentData.h index e26b85151c..f7e04329a0 100644 --- a/voxel-server/src/VoxelAgentData.h +++ b/voxel-server/src/VoxelAgentData.h @@ -50,8 +50,8 @@ public: bool getViewSent() const { return _viewSent; }; void setViewSent(bool viewSent) { _viewSent = viewSent; } - long long getLastTimeBagEmpty() const { return _lastTimeBagEmpty; }; - void setLastTimeBagEmpty(long long now) { _lastTimeBagEmpty = now; }; + long long getLastTimeBagEmpty() const { return _lastTimeBagEmpty; }; + void setLastTimeBagEmpty(long long lastTimeBagEmpty) { _lastTimeBagEmpty = lastTimeBagEmpty; }; private: diff --git a/voxel-server/src/main.cpp b/voxel-server/src/main.cpp index e21f46f6ca..ca7240b03c 100644 --- a/voxel-server/src/main.cpp +++ b/voxel-server/src/main.cpp @@ -266,7 +266,7 @@ void deepestLevelVoxelDistributor(AgentList* agentList, if (viewFrustumChanged || agentData->nodeBag.isEmpty()) { if (::debugVoxelSending) { printf("(viewFrustumChanged=%s || agentData->nodeBag.isEmpty() =%s)...\n", - debug::valueOf(viewFrustumChanged),debug::valueOf(agentData->nodeBag.isEmpty())); + debug::valueOf(viewFrustumChanged), debug::valueOf(agentData->nodeBag.isEmpty())); long long now = usecTimestampNow(); if (agentData->getLastTimeBagEmpty() > 0) { float elapsedSceneSend = (now - agentData->getLastTimeBagEmpty()) / 1000000.0f; From 430c70875dad64d76cf03f3635548642891e966d Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Wed, 3 Jul 2013 14:40:59 -0700 Subject: [PATCH 3/3] tweaks to debug messages (cherry picked from commit 873144ded360112d26c77f6426905f6ac3b27658) --- voxel-server/src/main.cpp | 8 +++++++- 1 file changed, 7 insertions(+), 1 deletion(-) diff --git a/voxel-server/src/main.cpp b/voxel-server/src/main.cpp index ca7240b03c..af7f321d5e 100644 --- a/voxel-server/src/main.cpp +++ b/voxel-server/src/main.cpp @@ -270,7 +270,13 @@ void deepestLevelVoxelDistributor(AgentList* agentList, long long now = usecTimestampNow(); if (agentData->getLastTimeBagEmpty() > 0) { float elapsedSceneSend = (now - agentData->getLastTimeBagEmpty()) / 1000000.0f; - printf(" elapsed time to send scene = %f seconds\n", elapsedSceneSend); + + if (viewFrustumChanged) { + printf("viewFrustumChanged resetting after elapsed time to send scene = %f seconds", elapsedSceneSend); + } else { + printf("elapsed time to send scene = %f seconds", elapsedSceneSend); + } + printf(" [occlusionCulling: %s]\n", debug::valueOf(agentData->getWantOcclusionCulling())); } agentData->setLastTimeBagEmpty(now); }