From f479c5edf3c5dc3adac0c8e4961aabbbd95492bc Mon Sep 17 00:00:00 2001 From: Daniel Chappuis Date: Tue, 26 Mar 2013 21:37:55 +0100 Subject: [PATCH] Finish the implementation of the profiler --- src/collision/CollisionDetection.cpp | 7 + src/engine/CollisionWorld.h | 1 + src/engine/ContactSolver.cpp | 3 + src/engine/DynamicsWorld.cpp | 24 ++++ src/engine/Profiler.cpp | 136 +++++++++++++++++-- src/engine/Profiler.h | 187 ++++++++++++++++++++++++--- src/engine/Timer.cpp | 2 +- src/engine/Timer.h | 3 +- 8 files changed, 333 insertions(+), 30 deletions(-) diff --git a/src/collision/CollisionDetection.cpp b/src/collision/CollisionDetection.cpp index 9d0254d2..44e24810 100644 --- a/src/collision/CollisionDetection.cpp +++ b/src/collision/CollisionDetection.cpp @@ -61,6 +61,8 @@ CollisionDetection::~CollisionDetection() { // Compute the collision detection void CollisionDetection::computeCollisionDetection() { + + PROFILE("CollisionDetection::computeCollisionDetection()"); // Compute the broad-phase collision detection computeBroadPhase(); @@ -72,6 +74,8 @@ void CollisionDetection::computeCollisionDetection() { // Compute the broad-phase collision detection void CollisionDetection::computeBroadPhase() { + PROFILE("CollisionDetection::computeBroadPhase()"); + // Notify the broad-phase algorithm about the bodies that have moved since last frame for (set::iterator it = mWorld->getBodiesBeginIterator(); it != mWorld->getBodiesEndIterator(); it++) { @@ -87,6 +91,9 @@ void CollisionDetection::computeBroadPhase() { // Compute the narrow-phase collision detection void CollisionDetection::computeNarrowPhase() { + + PROFILE("CollisionDetection::computeNarrowPhase()"); + map::iterator it; // For each possible collision pair of bodies diff --git a/src/engine/CollisionWorld.h b/src/engine/CollisionWorld.h index dde08972..4a929a3a 100644 --- a/src/engine/CollisionWorld.h +++ b/src/engine/CollisionWorld.h @@ -31,6 +31,7 @@ #include #include #include "../mathematics/mathematics.h" +#include "Profiler.h" #include "../body/CollisionBody.h" #include "OverlappingPair.h" #include "../collision/CollisionDetection.h" diff --git a/src/engine/ContactSolver.cpp b/src/engine/ContactSolver.cpp index a8004d12..e90ed978 100644 --- a/src/engine/ContactSolver.cpp +++ b/src/engine/ContactSolver.cpp @@ -27,6 +27,7 @@ #include "ContactSolver.h" #include "DynamicsWorld.h" #include "../body/RigidBody.h" +#include "Profiler.h" #include using namespace reactphysics3d; @@ -748,6 +749,8 @@ void ContactSolver::solveContactConstraints() { // Solve the constraints void ContactSolver::solve(decimal timeStep) { + PROFILE("ContactSolver::solve()"); + // Set the current time step mTimeStep = timeStep; diff --git a/src/engine/DynamicsWorld.cpp b/src/engine/DynamicsWorld.cpp index 884ac74c..48940f82 100644 --- a/src/engine/DynamicsWorld.cpp +++ b/src/engine/DynamicsWorld.cpp @@ -52,11 +52,28 @@ DynamicsWorld::~DynamicsWorld() { // Free the allocated memory for the constrained velocities cleanupConstrainedVelocitiesArray(); + +#ifdef IS_PROFILING_ACTIVE + + // Print the profiling report + Profiler::printReport(std::cout); + + // Destroy the profiler (release the allocated memory) + Profiler::destroy(); +#endif + } // Update the physics simulation void DynamicsWorld::update() { +#ifdef IS_PROFILING_ACTIVE + // Increment the frame counter of the profiler + Profiler::incrementFrameCounter(); +#endif + + PROFILE("DynamicsWorld::update()"); + assert(mTimer.getIsRunning()); // Compute the time since the last update() call and update the timer @@ -106,6 +123,9 @@ void DynamicsWorld::update() { // Update the position and orientation of the rigid bodies void DynamicsWorld::updateRigidBodiesPositionAndOrientation() { + + PROFILE("DynamicsWorld::updateRigidBodiesPositionAndOrientation()"); + decimal dt = static_cast(mTimer.getTimeStep()); // For each rigid body of the world @@ -159,6 +179,8 @@ void DynamicsWorld::updateRigidBodiesPositionAndOrientation() { // Compute and set the interpolation factor to all bodies void DynamicsWorld::setInterpolationFactorToAllBodies() { + + PROFILE("DynamicsWorld::setInterpolationFactorToAllBodies()"); // Compute the interpolation factor decimal factor = mTimer.computeInterpolationFactor(); @@ -215,6 +237,8 @@ void DynamicsWorld::cleanupConstrainedVelocitiesArray() { // Apply the gravity force to all bodies of the physics world void DynamicsWorld::applyGravity() { + PROFILE("DynamicsWorld::applyGravity()"); + // For each body of the physics world set::iterator it; for (it = getRigidBodiesBeginIterator(); it != getRigidBodiesEndIterator(); ++it) { diff --git a/src/engine/Profiler.cpp b/src/engine/Profiler.cpp index 0c915469..2759976a 100644 --- a/src/engine/Profiler.cpp +++ b/src/engine/Profiler.cpp @@ -33,6 +33,7 @@ using namespace reactphysics3d; // Initialization of static variables ProfileNode Profiler::mRootNode("Root", NULL); ProfileNode* Profiler::mCurrentNode = &Profiler::mRootNode; +long double Profiler::mProfilingStartTime = Timer::getCurrentSystemTime() * 1000.0; uint Profiler::mFrameCounter = 0; // Constructor @@ -40,7 +41,7 @@ ProfileNode::ProfileNode(const char* name, ProfileNode* parentNode) :mName(name), mNbTotalCalls(0), mStartingTime(0), mTotalTime(0), mRecursionCounter(0), mParentNode(parentNode), mChildNode(NULL), mSiblingNode(NULL) { - + reset(); } // Destructor @@ -65,8 +66,8 @@ ProfileNode* ProfileNode::findSubNode(const char* name) { // The nose has not been found. Therefore, we create it // and add it to the profiler tree ProfileNode* newNode = new ProfileNode(name, this); - newNode->mSiblingNode = child; - child = newNode; + newNode->mSiblingNode = mChildNode; + mChildNode = newNode; return newNode; } @@ -80,7 +81,7 @@ void ProfileNode::enterBlockOfCode() { // Get the current system time to initialize the starting time of // the profiling of the current block of code - mStartingTime = Timer::getCurrentSystemTime(); + mStartingTime = Timer::getCurrentSystemTime() * 1000.0; } mRecursionCounter++; @@ -93,7 +94,7 @@ bool ProfileNode::exitBlockOfCode() { if (mRecursionCounter == 0 && mNbTotalCalls != 0) { // Get the current system time - long double currentTime = Timer::getCurrentSystemTime(); + long double currentTime = Timer::getCurrentSystemTime() * 1000.0; // Increase the total elasped time in the current block of code mTotalTime += currentTime - mStartingTime; @@ -103,6 +104,59 @@ bool ProfileNode::exitBlockOfCode() { return (mRecursionCounter == 0); } +// Reset the profiling of the node +void ProfileNode::reset() { + mNbTotalCalls = 0; + mTotalTime = 0.0; + + // Reset the child node + if (mChildNode != NULL) { + mChildNode->reset(); + } + + // Reset the sibling node + if (mSiblingNode != NULL) { + mSiblingNode->reset(); + } +} + +// Destroy the node +void ProfileNode::destroy() { + delete mChildNode; + mChildNode = NULL; + delete mSiblingNode; + mSiblingNode = NULL; +} + +// Constructor +ProfileNodeIterator::ProfileNodeIterator(ProfileNode* startingNode) + :mCurrentParentNode(startingNode), + mCurrentChildNode(mCurrentParentNode->getChildNode()){ + +} + +// Enter a given child node +void ProfileNodeIterator::enterChild(int index) { + mCurrentChildNode = mCurrentParentNode->getChildNode(); + while ((mCurrentChildNode != NULL) && (index != 0)) { + index--; + mCurrentChildNode = mCurrentChildNode->getSiblingNode(); + } + + if (mCurrentChildNode != NULL) { + mCurrentParentNode = mCurrentChildNode; + mCurrentChildNode = mCurrentParentNode->getChildNode(); + } +} + +// Enter a given parent node +void ProfileNodeIterator::enterParent() { + if (mCurrentParentNode->getParentNode() != NULL) { + mCurrentParentNode = mCurrentParentNode->getParentNode(); + } + mCurrentChildNode = mCurrentParentNode->getChildNode(); +} + // Method called when we want to start profiling a block of code. void Profiler::startProfilingBlock(const char* name) { @@ -125,17 +179,79 @@ void Profiler::stopProfilingBlock() { if (mCurrentNode->exitBlockOfCode()) { mCurrentNode = mCurrentNode->getParentNode(); } - } -// Return an iterator over the profiler tree starting at the root -ProfileNodeIterator* Profiler::getIterator() { - return new ProfileNodeIterator(&mRootNode); +// Reset the timing data of the profiler (but not the profiler tree structure) +void Profiler::reset() { + mRootNode.reset(); + mRootNode.enterBlockOfCode(); + mFrameCounter = 0; + mProfilingStartTime = Timer::getCurrentSystemTime() * 1000.0; } // Print the report of the profiler in a given output stream -void printReport(std::ostream& outputStream) { +void Profiler::printReport(std::ostream& outputStream) { + ProfileNodeIterator* iterator = Profiler::getIterator(); + // Recursively print the report of each node of the profiler tree + printRecursiveNodeReport(iterator, 0, outputStream); + + // Destroy the iterator + destroyIterator(iterator); +} + +// Recursively print the report of a given node of the profiler tree +void Profiler::printRecursiveNodeReport(ProfileNodeIterator* iterator, + int spacing, + std::ostream& outputStream) { + iterator->first(); + + // If we are at the end of a branch in the profiler tree + if (iterator->isEnd()) { + return; + } + + long double parentTime = iterator->isRoot() ? getElapsedTimeSinceStart() : + iterator->getCurrentParentTotalTime(); + long double accumulatedTime = 0.0; + uint nbFrames = Profiler::getNbFrames(); + for (int i=0; igetCurrentParentName() << + " (total running time : " << parentTime << " ms) ---" << std::endl; + long double totalTime = 0.0; + + // Recurse over the children of the current node + int nbChildren = 0; + for (int i=0; !iterator->isEnd(); i++, iterator->next()) { + nbChildren++; + long double currentTotalTime = iterator->getCurrentTotalTime(); + accumulatedTime += currentTotalTime; + long double fraction = parentTime > std::numeric_limits::epsilon() ? + (currentTotalTime / parentTime) * 100.0 : 0.0; + for (int j=0; jgetCurrentName() << " : " << + fraction << " % | " << (currentTotalTime / long double(nbFrames)) << + " ms/frame (" << iterator->getCurrentNbTotalCalls() << " calls)" << + std::endl; + totalTime += currentTotalTime; + } + + if (parentTime < accumulatedTime) { + outputStream << "Something is wrong !" << std::endl; + } + for (int i=0; i std::numeric_limits::epsilon() ? + ((parentTime - accumulatedTime) / parentTime) * 100.0 : 0.0; + long double difference = parentTime - accumulatedTime; + outputStream << "| Unaccounted : " << difference << " ms (" << percentage << " %)" << std::endl; + + for (int i=0; ienterChild(i); + printRecursiveNodeReport(iterator, spacing + 3, outputStream); + iterator->enterParent(); + } } #endif diff --git a/src/engine/Profiler.h b/src/engine/Profiler.h index 1768b01e..286e909b 100644 --- a/src/engine/Profiler.h +++ b/src/engine/Profiler.h @@ -43,6 +43,8 @@ class ProfileNode { private : + // -------------------- Attributes -------------------- // + /// Name of the node const char* mName; @@ -69,6 +71,8 @@ class ProfileNode { public : + // -------------------- Methods -------------------- // + /// Constructor ProfileNode(const char* name, ProfileNode* parentNode); @@ -101,24 +105,34 @@ class ProfileNode { /// Called when we exit the block of code corresponding to this profile node bool exitBlockOfCode(); + + /// Reset the profiling of the node + void reset(); + + /// Destroy the node + void destroy(); }; // Class ProfileNodeIterator /** - * This class allow us to iterator over the profiler tree. + * This class allows us to iterator over the profiler tree. */ class ProfileNodeIterator { private : + // -------------------- Attributes -------------------- // + /// Current parent node - ProfileNode* mCurrentParent; + ProfileNode* mCurrentParentNode; /// Current child node - ProfileNode* mCurrentChild; + ProfileNode* mCurrentChildNode; public : + // -------------------- Methods -------------------- // + /// Constructor ProfileNodeIterator(ProfileNode* startingNode); @@ -129,8 +143,34 @@ class ProfileNodeIterator { void next(); /// Enter a given child node - void enterChild(); + void enterChild(int index); + /// Enter a given parent node + void enterParent(); + + /// Return true if we are at the root of the profiler tree + bool isRoot(); + + /// Return true if we are at the end of a branch of the profiler tree + bool isEnd(); + + /// Return the name of the current node + const char* getCurrentName(); + + /// Return the total time of the current node + long double getCurrentTotalTime(); + + /// Return the total number of calls of the current node + uint getCurrentNbTotalCalls(); + + /// Return the name of the current parent node + const char* getCurrentParentName(); + + /// Return the total time of the current parent node + long double getCurrentParentTotalTime(); + + /// Return the total number of calls of the current parent node + uint getCurrentParentNbTotalCalls(); }; // Class Profiler @@ -142,6 +182,8 @@ class Profiler { private : + // -------------------- Attributes -------------------- // + /// Root node of the profiler tree static ProfileNode mRootNode; @@ -151,8 +193,18 @@ class Profiler { /// Frame counter static uint mFrameCounter; + /// Starting profiling time + static long double mProfilingStartTime; + + /// Recursively print the report of a given node of the profiler tree + static void printRecursiveNodeReport(ProfileNodeIterator* iterator, + int spacing, + std::ostream& outputStream); + public : + // -------------------- Methods -------------------- // + /// Method called when we want to start profiling a block of code. static void startProfilingBlock(const char *name); @@ -160,11 +212,29 @@ class Profiler { /// startProfilingBlock() method has been called. static void stopProfilingBlock(); + /// Reset the timing data of the profiler (but not the profiler tree structure) + static void reset(); + + /// Return the number of frames + static uint getNbFrames(); + + /// Return the elasped time since the start/reset of the profiling + static long double getElapsedTimeSinceStart(); + + /// Increment the frame counter + static void incrementFrameCounter(); + /// Return an iterator over the profiler tree starting at the root static ProfileNodeIterator* getIterator(); /// Print the report of the profiler in a given output stream static void printReport(std::ostream& outputStream); + + /// Destroy a previously allocated iterator + static void destroyIterator(ProfileNodeIterator* iterator); + + /// Destroy the profiler (release the memory) + static void destroy(); }; // Class ProfileSample @@ -177,6 +247,8 @@ class ProfileSample { public : + // -------------------- Methods -------------------- // + /// Constructor ProfileSample(const char* name) { @@ -192,39 +264,120 @@ class ProfileSample { } }; -/// Use this macro to start profile a block of code +// Use this macro to start profile a block of code #define PROFILE(name) ProfileSample profileSample(name) -/// Return a pointer to the parent node -ProfileNode* ProfileNode::getParentNode() { +// Return true if we are at the root of the profiler tree +inline bool ProfileNodeIterator::isRoot() { + return (mCurrentParentNode->getParentNode() == NULL); +} + +// Return true if we are at the end of a branch of the profiler tree +inline bool ProfileNodeIterator::isEnd() { + return (mCurrentChildNode == NULL); +} + +// Return the name of the current node +inline const char* ProfileNodeIterator::getCurrentName() { + return mCurrentChildNode->getName(); +} + +// Return the total time of the current node +inline long double ProfileNodeIterator::getCurrentTotalTime() { + return mCurrentChildNode->getTotalTime(); +} + +// Return the total number of calls of the current node +inline uint ProfileNodeIterator::getCurrentNbTotalCalls() { + return mCurrentChildNode->getNbTotalCalls(); +} + +// Return the name of the current parent node +inline const char* ProfileNodeIterator::getCurrentParentName() { + return mCurrentParentNode->getName(); +} + +// Return the total time of the current parent node +inline long double ProfileNodeIterator::getCurrentParentTotalTime() { + return mCurrentParentNode->getTotalTime(); +} + +// Return the total number of calls of the current parent node +inline uint ProfileNodeIterator::getCurrentParentNbTotalCalls() { + return mCurrentParentNode->getNbTotalCalls(); +} + +// Go to the first node +inline void ProfileNodeIterator::first() { + mCurrentChildNode = mCurrentParentNode->getChildNode(); +} + +// Go to the next node +inline void ProfileNodeIterator::next() { + mCurrentChildNode = mCurrentChildNode->getSiblingNode(); +} + +// Return a pointer to the parent node +inline ProfileNode* ProfileNode::getParentNode() { return mParentNode; } -/// Return a pointer to a sibling node -ProfileNode* ProfileNode::getSiblingNode() { +// Return a pointer to a sibling node +inline ProfileNode* ProfileNode::getSiblingNode() { return mSiblingNode; } -/// Return a pointer to a child node -ProfileNode* ProfileNode::getChildNode() { +// Return a pointer to a child node +inline ProfileNode* ProfileNode::getChildNode() { return mChildNode; } -/// Return the name of the node -const char* ProfileNode::getName() { +// Return the name of the node +inline const char* ProfileNode::getName() { return mName; } -/// Return the total number of call of the corresponding block of code -uint ProfileNode::getNbTotalCalls() const { +// Return the total number of call of the corresponding block of code +inline uint ProfileNode::getNbTotalCalls() const { return mNbTotalCalls; } -/// Return the total time spent in the block of code -long double ProfileNode::getTotalTime() const { +// Return the total time spent in the block of code +inline long double ProfileNode::getTotalTime() const { return mTotalTime; } +// Return the number of frames +inline uint Profiler::getNbFrames() { + return mFrameCounter; +} + +// Return the elasped time since the start/reset of the profiling +inline long double Profiler::getElapsedTimeSinceStart() { + long double currentTime = Timer::getCurrentSystemTime() * 1000.0; + return currentTime - mProfilingStartTime; +} + +// Increment the frame counter +inline void Profiler::incrementFrameCounter() { + mFrameCounter++; +} + +// Return an iterator over the profiler tree starting at the root +inline ProfileNodeIterator* Profiler::getIterator() { + return new ProfileNodeIterator(&mRootNode); +} + +// Destroy a previously allocated iterator +inline void Profiler::destroyIterator(ProfileNodeIterator* iterator) { + delete iterator; +} + +// Destroy the profiler (release the memory) +inline void Profiler::destroy() { + mRootNode.destroy(); +} + } #else // In profile is not active diff --git a/src/engine/Timer.cpp b/src/engine/Timer.cpp index 74c08086..16dbb04c 100644 --- a/src/engine/Timer.cpp +++ b/src/engine/Timer.cpp @@ -39,7 +39,7 @@ Timer::~Timer() { } -// Return the current time of the system +// Return the current time of the system in seconds long double Timer::getCurrentSystemTime() { #if defined(WINDOWS_OS) diff --git a/src/engine/Timer.h b/src/engine/Timer.h index 7c70b52c..6c90ab05 100644 --- a/src/engine/Timer.h +++ b/src/engine/Timer.h @@ -74,7 +74,6 @@ class Timer { /// True if the timer is running bool mIsRunning; - // -------------------- Methods -------------------- // /// Private copy-constructor @@ -123,7 +122,7 @@ class Timer { /// Compute the interpolation factor decimal computeInterpolationFactor(); - /// Return the current time of the system + /// Return the current time of the system in seconds static long double getCurrentSystemTime(); };