Debugging.

Please enter the commit message for your changes. Lines starting

interface/src/Application.cpp

@@ -1117,6 +1117,8 @@ void Application::paintGL() {
     _inPaint = true;
     Finally clearFlagLambda([this] { _inPaint = false; });
 
+    _lastPaintWait = (float)(now - _paintWaitStart) / (float)USECS_PER_SECOND;
+    _lastInstantaneousFps = instantaneousFps;
     // Some LOD-like controls need to know a smoothly varying "potential" frame rate that doesn't
     // include time waiting for vsync, and which can report a number above target if we've got the headroom.
     // For example, if we're shooting for 75fps and paintWait is 3.3333ms (= 75% * 13.33ms), our deducedNonVSyncFps
@@ -1126,20 +1128,20 @@ void Application::paintGL() {
     // Time between previous paintGL call and this one, which can vary not only with vSync misses, but also with QT timing.
     // We're using this as a proxy for the time between vsync and displayEnd, below. (Not exact, but tends to be the same over time.)
     // This is not the same as update(deltaTime), because the latter attempts to throttle to 60hz and also clamps to 1/4 second.
-    //const float actualPeriod = diff / (float)USECS_PER_SECOND; // same as 1/instantaneousFps but easier for compiler to optimize
+/*    const float actualPeriod = diff / (float)USECS_PER_SECOND; // same as 1/instantaneousFps but easier for compiler to optimize
     // Note that _lastPaintWait (stored at end of last call) is for the same paint cycle.
-    float deducedNonVSyncPeriod = (float) getActiveDisplayPlugin()->getLastSynchronizedElapsed() / (float) MSECS_PER_SECOND; /*actualPeriod - _lastPaintWait + _marginForDeducedFramePeriod; // plus a some non-zero time for machinery we can't measure
+    float deducedNonVSyncPeriod = actualPeriod - _lastPaintWait + _marginForDeducedFramePeriod; // plus a some non-zero time for machinery we can't measure
     // We don't know how much time to allow for that, but if we went over the target period, we know it's at least the portion
     // of paintWait up to the next vSync. This gives us enough of a penalty so that when actualPeriod crosses two cycles,
     // the key part (and not an exagerated part) of _lastPaintWait is accounted for.
     const float targetPeriod = getTargetFramePeriod();
     if (_lastPaintWait > EPSILON && actualPeriod > targetPeriod) {
         // Don't use C++ remainder(). It's authors are mathematically insane.
-        deducedNonVSyncPeriod += fmod(actualPeriod, _lastPaintWait);
-    }*/
+        deducedNonVSyncPeriod += fmod(targetPeriod, _lastPaintWait);
+    }
     _lastDeducedNonVSyncFps = 1.0f / deducedNonVSyncPeriod;
-    _lastInstantaneousFps = instantaneousFps;
-
+    */
+ 
     auto displayPlugin = getActiveDisplayPlugin();
     // FIXME not needed anymore?
     _offscreenContext->makeCurrent();
@@ -1375,7 +1377,6 @@ void Application::paintGL() {
     }
 
     // deliver final composited scene to the display plugin
-    uint64_t displayStart = usecTimestampNow();
     {
         PROFILE_RANGE(__FUNCTION__ "/pluginOutput");
         PerformanceTimer perfTimer("pluginOutput");
@@ -1415,9 +1416,7 @@ void Application::paintGL() {
             batch.resetStages();
         });
     }
-    uint64_t displayEnd = usecTimestampNow();
-    const float displayPeriodUsec = (float)(displayEnd - displayStart); // usecs
-    _lastPaintWait = displayPeriodUsec / (float)USECS_PER_SECOND;
+    _paintWaitStart = usecTimestampNow();
 }
 
 void Application::runTests() {

interface/src/Application.h

@@ -443,6 +443,7 @@ private:
     QElapsedTimer _lastTimeUpdated;
     float _lastInstantaneousFps { 0.0f };
     float _lastPaintWait { 0.0f };
+    uint64_t _paintWaitStart { 0 };
     float _lastDeducedNonVSyncFps { 0.0f };
     float _marginForDeducedFramePeriod{ 0.002f }; // 2ms, adjustable
 

interface/src/avatar/Avatar.cpp

@@ -174,14 +174,14 @@ void Avatar::simulate(float deltaTime) {
             _shouldSkipRender = false;
             _skeletonModel.setVisibleInScene(true, qApp->getMain3DScene());
             if (!isControllerLogging) {  // Test for isMyAvatar is prophylactic. Never occurs in current code.
-                qCDebug(interfaceapp) << "Rerendering" << (isMyAvatar() ? "myself" : getSessionUUID()) << "for distance" << renderDistance;
+                //qCDebug(interfaceapp) << "Rerendering" << (isMyAvatar() ? "myself" : getSessionUUID()) << "for distance" << renderDistance;
             }
         }
     } else if (distance > renderDistance * (1.0f + SKIP_HYSTERESIS_PROPORTION)) {
         _shouldSkipRender = true;
         _skeletonModel.setVisibleInScene(false, qApp->getMain3DScene());
         if (!isControllerLogging) {
-            qCDebug(interfaceapp) << "Unrendering" << (isMyAvatar() ? "myself" : getSessionUUID()) << "for distance" << renderDistance;
+            //qCDebug(interfaceapp) << "Unrendering" << (isMyAvatar() ? "myself" : getSessionUUID()) << "for distance" << renderDistance;
         }
     }
 

interface/src/avatar/AvatarManager.cpp

@@ -111,7 +111,7 @@ void AvatarManager::init() {
     _renderDistanceController.setKP(0.0008f); // Usually about 0.6 of largest that doesn't oscillate when other parameters 0.
     _renderDistanceController.setKI(0.0006f); // Big enough to bring us to target with the above KP.
     _renderDistanceController.setKD(0.000001f); // A touch of kd increases the speed by which we get there.
-    _renderDistanceController.setHistorySize("av", 240); //FIXME
+    //_renderDistanceController.setHistorySize("av", 240); //FIXME
 }
 
 void AvatarManager::updateMyAvatar(float deltaTime) {
@@ -130,7 +130,7 @@ void AvatarManager::updateMyAvatar(float deltaTime) {
         _lastSendAvatarDataTime = now;
     }
 }
-
+#include "InterfaceLogging.h"
 void AvatarManager::updateOtherAvatars(float deltaTime) {
     // lock the hash for read to check the size
     QReadLocker lock(&_hashLock);
@@ -151,8 +151,21 @@ void AvatarManager::updateOtherAvatars(float deltaTime) {
     // The measured value is frame rate. When the controlled value (1 / render cutoff distance)
     // goes up, the render cutoff distance gets closer, the number of rendered avatars is less, and frame rate
     // goes up.
-    const float deduced = qApp->getLastDeducedNonVSyncFps();
-    const float distance = 1.0f / _renderDistanceController.update(deduced, deltaTime, false, qApp->getLastPaintWait(), qApp->getLastInstanteousFps());
+    const float targetFps = 60.0f;
+    const float instantaneousFps = qApp->getLastInstanteousFps();
+    const float paintWait = qApp->getLastPaintWait();
+    const float actual = 1.0f / instantaneousFps;
+    const float firstAdjusted = actual - paintWait + 0.002f;
+    const float machinery = (paintWait > 0.0001f) ? fmod(1.0f / targetFps, paintWait) : 0.0f;
+    const float secondAdjusted = firstAdjusted + machinery;
+    const float deduced = 1.0f / secondAdjusted;
+    qCDebug(interfaceapp) << "dump " << instantaneousFps << (1000.0f * paintWait)
+        << "(" << paintWait << actual
+        << "(" << firstAdjusted << machinery << secondAdjusted
+        << ")" << deduced << ")";
+
+    //const float deduced = qApp->getLastDeducedNonVSyncFps();
+    const float distance = 1.0f / _renderDistanceController.update(deduced, deltaTime, false, paintWait, instantaneousFps);
     _renderDistanceAverage.updateAverage(distance);
     _renderDistance = _renderDistanceAverage.getAverage();
     int renderableCount = 0;

libraries/shared/src/PIDController.cpp

@@ -70,7 +70,7 @@ void PIDController::reportHistory() {
     for (int i = 0; i < _history.size(); i++) {
         Row& row = _history[i];
         qCDebug(shared) << row.measured << row.dt <<
-        row.fixme1 << row.fixme2 <<
+        (row.fixme1 * 1000.0f) << (row.fixme2) <<
             "||" << row.error << row.accumulated << row.changed <<
             "||" << row.p << row.i << row.d << row.computed << 1.0f/row.computed;
     }