From e6966c2155e0561cf34d343047776f98da7ff35a Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Thu, 29 May 2014 12:12:23 -0700 Subject: [PATCH 1/2] add improved detailed rendering and FPS debugging stats --- interface/src/Application.cpp | 129 ++++++++++++++++++++------ interface/src/Menu.cpp | 9 +- interface/src/Menu.h | 5 + interface/src/renderer/GlowEffect.cpp | 4 + interface/src/ui/Stats.cpp | 73 ++++++++++++++- interface/src/ui/Stats.h | 1 + libraries/shared/src/PerfStat.cpp | 18 ++++ libraries/shared/src/PerfStat.h | 37 ++++++++ 8 files changed, 245 insertions(+), 31 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 4ee15bc949..db6333acee 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -554,6 +554,8 @@ void Application::initializeGL() { } void Application::paintGL() { + PerformanceTimer perfTimer("paintGL"); + PerformanceWarning::setSuppressShortTimings(Menu::getInstance()->isOptionChecked(MenuOption::SuppressShortTimings)); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::paintGL()"); @@ -648,7 +650,10 @@ void Application::paintGL() { _rearMirrorTools->render(true); } - _applicationOverlay.renderOverlay(); + { + PerformanceTimer perfTimer("paintGL/renderOverlay"); + _applicationOverlay.renderOverlay(); + } } _frameCount++; @@ -1288,11 +1293,13 @@ void Application::timer() { } void Application::idle() { + PerformanceTimer perfTimer("idle"); + // Normally we check PipelineWarnings, but since idle will often take more than 10ms we only show these idle timing // details if we're in ExtraDebugging mode. However, the ::update() and it's subcomponents will show their timing // details normally. bool showWarnings = getLogger()->extraDebugging(); - PerformanceWarning warn(showWarnings, "Application::idle()"); + PerformanceWarning warn(showWarnings, "idle()"); // Only run simulation code if more than IDLE_SIMULATE_MSECS have passed since last time we ran @@ -1300,15 +1307,18 @@ void Application::idle() { if (timeSinceLastUpdate > IDLE_SIMULATE_MSECS) { _lastTimeUpdated.start(); { + PerformanceTimer perfTimer("idle/update"); PerformanceWarning warn(showWarnings, "Application::idle()... update()"); const float BIGGEST_DELTA_TIME_SECS = 0.25f; update(glm::clamp((float)timeSinceLastUpdate / 1000.f, 0.f, BIGGEST_DELTA_TIME_SECS)); } { + PerformanceTimer perfTimer("idle/updateGL"); PerformanceWarning warn(showWarnings, "Application::idle()... updateGL()"); _glWidget->updateGL(); } { + PerformanceTimer perfTimer("idle/rest"); PerformanceWarning warn(showWarnings, "Application::idle()... rest of it"); _idleLoopStdev.addValue(timeSinceLastUpdate); @@ -1320,14 +1330,16 @@ void Application::idle() { } if (Menu::getInstance()->isOptionChecked(MenuOption::BuckyBalls)) { + PerformanceTimer perfTimer("idle/rest/_buckyBalls"); _buckyBalls.simulate(timeSinceLastUpdate / 1000.f, Application::getInstance()->getAvatar()->getHandData()); } // After finishing all of the above work, restart the idle timer, allowing 2ms to process events. idleTimer->start(2); - } - if (_numChangedSettings > 0) { - saveSettings(); + + if (_numChangedSettings > 0) { + saveSettings(); + } } } } @@ -1729,6 +1741,7 @@ bool Application::isLookingAtMyAvatar(Avatar* avatar) { } void Application::updateLOD() { + PerformanceTimer perfTimer("idle/update/updateLOD"); // adjust it unless we were asked to disable this feature, or if we're currently in throttleRendering mode if (!Menu::getInstance()->isOptionChecked(MenuOption::DisableAutoAdjustLOD) && !isThrottleRendering()) { Menu::getInstance()->autoAdjustLOD(_fps); @@ -1738,6 +1751,7 @@ void Application::updateLOD() { } void Application::updateMouseRay() { + PerformanceTimer perfTimer("idle/update/updateMouseRay"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateMouseRay()"); @@ -1770,6 +1784,7 @@ void Application::updateMouseRay() { } void Application::updateFaceshift() { + PerformanceTimer perfTimer("idle/update/updateFaceshift"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateFaceshift()"); @@ -1784,6 +1799,7 @@ void Application::updateFaceshift() { } void Application::updateVisage() { + PerformanceTimer perfTimer("idle/update/updateVisage"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateVisage()"); @@ -1793,6 +1809,7 @@ void Application::updateVisage() { } void Application::updateMyAvatarLookAtPosition() { + PerformanceTimer perfTimer("idle/update/updateMyAvatarLookAtPosition"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateMyAvatarLookAtPosition()"); @@ -1858,6 +1875,7 @@ void Application::updateMyAvatarLookAtPosition() { } void Application::updateThreads(float deltaTime) { + PerformanceTimer perfTimer("idle/update/updateThreads"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateThreads()"); @@ -1872,6 +1890,7 @@ void Application::updateThreads(float deltaTime) { } void Application::updateMetavoxels(float deltaTime) { + PerformanceTimer perfTimer("idle/update/updateMetavoxels"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateMetavoxels()"); @@ -1901,6 +1920,7 @@ void Application::cameraMenuChanged() { } void Application::updateCamera(float deltaTime) { + PerformanceTimer perfTimer("idle/update/updateCamera"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateCamera()"); @@ -1918,6 +1938,7 @@ void Application::updateCamera(float deltaTime) { } void Application::updateDialogs(float deltaTime) { + PerformanceTimer perfTimer("idle/update/updateDialogs"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateDialogs()"); @@ -1934,6 +1955,7 @@ void Application::updateDialogs(float deltaTime) { } void Application::updateCursor(float deltaTime) { + PerformanceTimer perfTimer("idle/update/updateCursor"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateCursor()"); @@ -1958,41 +1980,66 @@ void Application::updateCursor(float deltaTime) { } void Application::update(float deltaTime) { + //PerformanceTimer perfTimer("idle/update"); // NOTE: we track this above in Application::idle() + bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::update()"); updateLOD(); - - // check what's under the mouse and update the mouse voxel - updateMouseRay(); - + updateMouseRay(); // check what's under the mouse and update the mouse voxel updateFaceshift(); updateVisage(); - _myAvatar->updateLookAtTargetAvatar(); + + { + PerformanceTimer perfTimer("idle/update/updateLookAtTargetAvatar"); + _myAvatar->updateLookAtTargetAvatar(); + } updateMyAvatarLookAtPosition(); - _sixenseManager.update(deltaTime); - _joystickManager.update(); - _prioVR.update(deltaTime); + { + PerformanceTimer perfTimer("idle/update/sixense,joystick,prioVR"); + _sixenseManager.update(deltaTime); + _joystickManager.update(); + _prioVR.update(deltaTime); + } updateMyAvatar(deltaTime); // Sample hardware, update view frustum if needed, and send avatar data to mixer/nodes updateThreads(deltaTime); // If running non-threaded, then give the threads some time to process... - _avatarManager.updateOtherAvatars(deltaTime); //loop through all the other avatars and simulate them... + { + PerformanceTimer perfTimer("idle/update/_avatarManager"); + _avatarManager.updateOtherAvatars(deltaTime); //loop through all the other avatars and simulate them... + } updateMetavoxels(deltaTime); // update metavoxels updateCamera(deltaTime); // handle various camera tweaks like off axis projection updateDialogs(deltaTime); // update various stats dialogs if present updateCursor(deltaTime); // Handle cursor updates - _particles.update(); // update the particles... - _particleCollisionSystem.update(); // collide the particles... + { + PerformanceTimer perfTimer("idle/update/_particles"); + _particles.update(); // update the particles... + } + { + PerformanceTimer perfTimer("idle/update/_particleCollisionSystem"); + _particleCollisionSystem.update(); // collide the particles... + } - _models.update(); // update the models... + { + PerformanceTimer perfTimer("idle/update/_models"); + _models.update(); // update the models... + } - _overlays.update(deltaTime); + { + PerformanceTimer perfTimer("idle/update/_overlays"); + _overlays.update(deltaTime); + } - // let external parties know we're updating - emit simulating(deltaTime); + { + PerformanceTimer perfTimer("idle/update/emit simulating"); + // let external parties know we're updating + emit simulating(deltaTime); + } } void Application::updateMyAvatar(float deltaTime) { + PerformanceTimer perfTimer("idle/update/updateMyAvatar"); bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings); PerformanceWarning warn(showWarnings, "Application::updateMyAvatar()"); @@ -2253,6 +2300,7 @@ glm::vec3 Application::getSunDirection() { } void Application::updateShadowMap() { + PerformanceTimer perfTimer("pintGL/updateShadowMap"); QOpenGLFramebufferObject* fbo = _textureCache.getShadowFramebufferObject(); fbo->bind(); glEnable(GL_DEPTH_TEST); @@ -2392,6 +2440,7 @@ QImage Application::renderAvatarBillboard() { } void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { + PerformanceTimer perfTimer("paintGL/displaySide"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide()"); // transform by eye offset @@ -2424,9 +2473,13 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { glTranslatef(_viewMatrixTranslation.x, _viewMatrixTranslation.y, _viewMatrixTranslation.z); // Setup 3D lights (after the camera transform, so that they are positioned in world space) - setupWorldLight(); + { + PerformanceTimer perfTimer("paintGL/displaySide/setupWorldLight"); + setupWorldLight(); + } if (!selfAvatarOnly && Menu::getInstance()->isOptionChecked(MenuOption::Stars)) { + PerformanceTimer perfTimer("paintGL/displaySide/stars"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... stars..."); if (!_stars.isStarsLoaded()) { @@ -2455,6 +2508,7 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { // draw the sky dome if (!selfAvatarOnly && Menu::getInstance()->isOptionChecked(MenuOption::Atmosphere)) { + PerformanceTimer perfTimer("paintGL/displaySide/atmosphere"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... atmosphere..."); _environment.renderAtmospheres(whichCamera); @@ -2474,10 +2528,14 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { glMaterialfv(GL_FRONT, GL_SPECULAR, NO_SPECULAR_COLOR); // draw the audio reflector overlay - _audioReflector.render(); - + { + PerformanceTimer perfTimer("paintGL/displaySide/audioReflector"); + _audioReflector.render(); + } + // Draw voxels if (Menu::getInstance()->isOptionChecked(MenuOption::Voxels)) { + PerformanceTimer perfTimer("paintGL/displaySide/voxels"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... voxels..."); _voxels.render(); @@ -2485,12 +2543,14 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { // also, metavoxels if (Menu::getInstance()->isOptionChecked(MenuOption::Metavoxels)) { + PerformanceTimer perfTimer("paintGL/displaySide/metavoxels"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... metavoxels..."); _metavoxels.render(); } if (Menu::getInstance()->isOptionChecked(MenuOption::BuckyBalls)) { + PerformanceTimer perfTimer("paintGL/displaySide/buckyBalls"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... bucky balls..."); _buckyBalls.render(); @@ -2498,6 +2558,7 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { // render particles... if (Menu::getInstance()->isOptionChecked(MenuOption::Particles)) { + PerformanceTimer perfTimer("paintGL/displaySide/particles"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... particles..."); _particles.render(); @@ -2505,6 +2566,7 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { // render models... if (Menu::getInstance()->isOptionChecked(MenuOption::Models)) { + PerformanceTimer perfTimer("paintGL/displaySide/models"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... models..."); _models.render(); @@ -2512,6 +2574,7 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { // render the ambient occlusion effect if enabled if (Menu::getInstance()->isOptionChecked(MenuOption::AmbientOcclusion)) { + PerformanceTimer perfTimer("paintGL/displaySide/AmbientOcclusion"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... AmbientOcclusion..."); _ambientOcclusionEffect.render(); @@ -2525,16 +2588,21 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { } bool mirrorMode = (whichCamera.getInterpolatedMode() == CAMERA_MODE_MIRROR); - _avatarManager.renderAvatars(mirrorMode ? Avatar::MIRROR_RENDER_MODE : Avatar::NORMAL_RENDER_MODE, selfAvatarOnly); + { + PerformanceTimer perfTimer("paintGL/displaySide/renderAvatars"); + _avatarManager.renderAvatars(mirrorMode ? Avatar::MIRROR_RENDER_MODE : Avatar::NORMAL_RENDER_MODE, selfAvatarOnly); + } if (!selfAvatarOnly) { // Render the world box if (whichCamera.getMode() != CAMERA_MODE_MIRROR && Menu::getInstance()->isOptionChecked(MenuOption::Stats)) { + PerformanceTimer perfTimer("paintGL/displaySide/renderWorldBox"); renderWorldBox(); } - // brad's frustum for debugging + // view frustum for debugging if (Menu::getInstance()->isOptionChecked(MenuOption::DisplayFrustum) && whichCamera.getMode() != CAMERA_MODE_MIRROR) { + PerformanceTimer perfTimer("paintGL/displaySide/ViewFrustum"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... renderViewFrustum..."); renderViewFrustum(_viewFrustum); @@ -2542,6 +2610,7 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { // render voxel fades if they exist if (_voxelFades.size() > 0) { + PerformanceTimer perfTimer("paintGL/displaySide/voxel fades"); PerformanceWarning warn(Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings), "Application::displaySide() ... voxel fades..."); _voxelFadesLock.lockForWrite(); @@ -2557,10 +2626,16 @@ void Application::displaySide(Camera& whichCamera, bool selfAvatarOnly) { } // give external parties a change to hook in - emit renderingInWorldInterface(); + { + PerformanceTimer perfTimer("paintGL/displaySide/inWorldInterface"); + emit renderingInWorldInterface(); + } // render JS/scriptable overlays - _overlays.render3D(); + { + PerformanceTimer perfTimer("paintGL/displaySide/3dOverlays"); + _overlays.render3D(); + } } } diff --git a/interface/src/Menu.cpp b/interface/src/Menu.cpp index 7fd8f26006..25bf65d18e 100644 --- a/interface/src/Menu.cpp +++ b/interface/src/Menu.cpp @@ -386,8 +386,15 @@ Menu::Menu() : addCheckableActionToQMenuAndActionHash(handOptionsMenu, MenuOption::AlternateIK, 0, false); addDisabledActionAndSeparator(developerMenu, "Testing"); - + QMenu* timingMenu = developerMenu->addMenu("Timing and Statistics Tools"); + QMenu* perfTimerMenu = timingMenu->addMenu("Performance Timer"); + addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::DisplayTimingDetails, 0, true); + addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandDisplaySideTiming, 0, false); + addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandIdleTiming, 0, false); + addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandPaintGLTiming, 0, false); + addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandUpdateTiming, 0, false); + addCheckableActionToQMenuAndActionHash(timingMenu, MenuOption::TestPing, 0, true); addCheckableActionToQMenuAndActionHash(timingMenu, MenuOption::FrameTimer); addActionToQMenuAndActionHash(timingMenu, MenuOption::RunTimingTests, 0, this, SLOT(runTests())); diff --git a/interface/src/Menu.h b/interface/src/Menu.h index 50e59320b9..c1a9e4274b 100644 --- a/interface/src/Menu.h +++ b/interface/src/Menu.h @@ -321,10 +321,15 @@ namespace MenuOption { const QString DisplayModelBounds = "Display Model Bounds"; const QString DisplayModelElementProxy = "Display Model Element Bounds"; const QString DisplayModelElementChildProxies = "Display Model Element Children"; + const QString DisplayTimingDetails = "Display Timing Details"; const QString DontFadeOnVoxelServerChanges = "Don't Fade In/Out on Voxel Server Changes"; const QString EchoLocalAudio = "Echo Local Audio"; const QString EchoServerAudio = "Echo Server Audio"; const QString Enable3DTVMode = "Enable 3DTV Mode"; + const QString ExpandDisplaySideTiming = "Expand Display Side Timing"; + const QString ExpandIdleTiming = "Expand Idle Timing"; + const QString ExpandPaintGLTiming = "Expand PaintGL Timing"; + const QString ExpandUpdateTiming = "Expand Update Timing"; const QString Faceplus = "Faceplus"; const QString Faceshift = "Faceshift"; const QString FilterSixense = "Smooth Sixense Movement"; diff --git a/interface/src/renderer/GlowEffect.cpp b/interface/src/renderer/GlowEffect.cpp index 1eceb71752..262a632df0 100644 --- a/interface/src/renderer/GlowEffect.cpp +++ b/interface/src/renderer/GlowEffect.cpp @@ -14,6 +14,8 @@ #include +#include + #include "Application.h" #include "GlowEffect.h" #include "ProgramObject.h" @@ -119,6 +121,8 @@ static void maybeRelease(QOpenGLFramebufferObject* fbo) { } QOpenGLFramebufferObject* GlowEffect::render(bool toTexture) { + PerformanceTimer perfTimer("paintGL/glowEffect"); + QOpenGLFramebufferObject* primaryFBO = Application::getInstance()->getTextureCache()->getPrimaryFramebufferObject(); primaryFBO->release(); glBindTexture(GL_TEXTURE_2D, primaryFBO->texture()); diff --git a/interface/src/ui/Stats.cpp b/interface/src/ui/Stats.cpp index a391ed239c..d7ca0152fd 100644 --- a/interface/src/ui/Stats.cpp +++ b/interface/src/ui/Stats.cpp @@ -18,6 +18,8 @@ #include #include +#include + #include "Stats.h" #include "InterfaceConfig.h" #include "Menu.h" @@ -158,6 +160,33 @@ void Stats::drawBackground(unsigned int rgba, int x, int y, int width, int heigh glColor4f(1, 1, 1, 1); } +bool Stats::includeTimingRecord(const QString& name) { + bool included = false; + if (Menu::getInstance()->isOptionChecked(MenuOption::DisplayTimingDetails)) { + + if (name == "idle/update") { + included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandUpdateTiming) || + Menu::getInstance()->isOptionChecked(MenuOption::ExpandIdleTiming); + } else if (name == "idle/updateGL") { + included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandIdleTiming); + } else if (name.startsWith("idle/update")) { + included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandUpdateTiming); + } else if (name.startsWith("idle/")) { + included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandIdleTiming); + } else if (name == "paintGL/displaySide") { + included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandDisplaySideTiming) || + Menu::getInstance()->isOptionChecked(MenuOption::ExpandPaintGLTiming); + } else if (name.startsWith("paintGL/displaySide/")) { + included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandDisplaySideTiming); + } else if (name.startsWith("paintGL/")) { + included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandPaintGLTiming); + } else { + included = true; // include everything else + } + } + return included; +} + // display expanded or contracted stats void Stats::display( const float* color, @@ -190,6 +219,9 @@ void Stats::display( int totalServers = NodeList::getInstance()->size(); lines = _expanded ? 5 : 3; + + + drawBackground(backgroundColor, horizontalOffset, 0, _generalStatsWidth, lines * STATS_PELS_PER_LINE + 10); horizontalOffset += 5; @@ -345,11 +377,25 @@ void Stats::display( VoxelSystem* voxels = Application::getInstance()->getVoxels(); - lines = _expanded ? 12 : 3; + lines = _expanded ? 11 : 3; if (_expanded && Menu::getInstance()->isOptionChecked(MenuOption::AudioSpatialProcessing)) { lines += 9; // spatial audio processing adds 1 spacing line and 8 extra lines of info } + if (_expanded && Menu::getInstance()->isOptionChecked(MenuOption::DisplayTimingDetails)) { + // we will also include room for 1 line per timing record and a header + lines += 1; + + const QMap& allRecords = PerformanceTimer::getAllTimerRecords(); + QMapIterator i(allRecords); + while (i.hasNext()) { + i.next(); + if (includeTimingRecord(i.key())) { + lines++; + } + } + } + drawBackground(backgroundColor, horizontalOffset, 0, glWidget->width() - horizontalOffset, lines * STATS_PELS_PER_LINE + 10); horizontalOffset += 5; @@ -454,8 +500,6 @@ void Stats::display( } } - verticalOffset += (_expanded ? STATS_PELS_PER_LINE : 0); - QString serversTotalString = locale.toString((uint)totalNodes); // consider adding: .rightJustified(10, ' '); // Server Voxels @@ -508,6 +552,29 @@ void Stats::display( drawText(horizontalOffset, verticalOffset, scale, rotation, font, (char*)voxelStats.str().c_str(), color); } + // TODO: the display of these timing details should all be moved to JavaScript + if (_expanded && Menu::getInstance()->isOptionChecked(MenuOption::DisplayTimingDetails)) { + // Timing details... + const int TIMER_OUTPUT_LINE_LENGTH = 300; + char perfLine[TIMER_OUTPUT_LINE_LENGTH]; + verticalOffset += STATS_PELS_PER_LINE; + drawText(horizontalOffset, verticalOffset, scale, rotation, font, + "---------------- Function --------------- --msecs- -calls--", color); + + const QMap& allRecords = PerformanceTimer::getAllTimerRecords(); + QMapIterator i(allRecords); + while (i.hasNext()) { + i.next(); + if (includeTimingRecord(i.key())) { + sprintf(perfLine, "%40s: %8.4f [%6llu]", qPrintable(i.key()), + (float)i.value().getMovingAverage() / (float)USECS_PER_MSEC, + i.value().getCount()); + + verticalOffset += STATS_PELS_PER_LINE; + drawText(horizontalOffset, verticalOffset, scale, rotation, font, perfLine, color); + } + } + } if (_expanded && Menu::getInstance()->isOptionChecked(MenuOption::AudioSpatialProcessing)) { verticalOffset += STATS_PELS_PER_LINE; // space one line... diff --git a/interface/src/ui/Stats.h b/interface/src/ui/Stats.h index 1ce0807ee8..66d6ec99f0 100644 --- a/interface/src/ui/Stats.h +++ b/interface/src/ui/Stats.h @@ -30,6 +30,7 @@ public: void checkClick(int mouseX, int mouseY, int mouseDragStartedX, int mouseDragStartedY, int horizontalOffset); void resetWidth(int width, int horizontalOffset); void display(const float* color, int horizontalOffset, float fps, int packetsPerSecond, int bytesPerSecond, int voxelPacketsToProcess); + bool includeTimingRecord(const QString& name); private: static Stats* _sharedInstance; diff --git a/libraries/shared/src/PerfStat.cpp b/libraries/shared/src/PerfStat.cpp index 9235cb3f25..4dca3f3d49 100644 --- a/libraries/shared/src/PerfStat.cpp +++ b/libraries/shared/src/PerfStat.cpp @@ -52,4 +52,22 @@ PerformanceWarning::~PerformanceWarning() { } }; +QMap PerformanceTimer::_records; + +PerformanceTimer::~PerformanceTimer() { + quint64 end = usecTimestampNow(); + quint64 elapsedusec = (end - _start); + PerformanceTimerRecord& namedRecord = _records[_name]; + namedRecord.recordResult(elapsedusec); +} + +void PerformanceTimer::dumpAllTimerRecords() { + QMapIterator i(_records); + while (i.hasNext()) { + i.next(); + qDebug() << i.key() << ": average " << i.value().getAverage() + << " [" << i.value().getMovingAverage() << "]" + << "usecs over" << i.value().getCount() << "calls"; + } +} diff --git a/libraries/shared/src/PerfStat.h b/libraries/shared/src/PerfStat.h index 22cf14f207..f849fb844c 100644 --- a/libraries/shared/src/PerfStat.h +++ b/libraries/shared/src/PerfStat.h @@ -17,6 +17,7 @@ #include #include "SharedUtil.h" +#include "SimpleMovingAverage.h" #include #include @@ -49,5 +50,41 @@ public: static void setSuppressShortTimings(bool suppressShortTimings) { _suppressShortTimings = suppressShortTimings; } }; +class PerformanceTimerRecord { +public: + PerformanceTimerRecord() : _runningTotal(0), _totalCalls(0) {} + + void recordResult(quint64 elapsed) { _runningTotal += elapsed; _totalCalls++; _movingAverage.updateAverage(elapsed); } + quint64 getAverage() const { return (_totalCalls == 0) ? 0 : _runningTotal / _totalCalls; } + quint64 getMovingAverage() const { return (_totalCalls == 0) ? 0 : _movingAverage.getAverage(); } + quint64 getCount() const { return _totalCalls; } + +private: + quint64 _runningTotal; + quint64 _totalCalls; + SimpleMovingAverage _movingAverage; +}; + +class PerformanceTimer { +public: + + PerformanceTimer(const QString& name) : + _start(usecTimestampNow()), + _name(name) { } + + quint64 elapsed() const { return (usecTimestampNow() - _start); }; + + ~PerformanceTimer(); + + static const PerformanceTimerRecord& getTimerRecord(const QString& name) { return _records[name]; }; + static const QMap& getAllTimerRecords() { return _records; }; + static void dumpAllTimerRecords(); + +private: + quint64 _start; + QString _name; + static QMap _records; +}; + #endif // hifi_PerfStat_h From 7e3ef34e6c2ddb053843bc98e8fed8d902c28437 Mon Sep 17 00:00:00 2001 From: ZappoMan Date: Thu, 29 May 2014 15:34:20 -0700 Subject: [PATCH 2/2] CR feedback --- interface/src/ui/Stats.cpp | 3 --- 1 file changed, 3 deletions(-) diff --git a/interface/src/ui/Stats.cpp b/interface/src/ui/Stats.cpp index d7ca0152fd..42eae260c7 100644 --- a/interface/src/ui/Stats.cpp +++ b/interface/src/ui/Stats.cpp @@ -219,9 +219,6 @@ void Stats::display( int totalServers = NodeList::getInstance()->size(); lines = _expanded ? 5 : 3; - - - drawBackground(backgroundColor, horizontalOffset, 0, _generalStatsWidth, lines * STATS_PELS_PER_LINE + 10); horizontalOffset += 5;