add improved detailed rendering and FPS debugging stats

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) {
+            if (_numChangedSettings > 0) {
-            saveSettings();
+                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();
-
+    updateMouseRay(); // check what's under the mouse and update the mouse voxel
-    // check what's under the mouse and update the mouse voxel
-    updateMouseRay();
-
     updateFaceshift();
     updateVisage();
-    _myAvatar->updateLookAtTargetAvatar();
+
+    {
+        PerformanceTimer perfTimer("idle/update/updateLookAtTargetAvatar");
+        _myAvatar->updateLookAtTargetAvatar();
+    }
     updateMyAvatarLookAtPosition();
-    _sixenseManager.update(deltaTime);
+    {
-    _joystickManager.update();
+        PerformanceTimer perfTimer("idle/update/sixense,joystick,prioVR");
-    _prioVR.update(deltaTime);
+        _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();
+        }
     }
 }
 

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()));

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";

interface/src/renderer/GlowEffect.cpp

@@ -14,6 +14,8 @@
 
 #include <QOpenGLFramebufferObject>
 
+#include <PerfStat.h>
+
 #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());

interface/src/ui/Stats.cpp

@@ -18,6 +18,8 @@
 #include <glm/gtx/quaternion.hpp>
 #include <glm/gtx/vector_angle.hpp>
 
+#include <PerfStat.h>
+
 #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<QString, PerformanceTimerRecord>& allRecords = PerformanceTimer::getAllTimerRecords();
+        QMapIterator<QString, PerformanceTimerRecord> 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<QString, PerformanceTimerRecord>& allRecords = PerformanceTimer::getAllTimerRecords();
+        QMapIterator<QString, PerformanceTimerRecord> 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...

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;
 

libraries/shared/src/PerfStat.cpp

@@ -52,4 +52,22 @@ PerformanceWarning::~PerformanceWarning() {
     }
 };
 
+QMap<QString, PerformanceTimerRecord> PerformanceTimer::_records;
 
+
+PerformanceTimer::~PerformanceTimer() {
+    quint64 end = usecTimestampNow();
+    quint64 elapsedusec = (end - _start);
+    PerformanceTimerRecord& namedRecord = _records[_name];
+    namedRecord.recordResult(elapsedusec);
+}
+
+void PerformanceTimer::dumpAllTimerRecords() {
+    QMapIterator<QString, PerformanceTimerRecord> i(_records);
+    while (i.hasNext()) {
+        i.next();
+        qDebug() << i.key() << ": average " << i.value().getAverage() 
+            << " [" << i.value().getMovingAverage() << "]"
+            << "usecs over" << i.value().getCount() << "calls";
+    }
+}

libraries/shared/src/PerfStat.h

@@ -17,6 +17,7 @@
 
 #include <stdint.h>
 #include "SharedUtil.h"
+#include "SimpleMovingAverage.h"
 
 #include <cstring>
 #include <string>
@@ -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<QString, PerformanceTimerRecord>& getAllTimerRecords() { return _records; };
+    static void dumpAllTimerRecords();
+
+private:
+	quint64 _start;
+	QString _name;
+	static QMap<QString, PerformanceTimerRecord> _records;
+};
+
 
 #endif // hifi_PerfStat_h