From 068d04c58da8842ad2272e4280635573fcee81e2 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Wed, 6 Dec 2017 16:49:27 -0800 Subject: [PATCH 1/7] abstraction of recursion through bullet perf stats --- libraries/physics/src/PhysicsEngine.cpp | 52 ++++++++++++++----------- libraries/physics/src/PhysicsEngine.h | 1 - 2 files changed, 30 insertions(+), 23 deletions(-) diff --git a/libraries/physics/src/PhysicsEngine.cpp b/libraries/physics/src/PhysicsEngine.cpp index a64796308e..9ff6a59255 100644 --- a/libraries/physics/src/PhysicsEngine.cpp +++ b/libraries/physics/src/PhysicsEngine.cpp @@ -10,6 +10,7 @@ // #include +#include #include @@ -328,6 +329,33 @@ void PhysicsEngine::stepSimulation() { } } +using CProfileOperator = std::function; + +CProfileOperator harvestProfile = [](CProfileIterator* profileIterator, QString contextName) { + QString childContextName = contextName + QString("/") + QString(profileIterator->Get_Current_Name()); + uint64_t time = (uint64_t)((btScalar)MSECS_PER_SECOND * profileIterator->Get_Current_Total_Time()); + PerformanceTimer::addTimerRecord(childContextName, time); + }; + +void recurseOpOnPerformanceStats(CProfileOperator op, 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()) { + op(profileIterator, contextName); + profileIterator->Next(); + ++numChildren; + } + // recurse the children + for (int32_t i = 0; i < numChildren; ++i) { + profileIterator->Enter_Child(i); + recurseOpOnPerformanceStats(op, profileIterator, parentContextName); + } + // retreat back to parent + profileIterator->Enter_Parent(); +} + 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? @@ -340,7 +368,7 @@ void PhysicsEngine::harvestPerformanceStats() { for (int32_t childIndex = 0; !profileIterator->Is_Done(); ++childIndex) { if (QString(profileIterator->Get_Current_Name()) == "stepSimulation") { profileIterator->Enter_Child(childIndex); - recursivelyHarvestPerformanceStats(profileIterator, contextName); + recurseOpOnPerformanceStats(harvestProfile, profileIterator, contextName); break; } profileIterator->Next(); @@ -348,27 +376,6 @@ void PhysicsEngine::harvestPerformanceStats() { } } -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"); @@ -515,6 +522,7 @@ const VectorOfMotionStates& PhysicsEngine::getChangedMotionStates() { void PhysicsEngine::dumpStatsIfNecessary() { if (_dumpNextStats) { _dumpNextStats = false; + CProfileManager::Increment_Frame_Counter(); CProfileManager::dumpAll(); } } diff --git a/libraries/physics/src/PhysicsEngine.h b/libraries/physics/src/PhysicsEngine.h index 3063a4a89a..4e63e8ff3e 100644 --- a/libraries/physics/src/PhysicsEngine.h +++ b/libraries/physics/src/PhysicsEngine.h @@ -94,7 +94,6 @@ public: private: QList 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); From fcff9d7e369bb2b8e5c3f4233c9901d942d63465 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Thu, 7 Dec 2017 08:58:35 -0800 Subject: [PATCH 2/7] use class hierarchy instead of lambdas --- libraries/physics/src/PhysicsEngine.cpp | 33 ++++++++++++++++--------- 1 file changed, 22 insertions(+), 11 deletions(-) diff --git a/libraries/physics/src/PhysicsEngine.cpp b/libraries/physics/src/PhysicsEngine.cpp index 9ff6a59255..e73b9035e6 100644 --- a/libraries/physics/src/PhysicsEngine.cpp +++ b/libraries/physics/src/PhysicsEngine.cpp @@ -329,28 +329,38 @@ void PhysicsEngine::stepSimulation() { } } -using CProfileOperator = std::function; - -CProfileOperator harvestProfile = [](CProfileIterator* profileIterator, QString contextName) { - QString childContextName = contextName + QString("/") + QString(profileIterator->Get_Current_Name()); - uint64_t time = (uint64_t)((btScalar)MSECS_PER_SECOND * profileIterator->Get_Current_Total_Time()); - PerformanceTimer::addTimerRecord(childContextName, time); +class CProfileOperator { +public: + CProfileOperator(QString context) : _context(context) { }; + virtual void process(CProfileIterator*) const = 0; +protected: + QString _context; +}; -void recurseOpOnPerformanceStats(CProfileOperator op, CProfileIterator* profileIterator, QString contextName) { - QString parentContextName = contextName + QString("/") + QString(profileIterator->Get_Current_Parent_Name()); +class PhysicsStatsHarvester : public CProfileOperator { +public: + PhysicsStatsHarvester() : CProfileOperator("...") {} + void process(CProfileIterator* itr) const override { + QString name = _context + QString("/") + QString(itr->Get_Current_Name()); + uint64_t time = (uint64_t)((btScalar)MSECS_PER_SECOND * itr->Get_Current_Total_Time()); + PerformanceTimer::addTimerRecord(name, time); + }; +}; + +void recurseOpOnPerformanceStats(const CProfileOperator& op, CProfileIterator* profileIterator) { // get the stats for the children int32_t numChildren = 0; profileIterator->First(); while (!profileIterator->Is_Done()) { - op(profileIterator, contextName); + op.process(profileIterator); profileIterator->Next(); ++numChildren; } // recurse the children for (int32_t i = 0; i < numChildren; ++i) { profileIterator->Enter_Child(i); - recurseOpOnPerformanceStats(op, profileIterator, parentContextName); + recurseOpOnPerformanceStats(op, profileIterator); } // retreat back to parent profileIterator->Enter_Parent(); @@ -368,7 +378,8 @@ void PhysicsEngine::harvestPerformanceStats() { for (int32_t childIndex = 0; !profileIterator->Is_Done(); ++childIndex) { if (QString(profileIterator->Get_Current_Name()) == "stepSimulation") { profileIterator->Enter_Child(childIndex); - recurseOpOnPerformanceStats(harvestProfile, profileIterator, contextName); + PhysicsStatsHarvester harvester; + harvester.process(profileIterator); break; } profileIterator->Next(); From 4540e9e483a2f4803a51854a8fdb070fe5774cc4 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Thu, 7 Dec 2017 13:08:34 -0800 Subject: [PATCH 3/7] add ability to save simulation stats to file --- libraries/physics/src/PhysicsEngine.cpp | 116 +++++++++++++++++------- libraries/physics/src/PhysicsEngine.h | 1 + 2 files changed, 83 insertions(+), 34 deletions(-) diff --git a/libraries/physics/src/PhysicsEngine.cpp b/libraries/physics/src/PhysicsEngine.cpp index e73b9035e6..2eec4a3950 100644 --- a/libraries/physics/src/PhysicsEngine.cpp +++ b/libraries/physics/src/PhysicsEngine.cpp @@ -10,8 +10,11 @@ // #include + #include +#include + #include #include "CharacterController.h" @@ -331,58 +334,103 @@ void PhysicsEngine::stepSimulation() { class CProfileOperator { public: - CProfileOperator(QString context) : _context(context) { - }; - virtual void process(CProfileIterator*) const = 0; -protected: - QString _context; + 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 PhysicsStatsHarvester : public CProfileOperator { +class StatsHarvester : public CProfileOperator { public: - PhysicsStatsHarvester() : CProfileOperator("...") {} - void process(CProfileIterator* itr) const override { - QString name = _context + QString("/") + QString(itr->Get_Current_Name()); - uint64_t time = (uint64_t)((btScalar)MSECS_PER_SECOND * itr->Get_Current_Total_Time()); + 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); }; }; -void recurseOpOnPerformanceStats(const CProfileOperator& op, CProfileIterator* profileIterator) { - // get the stats for the children - int32_t numChildren = 0; - profileIterator->First(); - while (!profileIterator->Is_Done()) { - op.process(profileIterator); - profileIterator->Next(); - ++numChildren; +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"; + } } - // recurse the children - for (int32_t i = 0; i < numChildren; ++i) { - profileIterator->Enter_Child(i); - recurseOpOnPerformanceStats(op, profileIterator); + ~StatsWriter() { + _file.close(); } - // retreat back to parent - profileIterator->Enter_Parent(); -} + 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(); - if (profileIterator) { + CProfileIterator* itr = CProfileManager::Get_Iterator(); + if (itr) { // 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); - PhysicsStatsHarvester harvester; - harvester.process(profileIterator); + itr->First(); + for (int32_t childIndex = 0; !itr->Is_Done(); ++childIndex) { + if (QString(itr->Get_Current_Name()) == "stepSimulation") { + itr->Enter_Child(childIndex); + StatsHarvester harvester; + harvester.recurse(itr, "bt"); break; } - profileIterator->Next(); + itr->Next(); + } + } +} + +void PhysicsEngine::printPerformanceStatsToFile(const QString& filename) { + CProfileIterator* itr = CProfileManager::Get_Iterator(); + if (itr) { + // hunt for stepSimulation context + itr->First(); + for (int32_t childIndex = 0; !itr->Is_Done(); ++childIndex) { + if (QString(itr->Get_Current_Name()) == "stepSimulation") { + itr->Enter_Child(childIndex); + StatsWriter writer(filename); + writer.recurse(itr, ""); + break; + } + itr->Next(); } } } diff --git a/libraries/physics/src/PhysicsEngine.h b/libraries/physics/src/PhysicsEngine.h index 4e63e8ff3e..3956dd09d9 100644 --- a/libraries/physics/src/PhysicsEngine.h +++ b/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; } From 2538204b1eb05d8dd5632e5a530be0d2623ec503 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Thu, 7 Dec 2017 16:52:21 -0800 Subject: [PATCH 4/7] expose physics simulation stats to Test JS API --- interface/src/Application.cpp | 7 +++++-- interface/src/Application.h | 2 ++ interface/src/scripting/TestScriptingInterface.cpp | 4 ++++ interface/src/scripting/TestScriptingInterface.h | 5 +++++ libraries/physics/src/PhysicsEngine.cpp | 13 +++++++++++++ libraries/physics/src/PhysicsEngine.h | 9 +++++++-- libraries/physics/src/ThreadSafeDynamicsWorld.cpp | 8 +++++++- 7 files changed, 43 insertions(+), 5 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 0176acf108..3745a82b3c 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -3222,8 +3222,6 @@ void Application::keyPressEvent(QKeyEvent* event) { } } - - void Application::keyReleaseEvent(QKeyEvent* event) { _keysPressed.remove(event->key()); @@ -7506,4 +7504,9 @@ void Application::setAvatarOverrideUrl(const QUrl& url, bool save) { _avatarOverrideUrl = url; _saveAvatarOverrideUrl = save; } + +void Application::saveNextPhysicsStats(QString filename) { + _physicsEngine->saveNextPhysicsStats(filename); +} + #include "Application.moc" diff --git a/interface/src/Application.h b/interface/src/Application.h index 9542c5ccb6..ee16740f20 100644 --- a/interface/src/Application.h +++ b/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(); diff --git a/interface/src/scripting/TestScriptingInterface.cpp b/interface/src/scripting/TestScriptingInterface.cpp index d4b4ba1480..b53b9d5d5f 100644 --- a/interface/src/scripting/TestScriptingInterface.cpp +++ b/interface/src/scripting/TestScriptingInterface.cpp @@ -141,6 +141,10 @@ void TestScriptingInterface::endTraceEvent(QString name) { tracing::traceEvent(trace_test(), name, tracing::DurationEnd); } +void TestScriptingInterface::savePhysicsSimulationStats(QString filename) { + qApp->saveNextPhysicsStats(filename); +} + void TestScriptingInterface::profileRange(const QString& name, QScriptValue fn) { PROFILE_RANGE(script, name); fn.call(); diff --git a/interface/src/scripting/TestScriptingInterface.h b/interface/src/scripting/TestScriptingInterface.h index 73b8f0ac93..aca07d110b 100644 --- a/interface/src/scripting/TestScriptingInterface.h +++ b/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: diff --git a/libraries/physics/src/PhysicsEngine.cpp b/libraries/physics/src/PhysicsEngine.cpp index 2eec4a3950..36b677e92f 100644 --- a/libraries/physics/src/PhysicsEngine.cpp +++ b/libraries/physics/src/PhysicsEngine.cpp @@ -16,6 +16,7 @@ #include #include +#include #include "CharacterController.h" #include "ObjectMotionState.h" @@ -294,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 @@ -465,6 +467,7 @@ void PhysicsEngine::doOwnershipInfection(const btCollisionObject* objectA, const } void PhysicsEngine::updateContactMap() { + DETAILED_PROFILE_RANGE(simulation_physics, "updateContactMap"); BT_PROFILE("updateContactMap"); ++_numContactFrames; @@ -582,10 +585,20 @@ 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, diff --git a/libraries/physics/src/PhysicsEngine.h b/libraries/physics/src/PhysicsEngine.h index 3956dd09d9..6619a5489d 100644 --- a/libraries/physics/src/PhysicsEngine.h +++ b/libraries/physics/src/PhysicsEngine.h @@ -77,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; } @@ -116,6 +119,7 @@ private: QHash _objectDynamics; QHash> _objectDynamicsByBody; std::set _activeStaticBodies; + QString _statsFilename; glm::vec3 _originOffset; @@ -124,8 +128,9 @@ private: uint32_t _numContactFrames = 0; uint32_t _numSubsteps; - bool _dumpNextStats = false; - bool _hasOutgoingChanges = false; + bool _dumpNextStats { false }; + bool _saveNextStats { false }; + bool _hasOutgoingChanges { false }; }; diff --git a/libraries/physics/src/ThreadSafeDynamicsWorld.cpp b/libraries/physics/src/ThreadSafeDynamicsWorld.cpp index 24cfbc2609..abda5c82fc 100644 --- a/libraries/physics/src/ThreadSafeDynamicsWorld.cpp +++ b/libraries/physics/src/ThreadSafeDynamicsWorld.cpp @@ -18,6 +18,7 @@ #include #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 Date: Mon, 11 Dec 2017 11:27:33 -0800 Subject: [PATCH 5/7] cleanup prof stats and trace context names --- interface/src/Application.cpp | 18 +++++------- .../src/EntityTreeRenderer.cpp | 10 +++---- libraries/entities/src/EntityItem.cpp | 3 ++ libraries/entities/src/EntitySimulation.cpp | 12 +++----- libraries/entities/src/EntityTree.cpp | 24 ++++++++------- libraries/physics/src/EntityMotionState.cpp | 7 ++++- .../physics/src/PhysicalEntitySimulation.cpp | 29 ++++++++++++------- libraries/physics/src/PhysicsEngine.cpp | 2 +- .../physics/src/ThreadSafeDynamicsWorld.cpp | 2 +- 9 files changed, 59 insertions(+), 48 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index 3745a82b3c..ed1a9d41d2 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -4846,8 +4846,7 @@ void Application::update(float deltaTime) { if (_physicsEnabled) { { PROFILE_RANGE(simulation_physics, "PreStep"); - - PerformanceTimer perfTimer("updateStates)"); + PerformanceTimer perfTimer("preStep)"); static VectorOfMotionStates motionStates; _entitySimulation->getObjectsToRemoveFromPhysics(motionStates); _physicsEngine->removeObjects(motionStates); @@ -4880,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"); - PerformanceTimer perfTimer("handleOutgoingChanges"); + PROFILE_RANGE(simulation_physics, "HandleChanges"); + PerformanceTimer perfTimer("handleChanges"); const VectorOfMotionStates& outgoingChanges = _physicsEngine->getChangedMotionStates(); _entitySimulation->handleChangedMotionStates(outgoingChanges); @@ -4906,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... @@ -4927,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(); } diff --git a/libraries/entities-renderer/src/EntityTreeRenderer.cpp b/libraries/entities-renderer/src/EntityTreeRenderer.cpp index 5f7899ae74..485d3b68f8 100644 --- a/libraries/entities-renderer/src/EntityTreeRenderer.cpp +++ b/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 - // FIXME should be able to use std::remove_if, but it fails due to some + // Clear any expired entities + // 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 changedEntities; _changedEntitiesGuard.withWriteLock([&] { diff --git a/libraries/entities/src/EntityItem.cpp b/libraries/entities/src/EntityItem.cpp index 48370b02fd..e3abb98a7a 100644 --- a/libraries/entities/src/EntityItem.cpp +++ b/libraries/entities/src/EntityItem.cpp @@ -26,6 +26,7 @@ #include #include #include +#include #include #include // usecTimestampNow() #include @@ -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; diff --git a/libraries/entities/src/EntitySimulation.cpp b/libraries/entities/src/EntitySimulation.cpp index f91d728d78..36b0d8ab2d 100644 --- a/libraries/entities/src/EntitySimulation.cpp +++ b/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); - - { - PROFILE_RANGE(simulation_physics, "Sort"); - PerformanceTimer perfTimer("sortingEntities"); - sortEntitiesThatMoved(); - } + 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; diff --git a/libraries/entities/src/EntityTree.cpp b/libraries/entities/src/EntityTree.cpp index e62399ce95..10fcd19a8c 100644 --- a/libraries/entities/src/EntityTree.cpp +++ b/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 idsToDelete; - if (pendingDeletes.size() > 0) { - // translate into list of ID's - QSet idsToDelete; + for (auto entity : pendingDeletes) { + idsToDelete.insert(entity->getEntityItemID()); + } - for (auto entity : pendingDeletes) { - idsToDelete.insert(entity->getEntityItemID()); + // delete these things the roundabout way + deleteEntities(idsToDelete, true); } - - // delete these things the roundabout way - deleteEntities(idsToDelete, true); } }); } diff --git a/libraries/physics/src/EntityMotionState.cpp b/libraries/physics/src/EntityMotionState.cpp index 7e8b431ceb..a688d521d6 100644 --- a/libraries/physics/src/EntityMotionState.cpp +++ b/libraries/physics/src/EntityMotionState.cpp @@ -14,8 +14,9 @@ #include #include #include -#include #include +#include +#include #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; diff --git a/libraries/physics/src/PhysicalEntitySimulation.cpp b/libraries/physics/src/PhysicalEntitySimulation.cpp index 3e87b9437d..e4ba47e205 100644 --- a/libraries/physics/src/PhysicalEntitySimulation.cpp +++ b/libraries/physics/src/PhysicalEntitySimulation.cpp @@ -10,12 +10,14 @@ // +#include "PhysicalEntitySimulation.h" + +#include #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); - assert(state); - if (state->getType() == MOTIONSTATE_TYPE_ENTITY) { - EntityMotionState* entityState = static_cast(state); - EntityItemPointer entity = entityState->getEntity(); - assert(entity.get()); - if (entityState->isCandidateForOwnership()) { - _outgoingChanges.insert(entityState); + { + PROFILE_RANGE_EX(simulation_physics, "Filter", 0x00000000, (uint64_t)motionStates.size()); + for (auto stateItr : motionStates) { + ObjectMotionState* state = &(*stateItr); + assert(state); + if (state->getType() == MOTIONSTATE_TYPE_ENTITY) { + EntityMotionState* entityState = static_cast(state); + EntityItemPointer entity = entityState->getEntity(); + 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::iterator stateItr = _outgoingChanges.begin(); while (stateItr != _outgoingChanges.end()) { EntityMotionState* state = *stateItr; diff --git a/libraries/physics/src/PhysicsEngine.cpp b/libraries/physics/src/PhysicsEngine.cpp index 36b677e92f..fe794772e2 100644 --- a/libraries/physics/src/PhysicsEngine.cpp +++ b/libraries/physics/src/PhysicsEngine.cpp @@ -412,7 +412,7 @@ void PhysicsEngine::harvestPerformanceStats() { if (QString(itr->Get_Current_Name()) == "stepSimulation") { itr->Enter_Child(childIndex); StatsHarvester harvester; - harvester.recurse(itr, "bt"); + harvester.recurse(itr, "step/"); break; } itr->Next(); diff --git a/libraries/physics/src/ThreadSafeDynamicsWorld.cpp b/libraries/physics/src/ThreadSafeDynamicsWorld.cpp index abda5c82fc..5b8c0d5843 100644 --- a/libraries/physics/src/ThreadSafeDynamicsWorld.cpp +++ b/libraries/physics/src/ThreadSafeDynamicsWorld.cpp @@ -122,7 +122,7 @@ void ThreadSafeDynamicsWorld::synchronizeMotionState(btRigidBody* body) { } void ThreadSafeDynamicsWorld::synchronizeMotionStates() { - DETAILED_PROFILE_RANGE(simulation_physics, "syncMotionStates"); + PROFILE_RANGE(simulation_physics, "SyncMotionStates"); BT_PROFILE("syncMotionStates"); _changedMotionStates.clear(); From 74a1f5de9643bb06f0adec7b5dd437dfc1603eb3 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Mon, 11 Dec 2017 11:30:00 -0800 Subject: [PATCH 6/7] remove bullet stats when physics stats disabled --- interface/src/Menu.cpp | 3 ++- interface/src/ui/Stats.cpp | 2 ++ 2 files changed, 4 insertions(+), 1 deletion(-) diff --git a/interface/src/Menu.cpp b/interface/src/Menu.cpp index 9bbb72357b..2d15134b70 100644 --- a/interface/src/Menu.cpp +++ b/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); diff --git a/interface/src/ui/Stats.cpp b/interface/src/ui/Stats.cpp index e194551add..f991420fe8 100644 --- a/interface/src/ui/Stats.cpp +++ b/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; } From 87fa919ac8d2c38198c515df3e9dcdb49c32bc23 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Tue, 12 Dec 2017 14:11:25 -0800 Subject: [PATCH 7/7] save files to Documents by default --- .../src/scripting/TestScriptingInterface.cpp | 14 ++++-- libraries/shared/src/Trace.cpp | 45 +++++-------------- libraries/shared/src/shared/FileUtils.cpp | 45 +++++++++++++++++-- libraries/shared/src/shared/FileUtils.h | 3 ++ 4 files changed, 66 insertions(+), 41 deletions(-) diff --git a/interface/src/scripting/TestScriptingInterface.cpp b/interface/src/scripting/TestScriptingInterface.cpp index b53b9d5d5f..74a15db0ce 100644 --- a/interface/src/scripting/TestScriptingInterface.cpp +++ b/interface/src/scripting/TestScriptingInterface.cpp @@ -11,11 +11,12 @@ #include #include +#include #include #include -#include -#include #include +#include +#include #include "Application.h" @@ -141,8 +142,13 @@ void TestScriptingInterface::endTraceEvent(QString name) { tracing::traceEvent(trace_test(), name, tracing::DurationEnd); } -void TestScriptingInterface::savePhysicsSimulationStats(QString filename) { - qApp->saveNextPhysicsStats(filename); +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) { diff --git a/libraries/shared/src/Trace.cpp b/libraries/shared/src/Trace.cpp index d7feb65ff3..3f6a2dd643 100644 --- a/libraries/shared/src/Trace.cpp +++ b/libraries/shared/src/Trace.cpp @@ -16,7 +16,6 @@ #include #include #include -#include #include #include @@ -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) { - - QString path = originalPath; - - // Filter for specific tokens potentially present in the path: - 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); - } +void Tracer::serialize(const QString& filename) { + QString fullPath = FileUtils::replaceDateTimeTokens(filename); + fullPath = FileUtils::computeDocumentPath(fullPath); + if (!FileUtils::canCreateFile(fullPath)) { + return; } - - std::list currentEvents; { std::lock_guard 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 diff --git a/libraries/shared/src/shared/FileUtils.cpp b/libraries/shared/src/shared/FileUtils.cpp index 8c962dfd6d..dba0af7b16 100644 --- a/libraries/shared/src/shared/FileUtils.cpp +++ b/libraries/shared/src/shared/FileUtils.cpp @@ -12,6 +12,7 @@ #include "FileUtils.h" +#include #include #include #include @@ -20,6 +21,8 @@ #include #include +#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; +} diff --git a/libraries/shared/src/shared/FileUtils.h b/libraries/shared/src/shared/FileUtils.h index 4f2c1b7af5..d68fcd8a44 100644 --- a/libraries/shared/src/shared/FileUtils.h +++ b/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