Merge pull request #8879 from AndrewMeadows/show-physics-stats

add Bullet profile info to PerformanceTimer stats

interface/src/Application.cpp

@@ -3969,8 +3969,6 @@ void Application::update(float deltaTime) {
                 auto collisionEvents = _physicsEngine->getCollisionEvents();
                 avatarManager->handleCollisionEvents(collisionEvents);
 
-                _physicsEngine->dumpStatsIfNecessary();
-
                 if (!_aboutToQuit) {
                     PerformanceTimer perfTimer("entities");
                     // Collision events (and their scripts) must not be handled when we're locked, above. (That would risk
@@ -3983,6 +3981,13 @@ void Application::update(float deltaTime) {
                 }
 
                 myAvatar->harvestResultsFromPhysicsSimulation(deltaTime);
+
+                if (Menu::getInstance()->isOptionChecked(MenuOption::DisplayDebugTimingDetails) &&
+                        Menu::getInstance()->isOptionChecked(MenuOption::ExpandPhysicsSimulationTiming)) {
+                    _physicsEngine->harvestPerformanceStats();
+                }
+                // NOTE: the PhysicsEngine stats are written to stdout NOT to Qt log framework
+                _physicsEngine->dumpStatsIfNecessary();
             }
         }
     }

interface/src/Menu.cpp

@@ -605,6 +605,7 @@ Menu::Menu() {
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandMyAvatarSimulateTiming, 0, false);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandOtherAvatarTiming, 0, false);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandPaintGLTiming, 0, false);
+    addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandPhysicsSimulationTiming, 0, false);
 
     addCheckableActionToQMenuAndActionHash(timingMenu, MenuOption::FrameTimer);
     addActionToQMenuAndActionHash(timingMenu, MenuOption::RunTimingTests, 0, qApp, SLOT(runTests()));

interface/src/Menu.h

@@ -104,6 +104,7 @@ namespace MenuOption {
     const QString ExpandMyAvatarTiming = "Expand /myAvatar";
     const QString ExpandOtherAvatarTiming = "Expand /otherAvatar";
     const QString ExpandPaintGLTiming = "Expand /paintGL";
+    const QString ExpandPhysicsSimulationTiming = "Expand /physics";
     const QString ExpandUpdateTiming = "Expand /update";
     const QString Faceshift = "Faceshift";
     const QString FirstPerson = "First Person";

interface/src/ui/Stats.cpp

@@ -55,7 +55,9 @@ Stats::Stats(QQuickItem* parent) :  QQuickItem(parent) {
 bool Stats::includeTimingRecord(const QString& name) {
     if (Menu::getInstance()->isOptionChecked(MenuOption::DisplayDebugTimingDetails)) {
         if (name.startsWith("/idle/update/")) {
-            if (name.startsWith("/idle/update/myAvatar/")) {
+            if (name.startsWith("/idle/update/physics/")) {
+                return Menu::getInstance()->isOptionChecked(MenuOption::ExpandPhysicsSimulationTiming);
+            } else if (name.startsWith("/idle/update/myAvatar/")) {
                 if (name.startsWith("/idle/update/myAvatar/simulate/")) {
                     return Menu::getInstance()->isOptionChecked(MenuOption::ExpandMyAvatarSimulateTiming);
                 }
@@ -369,7 +371,7 @@ void Stats::updateStats(bool force) {
             QString functionName = j.value();
             const PerformanceTimerRecord& record = allRecords.value(functionName);
             perfLines += QString("%1: %2 [%3]\n").
-                arg(QString(qPrintable(functionName)), 90, noBreakingSpace).
+                arg(QString(qPrintable(functionName)), -80, noBreakingSpace).
                 arg((float)record.getMovingAverage() / (float)USECS_PER_MSEC, 8, 'f', 3, noBreakingSpace).
                 arg((int)record.getCount(), 6, 10, noBreakingSpace);
             linesDisplayed++;

libraries/physics/src/PhysicsEngine.cpp

@@ -11,6 +11,8 @@
 
 #include <PhysicsCollisionGroups.h>
 
+#include <PerfStat.h>
+
 #include "CharacterController.h"
 #include "ObjectMotionState.h"
 #include "PhysicsEngine.h"
@@ -286,6 +288,47 @@ void PhysicsEngine::stepSimulation() {
     }
 }
 
+void PhysicsEngine::harvestPerformanceStats() {
+    // unfortunately the full context names get too long for our stats presentation format
+    //QString contextName = PerformanceTimer::getContextName(); // TODO: how to show full context name?
+    QString contextName("...");
+
+    CProfileIterator* profileIterator = CProfileManager::Get_Iterator();
+    if (profileIterator) {
+        // hunt for stepSimulation context
+        profileIterator->First();
+        for (int32_t childIndex = 0; !profileIterator->Is_Done(); ++childIndex) {
+            if (QString(profileIterator->Get_Current_Name()) == "stepSimulation") {
+                profileIterator->Enter_Child(childIndex);
+                recursivelyHarvestPerformanceStats(profileIterator, contextName);
+                break;
+            }
+            profileIterator->Next();
+        }
+    }
+}
+
+void PhysicsEngine::recursivelyHarvestPerformanceStats(CProfileIterator* profileIterator, QString contextName) {
+    QString parentContextName = contextName + QString("/") + QString(profileIterator->Get_Current_Parent_Name());
+    // get the stats for the children
+    int32_t numChildren = 0;
+    profileIterator->First();
+    while (!profileIterator->Is_Done()) {
+        QString childContextName = parentContextName + QString("/") + QString(profileIterator->Get_Current_Name());
+        uint64_t time = (uint64_t)((btScalar)MSECS_PER_SECOND * profileIterator->Get_Current_Total_Time());
+        PerformanceTimer::addTimerRecord(childContextName, time);
+        profileIterator->Next();
+        ++numChildren;
+    }
+    // recurse the children
+    for (int32_t i = 0; i < numChildren; ++i) {
+        profileIterator->Enter_Child(i);
+        recursivelyHarvestPerformanceStats(profileIterator, contextName);
+    }
+    // retreat back to parent
+    profileIterator->Enter_Parent();
+}
+
 void PhysicsEngine::doOwnershipInfection(const btCollisionObject* objectA, const btCollisionObject* objectB) {
     BT_PROFILE("ownershipInfection");
 

libraries/physics/src/PhysicsEngine.h

@@ -59,6 +59,7 @@ public:
     void reinsertObject(ObjectMotionState* object);
 
     void stepSimulation();
+    void harvestPerformanceStats();
     void updateContactMap();
 
     bool hasOutgoingChanges() const { return _hasOutgoingChanges; }
@@ -89,6 +90,7 @@ public:
 
 private:
     void addObjectToDynamicsWorld(ObjectMotionState* motionState);
+    void recursivelyHarvestPerformanceStats(CProfileIterator* profileIterator, QString contextName);
 
     /// \brief bump any objects that touch this one, then remove contact info
     void bumpAndPruneContacts(ObjectMotionState* motionState);

libraries/shared/src/PerfStat.cpp

@@ -31,8 +31,8 @@ bool PerformanceWarning::_suppressShortTimings = false;
 // Destructor handles recording all of our stats
 PerformanceWarning::~PerformanceWarning() {
     quint64 end = usecTimestampNow();
-    quint64 elapsedusec = (end - _start);
-    double elapsedmsec = elapsedusec / 1000.0;
+    quint64 elapsedUsec = (end - _start);
+    double elapsedmsec = elapsedUsec / 1000.0;
     if ((_alwaysDisplay || _renderWarningsOn) && elapsedmsec > 1) {
         if (elapsedmsec > 1000) {
             double elapsedsec = (end - _start) / 1000000.0;
@@ -53,7 +53,7 @@ PerformanceWarning::~PerformanceWarning() {
     }
     // if the caller gave us a pointer to store the running total, track it now.
     if (_runningTotal) {
-        *_runningTotal += elapsedusec;
+        *_runningTotal += elapsedUsec;
     }
     if (_totalCalls) {
         *_totalCalls += 1;
@@ -65,11 +65,11 @@ PerformanceWarning::~PerformanceWarning() {
 // ----------------------------------------------------------------------------
 const quint64 STALE_STAT_PERIOD = 4 * USECS_PER_SECOND;
 
-void PerformanceTimerRecord::tallyResult(const quint64& now) { 
+void PerformanceTimerRecord::tallyResult(const quint64& now) {
     if (_numAccumulations > 0) {
-        _numTallies++; 
-        _movingAverage.updateAverage(_runningTotal - _lastTotal); 
-        _lastTotal = _runningTotal; 
+        _numTallies++;
+        _movingAverage.updateAverage(_runningTotal - _lastTotal);
+        _lastTotal = _runningTotal;
         _numAccumulations = 0;
         _expiry = now + STALE_STAT_PERIOD;
     }
@@ -96,10 +96,10 @@ PerformanceTimer::PerformanceTimer(const QString& name) {
 
 PerformanceTimer::~PerformanceTimer() {
     if (_isActive && _start != 0) {
-        quint64 elapsedusec = (usecTimestampNow() - _start);
+        quint64 elapsedUsec = (usecTimestampNow() - _start);
         QString& fullName = _fullNames[QThread::currentThread()];
         PerformanceTimerRecord& namedRecord = _records[fullName];
-        namedRecord.accumulateResult(elapsedusec);
+        namedRecord.accumulateResult(elapsedUsec);
         fullName.resize(fullName.size() - (_name.size() + 1));
     }
 }
@@ -109,6 +109,17 @@ bool PerformanceTimer::isActive() {
     return _isActive;
 }
 
+// static
+QString PerformanceTimer::getContextName() {
+    return _fullNames[QThread::currentThread()];
+}
+
+// static
+void PerformanceTimer::addTimerRecord(const QString& fullName, quint64 elapsedUsec) {
+    PerformanceTimerRecord& namedRecord = _records[fullName];
+    namedRecord.accumulateResult(elapsedUsec);
+}
+
 // static
 void PerformanceTimer::setActive(bool active) {
     if (active != _isActive) {
@@ -117,7 +128,7 @@ void PerformanceTimer::setActive(bool active) {
             _fullNames.clear();
             _records.clear();
         }
-        
+
         qDebug() << "PerformanceTimer has been turned" << ((active) ? "on" : "off");
     }
 }
@@ -142,7 +153,7 @@ void PerformanceTimer::dumpAllTimerRecords() {
     QMapIterator<QString, PerformanceTimerRecord> i(_records);
     while (i.hasNext()) {
         i.next();
-        qCDebug(shared) << i.key() << ": average " << i.value().getAverage() 
+        qCDebug(shared) << i.key() << ": average " << i.value().getAverage()
             << " [" << i.value().getMovingAverage() << "]"
             << "usecs over" << i.value().getCount() << "calls";
     }

libraries/shared/src/PerfStat.h

@@ -45,7 +45,7 @@ public:
         _alwaysDisplay(alwaysDisplay),
         _runningTotal(runningTotal),
         _totalCalls(totalCalls) { }
-        
+
     quint64 elapsed() const { return (usecTimestampNow() - _start); };
 
     ~PerformanceWarning();
@@ -56,14 +56,14 @@ public:
 class PerformanceTimerRecord {
 public:
     PerformanceTimerRecord() : _runningTotal(0), _lastTotal(0), _numAccumulations(0), _numTallies(0), _expiry(0) {}
-    
+
     void accumulateResult(const quint64& elapsed) { _runningTotal += elapsed; ++_numAccumulations; }
     void tallyResult(const quint64& now);
     bool isStale(const quint64& now) const { return now > _expiry; }
     quint64 getAverage() const { return (_numTallies == 0) ? 0 : _runningTotal / _numTallies; }
     quint64 getMovingAverage() const { return (_numTallies == 0) ? 0 : _movingAverage.getAverage(); }
     quint64 getCount() const { return _numTallies; }
-    
+
 private:
     quint64 _runningTotal;
     quint64 _lastTotal;
@@ -81,7 +81,9 @@ public:
 
     static bool isActive();
     static void setActive(bool active);
-    
+
+    static QString getContextName();
+    static void addTimerRecord(const QString& fullName, quint64 elapsedUsec);
     static const PerformanceTimerRecord& getTimerRecord(const QString& name) { return _records[name]; };
     static const QMap<QString, PerformanceTimerRecord>& getAllTimerRecords() { return _records; };
     static void tallyAllTimerRecords();