Don't drop to half the vsync rate when we can't keep up

examples/tests/performance/consoleSpawner.js

@@ -0,0 +1,161 @@
+// entityEditStressTest.js
+//
+// Created by Seiji Emery on 8/31/15
+// Copyright 2015 High Fidelity, Inc.
+//
+// Stress tests the client + server-side entity trees by spawning huge numbers of entities in
+// close proximity to your avatar and updating them continuously (ie. applying position edits), 
+// with the intent of discovering crashes and other bugs related to the entity, scripting, 
+// rendering, networking, and/or physics subsystems.
+//
+// This script was originally created to find + diagnose an a clientside crash caused by improper
+// locking of the entity tree, but can be reused for other purposes.
+//
+// Distributed under the Apache License, Version 2.0.
+// See the accompanying file LICENSE or http://www.apache.org/licenses/LICENSE-2.0.html
+//
+
+var NUM_ENTITIES = 20;           // number of entities to spawn
+var ENTITY_SPAWN_INTERVAL = 0.01;
+var ENTITY_SPAWN_LIMIT = 1000;
+var Y_OFFSET = 1.5;
+var ENTITY_LIFETIME = 600;   // Entity timeout (when/if we crash, we need the entities to delete themselves)
+var KEEPALIVE_INTERVAL = 15; // Refreshes the timeout every X seconds 
+var RADIUS = 0.5;   // Spawn within this radius (square)
+var TEST_ENTITY_NAME = "EntitySpawnTest";
+var UPDATE_INTERVAL = 0.1;
+    
+(function () {
+    this.makeEntity = function (properties) {
+        var entity = Entities.addEntity(properties);
+        return {
+            update: function (properties) {
+                Entities.editEntity(entity, properties);
+            },
+            destroy: function () {
+                Entities.deleteEntity(entity)
+            },
+            getAge: function () {
+                return Entities.getEntityProperties(entity).age;
+            }
+        };
+    }
+
+    this.randomPositionXZ = function (center, radius) {
+        return {
+            x: center.x + (Math.random() * radius * 2.0) - radius,
+            y: center.y,
+            z: center.z + (Math.random() * radius * 2.0) - radius
+        };
+    }
+    this.randomDimensions = function () {
+        return {
+            x: 0.1 + Math.random() * 0.1,
+            y: 0.1 + Math.random() * 0.05,
+            z: 0.1 + Math.random() * 0.1
+        };
+    }
+})();
+
+(function () {
+    var entities = [];
+    var entitiesToCreate = 0;
+    var entitiesSpawned = 0;
+
+
+    function clear () {
+        var ids = Entities.findEntities(MyAvatar.position, 50);
+        var that = this;
+        ids.forEach(function(id) {
+            var properties = Entities.getEntityProperties(id);
+            if (properties.name == TEST_ENTITY_NAME) {
+                Entities.deleteEntity(id);
+            }
+        }, this);
+    }    
+    
+    function createEntities () {
+        print("Creating " + NUM_ENTITIES + " entities (UPDATE_INTERVAL = " + UPDATE_INTERVAL + ", KEEPALIVE_INTERVAL = " + KEEPALIVE_INTERVAL + ")");
+        entitiesToCreate = NUM_ENTITIES;
+        Script.update.connect(spawnEntities);
+    }
+
+    var spawnTimer = 0.0;
+    function spawnEntities (dt) {
+        if (entitiesToCreate <= 0) {
+            Script.update.disconnect(spawnEntities);
+            print("Finished spawning entities");
+        } 
+        else if ((spawnTimer -= dt) < 0.0){
+            spawnTimer = ENTITY_SPAWN_INTERVAL;
+
+            var n = Math.min(entitiesToCreate, ENTITY_SPAWN_LIMIT);
+            print("Spawning " + n + " entities (" + (entitiesSpawned += n) + ")");
+
+            entitiesToCreate -= n;
+
+            var center = { x: 0, y: 0, z: 0 } //MyAvatar.position;
+//            center.y += 1.0;
+
+            for (; n > 0; --n) {
+                entities.push(makeEntity({
+                    type: "Model",
+                    name: TEST_ENTITY_NAME,
+                    position: randomPositionXZ(center, RADIUS),
+                    dimensions: randomDimensions(),
+                    modelURL: "https://s3.amazonaws.com/DreamingContent/models/console.fbx",
+                    lifetime: ENTITY_LIFETIME
+                }));
+            }
+        }
+    }
+
+    function despawnEntities () {
+        print("despawning entities");
+        entities.forEach(function (entity) {
+            entity.destroy();
+        });
+        entities = [];
+    }
+
+    var keepAliveTimer = 0.0;
+    var updateTimer = 0.0;
+
+    // Runs the following entity updates:
+    // a) refreshes the timeout interval every KEEPALIVE_INTERVAL seconds, and
+    // b) re-randomizes its position every UPDATE_INTERVAL seconds.
+    // This should be sufficient to crash the client until the entity tree bug is fixed (and thereafter if it shows up again).
+    function updateEntities (dt) {
+        var updateLifetime = ((keepAliveTimer -= dt) < 0.0) ? ((keepAliveTimer = KEEPALIVE_INTERVAL), true) : false;
+        var updateProperties = ((updateTimer -= dt) < 0.0) ? ((updateTimer = UPDATE_INTERVAL), true) : false;
+
+        if (updateLifetime || updateProperties) {
+            var center = MyAvatar.position;
+            center.y -= Y_OFFSET;
+
+            entities.forEach((updateLifetime && updateProperties && function (entity) {
+                entity.update({
+                    lifetime: entity.getAge() + ENTITY_LIFETIME,
+                    position: randomPositionXZ(center, RADIUS)
+                });
+            }) || (updateLifetime && function (entity) {
+                entity.update({
+                    lifetime: entity.getAge() + ENTITY_LIFETIME
+                });
+            }) || (updateProperties && function (entity) {
+                entity.update({
+                    position: randomPositionXZ(center, RADIUS)
+                });
+            }) || null, this);
+        }
+    }
+
+    function init () {
+        Script.update.disconnect(init);
+        clear();
+        createEntities();
+        //Script.update.connect(updateEntities);
+        Script.scriptEnding.connect(despawnEntities);
+    }
+    Script.update.connect(init);
+})();

interface/src/Application.cpp

@@ -210,6 +210,10 @@ static const QString INFO_EDIT_ENTITIES_PATH = "html/edit-commands.html";
 
 static const unsigned int THROTTLED_SIM_FRAMERATE = 15;
 static const int THROTTLED_SIM_FRAME_PERIOD_MS = MSECS_PER_SECOND / THROTTLED_SIM_FRAMERATE;
+static const unsigned int CAPPED_SIM_FRAMERATE = 60;
+static const int CAPPED_SIM_FRAME_PERIOD_MS = MSECS_PER_SECOND / CAPPED_SIM_FRAMERATE;
+
+static const uint32_t INVALID_FRAME = UINT32_MAX;
 
 static const float PHYSICS_READY_RANGE = 3.0f; // how far from avatar to check for entities that aren't ready for simulation
 
@@ -273,7 +277,8 @@ public:
 #endif
 
 enum CustomEventTypes {
-    Lambda = QEvent::User + 1
+    Lambda = QEvent::User + 1,
+    Paint = Lambda + 1,
 };
 
 class LambdaEvent : public QEvent {
@@ -984,6 +989,17 @@ Application::Application(int& argc, char** argv, QElapsedTimer& startupTimer) :
 
     connect(this, &Application::applicationStateChanged, this, &Application::activeChanged);
     qCDebug(interfaceapp, "Startup time: %4.2f seconds.", (double)startupTimer.elapsed() / 1000.0);
+    _idleTimer = new QTimer(this);
+    connect(_idleTimer, &QTimer::timeout, [=] {
+        idle(usecTimestampNow());
+    });
+    connect(this, &Application::beforeAboutToQuit, [=] {
+        disconnect(_idleTimer);
+    });
+    // Setting the interval to zero forces this to get called whenever there are no messages
+    // in the queue, which can be pretty damn frequent.  Hence the idle function has a bunch 
+    // of logic to abort early if it's being called to often.
+    _idleTimer->start(0);
 }
 
 void Application::aboutToQuit() {
@@ -1296,9 +1312,6 @@ void Application::initializeUi() {
 }
 
 void Application::paintGL() {
-
-
-
     // paintGL uses a queued connection, so we can get messages from the queue even after we've quit
     // and the plugins have shutdown
     if (_aboutToQuit) {
@@ -1628,6 +1641,7 @@ void Application::paintGL() {
     // Store both values now for use by next cycle.
     _lastInstantaneousFps = instantaneousFps;
     _lastUnsynchronizedFps = 1.0f / (((usecTimestampNow() - now) / (float)USECS_PER_SECOND) + paintWaitAndQTTimerAllowance);
+    _pendingPaint = false;
 }
 
 void Application::runTests() {
@@ -1716,6 +1730,10 @@ bool Application::event(QEvent* event) {
         return true;
     }
 
+    if ((int)event->type() == (int)Paint) {
+        paintGL();
+    }
+
     if (!_keyboardFocusedItem.isInvalidID()) {
         switch (event->type()) {
             case QEvent::KeyPress:
@@ -2400,26 +2418,62 @@ bool Application::acceptSnapshot(const QString& urlString) {
     return true;
 }
 
+static uint32_t _renderedFrameIndex { INVALID_FRAME };
+
 void Application::idle(uint64_t now) {
     if (_aboutToQuit) {
         return; // bail early, nothing to do here.
     }
-
+    
+    auto displayPlugin = getActiveDisplayPlugin();
     // depending on whether we're throttling or not.
     // Once rendering is off on another thread we should be able to have Application::idle run at start(0) in
     // perpetuity and not expect events to get backed up.
-    bool isThrottled = getActiveDisplayPlugin()->isThrottled();
+    bool isThrottled = displayPlugin->isThrottled();
     //  Only run simulation code if more than the targetFramePeriod have passed since last time we ran
     // This attempts to lock the simulation at 60 updates per second, regardless of framerate
     float timeSinceLastUpdateUs = (float)_lastTimeUpdated.nsecsElapsed() / NSECS_PER_USEC;
     float secondsSinceLastUpdate = timeSinceLastUpdateUs / USECS_PER_SECOND;
 
     if (isThrottled && (timeSinceLastUpdateUs / USECS_PER_MSEC) < THROTTLED_SIM_FRAME_PERIOD_MS) {
+        // Throttling both rendering and idle
         return; // bail early, we're throttled and not enough time has elapsed
     }
 
-    _lastTimeUpdated.start();
+    auto presentCount = displayPlugin->presentCount();
+    if (presentCount < _renderedFrameIndex) {
+        _renderedFrameIndex = INVALID_FRAME;
+    }
 
+    // Nested ifs are for clarity in the logic.  Don't collapse them into a giant single if.
+    // Don't saturate the main thread with rendering, no paint calls until the last one is complete
+    if (!_pendingPaint) {
+        // Also no paint calls until the display plugin has increased by at least one frame 
+        // (don't render at 90fps if the display plugin only goes at 60)
+        if (_renderedFrameIndex == INVALID_FRAME || presentCount > _renderedFrameIndex) {
+            // Record what present frame we're on
+            _renderedFrameIndex = presentCount;
+            // Don't allow paint requests to stack up in the event queue
+            _pendingPaint = true;
+            // But when we DO request a paint, get to it as soon as possible: high priority
+            postEvent(this, new QEvent(static_cast<QEvent::Type>(Paint)), Qt::HighEventPriority);
+        }
+    }  
+    
+    // For the rest of idle, we want to cap at the max sim rate, so we might not call 
+    // the remaining idle work every paint frame, or vice versa
+    // In theory this means we could call idle processing more often than painting,
+    // but in practice, when the paintGL calls aren't keeping up, there's no room left
+    // in the main thread to call idle more often than paint.
+    // This check is mostly to keep idle from burning up CPU cycles by running at 
+    // hundreds of idles per second when the rendering is that fast
+    if ((timeSinceLastUpdateUs / USECS_PER_MSEC) < CAPPED_SIM_FRAME_PERIOD_MS) {
+        // No paint this round, but might be time for a new idle, otherwise return
+        return;
+    }
+
+    // We're going to execute idle processing, so restart the last idle timer
+    _lastTimeUpdated.start();
 
     {
         PROFILE_RANGE(__FUNCTION__);
@@ -4777,11 +4831,11 @@ void Application::updateDisplayMode() {
         foreach(auto displayPlugin, standard) {
             addDisplayPluginToMenu(displayPlugin, first);
             // This must be a queued connection to avoid a deadlock
-            QObject::connect(displayPlugin.get(), &DisplayPlugin::requestRender, [=] {
-                postEvent(this, new LambdaEvent([=] {
-                    paintGL(); 
-                }), Qt::HighEventPriority);
-            });
+            //QObject::connect(displayPlugin.get(), &DisplayPlugin::requestRender, [=] {
+            //    postEvent(this, new LambdaEvent([=] {
+            //        paintGL(); 
+            //    }), Qt::HighEventPriority);
+            //});
 
             QObject::connect(displayPlugin.get(), &DisplayPlugin::recommendedFramebufferSizeChanged, [this](const QSize & size) {
                 resizeGL();

interface/src/Application.h

@@ -508,6 +508,8 @@ private:
     int _avatarAttachmentRequest = 0;
 
     bool _settingsLoaded { false };
+    bool _pendingPaint { false };
+    QTimer* _idleTimer { nullptr };
 };
 
 #endif // hifi_Application_h

libraries/display-plugins/src/display-plugins/Basic2DWindowOpenGLDisplayPlugin.cpp

@@ -46,35 +46,19 @@ void Basic2DWindowOpenGLDisplayPlugin::internalPresent() {
     }
     WindowOpenGLDisplayPlugin::internalPresent();
 }
-const uint32_t THROTTLED_FRAMERATE = 15;
-int Basic2DWindowOpenGLDisplayPlugin::getDesiredInterval() const {
-    static const int ULIMIITED_PAINT_TIMER_DELAY_MS = 1;
-    int result = ULIMIITED_PAINT_TIMER_DELAY_MS;
-    if (_isThrottled) {
-        // This test wouldn't be necessary if we could depend on updateFramerate setting _framerateTarget.
-        // Alas, that gets complicated: isThrottled() is const and other stuff depends on it.
-        result = MSECS_PER_SECOND / THROTTLED_FRAMERATE;
-    }
 
-    return result;
-}
+static const uint32_t MIN_THROTTLE_CHECK_FRAMES = 60;
 
 bool Basic2DWindowOpenGLDisplayPlugin::isThrottled() const {
-    static const QString ThrottleFPSIfNotFocus = "Throttle FPS If Not Focus"; // FIXME - this value duplicated in Menu.h
-
-    bool shouldThrottle = (!_container->isForeground() && _container->isOptionChecked(ThrottleFPSIfNotFocus));
-    
-    if (_isThrottled != shouldThrottle) {
-        _isThrottled = shouldThrottle;
-        _timer.start(getDesiredInterval());
+    static auto lastCheck = presentCount();
+    // Don't access the menu API every single frame
+    if ((presentCount() - lastCheck) > MIN_THROTTLE_CHECK_FRAMES) {
+        static const QString ThrottleFPSIfNotFocus = "Throttle FPS If Not Focus"; // FIXME - this value duplicated in Menu.h
+        _isThrottled  = (!_container->isForeground() && _container->isOptionChecked(ThrottleFPSIfNotFocus));
+        lastCheck = presentCount();
     }
-    
-    return shouldThrottle;
-}
 
-void Basic2DWindowOpenGLDisplayPlugin::updateFramerate() {
-    int newInterval = getDesiredInterval();
-    _timer.start(newInterval);
+    return _isThrottled;
 }
 
 // FIXME target the screen the window is currently on

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

@@ -31,11 +31,9 @@ public:
     virtual bool isThrottled() const override;
 
 protected:
-    int getDesiredInterval() const;
     mutable bool _isThrottled = false;
 
 private:
-    void updateFramerate();
     static const QString NAME;
     QScreen* getFullscreenTarget();
     std::vector<QAction*> _framerateActions;

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

@@ -188,19 +188,6 @@ OpenGLDisplayPlugin::OpenGLDisplayPlugin() {
         cleanupForSceneTexture(texture);
         _container->releaseSceneTexture(texture);
     });
-
-    connect(&_timer, &QTimer::timeout, this, [&] {
-#ifdef Q_OS_MAC
-        // On Mac, QT thread timing is such that we can miss one or even two cycles quite often, giving a render rate (including update/simulate)
-        // far lower than what we want. This hack keeps that rate more natural, at the expense of some wasted rendering.
-        // This is likely to be mooted by further planned changes.
-        if (_active && _sceneTextureEscrow.depth() <= 1) {
-#else
-        if (_active && _sceneTextureEscrow.depth() < 1) {
-#endif
-            emit requestRender();
-        }
-    });
 }
 
 void OpenGLDisplayPlugin::cleanupForSceneTexture(uint32_t sceneTexture) {
@@ -214,7 +201,6 @@ void OpenGLDisplayPlugin::activate() {
     _vsyncSupported = _container->getPrimaryWidget()->isVsyncSupported();
 
 #if THREADED_PRESENT
-    _timer.start(1);
     // Start the present thread if necessary
     auto presentThread = DependencyManager::get<PresentThread>();
     if (!presentThread) {
@@ -236,12 +222,9 @@ void OpenGLDisplayPlugin::activate() {
     _container->makeRenderingContextCurrent();
 #endif
     DisplayPlugin::activate();
-
-    
 }
 
 void OpenGLDisplayPlugin::stop() {
-    _timer.stop();
 }
 
 void OpenGLDisplayPlugin::deactivate() {
@@ -250,7 +233,6 @@ void OpenGLDisplayPlugin::deactivate() {
         Lock lock(_mutex);
         _deactivateWait.wait(lock, [&]{ return _uncustomized; });
     }
-    _timer.stop();
 #else
     static auto widget = _container->getPrimaryWidget();
     widget->makeCurrent();
@@ -376,16 +358,12 @@ void OpenGLDisplayPlugin::internalPresent() {
 }
 
 void OpenGLDisplayPlugin::present() {
+    incrementPresentCount();
     updateTextures();
     if (_currentSceneTexture) {
         internalPresent();
         updateFramerate();
     }
-
-#if THREADED_PRESENT 
-#else
-    emit requestRender();
-#endif
 }
 
 float OpenGLDisplayPlugin::presentRate() {

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

@@ -73,7 +73,6 @@ protected:
     // Plugin specific functionality to composite the scene and overlay and present the result
     virtual void internalPresent();
 
-    mutable QTimer _timer;
     ProgramPtr _program;
     ShapeWrapperPtr _plane;
 

libraries/plugins/src/plugins/DisplayPlugin.h

@@ -8,6 +8,7 @@
 #pragma once
 
 #include <functional>
+#include <atomic>
 
 #include <glm/glm.hpp>
 #include <glm/gtc/quaternion.hpp>
@@ -122,10 +123,17 @@ public:
     virtual void resetSensors() {}
     virtual float devicePixelRatio() { return 1.0f; }
     virtual float presentRate() { return -1.0f; }
+    uint32_t presentCount() const { return _presentedFrameIndex; }
 
     static const QString& MENU_PATH();
+
 signals:
     void recommendedFramebufferSizeChanged(const QSize & size);
-    void requestRender();
+
+protected:
+    void incrementPresentCount() { ++_presentedFrameIndex; }
+
+private:
+    std::atomic<uint32_t> _presentedFrameIndex;
 };