Merge pull request #2956 from ZappoMan/perfstats

Fix Ray Intersection bug that was causing low FPS... also added more performance debugging

interface/src/Application.cpp

@@ -2001,8 +2001,14 @@ void Application::update(float deltaTime) {
         _joystickManager.update();
         _prioVR.update(deltaTime);
     }
-    updateMyAvatar(deltaTime); // Sample hardware, update view frustum if needed, and send avatar data to mixer/nodes
+    
+    {
+        PerformanceTimer perfTimer("idle/update/updateMyAvatar");
+        updateMyAvatar(deltaTime); // Sample hardware, update view frustum if needed, and send avatar data to mixer/nodes
+    }
+    
     updateThreads(deltaTime); // If running non-threaded, then give the threads some time to process...
+    
     {
         PerformanceTimer perfTimer("idle/update/_avatarManager");
         _avatarManager.updateOtherAvatars(deltaTime); //loop through all the other avatars and simulate them...
@@ -2039,17 +2045,22 @@ void Application::update(float deltaTime) {
 }
 
 void Application::updateMyAvatar(float deltaTime) {
-    PerformanceTimer perfTimer("idle/update/updateMyAvatar");
+    PerformanceTimer perfTimer("updateMyAvatar");
     bool showWarnings = Menu::getInstance()->isOptionChecked(MenuOption::PipelineWarnings);
     PerformanceWarning warn(showWarnings, "Application::updateMyAvatar()");
 
-    _myAvatar->update(deltaTime);
+    {
+        PerformanceTimer perfTimer("updateMyAvatar/_myAvatar->update()");
+        _myAvatar->update(deltaTime);
+    }
 
-    // send head/hand data to the avatar mixer and voxel server
+    {
-    QByteArray packet = byteArrayWithPopulatedHeader(PacketTypeAvatarData);
+        // send head/hand data to the avatar mixer and voxel server
-    packet.append(_myAvatar->toByteArray());
+        PerformanceTimer perfTimer("updateMyAvatar/sendToAvatarMixer");
-
+        QByteArray packet = byteArrayWithPopulatedHeader(PacketTypeAvatarData);
-    controlledBroadcastToNodes(packet, NodeSet() << NodeType::AvatarMixer);
+        packet.append(_myAvatar->toByteArray());
+        controlledBroadcastToNodes(packet, NodeSet() << NodeType::AvatarMixer);
+    }
 
     // Update _viewFrustum with latest camera and view frustum data...
     // NOTE: we get this from the view frustum, to make it simpler, since the
@@ -2057,22 +2068,28 @@ void Application::updateMyAvatar(float deltaTime) {
     // We could optimize this to not actually load the viewFrustum, since we don't
     // actually need to calculate the view frustum planes to send these details
     // to the server.
-    loadViewFrustum(_myCamera, _viewFrustum);
+    {
+        PerformanceTimer perfTimer("updateMyAvatar/loadViewFrustum");
+        loadViewFrustum(_myCamera, _viewFrustum);
+    }
 
     // Update my voxel servers with my current voxel query...
-    quint64 now = usecTimestampNow();
+    {
-    quint64 sinceLastQuery = now - _lastQueriedTime;
+        PerformanceTimer perfTimer("updateMyAvatar/queryOctree");
-    const quint64 TOO_LONG_SINCE_LAST_QUERY = 3 * USECS_PER_SECOND;
+        quint64 now = usecTimestampNow();
-    bool queryIsDue = sinceLastQuery > TOO_LONG_SINCE_LAST_QUERY;
+        quint64 sinceLastQuery = now - _lastQueriedTime;
-    bool viewIsDifferentEnough = !_lastQueriedViewFrustum.isVerySimilar(_viewFrustum);
+        const quint64 TOO_LONG_SINCE_LAST_QUERY = 3 * USECS_PER_SECOND;
+        bool queryIsDue = sinceLastQuery > TOO_LONG_SINCE_LAST_QUERY;
+        bool viewIsDifferentEnough = !_lastQueriedViewFrustum.isVerySimilar(_viewFrustum);
 
-    // if it's been a while since our last query or the view has significantly changed then send a query, otherwise suppress it
+        // if it's been a while since our last query or the view has significantly changed then send a query, otherwise suppress it
-    if (queryIsDue || viewIsDifferentEnough) {
+        if (queryIsDue || viewIsDifferentEnough) {
-        _lastQueriedTime = now;
+            _lastQueriedTime = now;
-        queryOctree(NodeType::VoxelServer, PacketTypeVoxelQuery, _voxelServerJurisdictions);
+            queryOctree(NodeType::VoxelServer, PacketTypeVoxelQuery, _voxelServerJurisdictions);
-        queryOctree(NodeType::ParticleServer, PacketTypeParticleQuery, _particleServerJurisdictions);
+            queryOctree(NodeType::ParticleServer, PacketTypeParticleQuery, _particleServerJurisdictions);
-        queryOctree(NodeType::ModelServer, PacketTypeModelQuery, _modelServerJurisdictions);
+            queryOctree(NodeType::ModelServer, PacketTypeModelQuery, _modelServerJurisdictions);
-        _lastQueriedViewFrustum = _viewFrustum;
+            _lastQueriedViewFrustum = _viewFrustum;
+        }
     }
 }
 
@@ -2300,7 +2317,7 @@ glm::vec3 Application::getSunDirection() {
 }
 
 void Application::updateShadowMap() {
-    PerformanceTimer perfTimer("pintGL/updateShadowMap");
+    PerformanceTimer perfTimer("paintGL/updateShadowMap");
     QOpenGLFramebufferObject* fbo = _textureCache.getShadowFramebufferObject();
     fbo->bind();
     glEnable(GL_DEPTH_TEST);

interface/src/Menu.cpp

@@ -391,6 +391,9 @@ Menu::Menu() :
     QMenu* perfTimerMenu = timingMenu->addMenu("Performance Timer");
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::DisplayTimingDetails, 0, true);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandDisplaySideTiming, 0, false);
+    addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandAvatarSimulateTiming, 0, false);
+    addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandAvatarUpdateTiming, 0, false);
+    addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandMiscAvatarTiming, 0, false);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandIdleTiming, 0, false);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandPaintGLTiming, 0, false);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandUpdateTiming, 0, false);

interface/src/Menu.h

@@ -326,6 +326,9 @@ namespace MenuOption {
     const QString EchoLocalAudio = "Echo Local Audio";
     const QString EchoServerAudio = "Echo Server Audio";
     const QString Enable3DTVMode = "Enable 3DTV Mode";
+    const QString ExpandMiscAvatarTiming = "Expand Misc MyAvatar Timing";
+    const QString ExpandAvatarUpdateTiming = "Expand MyAvatar update Timing";
+    const QString ExpandAvatarSimulateTiming = "Expand MyAvatar simulate Timing";
     const QString ExpandDisplaySideTiming = "Expand Display Side Timing";
     const QString ExpandIdleTiming = "Expand Idle Timing";
     const QString ExpandPaintGLTiming = "Expand PaintGL Timing";

interface/src/avatar/MyAvatar.cpp

@@ -24,9 +24,9 @@
 #include <GeometryUtil.h>
 #include <NodeList.h>
 #include <PacketHeaders.h>
-#include <SharedUtil.h>
+#include <PerfStat.h>
-
 #include <ShapeCollider.h>
+#include <SharedUtil.h>
 
 #include "Application.h"
 #include "Audio.h"
@@ -103,10 +103,15 @@ void MyAvatar::reset() {
 }
 
 void MyAvatar::update(float deltaTime) {
+    PerformanceTimer perfTimer("MyAvatar::update/");
     Head* head = getHead();
     head->relaxLean(deltaTime);
-    updateFromTrackers(deltaTime);
+    {
+        PerformanceTimer perfTimer("MyAvatar::update/updateFromTrackers");
+        updateFromTrackers(deltaTime);
+    }
     if (Menu::getInstance()->isOptionChecked(MenuOption::MoveWithLean)) {
+        PerformanceTimer perfTimer("MyAvatar::update/moveWithLean");
         // Faceshift drive is enabled, set the avatar drive based on the head position
         moveWithLean();
     }
@@ -117,13 +122,18 @@ void MyAvatar::update(float deltaTime) {
     head->setAudioAverageLoudness(audio->getAudioAverageInputLoudness());
 
     if (_motionBehaviors & AVATAR_MOTION_OBEY_ENVIRONMENTAL_GRAVITY) {
+        PerformanceTimer perfTimer("MyAvatar::update/gravityWork");
         setGravity(Application::getInstance()->getEnvironment()->getGravity(getPosition()));
     }
 
-    simulate(deltaTime);
+    {
+        PerformanceTimer perfTimer("MyAvatar::update/simulate");
+        simulate(deltaTime);
+    }
 }
 
 void MyAvatar::simulate(float deltaTime) {
+    PerformanceTimer perfTimer("MyAvatar::simulate");
 
     if (_scale != _targetScale) {
         float scale = (1.0f - SMOOTHING_RATIO) * _scale + SMOOTHING_RATIO * _targetScale;
@@ -134,34 +144,56 @@ void MyAvatar::simulate(float deltaTime) {
     // no extra movement of the hand here any more ...
     _handState = HAND_STATE_NULL;
 
-    updateOrientation(deltaTime);
+    {
-    updatePosition(deltaTime);
+        PerformanceTimer perfTimer("MyAvatar::simulate/updateOrientation");
-
+        updateOrientation(deltaTime);
-    // update avatar skeleton and simulate hand and head
+    }
-    getHand()->collideAgainstOurself(); 
+    {
-    getHand()->simulate(deltaTime, true);
+        PerformanceTimer perfTimer("MyAvatar::simulate/updatePosition");
-
+        updatePosition(deltaTime);
-    _skeletonModel.simulate(deltaTime);
-    simulateAttachments(deltaTime);
-
-    // copy out the skeleton joints from the model
-    _jointData.resize(_skeletonModel.getJointStateCount());
-    for (int i = 0; i < _jointData.size(); i++) {
-        JointData& data = _jointData[i];
-        data.valid = _skeletonModel.getJointState(i, data.rotation);
     }
 
-    Head* head = getHead();
+    {
-    glm::vec3 headPosition;
+        PerformanceTimer perfTimer("MyAvatar::simulate/hand Collision,simulate");
-    if (!_skeletonModel.getHeadPosition(headPosition)) {
+        // update avatar skeleton and simulate hand and head
-        headPosition = _position;
+        getHand()->collideAgainstOurself(); 
+        getHand()->simulate(deltaTime, true);
+    }
+
+    {
+        PerformanceTimer perfTimer("MyAvatar::simulate/_skeletonModel.simulate()");
+        _skeletonModel.simulate(deltaTime);
+    }
+    {
+        PerformanceTimer perfTimer("MyAvatar::simulate/simulateAttachments");
+        simulateAttachments(deltaTime);
+    }
+
+    {
+        PerformanceTimer perfTimer("MyAvatar::simulate/copy joints");
+        // copy out the skeleton joints from the model
+        _jointData.resize(_skeletonModel.getJointStateCount());
+        for (int i = 0; i < _jointData.size(); i++) {
+            JointData& data = _jointData[i];
+            data.valid = _skeletonModel.getJointState(i, data.rotation);
+        }
+    }
+
+    {
+        PerformanceTimer perfTimer("MyAvatar::simulate/head Simulate");
+        Head* head = getHead();
+        glm::vec3 headPosition;
+        if (!_skeletonModel.getHeadPosition(headPosition)) {
+            headPosition = _position;
+        }
+        head->setPosition(headPosition);
+        head->setScale(_scale);
+        head->simulate(deltaTime, true);
     }
-    head->setPosition(headPosition);
-    head->setScale(_scale);
-    head->simulate(deltaTime, true);
 
     // now that we're done stepping the avatar forward in time, compute new collisions
     if (_collisionGroups != 0) {
+        PerformanceTimer perfTimer("MyAvatar::simulate/_collisionGroups");
         Camera* myCamera = Application::getInstance()->getCamera();
 
         float radius = getSkeletonHeight() * COLLISION_RADIUS_SCALE;
@@ -171,14 +203,17 @@ void MyAvatar::simulate(float deltaTime) {
         }
         updateShapePositions();
         if (_collisionGroups & COLLISION_GROUP_ENVIRONMENT) {
+            PerformanceTimer perfTimer("MyAvatar::simulate/updateCollisionWithEnvironment");
             updateCollisionWithEnvironment(deltaTime, radius);
         }
         if (_collisionGroups & COLLISION_GROUP_VOXELS) {
+            PerformanceTimer perfTimer("MyAvatar::simulate/updateCollisionWithVoxels");
             updateCollisionWithVoxels(deltaTime, radius);
         } else {
             _trapDuration = 0.0f;
         }
         if (_collisionGroups & COLLISION_GROUP_AVATARS) {
+            PerformanceTimer perfTimer("MyAvatar::simulate/updateCollisionWithAvatars");
             updateCollisionWithAvatars(deltaTime);
         }
     }
@@ -791,6 +826,7 @@ bool MyAvatar::shouldRenderHead(const glm::vec3& cameraPosition, RenderMode rend
 }
 
 float MyAvatar::computeDistanceToFloor(const glm::vec3& startPoint) {
+    PerformanceTimer perfTimer("MyAvatar::computeDistanceToFloor()");
     glm::vec3 direction = -_worldUpDirection;
     OctreeElement* elementHit; // output from findRayIntersection
     float distance = FLT_MAX; // output from findRayIntersection
@@ -876,6 +912,7 @@ void MyAvatar::updateOrientation(float deltaTime) {
 const float NEARBY_FLOOR_THRESHOLD = 5.0f;
 
 void MyAvatar::updatePosition(float deltaTime) {
+    PerformanceTimer perfTimer("MyAvatar::updatePosition");
     float keyboardInput = fabsf(_driveKeys[FWD] - _driveKeys[BACK]) + 
         fabsf(_driveKeys[RIGHT] - _driveKeys[LEFT]) + 
         fabsf(_driveKeys[UP] - _driveKeys[DOWN]);

interface/src/ui/Stats.cpp

@@ -173,6 +173,12 @@ bool Stats::includeTimingRecord(const QString& name) {
             included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandUpdateTiming);
         } else if (name.startsWith("idle/")) {
             included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandIdleTiming);
+        } else if (name.startsWith("MyAvatar::simulate")) {
+            included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandAvatarSimulateTiming);
+        } else if (name.startsWith("MyAvatar::update/") || name.startsWith("updateMyAvatar")) {
+            included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandAvatarUpdateTiming);
+        } else if (name.startsWith("MyAvatar::")) {
+            included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandMiscAvatarTiming);
         } else if (name == "paintGL/displaySide") {
             included = Menu::getInstance()->isOptionChecked(MenuOption::ExpandDisplaySideTiming) ||
                        Menu::getInstance()->isOptionChecked(MenuOption::ExpandPaintGLTiming);
@@ -556,14 +562,14 @@ void Stats::display(
         char perfLine[TIMER_OUTPUT_LINE_LENGTH];
         verticalOffset += STATS_PELS_PER_LINE;
         drawText(horizontalOffset, verticalOffset, scale, rotation, font, 
-                "---------------- Function --------------- --msecs- -calls--", color);
+                "--------------------- Function -------------------- --msecs- -calls--", color);
 
         const QMap<QString, PerformanceTimerRecord>& allRecords = PerformanceTimer::getAllTimerRecords();
         QMapIterator<QString, PerformanceTimerRecord> i(allRecords);
         while (i.hasNext()) {
             i.next();
             if (includeTimingRecord(i.key())) {
-                sprintf(perfLine, "%40s: %8.4f [%6llu]", qPrintable(i.key()),
+                sprintf(perfLine, "%50s: %8.4f [%6llu]", qPrintable(i.key()),
                             (float)i.value().getMovingAverage() / (float)USECS_PER_MSEC,
                             i.value().getCount());
             

libraries/octree/src/OctreeElement.cpp

@@ -1308,11 +1308,6 @@ bool OctreeElement::findRayIntersection(const glm::vec3& origin, const glm::vec3
 
     keepSearching = true; // assume that we will continue searching after this.
 
-    // by default, we only allow intersections with leaves with content
-    if (!canRayIntersect()) {
-        return false; // we don't intersect with non-leaves, and we keep searching
-    }
-
     AACube cube = getAACube();
     float localDistance;
     BoxFace localFace;
@@ -1323,6 +1318,11 @@ bool OctreeElement::findRayIntersection(const glm::vec3& origin, const glm::vec3
         return false; // we did not intersect
     }
 
+    // by default, we only allow intersections with leaves with content
+    if (!canRayIntersect()) {
+        return false; // we don't intersect with non-leaves, and we keep searching
+    }
+
     // we did hit this element, so calculate appropriate distances    
     localDistance *= TREE_SCALE;
     if (localDistance < distance) {
@@ -1346,6 +1346,7 @@ bool OctreeElement::findDetailedRayIntersection(const glm::vec3& origin, const g
         if (intersectedObject) {
             *intersectedObject = this;
         }
+        keepSearching = false;
         return true; // we did intersect
     }
     return false; // we did not intersect