From c3f41cdd89a1c84a45cbe0595c821eea38607425 Mon Sep 17 00:00:00 2001 From: Zach Pomerantz Date: Tue, 10 May 2016 09:41:44 -0700 Subject: [PATCH 1/6] Add PAINT_DELAY_DEBUG log --- interface/src/Application.cpp | 14 ++++++++++++++ libraries/plugins/src/plugins/DisplayPlugin.cpp | 12 ++++++++++++ libraries/plugins/src/plugins/DisplayPlugin.h | 6 +++++- 3 files changed, 31 insertions(+), 1 deletion(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index aa98724a7d..0568b2f20e 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -2624,6 +2624,20 @@ void Application::idle(uint64_t now) { return; // bail early, we're throttled and not enough time has elapsed } +#ifdef DEBUG_PAINT_DELAY + static uint64_t paintDelaySamples{ 0 }; + static uint64_t paintDelayUsecs{ 0 }; + + paintDelayUsecs += displayPlugin->getPaintDelayUsecs(); + + static const int PAINT_DELAY_THROTTLE = 1000; + if (++paintDelaySamples % PAINT_DELAY_THROTTLE == 0) { + qCDebug(interfaceapp).nospace() << + "Paint delay (" << paintDelaySamples << " samples): " << + (float)paintDelaySamples / paintDelayUsecs << "us"; + } +#endif + auto presentCount = displayPlugin->presentCount(); if (presentCount < _renderedFrameIndex) { _renderedFrameIndex = INVALID_FRAME; diff --git a/libraries/plugins/src/plugins/DisplayPlugin.cpp b/libraries/plugins/src/plugins/DisplayPlugin.cpp index c7fa5f5671..f946547ebe 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.cpp +++ b/libraries/plugins/src/plugins/DisplayPlugin.cpp @@ -1,5 +1,6 @@ #include "DisplayPlugin.h" +#include #include #include "PluginContainer.h" @@ -23,4 +24,15 @@ void DisplayPlugin::deactivate() { Parent::deactivate(); } +int64_t DisplayPlugin::getPaintDelayUsecs() const { + return _paintDelayTimer.isValid() ? _paintDelayTimer.nsecsElapsed() / NSECS_PER_USEC : 0; +} +void DisplayPlugin::incrementPresentCount() { +#ifdef DEBUG_PAINT_DELAY + // Avoid overhead if we are not debugging + _paintDelayTimer.start(); +#endif + + ++_presentedFrameIndex; +} diff --git a/libraries/plugins/src/plugins/DisplayPlugin.h b/libraries/plugins/src/plugins/DisplayPlugin.h index 91dcf9398f..03a7737c3e 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.h +++ b/libraries/plugins/src/plugins/DisplayPlugin.h @@ -15,6 +15,7 @@ #include #include +#include class QImage; #include @@ -156,6 +157,8 @@ public: // Rate at which rendered frames are being skipped virtual float droppedFrameRate() const { return -1.0f; } uint32_t presentCount() const { return _presentedFrameIndex; } + // Time since last call to incrementPresentCount. Only valid if DEBUG_PAINT_DELAY is defined + int64_t getPaintDelayUsecs() const; virtual void cycleDebugOutput() {} @@ -165,9 +168,10 @@ signals: void recommendedFramebufferSizeChanged(const QSize & size); protected: - void incrementPresentCount() { ++_presentedFrameIndex; } + void incrementPresentCount(); private: std::atomic _presentedFrameIndex; + QElapsedTimer _paintDelayTimer; }; From 783be531254e4b0e4e7eb5df7162ca880b9020ac Mon Sep 17 00:00:00 2001 From: Zach Pomerantz Date: Tue, 10 May 2016 11:20:08 -0700 Subject: [PATCH 2/6] Trigger Idle from present Paint --- interface/src/Application.cpp | 117 +++++------------- interface/src/Application.h | 10 +- .../plugins/src/plugins/DisplayPlugin.cpp | 3 + libraries/plugins/src/plugins/DisplayPlugin.h | 4 + 4 files changed, 49 insertions(+), 85 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 0568b2f20e..bce0b77096 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -347,19 +347,14 @@ public: }; #endif -enum CustomEventTypes { - Lambda = QEvent::User + 1, - Paint = Lambda + 1, -}; - class LambdaEvent : public QEvent { std::function _fun; public: LambdaEvent(const std::function & fun) : - QEvent(static_cast(Lambda)), _fun(fun) { + QEvent(static_cast(Application::Lambda)), _fun(fun) { } LambdaEvent(std::function && fun) : - QEvent(static_cast(Lambda)), _fun(fun) { + QEvent(static_cast(Application::Lambda)), _fun(fun) { } void call() const { _fun(); } }; @@ -1060,18 +1055,6 @@ 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 too often. - _idleTimer->start(0); } @@ -1437,23 +1420,15 @@ void Application::initializeUi() { }); } - void Application::paintGL() { - updateHeartbeat(); - // Some plugins process message events, potentially leading to - // re-entering a paint event. don't allow further processing if this - // happens - if (_inPaint) { + // Some plugins process message events, allowing paintGL to be called reentrantly. + if (_inPaint || _aboutToQuit) { return; } - _inPaint = true; - Finally clearFlagLambda([this] { _inPaint = false; }); - // 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) { - return; - } + _inPaint = true; + Finally clearFlag([this] { _inPaint = false; }); + _frameCount++; _frameCounter.increment(); @@ -1811,14 +1786,16 @@ bool Application::event(QEvent* event) { return false; } - if ((int)event->type() == (int)Lambda) { - static_cast(event)->call(); + if ((int)event->type() == (int)Idle) { + idle(); + removePostedEvents(this, Idle); // clear pending idles so we don't clog the pipes return true; - } - - if ((int)event->type() == (int)Paint) { + } else if ((int)event->type() == (int)Paint) { paintGL(); return true; + } else if ((int)event->type() == (int)Lambda) { + static_cast(event)->call(); + return true; } if (!_keyboardFocusedItem.isInvalidID()) { @@ -2595,34 +2572,13 @@ bool Application::acceptSnapshot(const QString& urlString) { static uint32_t _renderedFrameIndex { INVALID_FRAME }; -void Application::idle(uint64_t now) { - // NOTICE NOTICE NOTICE NOTICE - // Do not insert new code between here and the PROFILE_RANGE declaration - // unless you know exactly what you're doing. This idle function can be - // called thousands per second or more, so any additional work that's done - // here will have a serious impact on CPU usage. Only add code after all - // the thottling logic, i.e. after PROFILE_RANGE - // NOTICE NOTICE NOTICE NOTICE - updateHeartbeat(); - - if (_aboutToQuit || _inPaint) { - return; // bail early, nothing to do here. +void Application::idle() { + // idle is called on a queued connection, so make sure we should be here. + if (_inPaint || _aboutToQuit) { + return; } 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 = 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 - } #ifdef DEBUG_PAINT_DELAY static uint64_t paintDelaySamples{ 0 }; @@ -2638,43 +2594,38 @@ void Application::idle(uint64_t now) { } #endif - auto presentCount = displayPlugin->presentCount(); - if (presentCount < _renderedFrameIndex) { - _renderedFrameIndex = INVALID_FRAME; - } + float msecondsSinceLastUpdate = (float)_lastTimeUpdated.nsecsElapsed() / NSECS_PER_USEC / USECS_PER_MSEC; - // Don't saturate the main thread with rendering and simulation, - // unless display plugin has increased by at least one frame - if (_renderedFrameIndex == INVALID_FRAME || presentCount > _renderedFrameIndex) { - // Record what present frame we're on - _renderedFrameIndex = presentCount; - - // request a paint, get to it as soon as possible: high priority - postEvent(this, new QEvent(static_cast(Paint)), Qt::HighEventPriority); - } else { - // there's no use in simulating or rendering faster then the present rate. + // Throttle if requested + if (displayPlugin->isThrottled() && (msecondsSinceLastUpdate < THROTTLED_SIM_FRAME_PERIOD_MS)) { return; } - // NOTICE NOTICE NOTICE NOTICE - // do NOT add new code above this line unless you want it to be executed potentially - // thousands of times per second - // NOTICE NOTICE NOTICE NOTICE + // Sync up the _renderedFrameIndex + _renderedFrameIndex = displayPlugin->presentCount(); - PROFILE_RANGE(__FUNCTION__); + // Request a paint ASAP + postEvent(this, new QEvent(static_cast(Paint)), Qt::HighEventPriority); + + // Update the deadlock watchdog + updateHeartbeat(); + + auto offscreenUi = DependencyManager::get(); // These tasks need to be done on our first idle, because we don't want the showing of // overlay subwindows to do a showDesktop() until after the first time through static bool firstIdle = true; if (firstIdle) { firstIdle = false; - auto offscreenUi = DependencyManager::get(); connect(offscreenUi.data(), &OffscreenUi::showDesktop, this, &Application::showDesktop); _overlayConductor.setEnabled(Menu::getInstance()->isOptionChecked(MenuOption::Overlays)); } + PROFILE_RANGE(__FUNCTION__); + + float secondsSinceLastUpdate = msecondsSinceLastUpdate / MSECS_PER_SECOND; + // If the offscreen Ui has something active that is NOT the root, then assume it has keyboard focus. - auto offscreenUi = DependencyManager::get(); if (_keyboardDeviceHasFocus && offscreenUi && offscreenUi->getWindow()->activeFocusItem() != offscreenUi->getRootItem()) { _keyboardMouseDevice->pluginFocusOutEvent(); _keyboardDeviceHasFocus = false; diff --git a/interface/src/Application.h b/interface/src/Application.h index f52dfc8c07..e13dffbcf1 100644 --- a/interface/src/Application.h +++ b/interface/src/Application.h @@ -33,6 +33,7 @@ #include #include #include +#include #include #include #include @@ -93,6 +94,12 @@ class Application : public QApplication, public AbstractViewStateInterface, publ friend class PluginContainerProxy; public: + enum Event { + Idle = DisplayPlugin::Paint, + Paint = Idle + 1, + Lambda = Paint + 1 + }; + // FIXME? Empty methods, do we still need them? static void initPlugins(); static void shutdownPlugins(); @@ -282,7 +289,6 @@ public slots: private slots: void showDesktop(); void clearDomainOctreeDetails(); - void idle(uint64_t now); void aboutToQuit(); void resettingDomain(); @@ -321,6 +327,7 @@ private: void cleanupBeforeQuit(); + void idle(); void update(float deltaTime); // Various helper functions called during update() @@ -498,7 +505,6 @@ private: int _avatarAttachmentRequest = 0; bool _settingsLoaded { false }; - QTimer* _idleTimer { nullptr }; bool _fakedMouseEvent { false }; diff --git a/libraries/plugins/src/plugins/DisplayPlugin.cpp b/libraries/plugins/src/plugins/DisplayPlugin.cpp index f946547ebe..f52910b952 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.cpp +++ b/libraries/plugins/src/plugins/DisplayPlugin.cpp @@ -35,4 +35,7 @@ void DisplayPlugin::incrementPresentCount() { #endif ++_presentedFrameIndex; + + // Alert the app that it needs to paint a new presentation frame + qApp->postEvent(qApp, new QEvent(static_cast(Paint)), Qt::HighEventPriority); } diff --git a/libraries/plugins/src/plugins/DisplayPlugin.h b/libraries/plugins/src/plugins/DisplayPlugin.h index 03a7737c3e..1e9b16eeac 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.h +++ b/libraries/plugins/src/plugins/DisplayPlugin.h @@ -60,6 +60,10 @@ class DisplayPlugin : public Plugin { Q_OBJECT using Parent = Plugin; public: + enum Event { + Paint = QEvent::User + 1 + }; + bool activate() override; void deactivate() override; virtual bool isHmd() const { return false; } From 4711c23d9d5b612214689c9711dcd7a8709128fe Mon Sep 17 00:00:00 2001 From: Zach Pomerantz Date: Tue, 10 May 2016 14:34:12 -0700 Subject: [PATCH 3/6] Delay AvatarInputs instantiation to first paint --- interface/src/Application.cpp | 4 +++- 1 file changed, 3 insertions(+), 1 deletion(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index bce0b77096..4ae206795d 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -2619,6 +2619,9 @@ void Application::idle() { firstIdle = false; connect(offscreenUi.data(), &OffscreenUi::showDesktop, this, &Application::showDesktop); _overlayConductor.setEnabled(Menu::getInstance()->isOptionChecked(MenuOption::Overlays)); + } else { + // FIXME: AvatarInputs are positioned incorrectly if instantiated before the first paint + AvatarInputs::getInstance()->update(); } PROFILE_RANGE(__FUNCTION__); @@ -2641,7 +2644,6 @@ void Application::idle() { checkChangeCursor(); Stats::getInstance()->updateStats(); - AvatarInputs::getInstance()->update(); _simCounter.increment(); From dd6a4dd091b87262716db6ece18dc8a8dd77f665 Mon Sep 17 00:00:00 2001 From: Zach Pomerantz Date: Tue, 10 May 2016 16:06:33 -0700 Subject: [PATCH 4/6] Make getPaintDelayUsecs threadsafe --- libraries/plugins/src/plugins/DisplayPlugin.cpp | 6 +++++- libraries/plugins/src/plugins/DisplayPlugin.h | 3 ++- 2 files changed, 7 insertions(+), 2 deletions(-) diff --git a/libraries/plugins/src/plugins/DisplayPlugin.cpp b/libraries/plugins/src/plugins/DisplayPlugin.cpp index f52910b952..430da00061 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.cpp +++ b/libraries/plugins/src/plugins/DisplayPlugin.cpp @@ -25,13 +25,17 @@ void DisplayPlugin::deactivate() { } int64_t DisplayPlugin::getPaintDelayUsecs() const { + std::lock_guard lock(_paintDelayMutex); return _paintDelayTimer.isValid() ? _paintDelayTimer.nsecsElapsed() / NSECS_PER_USEC : 0; } void DisplayPlugin::incrementPresentCount() { #ifdef DEBUG_PAINT_DELAY // Avoid overhead if we are not debugging - _paintDelayTimer.start(); + { + std::lock_guard lock(_paintDelayMutex); + _paintDelayTimer.start(); + } #endif ++_presentedFrameIndex; diff --git a/libraries/plugins/src/plugins/DisplayPlugin.h b/libraries/plugins/src/plugins/DisplayPlugin.h index 1e9b16eeac..3a668f27d7 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.h +++ b/libraries/plugins/src/plugins/DisplayPlugin.h @@ -161,7 +161,7 @@ public: // Rate at which rendered frames are being skipped virtual float droppedFrameRate() const { return -1.0f; } uint32_t presentCount() const { return _presentedFrameIndex; } - // Time since last call to incrementPresentCount. Only valid if DEBUG_PAINT_DELAY is defined + // Time since last call to incrementPresentCount (only valid if DEBUG_PAINT_DELAY is defined) int64_t getPaintDelayUsecs() const; virtual void cycleDebugOutput() {} @@ -176,6 +176,7 @@ protected: private: std::atomic _presentedFrameIndex; + mutable std::mutex _paintDelayMutex; QElapsedTimer _paintDelayTimer; }; From 2d4fd783bd7f808dc9c718092f45b8b25c0de327 Mon Sep 17 00:00:00 2001 From: Zach Pomerantz Date: Tue, 10 May 2016 16:09:04 -0700 Subject: [PATCH 5/6] Rename Paint/Idle events to Present --- interface/src/Application.cpp | 4 ++-- interface/src/Application.h | 4 ++-- libraries/plugins/src/plugins/DisplayPlugin.cpp | 2 +- libraries/plugins/src/plugins/DisplayPlugin.h | 2 +- 4 files changed, 6 insertions(+), 6 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 4ae206795d..3ba362e56d 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -1786,9 +1786,9 @@ bool Application::event(QEvent* event) { return false; } - if ((int)event->type() == (int)Idle) { + if ((int)event->type() == (int)Present) { idle(); - removePostedEvents(this, Idle); // clear pending idles so we don't clog the pipes + removePostedEvents(this, Present); // clear pending presents so we don't clog the pipes return true; } else if ((int)event->type() == (int)Paint) { paintGL(); diff --git a/interface/src/Application.h b/interface/src/Application.h index e13dffbcf1..0d88352b2f 100644 --- a/interface/src/Application.h +++ b/interface/src/Application.h @@ -95,8 +95,8 @@ class Application : public QApplication, public AbstractViewStateInterface, publ public: enum Event { - Idle = DisplayPlugin::Paint, - Paint = Idle + 1, + Present = DisplayPlugin::Present, + Paint = Present + 1, Lambda = Paint + 1 }; diff --git a/libraries/plugins/src/plugins/DisplayPlugin.cpp b/libraries/plugins/src/plugins/DisplayPlugin.cpp index 430da00061..a217041f4e 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.cpp +++ b/libraries/plugins/src/plugins/DisplayPlugin.cpp @@ -41,5 +41,5 @@ void DisplayPlugin::incrementPresentCount() { ++_presentedFrameIndex; // Alert the app that it needs to paint a new presentation frame - qApp->postEvent(qApp, new QEvent(static_cast(Paint)), Qt::HighEventPriority); + qApp->postEvent(qApp, new QEvent(static_cast(Present)), Qt::HighEventPriority); } diff --git a/libraries/plugins/src/plugins/DisplayPlugin.h b/libraries/plugins/src/plugins/DisplayPlugin.h index 3a668f27d7..41f380aa86 100644 --- a/libraries/plugins/src/plugins/DisplayPlugin.h +++ b/libraries/plugins/src/plugins/DisplayPlugin.h @@ -61,7 +61,7 @@ class DisplayPlugin : public Plugin { using Parent = Plugin; public: enum Event { - Paint = QEvent::User + 1 + Present = QEvent::User + 1 }; bool activate() override; From 25deaf5bda523ef53c574e997dae4b515be42931 Mon Sep 17 00:00:00 2001 From: Zach Pomerantz Date: Wed, 11 May 2016 18:27:32 -0700 Subject: [PATCH 6/6] Repost missed Presents with low priority --- interface/src/Application.cpp | 21 ++++++++++++++++++--- 1 file changed, 18 insertions(+), 3 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 3ba362e56d..3599303239 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -1786,14 +1786,29 @@ bool Application::event(QEvent* event) { return false; } + static bool justPresented = false; if ((int)event->type() == (int)Present) { + if (justPresented) { + justPresented = false; + + // If presentation is hogging the main thread, repost as low priority to avoid hanging the GUI. + // This has the effect of allowing presentation to exceed the paint budget by X times and + // only dropping every (1/X) frames, instead of every ceil(X) frames. + // (e.g. at a 60FPS target, painting for 17us would fall to 58.82FPS instead of 30FPS). + removePostedEvents(this, Present); + postEvent(this, new QEvent(static_cast(Present)), Qt::LowEventPriority); + return true; + } + idle(); - removePostedEvents(this, Present); // clear pending presents so we don't clog the pipes return true; } else if ((int)event->type() == (int)Paint) { + justPresented = true; paintGL(); return true; - } else if ((int)event->type() == (int)Lambda) { + } + + if ((int)event->type() == (int)Lambda) { static_cast(event)->call(); return true; } @@ -2605,7 +2620,7 @@ void Application::idle() { _renderedFrameIndex = displayPlugin->presentCount(); // Request a paint ASAP - postEvent(this, new QEvent(static_cast(Paint)), Qt::HighEventPriority); + postEvent(this, new QEvent(static_cast(Paint)), Qt::HighEventPriority + 1); // Update the deadlock watchdog updateHeartbeat();