From e44672180ae2e51ec59531f347e7502227a1d434 Mon Sep 17 00:00:00 2001 From: Andrew Meadows Date: Fri, 21 Oct 2016 13:22:22 -0700 Subject: [PATCH] add Bullet profile info to PerformanceTimer stats --- interface/src/Application.cpp | 9 ++++-- interface/src/Menu.cpp | 1 + interface/src/Menu.h | 1 + interface/src/ui/Stats.cpp | 6 ++-- libraries/physics/src/PhysicsEngine.cpp | 43 +++++++++++++++++++++++++ libraries/physics/src/PhysicsEngine.h | 2 ++ libraries/shared/src/PerfStat.cpp | 33 ++++++++++++------- libraries/shared/src/PerfStat.h | 10 +++--- 8 files changed, 86 insertions(+), 19 deletions(-) diff --git a/interface/src/Application.cpp b/interface/src/Application.cpp index f8be4d637b..15fc69cc42 100644 --- a/interface/src/Application.cpp +++ b/interface/src/Application.cpp @@ -3968,8 +3968,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 @@ -3982,6 +3980,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(); } } } diff --git a/interface/src/Menu.cpp b/interface/src/Menu.cpp index a475b3e6d6..17451e716f 100644 --- a/interface/src/Menu.cpp +++ b/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())); diff --git a/interface/src/Menu.h b/interface/src/Menu.h index 95cd4c5aa6..d224f17825 100644 --- a/interface/src/Menu.h +++ b/interface/src/Menu.h @@ -105,6 +105,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"; diff --git a/interface/src/ui/Stats.cpp b/interface/src/ui/Stats.cpp index 10773f20c9..9b7cd54be8 100644 --- a/interface/src/ui/Stats.cpp +++ b/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); } @@ -363,7 +365,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++; diff --git a/libraries/physics/src/PhysicsEngine.cpp b/libraries/physics/src/PhysicsEngine.cpp index 1c6d5d535e..ba002d925c 100644 --- a/libraries/physics/src/PhysicsEngine.cpp +++ b/libraries/physics/src/PhysicsEngine.cpp @@ -11,6 +11,8 @@ #include +#include + #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"); diff --git a/libraries/physics/src/PhysicsEngine.h b/libraries/physics/src/PhysicsEngine.h index 72a41b391a..bbafbb06b6 100644 --- a/libraries/physics/src/PhysicsEngine.h +++ b/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); diff --git a/libraries/shared/src/PerfStat.cpp b/libraries/shared/src/PerfStat.cpp index 615330e13f..d202fdb248 100644 --- a/libraries/shared/src/PerfStat.cpp +++ b/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 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"; } diff --git a/libraries/shared/src/PerfStat.h b/libraries/shared/src/PerfStat.h index 5a66990b16..785920779e 100644 --- a/libraries/shared/src/PerfStat.h +++ b/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& getAllTimerRecords() { return _records; }; static void tallyAllTimerRecords();