Merge pull request #11965 from AndrewMeadows/expose-physics-perf-stats-to-js

Cleanup names of debug stats and trace contexts.

interface/src/Application.cpp

@@ -3222,8 +3222,6 @@ void Application::keyPressEvent(QKeyEvent* event) {
     }
 }
 
-
-
 void Application::keyReleaseEvent(QKeyEvent* event) {
     _keysPressed.remove(event->key());
 
@@ -4848,8 +4846,7 @@ void Application::update(float deltaTime) {
         if (_physicsEnabled) {
             {
                 PROFILE_RANGE(simulation_physics, "PreStep");
-
+                PerformanceTimer perfTimer("preStep)");
-                PerformanceTimer perfTimer("updateStates)");
                 static VectorOfMotionStates motionStates;
                 _entitySimulation->getObjectsToRemoveFromPhysics(motionStates);
                 _physicsEngine->removeObjects(motionStates);
@@ -4882,22 +4879,22 @@ void Application::update(float deltaTime) {
             }
             {
                 PROFILE_RANGE(simulation_physics, "Step");
-                PerformanceTimer perfTimer("stepSimulation");
+                PerformanceTimer perfTimer("step");
                 getEntities()->getTree()->withWriteLock([&] {
                     _physicsEngine->stepSimulation();
                 });
             }
             {
                 PROFILE_RANGE(simulation_physics, "PostStep");
-                PerformanceTimer perfTimer("harvestChanges");
+                PerformanceTimer perfTimer("postStep");
                 if (_physicsEngine->hasOutgoingChanges()) {
                     // grab the collision events BEFORE handleOutgoingChanges() because at this point
                     // we have a better idea of which objects we own or should own.
                     auto& collisionEvents = _physicsEngine->getCollisionEvents();
 
                     getEntities()->getTree()->withWriteLock([&] {
-                        PROFILE_RANGE(simulation_physics, "Harvest");
+                        PROFILE_RANGE(simulation_physics, "HandleChanges");
-                        PerformanceTimer perfTimer("handleOutgoingChanges");
+                        PerformanceTimer perfTimer("handleChanges");
 
                         const VectorOfMotionStates& outgoingChanges = _physicsEngine->getChangedMotionStates();
                         _entitySimulation->handleChangedMotionStates(outgoingChanges);
@@ -4908,17 +4905,15 @@ void Application::update(float deltaTime) {
                     });
 
                     if (!_aboutToQuit) {
-                        // handleCollisionEvents() AFTER handleOutgoinChanges()
+                        // handleCollisionEvents() AFTER handleOutgoingChanges()
                         {
                             PROFILE_RANGE(simulation_physics, "CollisionEvents");
-                            PerformanceTimer perfTimer("entities");
                             avatarManager->handleCollisionEvents(collisionEvents);
                             // Collision events (and their scripts) must not be handled when we're locked, above. (That would risk
                             // deadlock.)
                             _entitySimulation->handleCollisionEvents(collisionEvents);
                         }
 
-                        PROFILE_RANGE(simulation_physics, "UpdateEntities");
                         // NOTE: the getEntities()->update() call below will wait for lock
                         // and will simulate entity motion (the EntityTree has been given an EntitySimulation).
                         getEntities()->update(true); // update the models...
@@ -4929,7 +4924,8 @@ void Application::update(float deltaTime) {
                         myAvatar->harvestResultsFromPhysicsSimulation(deltaTime);
                     }
 
-                    if (Menu::getInstance()->isOptionChecked(MenuOption::DisplayDebugTimingDetails) &&
+                    if (PerformanceTimer::isActive() &&
+                            Menu::getInstance()->isOptionChecked(MenuOption::DisplayDebugTimingDetails) &&
                             Menu::getInstance()->isOptionChecked(MenuOption::ExpandPhysicsSimulationTiming)) {
                         _physicsEngine->harvestPerformanceStats();
                     }
@@ -7506,4 +7502,9 @@ void Application::setAvatarOverrideUrl(const QUrl& url, bool save) {
     _avatarOverrideUrl = url;
     _saveAvatarOverrideUrl = save;
 }
+
+void Application::saveNextPhysicsStats(QString filename) {
+    _physicsEngine->saveNextPhysicsStats(filename);
+}
+
 #include "Application.moc"

interface/src/Application.h

@@ -280,6 +280,7 @@ public:
     void clearAvatarOverrideUrl() { _avatarOverrideUrl = QUrl(); _saveAvatarOverrideUrl = false; }
     QUrl getAvatarOverrideUrl() { return _avatarOverrideUrl; }
     bool getSaveAvatarOverrideUrl() { return _saveAvatarOverrideUrl; }
+    void saveNextPhysicsStats(QString filename);
 
 signals:
     void svoImportRequested(const QString& url);
@@ -432,6 +433,7 @@ private slots:
 
     void handleSandboxStatus(QNetworkReply* reply);
     void switchDisplayMode();
+
 private:
     static void initDisplay();
     void init();

interface/src/Menu.cpp

@@ -645,7 +645,8 @@ Menu::Menu() {
     // Developer > Timing >>>
     MenuWrapper* timingMenu = developerMenu->addMenu("Timing");
     MenuWrapper* perfTimerMenu = timingMenu->addMenu("Performance Timer");
-    addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::DisplayDebugTimingDetails, 0, false);
+    addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::DisplayDebugTimingDetails, 0, false,
+            qApp, SLOT(enablePerfStats(bool)));
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::OnlyDisplayTopTen, 0, true);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandUpdateTiming, 0, false);
     addCheckableActionToQMenuAndActionHash(perfTimerMenu, MenuOption::ExpandMyAvatarTiming, 0, false);

interface/src/scripting/TestScriptingInterface.cpp

@@ -11,11 +11,12 @@
 #include <QtCore/QLoggingCategory>
 #include <QtCore/QThread>
 
+#include <shared/FileUtils.h>
 #include <shared/QtHelpers.h>
 #include <DependencyManager.h>
-#include <Trace.h>
-#include <StatTracker.h>
 #include <OffscreenUi.h>
+#include <StatTracker.h>
+#include <Trace.h>
 
 #include "Application.h"
 
@@ -141,6 +142,15 @@ void TestScriptingInterface::endTraceEvent(QString name) {
     tracing::traceEvent(trace_test(), name, tracing::DurationEnd);
 }
 
+void TestScriptingInterface::savePhysicsSimulationStats(QString originalPath) {
+    QString path = FileUtils::replaceDateTimeTokens(originalPath);
+    path = FileUtils::computeDocumentPath(path);
+    if (!FileUtils::canCreateFile(path)) {
+        return;
+    }
+    qApp->saveNextPhysicsStats(path);
+}
+
 void TestScriptingInterface::profileRange(const QString& name, QScriptValue fn) {
     PROFILE_RANGE(script, name);
     fn.call();

interface/src/scripting/TestScriptingInterface.h

@@ -71,6 +71,11 @@ public slots:
 
     void endTraceEvent(QString name);
 
+    /**jsdoc
+     * Write detailed timing stats of next physics stepSimulation() to filename
+     */
+    void savePhysicsSimulationStats(QString filename);
+
     Q_INVOKABLE void profileRange(const QString& name, QScriptValue function);
 
 private:

interface/src/ui/Stats.cpp

@@ -78,6 +78,8 @@ bool Stats::includeTimingRecord(const QString& name) {
             return Menu::getInstance()->isOptionChecked(MenuOption::ExpandPaintGLTiming);
         } else if (name.startsWith("/paintGL/")) {
             return Menu::getInstance()->isOptionChecked(MenuOption::ExpandPaintGLTiming);
+        } else if (name.startsWith("step/")) {
+            return Menu::getInstance()->isOptionChecked(MenuOption::ExpandPhysicsSimulationTiming);
         }
         return true;
     }

libraries/entities-renderer/src/EntityTreeRenderer.cpp

@@ -251,10 +251,10 @@ void EntityTreeRenderer::shutdown() {
 }
 
 void EntityTreeRenderer::addPendingEntities(const render::ScenePointer& scene, render::Transaction& transaction) {
-    PROFILE_RANGE_EX(simulation_physics, "Add", 0xffff00ff, (uint64_t)_entitiesToAdd.size());
+    PROFILE_RANGE_EX(simulation_physics, "AddToScene", 0xffff00ff, (uint64_t)_entitiesToAdd.size());
     PerformanceTimer pt("add");
-    // Clear any expired entities 
+    // Clear any expired entities
-    // FIXME should be able to use std::remove_if, but it fails due to some 
+    // FIXME should be able to use std::remove_if, but it fails due to some
     // weird compilation error related to EntityItemID assignment operators
     for (auto itr = _entitiesToAdd.begin(); _entitiesToAdd.end() != itr; ) {
         if (itr->second.expired()) {
@@ -272,7 +272,7 @@ void EntityTreeRenderer::addPendingEntities(const render::ScenePointer& scene, r
                 continue;
             }
 
-            // Path to the parent transforms is not valid, 
+            // Path to the parent transforms is not valid,
             // don't add to the scene graph yet
             if (!entity->isParentPathComplete()) {
                 continue;
@@ -296,7 +296,7 @@ void EntityTreeRenderer::addPendingEntities(const render::ScenePointer& scene, r
 }
 
 void EntityTreeRenderer::updateChangedEntities(const render::ScenePointer& scene, const ViewFrustum& view, render::Transaction& transaction) {
-    PROFILE_RANGE_EX(simulation_physics, "Change", 0xffff00ff, (uint64_t)_changedEntities.size());
+    PROFILE_RANGE_EX(simulation_physics, "ChangeInScene", 0xffff00ff, (uint64_t)_changedEntities.size());
     PerformanceTimer pt("change");
     std::unordered_set<EntityItemID> changedEntities;
     _changedEntitiesGuard.withWriteLock([&] {

libraries/entities/src/EntityItem.cpp

@@ -26,6 +26,7 @@
 #include <GLMHelpers.h>
 #include <Octree.h>
 #include <PhysicsHelpers.h>
+#include <Profile.h>
 #include <RegisteredMetaTypes.h>
 #include <SharedUtil.h> // usecTimestampNow()
 #include <LogHandler.h>
@@ -984,6 +985,7 @@ void EntityItem::setCollisionSoundURL(const QString& value) {
 }
 
 void EntityItem::simulate(const quint64& now) {
+    DETAILED_PROFILE_RANGE(simulation_physics, "Simulate");
     if (getLastSimulated() == 0) {
         setLastSimulated(now);
     }
@@ -1039,6 +1041,7 @@ void EntityItem::simulate(const quint64& now) {
 }
 
 bool EntityItem::stepKinematicMotion(float timeElapsed) {
+    DETAILED_PROFILE_RANGE(simulation_physics, "StepKinematicMotion");
     // get all the data
     Transform transform;
     glm::vec3 linearVelocity;

libraries/entities/src/EntitySimulation.cpp

@@ -29,7 +29,6 @@ void EntitySimulation::setEntityTree(EntityTreePointer tree) {
 }
 
 void EntitySimulation::updateEntities() {
-    PROFILE_RANGE(simulation_physics, "ES::updateEntities");
     QMutexLocker lock(&_mutex);
     quint64 now = usecTimestampNow();
 
@@ -38,12 +37,7 @@ void EntitySimulation::updateEntities() {
     callUpdateOnEntitiesThatNeedIt(now);
     moveSimpleKinematics(now);
     updateEntitiesInternal(now);
-
+    sortEntitiesThatMoved();
-    {
-        PROFILE_RANGE(simulation_physics, "Sort");
-        PerformanceTimer perfTimer("sortingEntities");
-        sortEntitiesThatMoved();
-    }
 }
 
 void EntitySimulation::takeEntitiesToDelete(VectorOfEntities& entitiesToDelete) {
@@ -101,6 +95,7 @@ void EntitySimulation::changeEntityInternal(EntityItemPointer entity) {
 // protected
 void EntitySimulation::expireMortalEntities(const quint64& now) {
     if (now > _nextExpiry) {
+        PROFILE_RANGE_EX(simulation_physics, "ExpireMortals", 0xffff00ff, (uint64_t)_mortalEntities.size());
         // only search for expired entities if we expect to find one
         _nextExpiry = quint64(-1);
         QMutexLocker lock(&_mutex);
@@ -146,6 +141,7 @@ void EntitySimulation::callUpdateOnEntitiesThatNeedIt(const quint64& now) {
 
 // protected
 void EntitySimulation::sortEntitiesThatMoved() {
+    PROFILE_RANGE_EX(simulation_physics, "SortTree", 0xffff00ff, (uint64_t)_entitiesToSort.size());
     // NOTE: this is only for entities that have been moved by THIS EntitySimulation.
     // External changes to entity position/shape are expected to be sorted outside of the EntitySimulation.
     MovingEntitiesOperator moveOperator;
@@ -265,7 +261,7 @@ void EntitySimulation::clearEntities() {
 }
 
 void EntitySimulation::moveSimpleKinematics(const quint64& now) {
-    PROFILE_RANGE_EX(simulation_physics, "Kinematics", 0xffff00ff, (uint64_t)_simpleKinematicEntities.size());
+    PROFILE_RANGE_EX(simulation_physics, "MoveSimples", 0xffff00ff, (uint64_t)_simpleKinematicEntities.size());
     SetOfEntities::iterator itemItr = _simpleKinematicEntities.begin();
     while (itemItr != _simpleKinematicEntities.end()) {
         EntityItemPointer entity = *itemItr;

libraries/entities/src/EntityTree.cpp

@@ -1770,24 +1770,26 @@ void EntityTree::addToNeedsParentFixupList(EntityItemPointer entity) {
 }
 
 void EntityTree::update(bool simulate) {
-    PROFILE_RANGE(simulation_physics, "ET::update");
+    PROFILE_RANGE(simulation_physics, "UpdateTree");
     fixupNeedsParentFixups();
     if (simulate && _simulation) {
         withWriteLock([&] {
             _simulation->updateEntities();
-            VectorOfEntities pendingDeletes;
+            {
-            _simulation->takeEntitiesToDelete(pendingDeletes);
+                PROFILE_RANGE(simulation_physics, "Deletes");
+                VectorOfEntities pendingDeletes;
+                _simulation->takeEntitiesToDelete(pendingDeletes);
+                if (pendingDeletes.size() > 0) {
+                    // translate into list of ID's
+                    QSet<EntityItemID> idsToDelete;
 
-            if (pendingDeletes.size() > 0) {
+                    for (auto entity : pendingDeletes) {
-                // translate into list of ID's
+                        idsToDelete.insert(entity->getEntityItemID());
-                QSet<EntityItemID> idsToDelete;
+                    }
 
-                for (auto entity : pendingDeletes) {
+                    // delete these things the roundabout way
-                    idsToDelete.insert(entity->getEntityItemID());
+                    deleteEntities(idsToDelete, true);
                 }
-
-                // delete these things the roundabout way
-                deleteEntities(idsToDelete, true);
             }
         });
     }

libraries/physics/src/EntityMotionState.cpp

@@ -14,8 +14,9 @@
 #include <EntityItem.h>
 #include <EntityItemProperties.h>
 #include <EntityEditPacketSender.h>
-#include <PhysicsCollisionGroups.h>
 #include <LogHandler.h>
+#include <PhysicsCollisionGroups.h>
+#include <Profile.h>
 
 #include "BulletUtil.h"
 #include "EntityMotionState.h"
@@ -325,6 +326,7 @@ bool EntityMotionState::isCandidateForOwnership() const {
 }
 
 bool EntityMotionState::remoteSimulationOutOfSync(uint32_t simulationStep) {
+    DETAILED_PROFILE_RANGE(simulation_physics, "CheckOutOfSync");
     // NOTE: we only get here if we think we own the simulation
     assert(_body);
 
@@ -476,6 +478,7 @@ bool EntityMotionState::remoteSimulationOutOfSync(uint32_t simulationStep) {
 }
 
 bool EntityMotionState::shouldSendUpdate(uint32_t simulationStep) {
+    DETAILED_PROFILE_RANGE(simulation_physics, "ShouldSend");
     // NOTE: we expect _entity and _body to be valid in this context, since shouldSendUpdate() is only called
     // after doesNotNeedToSendUpdate() returns false and that call should return 'true' if _entity or _body are NULL.
     assert(_entity);
@@ -516,6 +519,7 @@ bool EntityMotionState::shouldSendUpdate(uint32_t simulationStep) {
 }
 
 void EntityMotionState::sendUpdate(OctreeEditPacketSender* packetSender, uint32_t step) {
+    DETAILED_PROFILE_RANGE(simulation_physics, "Send");
     assert(_entity);
     assert(entityTreeIsLocked());
 
@@ -731,6 +735,7 @@ void EntityMotionState::resetMeasuredBodyAcceleration() {
 }
 
 void EntityMotionState::measureBodyAcceleration() {
+    DETAILED_PROFILE_RANGE(simulation_physics, "MeasureAccel");
     // try to manually measure the true acceleration of the object
     uint32_t thisStep = ObjectMotionState::getWorldSimulationStep();
     uint32_t numSubsteps = thisStep - _lastMeasureStep;

libraries/physics/src/PhysicalEntitySimulation.cpp

@@ -10,12 +10,14 @@
 //
 
 
+#include "PhysicalEntitySimulation.h"
+
+#include <Profile.h>
 
 #include "PhysicsHelpers.h"
 #include "PhysicsLogging.h"
 #include "ShapeManager.h"
 
-#include "PhysicalEntitySimulation.h"
 
 PhysicalEntitySimulation::PhysicalEntitySimulation() {
 }
@@ -274,20 +276,24 @@ void PhysicalEntitySimulation::handleDeactivatedMotionStates(const VectorOfMotio
 }
 
 void PhysicalEntitySimulation::handleChangedMotionStates(const VectorOfMotionStates& motionStates) {
+    PROFILE_RANGE_EX(simulation_physics, "ChangedEntities", 0x00000000, (uint64_t)motionStates.size());
     QMutexLocker lock(&_mutex);
 
     // walk the motionStates looking for those that correspond to entities
-    for (auto stateItr : motionStates) {
+    {
-        ObjectMotionState* state = &(*stateItr);
+        PROFILE_RANGE_EX(simulation_physics, "Filter", 0x00000000, (uint64_t)motionStates.size());
-        assert(state);
+        for (auto stateItr : motionStates) {
-        if (state->getType() == MOTIONSTATE_TYPE_ENTITY) {
+            ObjectMotionState* state = &(*stateItr);
-            EntityMotionState* entityState = static_cast<EntityMotionState*>(state);
+            assert(state);
-            EntityItemPointer entity = entityState->getEntity();
+            if (state->getType() == MOTIONSTATE_TYPE_ENTITY) {
-            assert(entity.get());
+                EntityMotionState* entityState = static_cast<EntityMotionState*>(state);
-            if (entityState->isCandidateForOwnership()) {
+                EntityItemPointer entity = entityState->getEntity();
-                _outgoingChanges.insert(entityState);
+                assert(entity.get());
+                if (entityState->isCandidateForOwnership()) {
+                    _outgoingChanges.insert(entityState);
+                }
+                _entitiesToSort.insert(entity);
             }
-            _entitiesToSort.insert(entity);
         }
     }
 
@@ -302,6 +308,7 @@ void PhysicalEntitySimulation::handleChangedMotionStates(const VectorOfMotionSta
         }
 
         // look for entities to prune or update
+        PROFILE_RANGE_EX(simulation_physics, "Prune/Send", 0x00000000, (uint64_t)_outgoingChanges.size());
         QSet<EntityMotionState*>::iterator stateItr = _outgoingChanges.begin();
         while (stateItr != _outgoingChanges.end()) {
             EntityMotionState* state = *stateItr;

libraries/physics/src/PhysicsEngine.cpp

@@ -11,7 +11,12 @@
 
 #include <PhysicsCollisionGroups.h>
 
+#include <functional>
+
+#include <QFile>
+
 #include <PerfStat.h>
+#include <Profile.h>
 
 #include "CharacterController.h"
 #include "ObjectMotionState.h"
@@ -290,6 +295,7 @@ void PhysicsEngine::stepSimulation() {
     float timeStep = btMin(dt, MAX_TIMESTEP);
 
     if (_myAvatarController) {
+        DETAILED_PROFILE_RANGE(simulation_physics, "avatarController");
         BT_PROFILE("avatarController");
         // TODO: move this stuff outside and in front of stepSimulation, because
         // the updateShapeIfNecessary() call needs info from MyAvatar and should
@@ -328,45 +334,107 @@ void PhysicsEngine::stepSimulation() {
     }
 }
 
+class CProfileOperator {
+public:
+    CProfileOperator() {}
+    void recurse(CProfileIterator* itr, QString context) {
+        // The context string will get too long if we accumulate it properly
+        //QString newContext = context + QString("/") + itr->Get_Current_Parent_Name();
+        // so we use this four-character indentation
+        QString newContext = context + QString(".../");
+        process(itr, newContext);
+
+        // count the children
+        int32_t numChildren = 0;
+        itr->First();
+        while (!itr->Is_Done()) {
+            itr->Next();
+            ++numChildren;
+        }
+
+        // recurse the children
+        if (numChildren > 0) {
+            // recurse the children
+            for (int32_t i = 0; i < numChildren; ++i) {
+                itr->Enter_Child(i);
+                recurse(itr, newContext);
+            }
+        }
+        // retreat back to parent
+        itr->Enter_Parent();
+    }
+    virtual void process(CProfileIterator*, QString context) = 0;
+};
+
+class StatsHarvester : public CProfileOperator {
+public:
+    StatsHarvester() {}
+    void process(CProfileIterator* itr, QString context) override {
+            QString name = context + itr->Get_Current_Parent_Name();
+            uint64_t time = (uint64_t)((btScalar)MSECS_PER_SECOND * itr->Get_Current_Parent_Total_Time());
+            PerformanceTimer::addTimerRecord(name, time);
+        };
+};
+
+class StatsWriter : public CProfileOperator {
+public:
+    StatsWriter(QString filename) : _file(filename) {
+        _file.open(QFile::WriteOnly);
+        if (_file.error() != QFileDevice::NoError) {
+            qCDebug(physics) << "unable to open file " << _file.fileName() << " to save stepSimulation() stats";
+        }
+    }
+    ~StatsWriter() {
+        _file.close();
+    }
+    void process(CProfileIterator* itr, QString context) override {
+        QString name = context + itr->Get_Current_Parent_Name();
+        float time = (btScalar)MSECS_PER_SECOND * itr->Get_Current_Parent_Total_Time();
+        if (_file.error() == QFileDevice::NoError) {
+            QTextStream s(&_file);
+            s << name << " = " << time << "\n";
+        }
+    }
+protected:
+    QFile _file;
+};
+
 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();
+    CProfileIterator* itr = CProfileManager::Get_Iterator();
-    if (profileIterator) {
+    if (itr) {
         // hunt for stepSimulation context
-        profileIterator->First();
+        itr->First();
-        for (int32_t childIndex = 0; !profileIterator->Is_Done(); ++childIndex) {
+        for (int32_t childIndex = 0; !itr->Is_Done(); ++childIndex) {
-            if (QString(profileIterator->Get_Current_Name()) == "stepSimulation") {
+            if (QString(itr->Get_Current_Name()) == "stepSimulation") {
-                profileIterator->Enter_Child(childIndex);
+                itr->Enter_Child(childIndex);
-                recursivelyHarvestPerformanceStats(profileIterator, contextName);
+                StatsHarvester harvester;
+                harvester.recurse(itr, "step/");
                 break;
             }
-            profileIterator->Next();
+            itr->Next();
         }
     }
 }
 
-void PhysicsEngine::recursivelyHarvestPerformanceStats(CProfileIterator* profileIterator, QString contextName) {
+void PhysicsEngine::printPerformanceStatsToFile(const QString& filename) {
-    QString parentContextName = contextName + QString("/") + QString(profileIterator->Get_Current_Parent_Name());
+    CProfileIterator* itr = CProfileManager::Get_Iterator();
-    // get the stats for the children
+    if (itr) {
-    int32_t numChildren = 0;
+        // hunt for stepSimulation context
-    profileIterator->First();
+        itr->First();
-    while (!profileIterator->Is_Done()) {
+        for (int32_t childIndex = 0; !itr->Is_Done(); ++childIndex) {
-        QString childContextName = parentContextName + QString("/") + QString(profileIterator->Get_Current_Name());
+            if (QString(itr->Get_Current_Name()) == "stepSimulation") {
-        uint64_t time = (uint64_t)((btScalar)MSECS_PER_SECOND * profileIterator->Get_Current_Total_Time());
+                itr->Enter_Child(childIndex);
-        PerformanceTimer::addTimerRecord(childContextName, time);
+                StatsWriter writer(filename);
-        profileIterator->Next();
+                writer.recurse(itr, "");
-        ++numChildren;
+                break;
+            }
+            itr->Next();
+        }
     }
-    // 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) {
@@ -399,6 +467,7 @@ void PhysicsEngine::doOwnershipInfection(const btCollisionObject* objectA, const
 }
 
 void PhysicsEngine::updateContactMap() {
+    DETAILED_PROFILE_RANGE(simulation_physics, "updateContactMap");
     BT_PROFILE("updateContactMap");
     ++_numContactFrames;
 
@@ -515,10 +584,21 @@ const VectorOfMotionStates& PhysicsEngine::getChangedMotionStates() {
 void PhysicsEngine::dumpStatsIfNecessary() {
     if (_dumpNextStats) {
         _dumpNextStats = false;
+        CProfileManager::Increment_Frame_Counter();
+        if (_saveNextStats) {
+            _saveNextStats = false;
+            printPerformanceStatsToFile(_statsFilename);
+        }
         CProfileManager::dumpAll();
     }
 }
 
+void PhysicsEngine::saveNextPhysicsStats(QString filename) {
+    _saveNextStats = true;
+    _dumpNextStats = true;
+    _statsFilename = filename;
+}
+
 // Bullet collision flags are as follows:
 // CF_STATIC_OBJECT= 1,
 // CF_KINEMATIC_OBJECT= 2,

libraries/physics/src/PhysicsEngine.h

@@ -62,6 +62,7 @@ public:
 
     void stepSimulation();
     void harvestPerformanceStats();
+    void printPerformanceStatsToFile(const QString& filename);
     void updateContactMap();
 
     bool hasOutgoingChanges() const { return _hasOutgoingChanges; }
@@ -76,6 +77,9 @@ public:
     /// \brief prints timings for last frame if stats have been requested.
     void dumpStatsIfNecessary();
 
+    /// \brief saves timings for last frame in filename
+    void saveNextPhysicsStats(QString filename);
+
     /// \param offset position of simulation origin in domain-frame
     void setOriginOffset(const glm::vec3& offset) { _originOffset = offset; }
 
@@ -94,7 +98,6 @@ public:
 private:
     QList<EntityDynamicPointer> removeDynamicsForBody(btRigidBody* body);
     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);
@@ -116,6 +119,7 @@ private:
     QHash<QUuid, EntityDynamicPointer> _objectDynamics;
     QHash<btRigidBody*, QSet<QUuid>> _objectDynamicsByBody;
     std::set<btRigidBody*> _activeStaticBodies;
+    QString _statsFilename;
 
     glm::vec3 _originOffset;
 
@@ -124,8 +128,9 @@ private:
     uint32_t _numContactFrames = 0;
     uint32_t _numSubsteps;
 
-    bool _dumpNextStats = false;
+    bool _dumpNextStats { false };
-    bool _hasOutgoingChanges = false;
+    bool _saveNextStats { false };
+    bool _hasOutgoingChanges { false };
 
 };
 

libraries/physics/src/ThreadSafeDynamicsWorld.cpp

@@ -18,6 +18,7 @@
 #include <LinearMath/btQuickprof.h>
 
 #include "ThreadSafeDynamicsWorld.h"
+#include "Profile.h"
 
 ThreadSafeDynamicsWorld::ThreadSafeDynamicsWorld(
         btDispatcher* dispatcher,
@@ -29,6 +30,7 @@ ThreadSafeDynamicsWorld::ThreadSafeDynamicsWorld(
 
 int ThreadSafeDynamicsWorld::stepSimulationWithSubstepCallback(btScalar timeStep, int maxSubSteps,
                                                                btScalar fixedTimeStep, SubStepCallback onSubStep) {
+    DETAILED_PROFILE_RANGE(simulation_physics, "stepWithCB");
     BT_PROFILE("stepSimulationWithSubstepCallback");
     int subSteps = 0;
     if (maxSubSteps) {
@@ -68,11 +70,13 @@ int ThreadSafeDynamicsWorld::stepSimulationWithSubstepCallback(btScalar timeStep
         saveKinematicState(fixedTimeStep*clampedSimulationSteps);
 
         {
+            DETAILED_PROFILE_RANGE(simulation_physics, "applyGravity");
             BT_PROFILE("applyGravity");
             applyGravity();
         }
 
         for (int i=0;i<clampedSimulationSteps;i++) {
+            DETAILED_PROFILE_RANGE(simulation_physics, "substep");
             internalSingleStepSimulation(fixedTimeStep);
             onSubStep();
         }
@@ -118,7 +122,8 @@ void ThreadSafeDynamicsWorld::synchronizeMotionState(btRigidBody* body) {
 }
 
 void ThreadSafeDynamicsWorld::synchronizeMotionStates() {
-    BT_PROFILE("synchronizeMotionStates");
+    PROFILE_RANGE(simulation_physics, "SyncMotionStates");
+    BT_PROFILE("syncMotionStates");
     _changedMotionStates.clear();
 
     // NOTE: m_synchronizeAllMotionStates is 'false' by default for optimization.
@@ -161,6 +166,7 @@ void ThreadSafeDynamicsWorld::saveKinematicState(btScalar timeStep) {
 ///would like to iterate over m_nonStaticRigidBodies, but unfortunately old API allows
 ///to switch status _after_ adding kinematic objects to the world
 ///fix it for Bullet 3.x release
+    DETAILED_PROFILE_RANGE(simulation_physics, "saveKinematicState");
     BT_PROFILE("saveKinematicState");
     for (int i=0;i<m_collisionObjects.size();i++)
     {

libraries/shared/src/Trace.cpp

@@ -16,7 +16,6 @@
 #include <QtCore/QFileInfo>
 #include <QtCore/QDir>
 #include <QtCore/QStandardPaths>
-#include <QtCore/QDateTime>
 
 #include <QtCore/QFile>
 #include <QtCore/QFileInfo>
@@ -31,6 +30,8 @@
 
 #include "Gzip.h"
 #include "PortableHighResolutionClock.h"
+#include "SharedLogging.h"
+#include "shared/FileUtils.h"
 #include "shared/GlobalAppProperties.h"
 
 using namespace tracing;
@@ -104,30 +105,13 @@ void TraceEvent::writeJson(QTextStream& out) const {
 #endif
 }
 
-void Tracer::serialize(const QString& originalPath) {
+void Tracer::serialize(const QString& filename) {
-
+    QString fullPath = FileUtils::replaceDateTimeTokens(filename);
-    QString path = originalPath;
+    fullPath = FileUtils::computeDocumentPath(fullPath);
-
+    if (!FileUtils::canCreateFile(fullPath)) {
-    // Filter for specific tokens potentially present in the path:
+        return;
-    auto now = QDateTime::currentDateTime();
-
-    path = path.replace("{DATE}", now.date().toString("yyyyMMdd"));
-    path = path.replace("{TIME}", now.time().toString("HHmm"));
-
-    // If the filename is relative, turn it into an absolute path relative to the document directory.
-    QFileInfo originalFileInfo(path);
-    if (originalFileInfo.isRelative()) {
-        QString docsLocation = QStandardPaths::writableLocation(QStandardPaths::DocumentsLocation);
-        path = docsLocation + "/" + path;
-        QFileInfo info(path);
-        if (!info.absoluteDir().exists()) {
-            QString originalRelativePath = originalFileInfo.path();
-            QDir(docsLocation).mkpath(originalRelativePath);
-        }
     }
 
-
-
     std::list<TraceEvent> currentEvents;
     {
         std::lock_guard<std::mutex> guard(_eventsMutex);
@@ -137,11 +121,6 @@ void Tracer::serialize(const QString& originalPath) {
         }
     }
 
-    // If the file exists and we can't remove it, fail early
-    if (QFileInfo(path).exists() && !QFile::remove(path)) {
-        return;
-    }
-
     // If we can't open a temp file for writing, fail early
     QByteArray data;
     {
@@ -159,15 +138,16 @@ void Tracer::serialize(const QString& originalPath) {
         out << "\n]";
     }
 
-    if (path.endsWith(".gz")) {
+    if (fullPath.endsWith(".gz")) {
         QByteArray compressed;
         gzip(data, compressed);
         data = compressed;
-    } 
+    }
-    
+
     {
-        QFile file(path);
+        QFile file(fullPath);
         if (!file.open(QIODevice::WriteOnly)) {
+            qDebug(shared) << "failed to open file '" << fullPath << "'";
             return;
         }
         file.write(data);
@@ -191,7 +171,6 @@ void Tracer::serialize(const QString& originalPath) {
                 } }
             }
         };
-        
         data = document.toJson(QJsonDocument::Compact);
     }
 #endif

libraries/shared/src/shared/FileUtils.cpp

@@ -12,6 +12,7 @@
 
 #include "FileUtils.h"
 
+#include <QtCore/QDateTime>
 #include <QtCore/QDir>
 #include <QtCore/QFileInfo>
 #include <QtCore/QProcess>
@@ -20,6 +21,8 @@
 #include <QtCore/QRegularExpression>
 #include <QtGui/QDesktopServices>
 
+#include "../SharedLogging.h"
+
 
 QString FileUtils::readFile(const QString& filename) {
     QFile file(filename);
@@ -82,20 +85,54 @@ QString FileUtils::standardPath(QString subfolder) {
     // standard path
     // Mac: ~/Library/Application Support/Interface
     QString path = QStandardPaths::writableLocation(QStandardPaths::DataLocation);
-    
     if (!subfolder.startsWith("/")) {
         subfolder.prepend("/");
     }
-    
     if (!subfolder.endsWith("/")) {
         subfolder.append("/");
     }
-    
     path.append(subfolder);
     QDir logDir(path);
     if (!logDir.exists(path)) {
         logDir.mkpath(path);
     }
-    
     return path;
 }
+
+QString FileUtils::replaceDateTimeTokens(const QString& originalPath) {
+    // Filter for specific tokens potentially present in the path:
+    auto now = QDateTime::currentDateTime();
+    QString path = originalPath;
+    path.replace("{DATE}", now.date().toString("yyyyMMdd"));
+    path.replace("{TIME}", now.time().toString("HHmm"));
+    return path;
+}
+
+
+QString FileUtils::computeDocumentPath(const QString& originalPath) {
+    // If the filename is relative, turn it into an absolute path relative to the document directory.
+    QString path = originalPath;
+    QFileInfo originalFileInfo(originalPath);
+    if (originalFileInfo.isRelative()) {
+        QString docsLocation = QStandardPaths::writableLocation(QStandardPaths::DocumentsLocation);
+        path = docsLocation + "/" + originalPath;
+    }
+    return path;
+}
+
+bool FileUtils::canCreateFile(const QString& fullPath) {
+    // If the file exists and we can't remove it, fail early
+    QFileInfo fileInfo(fullPath);
+    if (fileInfo.exists() && !QFile::remove(fullPath)) {
+        qDebug(shared) << "unable to overwrite file '" << fullPath << "'";
+        return false;
+    }
+    QDir dir(fileInfo.absolutePath());
+    if (!dir.exists()) {
+        if (!dir.mkpath(fullPath)) {
+            qDebug(shared) << "unable to create dir '" << dir.absolutePath() << "'";
+            return false;
+        }
+    }
+    return true;
+}

libraries/shared/src/shared/FileUtils.h

@@ -21,6 +21,9 @@ public:
     static QString standardPath(QString subfolder);
     static QString readFile(const QString& filename);
     static QStringList readLines(const QString& filename, QString::SplitBehavior splitBehavior = QString::KeepEmptyParts);
+    static QString replaceDateTimeTokens(const QString& path);
+    static QString computeDocumentPath(const QString& path);
+    static bool canCreateFile(const QString& fullPath);
 };
 
 #endif // hifi_FileUtils_h