From 908e153c3609d750917293570bdee25c6527c2e6 Mon Sep 17 00:00:00 2001 From: Brad Davis Date: Wed, 10 Feb 2016 10:21:19 -0800 Subject: [PATCH] Don't drop to half the vsync rate when we can't keep up --- examples/tests/performance/consoleSpawner.js | 161 ++++++++++++++++++ interface/src/Application.cpp | 78 +++++++-- interface/src/Application.h | 2 + .../Basic2DWindowOpenGLDisplayPlugin.cpp | 32 +--- .../Basic2DWindowOpenGLDisplayPlugin.h | 2 - .../display-plugins/OpenGLDisplayPlugin.cpp | 24 +-- .../src/display-plugins/OpenGLDisplayPlugin.h | 1 - libraries/plugins/src/plugins/DisplayPlugin.h | 10 +- 8 files changed, 247 insertions(+), 63 deletions(-) create mode 100644 examples/tests/performance/consoleSpawner.js diff --git a/examples/tests/performance/consoleSpawner.js b/examples/tests/performance/consoleSpawner.js new file mode 100644 index 0000000000..d85cad8d0c --- /dev/null +++ b/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); +})(); \ No newline at end of file diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index c0416e75da..1b1b3d2338 100644 --- a/interface/src/Application.cpp +++ b/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(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(); diff --git a/interface/src/Application.h b/interface/src/Application.h index 8aa2de53a5..3880263aee 100644 --- a/interface/src/Application.h +++ b/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 diff --git a/libraries/display-plugins/src/display-plugins/Basic2DWindowOpenGLDisplayPlugin.cpp b/libraries/display-plugins/src/display-plugins/Basic2DWindowOpenGLDisplayPlugin.cpp index fb6e9c3b65..6b111ad751 100644 --- a/libraries/display-plugins/src/display-plugins/Basic2DWindowOpenGLDisplayPlugin.cpp +++ b/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 diff --git a/libraries/display-plugins/src/display-plugins/Basic2DWindowOpenGLDisplayPlugin.h b/libraries/display-plugins/src/display-plugins/Basic2DWindowOpenGLDisplayPlugin.h index 6523b58914..23b5d32252 100644 --- a/libraries/display-plugins/src/display-plugins/Basic2DWindowOpenGLDisplayPlugin.h +++ b/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 _framerateActions; diff --git a/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp b/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp index 2da60e4205..ab9017d0fc 100644 --- a/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.cpp +++ b/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(); 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() { diff --git a/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.h b/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.h index d1000267ef..5ff9b22e1a 100644 --- a/libraries/display-plugins/src/display-plugins/OpenGLDisplayPlugin.h +++ b/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; diff --git a/libraries/plugins/src/plugins/DisplayPlugin.h b/libraries/plugins/src/plugins/DisplayPlugin.h index 7f3b38e4a2..744d678fff 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.h +++ b/libraries/plugins/src/plugins/DisplayPlugin.h @@ -8,6 +8,7 @@ #pragma once #include +#include #include #include @@ -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 _presentedFrameIndex; };