cleanup debug stats, use more correct names

interface/resources/qml/Stats.qml

@@ -55,7 +55,11 @@ Item {
                         text: "Avatars: " + root.avatarCount
                     }
                     StatText {
-                        text: "Frame Rate: " + root.framerate.toFixed(2);
+                        text: "Game Rate: " + root.gameLoopRate
+                    }
+                    StatText {
+                        visible: root.expanded
+                        text: root.gameUpdateStats
                     }
                     StatText {
                         text: "Render Rate: " + root.renderrate.toFixed(2);
@@ -64,21 +68,17 @@ Item {
                         text: "Present Rate: " + root.presentrate.toFixed(2);
                     }
                     StatText {
-                        text: "Present New Rate: " + root.presentnewrate.toFixed(2);
+                        visible: root.expanded
+                        text: "    Present New Rate: " + root.presentnewrate.toFixed(2);
                     }
                     StatText {
-                        text: "Present Drop Rate: " + root.presentdroprate.toFixed(2);
+                        visible: root.expanded
+                        text: "    Present Drop Rate: " + root.presentdroprate.toFixed(2);
                     }
                     StatText {
                         text: "Stutter Rate: " + root.stutterrate.toFixed(3);
                         visible: root.stutterrate != -1;
                     }
-                    StatText {
-                        text: "Simrate: " + root.simrate
-                    }
-                    StatText {
-                        text: "Avatar Simrate: " + root.avatarSimrate
-                    }
                     StatText {
                         text: "Missed Frame Count: " + root.appdropped;
                         visible: root.appdropped > 0;
@@ -261,9 +261,6 @@ Item {
                     StatText {
                         text: "GPU: " + root.gpuFrameTime.toFixed(1) + " ms"
                     }
-                    StatText {
-                        text: "Avatar: " + root.avatarSimulationTime.toFixed(1) + " ms"
-                    }
                     StatText {
                         text: "Triangles: " + root.triangles +
                             " / Material Switches: " + root.materialSwitches

interface/src/Application.cpp

@@ -1545,15 +1545,13 @@ Application::Application(int& argc, char** argv, QElapsedTimer& startupTimer, bo
 
         auto displayPlugin = qApp->getActiveDisplayPlugin();
 
-        properties["fps"] = _frameCounter.rate();
+        properties["render_rate"] = _renderLoopCounter.rate();
-        properties["target_frame_rate"] = getTargetFrameRate();
+        properties["target_render_rate"] = getTargetRenderFrameRate();
-        properties["render_rate"] = displayPlugin->renderRate();
         properties["present_rate"] = displayPlugin->presentRate();
         properties["new_frame_present_rate"] = displayPlugin->newFramePresentRate();
         properties["dropped_frame_rate"] = displayPlugin->droppedFrameRate();
         properties["stutter_rate"] = displayPlugin->stutterRate();
-        properties["sim_rate"] = getAverageSimsPerSecond();
+        properties["game_rate"] = getGameLoopRate();
-        properties["avatar_sim_rate"] = getAvatarSimrate();
         properties["has_async_reprojection"] = displayPlugin->hasAsyncReprojection();
         properties["hardware_stats"] = displayPlugin->getHardwareStats();
 
@@ -2388,11 +2386,11 @@ void Application::paintGL() {
         return;
     }
 
-    _frameCount++;
+    _renderFrameCount++;
     _lastTimeRendered.start();
 
     auto lastPaintBegin = usecTimestampNow();
-    PROFILE_RANGE_EX(render, __FUNCTION__, 0xff0000ff, (uint64_t)_frameCount);
+    PROFILE_RANGE_EX(render, __FUNCTION__, 0xff0000ff, (uint64_t)_renderFrameCount);
     PerformanceTimer perfTimer("paintGL");
 
     if (nullptr == _displayPlugin) {
@@ -2409,7 +2407,7 @@ void Application::paintGL() {
         PROFILE_RANGE(render, "/pluginBeginFrameRender");
         // If a display plugin loses it's underlying support, it
         // needs to be able to signal us to not use it
-        if (!displayPlugin->beginFrameRender(_frameCount)) {
+        if (!displayPlugin->beginFrameRender(_renderFrameCount)) {
             updateDisplayMode();
             return;
         }
@@ -2564,14 +2562,14 @@ void Application::paintGL() {
             }
             // Update camera position
             if (!isHMDMode()) {
-                _myCamera.update(1.0f / _frameCounter.rate());
+                _myCamera.update();
             }
         }
     }
 
     {
         PROFILE_RANGE(render, "/updateCompositor");
-        getApplicationCompositor().setFrameInfo(_frameCount, _myCamera.getTransform(), getMyAvatar()->getSensorToWorldMatrix());
+        getApplicationCompositor().setFrameInfo(_renderFrameCount, _myCamera.getTransform(), getMyAvatar()->getSensorToWorldMatrix());
     }
 
     gpu::FramebufferPointer finalFramebuffer;
@@ -2652,7 +2650,7 @@ void Application::paintGL() {
     }
 
     auto frame = _gpuContext->endFrame();
-    frame->frameIndex = _frameCount;
+    frame->frameIndex = _renderFrameCount;
     frame->framebuffer = finalFramebuffer;
     frame->framebufferRecycler = [](const gpu::FramebufferPointer& framebuffer){
         DependencyManager::get<FramebufferCache>()->releaseFramebuffer(framebuffer);
@@ -2663,7 +2661,7 @@ void Application::paintGL() {
     {
         PROFILE_RANGE(render, "/pluginOutput");
         PerformanceTimer perfTimer("pluginOutput");
-        _frameCounter.increment();
+        _renderLoopCounter.increment();
         displayPlugin->submitFrame(frame);
     }
 
@@ -4041,7 +4039,7 @@ void Application::idle() {
     if (displayPlugin) {
         PROFILE_COUNTER_IF_CHANGED(app, "present", float, displayPlugin->presentRate());
     }
-    PROFILE_COUNTER_IF_CHANGED(app, "fps", float, _frameCounter.rate());
+    PROFILE_COUNTER_IF_CHANGED(app, "renderLoopRate", float, _renderLoopCounter.rate());
     PROFILE_COUNTER_IF_CHANGED(app, "currentDownloads", int, ResourceCache::getLoadingRequests().length());
     PROFILE_COUNTER_IF_CHANGED(app, "pendingDownloads", int, ResourceCache::getPendingRequestCount());
     PROFILE_COUNTER_IF_CHANGED(app, "currentProcessing", int, DependencyManager::get<StatTracker>()->getStat("Processing").toInt());
@@ -4077,8 +4075,6 @@ void Application::idle() {
 
     Stats::getInstance()->updateStats();
 
-    _simCounter.increment();
-
     // 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 its subcomponents will show their timing
     // details normally.
@@ -4158,6 +4154,7 @@ void Application::idle() {
         Menu::getInstance()->setIsOptionChecked(MenuOption::ThirdPerson, !(myAvatar->getBoomLength() <= MyAvatar::ZOOM_MIN));
         cameraMenuChanged();
     }
+    _gameLoopCounter.increment();
 }
 
 ivec2 Application::getMouse() const {
@@ -4844,7 +4841,7 @@ static bool domainLoadingInProgress = false;
 
 void Application::update(float deltaTime) {
 
-    PROFILE_RANGE_EX(app, __FUNCTION__, 0xffff0000, (uint64_t)_frameCount + 1);
+    PROFILE_RANGE_EX(app, __FUNCTION__, 0xffff0000, (uint64_t)_renderFrameCount + 1);
 
     bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings);
     PerformanceWarning warn(showWarnings, "Application::update()");
@@ -5138,22 +5135,22 @@ void Application::update(float deltaTime) {
 
     // AvatarManager update
     {
-        PerformanceTimer perfTimer("AvatarManager");
-        _avatarSimCounter.increment();
-
         {
+            PerformanceTimer perfTimer("otherAvatars");
             PROFILE_RANGE_EX(simulation, "OtherAvatars", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount());
             avatarManager->updateOtherAvatars(deltaTime);
         }
 
-        qApp->updateMyAvatarLookAtPosition();
-
         {
             PROFILE_RANGE_EX(simulation, "MyAvatar", 0xffff00ff, (uint64_t)getActiveDisplayPlugin()->presentCount());
+            PerformanceTimer perfTimer("MyAvatar");
+            qApp->updateMyAvatarLookAtPosition();
             avatarManager->updateMyAvatar(deltaTime);
         }
     }
 
+    PerformanceTimer perfTimer("misc");
+    // TODO: break these out into distinct perfTimers when they prove interesting
     {
         PROFILE_RANGE(app, "RayPickManager");
         _rayPickManager.update();
@@ -5471,7 +5468,7 @@ bool Application::isHMDMode() const {
     return getActiveDisplayPlugin()->isHmd();
 }
 
-float Application::getTargetFrameRate() const { return getActiveDisplayPlugin()->getTargetFrameRate(); }
+float Application::getTargetRenderFrameRate() const { return getActiveDisplayPlugin()->getTargetFrameRate(); }
 
 QRect Application::getDesirableApplicationGeometry() const {
     QRect applicationGeometry = getWindow()->geometry();

interface/src/Application.h

@@ -192,10 +192,9 @@ public:
 
     Overlays& getOverlays() { return _overlays; }
 
-
+    size_t getRenderFrameCount() const { return _renderFrameCount; }
-    size_t getFrameCount() const { return _frameCount; }
+    float getRenderLoopRate() const { return _renderLoopCounter.rate(); }
-    float getFps() const { return _frameCounter.rate(); }
+    float getTargetRenderFrameRate() const; // frames/second
-    float getTargetFrameRate() const; // frames/second
 
     float getFieldOfView() { return _fieldOfView.get(); }
     void setFieldOfView(float fov);
@@ -266,8 +265,7 @@ public:
 
     void updateMyAvatarLookAtPosition();
 
-    float getAvatarSimrate() const { return _avatarSimCounter.rate(); }
+    float getGameLoopRate() const { return _gameLoopCounter.rate(); }
-    float getAverageSimsPerSecond() const { return _simCounter.rate(); }
 
     void takeSnapshot(bool notify, bool includeAnimated = false, float aspectRatio = 0.0f);
     void takeSecondaryCameraSnapshot();
@@ -531,12 +529,11 @@ private:
     QUndoStack _undoStack;
     UndoStackScriptingInterface _undoStackScriptingInterface;
 
-    uint32_t _frameCount { 0 };
+    uint32_t _renderFrameCount { 0 };
 
     // Frame Rate Measurement
-    RateCounter<> _frameCounter;
+    RateCounter<500> _renderLoopCounter;
-    RateCounter<> _avatarSimCounter;
+    RateCounter<500> _gameLoopCounter;
-    RateCounter<> _simCounter;
 
     QTimer _minimizedWindowTimer;
     QElapsedTimer _timerStart;

interface/src/avatar/AvatarManager.cpp

@@ -252,11 +252,12 @@ void AvatarManager::updateOtherAvatars(float deltaTime) {
         qApp->getMain3DScene()->enqueueTransaction(transaction);
     }
 
-    _avatarSimulationTime = (float)(usecTimestampNow() - startTime) / (float)USECS_PER_MSEC;
     _numAvatarsUpdated = numAvatarsUpdated;
     _numAvatarsNotUpdated = numAVatarsNotUpdated;
 
     simulateAvatarFades(deltaTime);
+
+    _avatarSimulationTime = (float)(usecTimestampNow() - startTime) / (float)USECS_PER_MSEC;
 }
 
 void AvatarManager::postUpdate(float deltaTime, const render::ScenePointer& scene) {

interface/src/scripting/RatesScriptingInterface.h

@@ -22,16 +22,14 @@ class RatesScriptingInterface : public QObject {
     Q_PROPERTY(float newFrame READ getNewFrameRate)
     Q_PROPERTY(float dropped READ getDropRate)
     Q_PROPERTY(float simulation READ getSimulationRate)
-    Q_PROPERTY(float avatar READ getAvatarRate)
 
 public:
     RatesScriptingInterface(QObject* parent) : QObject(parent) {}
-    float getRenderRate() { return qApp->getFps(); }
+    float getRenderRate() { return qApp->getRenderLoopRate(); }
     float getPresentRate() { return qApp->getActiveDisplayPlugin()->presentRate(); }
     float getNewFrameRate() { return qApp->getActiveDisplayPlugin()->newFramePresentRate(); }
     float getDropRate() { return qApp->getActiveDisplayPlugin()->droppedFrameRate(); }
-    float getSimulationRate() { return qApp->getAverageSimsPerSecond(); }
+    float getSimulationRate() { return qApp->getGameLoopRate(); }
-    float getAvatarRate() { return qApp->getAvatarSimrate(); }
 };
 
 #endif // HIFI_INTERFACE_RATES_SCRIPTING_INTERFACE_H

interface/src/ui/Stats.cpp

@@ -8,6 +8,7 @@
 
 #include "Stats.h"
 
+#include <queue>
 #include <sstream>
 #include <QFontDatabase>
 
@@ -129,7 +130,7 @@ void Stats::updateStats(bool force) {
     STAT_UPDATE(updatedAvatarCount, avatarManager->getNumAvatarsUpdated());
     STAT_UPDATE(notUpdatedAvatarCount, avatarManager->getNumAvatarsNotUpdated());
     STAT_UPDATE(serverCount, (int)nodeList->size());
-    STAT_UPDATE_FLOAT(framerate, qApp->getFps(), 0.1f);
+    STAT_UPDATE_FLOAT(renderrate, qApp->getRenderLoopRate(), 0.1f);
     if (qApp->getActiveDisplayPlugin()) {
         auto displayPlugin = qApp->getActiveDisplayPlugin();
         auto stats = displayPlugin->getHardwareStats();
@@ -137,7 +138,6 @@ void Stats::updateStats(bool force) {
         STAT_UPDATE(longrenders, stats["long_render_count"].toInt());
         STAT_UPDATE(longsubmits, stats["long_submit_count"].toInt());
         STAT_UPDATE(longframes, stats["long_frame_count"].toInt());
-        STAT_UPDATE_FLOAT(renderrate, displayPlugin->renderRate(), 0.1f);
         STAT_UPDATE_FLOAT(presentrate, displayPlugin->presentRate(), 0.1f);
         STAT_UPDATE_FLOAT(presentnewrate, displayPlugin->newFramePresentRate(), 0.1f);
         STAT_UPDATE_FLOAT(presentdroprate, displayPlugin->droppedFrameRate(), 0.1f);
@@ -150,8 +150,7 @@ void Stats::updateStats(bool force) {
         STAT_UPDATE(presentnewrate, -1);
         STAT_UPDATE(presentdroprate, -1);
     }
-    STAT_UPDATE(simrate, (int)qApp->getAverageSimsPerSecond());
+    STAT_UPDATE(gameLoopRate, (int)qApp->getGameLoopRate());
-    STAT_UPDATE(avatarSimrate, (int)qApp->getAvatarSimrate());
 
     auto bandwidthRecorder = DependencyManager::get<BandwidthRecorder>();
     STAT_UPDATE(packetInCount, (int)bandwidthRecorder->getCachedTotalAverageInputPacketsPerSecond());
@@ -453,9 +452,47 @@ void Stats::updateStats(bool force) {
         }
         _timingStats = perfLines;
         emit timingStatsChanged();
+
+        // build _gameUpdateStats
+        class SortableStat {
+        public:
+            SortableStat(QString a, float p) : message(a), priority(p) {}
+            QString message;
+            float priority;
+            bool operator<(const SortableStat& other) const { return priority < other.priority; }
+        };
+
+        std::priority_queue<SortableStat> idleUpdateStats;
+        auto itr = allRecords.find("/idle/update");
+        if (itr != allRecords.end()) {
+            uint64_t dt = (float)itr.value().getMovingAverage() / (float)USECS_PER_MSEC;
+            _gameUpdateStats = QString("/idle/update = %1 ms").arg(dt);
+
+            QVector<QString> categories = { "devices", "physics", "otherAvatars", "MyAvatar", "misc" };
+            for (int32_t j = 0; j < categories.size(); ++j) {
+                QString recordKey = "/idle/update/" + categories[j];
+                itr = allRecords.find(recordKey);
+                if (itr != allRecords.end()) {
+                    uint64_t dt = (float)itr.value().getMovingAverage() / (float)USECS_PER_MSEC;
+                    QString message = QString("\n    %1 = %2").arg(categories[j]).arg(dt);
+                    idleUpdateStats.push(SortableStat(message, dt));
+                }
+            }
+            while (!idleUpdateStats.empty()) {
+                SortableStat stat = idleUpdateStats.top();
+                _gameUpdateStats += stat.message;
+                idleUpdateStats.pop();
+            }
+            emit gameUpdateStatsChanged();
+        } else if (_gameUpdateStats != "") {
+            _gameUpdateStats = "";
+            emit gameUpdateStatsChanged();
+        }
     } else if (_timingExpanded) {
         _timingExpanded = false;
         emit timingExpandedChanged();
+        _gameUpdateStats = "";
+        emit gameUpdateStatsChanged();
     }
 }
 

interface/src/ui/Stats.h

@@ -32,8 +32,6 @@ class Stats : public QQuickItem {
 
     STATS_PROPERTY(int, serverCount, 0)
     // How often the app is creating new gpu::Frames
-    STATS_PROPERTY(float, framerate, 0)
-    // How often the display plugin is executing a given frame
     STATS_PROPERTY(float, renderrate, 0)
     // How often the display plugin is presenting to the device
     STATS_PROPERTY(float, presentrate, 0)
@@ -47,8 +45,7 @@ class Stats : public QQuickItem {
 
     STATS_PROPERTY(float, presentnewrate, 0)
     STATS_PROPERTY(float, presentdroprate, 0)
-    STATS_PROPERTY(int, simrate, 0)
+    STATS_PROPERTY(int, gameLoopRate, 0)
-    STATS_PROPERTY(int, avatarSimrate, 0)
     STATS_PROPERTY(int, avatarCount, 0)
     STATS_PROPERTY(int, updatedAvatarCount, 0)
     STATS_PROPERTY(int, notUpdatedAvatarCount, 0)
@@ -108,6 +105,7 @@ class Stats : public QQuickItem {
     STATS_PROPERTY(QString, packetStats, QString())
     STATS_PROPERTY(QString, lodStatus, QString())
     STATS_PROPERTY(QString, timingStats, QString())
+    STATS_PROPERTY(QString, gameUpdateStats, QString())
     STATS_PROPERTY(int, serverElements, 0)
     STATS_PROPERTY(int, serverInternal, 0)
     STATS_PROPERTY(int, serverLeaves, 0)
@@ -167,7 +165,6 @@ signals:
     void longrendersChanged();
     void longframesChanged();
     void appdroppedChanged();
-    void framerateChanged();
     void expandedChanged();
     void timingExpandedChanged();
     void serverCountChanged();
@@ -176,8 +173,7 @@ signals:
     void presentnewrateChanged();
     void presentdroprateChanged();
     void stutterrateChanged();
-    void simrateChanged();
+    void gameLoopRateChanged();
-    void avatarSimrateChanged();
     void avatarCountChanged();
     void updatedAvatarCountChanged();
     void notUpdatedAvatarCountChanged();
@@ -242,6 +238,7 @@ signals:
     void localInternalChanged();
     void localLeavesChanged();
     void timingStatsChanged();
+    void gameUpdateStatsChanged();
     void glContextSwapchainMemoryChanged();
     void qmlTextureMemoryChanged();
     void texturePendingTransfersChanged();

libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.h

@@ -129,10 +129,10 @@ protected:
     bool _vsyncEnabled { true };
     QThread* _presentThread{ nullptr };
     std::queue<gpu::FramePointer> _newFrameQueue;
-    RateCounter<100> _droppedFrameRate;
+    RateCounter<200> _droppedFrameRate;
-    RateCounter<100> _newFrameRate;
+    RateCounter<200> _newFrameRate;
-    RateCounter<100> _presentRate;
+    RateCounter<200> _presentRate;
-    RateCounter<100> _renderRate;
+    RateCounter<200> _renderRate;
 
     gpu::FramePointer _currentFrame;
     gpu::Frame* _lastFrame { nullptr };

libraries/shared/src/shared/Camera.cpp

@@ -45,7 +45,7 @@ Camera::Camera() :
 {
 }
 
-void Camera::update(float deltaTime) {
+void Camera::update() {
     if (_isKeepLookingAt) {
         lookAt(_lookingAt);
     }

libraries/shared/src/shared/Camera.h

@@ -53,7 +53,7 @@ public:
 
     void initialize(); // instantly put the camera at the ideal position and orientation.
 
-    void update( float deltaTime );
+    void update();
 
     CameraMode getMode() const { return _mode; }
     void setMode(CameraMode m);