From 5f6fb3a3aeff6df71571a982dd00f7dfe25c7f2f Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Sat, 5 Oct 2013 00:55:34 -0700 Subject: [PATCH] added some timing debugging --- interface/src/Application.cpp | 46 ++++++++++++++++++++++++-- interface/src/Menu.cpp | 2 ++ interface/src/Menu.h | 2 ++ interface/src/VoxelPacketProcessor.cpp | 9 +++-- interface/src/VoxelSystem.cpp | 4 +++ libraries/shared/src/PerfStat.cpp | 13 ++++++-- libraries/shared/src/PerfStat.h | 3 ++ 7 files changed, 71 insertions(+), 8 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 615fcfaa01..6d7686328f 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -324,6 +324,8 @@ void Application::initializeGL() { } void Application::paintGL() { + PerformanceWarning::setSuppressShortTimings(Menu::getInstance()->isOptionChecked(MenuOption::SuppressShortTimings)); + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::paintGL()"); PerfStat("display"); glEnable(GL_LINE_SMOOTH); @@ -1181,6 +1183,7 @@ void Application::idle() { double timeSinceLastUpdate = diffclock(&_lastTimeUpdated, &check); if (timeSinceLastUpdate > IDLE_SIMULATE_MSECS) { + const float BIGGEST_DELTA_TIME_SECS = 0.25f; update(glm::clamp((float)timeSinceLastUpdate / 1000.f, 0.f, BIGGEST_DELTA_TIME_SECS)); _glWidget->updateGL(); @@ -2379,6 +2382,7 @@ void Application::computeOffAxisFrustum(float& left, float& right, float& bottom } void Application::displaySide(Camera& whichCamera) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide()"); // transform by eye offset // flip x if in mirror mode (also requires reversing winding order for backface culling) @@ -2410,6 +2414,8 @@ void Application::displaySide(Camera& whichCamera) { setupWorldLight(whichCamera); if (Menu::getInstance()->isOptionChecked(MenuOption::Stars)) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... stars..."); if (!_stars.getFileLoaded()) { _stars.readInput(STAR_FILE, STAR_CACHE_FILE, 0); } @@ -2435,6 +2441,8 @@ void Application::displaySide(Camera& whichCamera) { // draw the sky dome if (Menu::getInstance()->isOptionChecked(MenuOption::Atmosphere)) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... atmosphere..."); _environment.renderAtmospheres(whichCamera); } @@ -2457,6 +2465,9 @@ void Application::displaySide(Camera& whichCamera) { //draw a grid ground plane.... if (Menu::getInstance()->isOptionChecked(MenuOption::GroundPlane)) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... ground plane..."); + // draw grass plane with fog glEnable(GL_FOG); glEnable(GL_NORMALIZE); @@ -2480,7 +2491,11 @@ void Application::displaySide(Camera& whichCamera) { } // Draw voxels if (Menu::getInstance()->isOptionChecked(MenuOption::Voxels)) { - _voxels.render(Menu::getInstance()->isOptionChecked(MenuOption::VoxelTextures)); + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... voxels..."); + if (!Menu::getInstance()->isOptionChecked(MenuOption::DontRenderVoxels)) { + _voxels.render(Menu::getInstance()->isOptionChecked(MenuOption::VoxelTextures)); + } } // restore default, white specular @@ -2488,6 +2503,9 @@ void Application::displaySide(Camera& whichCamera) { // indicate what we'll be adding/removing in mouse mode, if anything if (_mouseVoxel.s != 0) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... voxels TOOLS UX..."); + glDisable(GL_LIGHTING); glPushMatrix(); glScalef(TREE_SCALE, TREE_SCALE, TREE_SCALE); @@ -2533,6 +2551,9 @@ void Application::displaySide(Camera& whichCamera) { } if (Menu::getInstance()->isOptionChecked(MenuOption::VoxelSelectMode) && _pasteMode) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... PASTE Preview..."); + glPushMatrix(); glTranslatef(_mouseVoxel.x * TREE_SCALE, _mouseVoxel.y * TREE_SCALE, @@ -2548,6 +2569,10 @@ void Application::displaySide(Camera& whichCamera) { _myAvatar.renderScreenTint(SCREEN_TINT_BEFORE_AVATARS, whichCamera); if (Menu::getInstance()->isOptionChecked(MenuOption::Avatars)) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... Avatars..."); + + // Render avatars of other nodes NodeList* nodeList = NodeList::getInstance(); @@ -2592,16 +2617,22 @@ void Application::displaySide(Camera& whichCamera) { // render the ambient occlusion effect if enabled if (Menu::getInstance()->isOptionChecked(MenuOption::AmbientOcclusion)) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... AmbientOcclusion..."); _ambientOcclusionEffect.render(); } // brad's frustum for debugging if (Menu::getInstance()->isOptionChecked(MenuOption::DisplayFrustum)) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... renderViewFrustum..."); renderViewFrustum(_viewFrustum); } // render voxel fades if they exist if (_voxelFades.size() > 0) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... voxel fades..."); for(std::vector::iterator fade = _voxelFades.begin(); fade != _voxelFades.end();) { fade->render(); if(fade->isDone()) { @@ -2611,11 +2642,18 @@ void Application::displaySide(Camera& whichCamera) { } } } - - renderFollowIndicator(); + + { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... renderFollowIndicator..."); + renderFollowIndicator(); + } // render transmitter pick ray, if non-empty if (_transmitterPickStart != _transmitterPickEnd) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "Application::displaySide() ... transmitter pick ray..."); + Glower glower; const float TRANSMITTER_PICK_COLOR[] = { 1.0f, 1.0f, 0.0f }; glColor3fv(TRANSMITTER_PICK_COLOR); @@ -2637,6 +2675,8 @@ void Application::displaySide(Camera& whichCamera) { } void Application::displayOverlay() { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displayOverlay()"); + // Render 2D overlay: I/O level bar graphs and text glMatrixMode(GL_PROJECTION); glPushMatrix(); diff --git a/interface/src/Menu.cpp b/interface/src/Menu.cpp index 4ff97a39f1..ededcbccd0 100644 --- a/interface/src/Menu.cpp +++ b/interface/src/Menu.cpp @@ -239,6 +239,7 @@ Menu::Menu() : true, appInstance, SLOT(setRenderVoxels(bool))); + addCheckableActionToQMenuAndActionHash(voxelOptionsMenu, MenuOption::DontRenderVoxels); addCheckableActionToQMenuAndActionHash(voxelOptionsMenu, MenuOption::VoxelTextures); addCheckableActionToQMenuAndActionHash(voxelOptionsMenu, MenuOption::AmbientOcclusion); addCheckableActionToQMenuAndActionHash(voxelOptionsMenu, MenuOption::UseVoxelShader, 0, @@ -346,6 +347,7 @@ Menu::Menu() : QMenu* renderDebugMenu = developerMenu->addMenu("Render Debugging Tools"); addCheckableActionToQMenuAndActionHash(renderDebugMenu, MenuOption::PipelineWarnings); + addCheckableActionToQMenuAndActionHash(renderDebugMenu, MenuOption::SuppressShortTimings); addActionToQMenuAndActionHash(renderDebugMenu, MenuOption::KillLocalVoxels, diff --git a/interface/src/Menu.h b/interface/src/Menu.h index d72a0397e8..5c21a35b35 100644 --- a/interface/src/Menu.h +++ b/interface/src/Menu.h @@ -138,6 +138,7 @@ namespace MenuOption { const QString DestructiveAddVoxel = "Create Voxel is Destructive"; const QString DeltaSending = "Delta Sending"; const QString DisplayFrustum = "Display Frustum"; + const QString DontRenderVoxels = "Don't Render Voxels"; const QString EchoAudio = "Echo Audio"; const QString ExportVoxels = "Export Voxels"; const QString HeadMouse = "Head Mouse"; @@ -193,6 +194,7 @@ namespace MenuOption { const QString ShowTrueColors = "Show TRUE Colors"; const QString SimulateLeapHand = "Simulate Leap Hand"; const QString SkeletonTracking = "Skeleton Tracking"; + const QString SuppressShortTimings = "Suppress Timings Less than 10ms"; const QString LEDTracking = "LED Tracking"; const QString Stars = "Stars"; const QString Stats = "Stats"; diff --git a/interface/src/VoxelPacketProcessor.cpp b/interface/src/VoxelPacketProcessor.cpp index 5d05253e36..8dc5092a64 100644 --- a/interface/src/VoxelPacketProcessor.cpp +++ b/interface/src/VoxelPacketProcessor.cpp @@ -47,15 +47,18 @@ void VoxelPacketProcessor::processPacket(sockaddr& senderAddress, unsigned char* if (Menu::getInstance()->isOptionChecked(MenuOption::Voxels)) { Node* voxelServer = NodeList::getInstance()->nodeWithAddress(&senderAddress); if (voxelServer && socketMatch(voxelServer->getActiveSocket(), &senderAddress)) { - voxelServer->lock(); + + voxelServer->lock(); // do we really need to lock this? just to get the ID? + int nodeID = voxelServer->getNodeID(); + voxelServer->unlock(); + if (packetData[0] == PACKET_TYPE_ENVIRONMENT_DATA) { app->_environment.parseData(&senderAddress, packetData, messageLength); } else { - app->_voxels.setDataSourceID(voxelServer->getNodeID()); + app->_voxels.setDataSourceID(nodeID); app->_voxels.parseData(packetData, messageLength); app->_voxels.setDataSourceID(UNKNOWN_NODE_ID); } - voxelServer->unlock(); } } } diff --git a/interface/src/VoxelSystem.cpp b/interface/src/VoxelSystem.cpp index a83914ed96..f0d6777053 100644 --- a/interface/src/VoxelSystem.cpp +++ b/interface/src/VoxelSystem.cpp @@ -1077,6 +1077,8 @@ void VoxelSystem::render(bool texture) { updateVBOs(); if (_useVoxelShader) { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), + "render().. _useVoxelShader openGL.."); Application::getInstance()->getVoxelShader().begin(); @@ -1106,6 +1108,8 @@ void VoxelSystem::render(bool texture) { Application::getInstance()->getVoxelShader().end(); } else { + PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "render().. openGL..."); + // tell OpenGL where to find vertex and color information glEnableClientState(GL_VERTEX_ARRAY); glEnableClientState(GL_COLOR_ARRAY); diff --git a/libraries/shared/src/PerfStat.cpp b/libraries/shared/src/PerfStat.cpp index 5199c09937..31f4b1a30b 100644 --- a/libraries/shared/src/PerfStat.cpp +++ b/libraries/shared/src/PerfStat.cpp @@ -103,6 +103,7 @@ int PerfStat::DumpStats(char** array) { return lineCount; } +bool PerformanceWarning::_suppressShortTimings = false; // Destructor handles recording all of our stats PerformanceWarning::~PerformanceWarning() { @@ -111,9 +112,17 @@ PerformanceWarning::~PerformanceWarning() { if ((_alwaysDisplay || _renderWarningsOn) && elapsedmsec > 1) { if (elapsedmsec > 1000) { double elapsedsec = (end - _start) / 1000000.0; - qDebug("%s%s took %lf seconds\n", (_alwaysDisplay ? "" : "WARNING!"), _message, elapsedsec); + qDebug("%s took %lf seconds %s\n", _message, elapsedsec, (_alwaysDisplay ? "" : "WARNING!") ); } else { - qDebug("%s%s took %lf milliseconds\n", (_alwaysDisplay ? "" : "WARNING!"), _message, elapsedmsec); + if (_suppressShortTimings) { + if (elapsedmsec > 10) { + qDebug("%s took %lf milliseconds %s\n", _message, elapsedmsec, + (_alwaysDisplay || (elapsedmsec < 10) ? "" : "WARNING!")); + } + } else { + qDebug("%s took %lf milliseconds %s\n", _message, elapsedmsec, + (_alwaysDisplay || (elapsedmsec < 10) ? "" : "WARNING!")); + } } } else if (_alwaysDisplay) { qDebug("%s took %lf milliseconds\n", _message, elapsedmsec); diff --git a/libraries/shared/src/PerfStat.h b/libraries/shared/src/PerfStat.h index 320da3d280..2c5924e5ce 100644 --- a/libraries/shared/src/PerfStat.h +++ b/libraries/shared/src/PerfStat.h @@ -89,6 +89,7 @@ private: const char* _message; bool _renderWarningsOn; bool _alwaysDisplay; + static bool _suppressShortTimings; public: PerformanceWarning(bool renderWarnings, const char* message, bool alwaysDisplay = false) : _start(usecTimestampNow()), @@ -97,6 +98,8 @@ public: _alwaysDisplay(alwaysDisplay) { } ~PerformanceWarning(); + + static void setSuppressShortTimings(bool suppressShortTimings) { _suppressShortTimings = suppressShortTimings; } };