Finish the implementation of the profiler

src/collision/CollisionDetection.cpp

@@ -62,6 +62,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<CollisionBody*>::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<bodyindexpair, BroadPhasePair*>::iterator it;
     
     // For each possible collision pair of bodies

src/engine/CollisionWorld.h

@@ -31,6 +31,7 @@
 #include <set>
 #include <algorithm>
 #include "../mathematics/mathematics.h"
+#include "Profiler.h"
 #include "../body/CollisionBody.h"
 #include "OverlappingPair.h"
 #include "../collision/CollisionDetection.h"

src/engine/ContactSolver.cpp

@@ -27,6 +27,7 @@
 #include "ContactSolver.h"
 #include "DynamicsWorld.h"
 #include "../body/RigidBody.h"
+#include "Profiler.h"
 #include <limits>
 
 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;
 

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<decimal>(mTimer.getTimeStep());
     
     // For each rigid body of the world
@@ -160,6 +180,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();
     assert(factor >= 0.0 && factor <= 1.0);
@@ -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<RigidBody*>::iterator it;
     for (it = getRigidBodiesBeginIterator(); it != getRigidBodiesEndIterator(); ++it) {

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;
+    newNode->mSiblingNode = mChildNode;
-    child = newNode;
+    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
+// Reset the timing data of the profiler (but not the profiler tree structure)
-ProfileNodeIterator* Profiler::getIterator() {
+void Profiler::reset() {
-    return new ProfileNodeIterator(&mRootNode);
+    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; i<spacing; i++) outputStream << " ";
+    outputStream << "---------------" << std::endl;
+    for (int i=0; i<spacing; i++) outputStream << " ";
+    outputStream << "| Profiling : " << iterator->getCurrentParentName() <<
+                    " (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<long double>::epsilon() ?
+                               (currentTotalTime / parentTime) * 100.0 : 0.0;
+        for (int j=0; j<spacing; j++) outputStream << " ";
+        outputStream << "|   " << i << " -- " << iterator->getCurrentName() << " : " <<
+                        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<spacing; i++) outputStream << " ";
+    long double percentage = parentTime > std::numeric_limits<long double>::epsilon() ?
+                ((parentTime - accumulatedTime) / parentTime) * 100.0 : 0.0;
+    long double difference = parentTime - accumulatedTime;
+    outputStream << "| Unaccounted : " << difference << " ms (" << percentage << " %)" << std::endl;
+
+    for (int i=0; i<nbChildren; i++){
+        iterator->enterChild(i);
+        printRecursiveNodeReport(iterator, spacing + 3, outputStream);
+        iterator->enterParent();
+    }
 }
 
 #endif

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
+// Return true if we are at the root of the profiler tree
-ProfileNode* ProfileNode::getParentNode() {
+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
+// Return a pointer to a sibling node
-ProfileNode* ProfileNode::getSiblingNode() {
+inline ProfileNode* ProfileNode::getSiblingNode() {
     return mSiblingNode;
 }
 
-/// Return a pointer to a child node
+// Return a pointer to a child node
-ProfileNode* ProfileNode::getChildNode() {
+inline ProfileNode* ProfileNode::getChildNode() {
     return mChildNode;
 }
 
-/// Return the name of the node
+// Return the name of the node
-const char* ProfileNode::getName() {
+inline const char* ProfileNode::getName() {
     return mName;
 }
 
-/// Return the total number of call of the corresponding block of code
+// Return the total number of call of the corresponding block of code
-uint ProfileNode::getNbTotalCalls() const {
+inline uint ProfileNode::getNbTotalCalls() const {
     return mNbTotalCalls;
 }
 
-/// Return the total time spent in the block of code
+// Return the total time spent in the block of code
-long double ProfileNode::getTotalTime() const {
+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

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)

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();
 };