Make profiler start/stop calls use counters to make profiling recursive functions easier.

IGUIProfiler can now work with any profiler using the IProfiler interface.
Some spelling fixes.


git-svn-id: svn://svn.code.sf.net/p/irrlicht/code/trunk@4969 dfc29bdd-3216-0410-991c-e03cc46cb475

examples/30.Profiling/main.cpp

@@ -1,12 +1,12 @@
 // This file is part of the "Irrlicht Engine".
 // For conditions of distribution and use, see copyright notice in irrlicht.h
-// Written by Michael Zeilfelder
+// Copyright by Michael Zeilfelder
 
 /** Example 030 Profiling
 
 Profiling is used to get runtime information about code code.
 
-There exist several indepent profiling tools.
+There exist several independent profiling tools.
 Examples for free profilers are "gprof" for the GNU toolchain and "very sleepy"
 from codersnotes for Windows. Proprietary tools are for example "VTune" from
 Intel or "AMD APP Profiler". Those tools work by sampling the running
@@ -30,7 +30,7 @@ has a low overhead and affects only the areas which you want to time. So you
 can profile applications with nearly original speed.
 
 Irrlicht itself has such profiling information, which is useful to figure out
-where the runtime inside the engine is spend. To get that profilng data you
+where the runtime inside the engine is spend. To get that profiling data you
 need to recompile Irrlicht with _IRR_COMPILE_WITH_PROFILING_ enabled as
 collecting profiling information is disabled by default for speed reasons.
 */
@@ -42,7 +42,7 @@ collecting profiling information is disabled by default for speed reasons.
 	the software by removing a single define.Or sometimes you might want to
 	have several such defines for different areas of your application code.
 */
-#define ENABLE_MY_PROFILE	// outcomment to remove the profiling code
+#define ENABLE_MY_PROFILE	// comment out to remove the profiling code
 #ifdef ENABLE_MY_PROFILE
 	// calls code X
 	#define MY_PROFILE(X) X
@@ -67,7 +67,7 @@ using namespace io;
 using namespace gui;
 
 /*
-	We have the choice between working with fixed and with automatic profling id's.
+	We have the choice between working with fixed and with automatic profiling id's.
 	Here are some fixed ID's we will be using.
 */
 enum EProfiles
@@ -138,7 +138,7 @@ public:
 					case KEY_F9:
 					{
 						u32 index = 0;
-						if ( getProfiler().findGroupIndex(index, L"group a") )
+						if ( getProfiler().findGroupIndex(index, L"grp runtime") )
 						{
 							getProfiler().resetGroup(index);
 						}
@@ -182,7 +182,7 @@ public:
 				/*
 					Simple scene with cube and light.
 				*/
-				MY_PROFILE(CProfileScope p(L"cube", L"scenes");)
+				MY_PROFILE(CProfileScope p(L"cube", L"grp switch scene");)
 
 				SceneManager->addCameraSceneNode (0, core::vector3df(0, 0, 0),
 											core::vector3df(0, 0, 100),
@@ -203,7 +203,7 @@ public:
 				/*
 					Our typical Irrlicht example quake map.
 				*/
-				MY_PROFILE(CProfileScope p(L"quake map", L"scenes");)
+				MY_PROFILE(CProfileScope p(L"quake map", L"grp switch scene");)
 
 				scene::IAnimatedMesh* mesh = SceneManager->getMesh("20kdm2.bsp");
 				scene::ISceneNode* node = 0;
@@ -220,7 +220,7 @@ public:
 				/*
 					Stress-test Irrlicht a little bit by creating many objects.
 				*/
-				MY_PROFILE(CProfileScope p(L"dwarfes", L"scenes");)
+				MY_PROFILE(CProfileScope p(L"dwarfes", L"grp switch scene");)
 
 				scene::IAnimatedMesh* aniMesh = SceneManager->getMesh( "../../media/dwarf.x" );
 				if (aniMesh)
@@ -279,6 +279,20 @@ public:
 	scene::ISceneManager* SceneManager;
 };
 
+void recursive(int recursion)
+{
+	/*
+		As the profiler uses internally counters for start stop and only
+		takes profile data when that counter is zero we count all recursions
+		as a single call.
+		If you want to profile each call on it's own you have to use explicit start/stop calls and
+		stop the profile id right before the recursive call.
+	*/
+	MY_PROFILE(CProfileScope p3(L"recursive", L"grp runtime");)
+	if (recursion > 0 )
+		recursive(recursion-1);
+}
+
 int main()
 {
 	/*
@@ -291,7 +305,7 @@ int main()
 	/*
 		Profiler is independent of the device - so we can time the device setup
 	*/
-	MY_PROFILE(s32 pDev = getProfiler().add(L"createDevice", L"group a");)
+	MY_PROFILE(s32 pDev = getProfiler().add(L"createDevice", L"grp runtime");)
 	MY_PROFILE(getProfiler().start(pDev);)
 
 	IrrlichtDevice * device = createDevice(driverType, core::dimension2d<u32>(640, 480));
@@ -330,7 +344,7 @@ int main()
 			L"F5 to flip between including the group overview\n"
 			L"F6 to flip between ignoring and showing uncalled data\n"
 			L"F8 to change our scene\n"
-			L"F9 to reset the \"group a\" data\n"
+			L"F9 to reset the \"grp runtime\" data\n"
 			L"F10 to reset the scope 3 data\n"
 			L"F11 to reset all data\n"
 			, recti(10,10, 250, 120), true, true, 0, -1, true);
@@ -358,14 +372,14 @@ int main()
 		Groups exist to sort the display data in a nicer way.
 	*/
 	MY_PROFILE(
-		getProfiler().add(EP_APP_TIME_ONCE, L"full time", L"group a");
+		getProfiler().add(EP_APP_TIME_ONCE, L"full time", L"grp runtime");
-		getProfiler().add(EP_APP_TIME_UPDATED, L"full time updated", L"group a");
+		getProfiler().add(EP_APP_TIME_UPDATED, L"full time updated", L"grp runtime");
-		getProfiler().add(EP_SCOPE1, L"scope 1", L"group a");
+		getProfiler().add(EP_SCOPE1, L"scope 1", L"grp runtime");
-		getProfiler().add(EP_DRAW_SCENE, L"draw scene", L"group a");
+		getProfiler().add(EP_DRAW_SCENE, L"draw scene", L"grp runtime");
 	)
 
     /*
-		Two timers which run the whole time. One will be continuosly updated the other won't.
+		Two timers which run the whole time. One will be continuously updated the other won't.
     */
 	MY_PROFILE(getProfiler().start(EP_APP_TIME_ONCE);)
 	MY_PROFILE(getProfiler().start(EP_APP_TIME_UPDATED);)
@@ -407,14 +421,14 @@ int main()
 				just need to run a quick check without the hassle of setting
 				up id's.
 			*/
-			MY_PROFILE(CProfileScope p3(L"scope 3", L"group a");)
+			MY_PROFILE(CProfileScope p3(L"scope 3", L"grp runtime");)
 
 			/*
 				Second CProfileScope solution will create a data block on first
 				call. So it's a little bit slower on the first run. But usually
-				that's hardly noticable.
+				that's hardly noticeable.
 			*/
-			MY_PROFILE(CProfileScope p2(EP_SCOPE2, L"scope 2", L"group a");)
+			MY_PROFILE(CProfileScope p2(EP_SCOPE2, L"scope 2", L"grp runtime");)
 
 			/*
 				Last CProfileScope solution is the fastest one. But you must add
@@ -422,6 +436,11 @@ int main()
 			*/
 			MY_PROFILE(CProfileScope p1(EP_SCOPE1));
 
+			/*
+				Call a recursive function to show how profiler only counts it once.
+			*/
+			recursive(5);
+
 			driver->beginScene(true, true, SColor(0,200,200,200));
 
 			/*
@@ -436,7 +455,7 @@ int main()
 				If it doesn't matter if the profiler takes some time you can also
 				be lazy and create id's automatically on the spot:
 			*/
-			MY_PROFILE(s32 pEnv = getProfiler().add(L"draw env", L"group a");)
+			MY_PROFILE(s32 pEnv = getProfiler().add(L"draw env", L"grp runtime");)
 			MY_PROFILE(getProfiler().start(pEnv);)
 			env->drawAll();
 			MY_PROFILE(getProfiler().stop(pEnv);)

include/IGUIProfiler.h

@@ -9,6 +9,8 @@
 
 namespace irr
 {
+class IProfiler;
+
 namespace gui
 {
 	class IGUIFont;
@@ -18,7 +20,8 @@ namespace gui
 	{
 	public:
 		//! constructor
-		IGUIProfiler(IGUIEnvironment* environment, IGUIElement* parent, s32 id, core::rect<s32> rectangle)
+		/** \param profiler You can pass a custom profiler, but typically you can pass 0 in which cases it takes the global profiler from Irrlicht */
+		IGUIProfiler(IGUIEnvironment* environment, IGUIElement* parent, s32 id, core::rect<s32> rectangle, IProfiler* profiler = NULL)
 			: IGUIElement(EGUIET_PROFILER, environment, parent, id, rectangle)
 		{}
 

include/IProfiler.h

@@ -16,16 +16,6 @@ namespace irr
 
 class ITimer;
 
-//! For internal engine use:
-//! Code inside IRR_PROFILE is only executed when _IRR_COMPILE_WITH_PROFILING_ is set
-//! This allows disabling all profiler code completely by changing that define.
-//! It's generally useful to wrap profiler-calls in application code with a similar macro.
-#ifdef _IRR_COMPILE_WITH_PROFILING_
-	#define IRR_PROFILE(X) X
-#else
-	#define IRR_PROFILE(X)
-#endif // IRR_PROFILE
-
 //! Used to store the profile data (and also used for profile group data).
 struct SProfileData
 {
@@ -57,13 +47,13 @@ struct SProfileData
 		return Name;
 	}
 
-	//! Each call to Profiler::stop for this data increases the counter by 1.
+	//! Each time profiling for this data is stopped it increases the counter by 1.
 	u32 getCallsCounter() const
 	{
 		return CountCalls;
 	}
 
-	//! Longest time any call from start/stop ever took for this id.
+	//! Longest time a profile call for this id took from start until it was stopped again.
 	u32 getLongestTime() const
 	{
 		return LongestTime;
@@ -86,12 +76,14 @@ private:
 		LongestTime = 0;
 		TimeSum = 0;
 		LastTimeStarted = 0;
+		StartStopCounter = 0;
 	}
 
 	s32 Id;
     u32 GroupIndex;
 	core::stringw Name;
 
+	s32 StartStopCounter; // 0 means stopped > 0 means it runs.
     u32 CountCalls;
     u32 LongestTime;
     u32 TimeSum;
@@ -105,7 +97,7 @@ private:
 // This is why the class works without a virtual functions interface contrary to the usual Irrlicht design.
 // And also why it works with id's instead of strings in the start/stop functions even if it makes using
 // the class slightly harder.
-// The class comes without reference-counting because the profiler-instance is never released (TBD).
+// The class comes without reference-counting because the profiler instance is never released (TBD).
 class IProfiler
 {
 public:
@@ -177,11 +169,16 @@ public:
 
 
 	//! Start profile-timing for the given id
-	/** NOTE: you have to add the id first with one of the ::add functions */
+	/** This increases an internal run-counter for the given id. It will profile as long as that counter is > 0.
+	NOTE: you have to add the id first with one of the ::add functions
+	*/
 	inline void start(s32 id);
 
 	//! Stop profile-timing for the given id
-	/** NOTE: timer must have been started first with the ::start function */
+	/** This increases an internal run-counter for the given id. If it reaches 0 the time since start is recorded.
+		You should have the same amount of start and stop calls. If stop is called more often than start
+		then the additional stop calls will be ignored (counter never goes below 0)
+	*/
     inline void stop(s32 id);
 
 	//! Reset profile data for the given id
@@ -214,7 +211,7 @@ protected:
 
 	// I would prefer using os::Timer, but os.h is not in the public interface so far.
 	// Timer must be initialized by the implementation.
-    ITimer * Timer;	
+    ITimer * Timer;
 	core::array<SProfileData> ProfileDatas;
     core::array<SProfileData> ProfileGroups;
 
@@ -286,7 +283,9 @@ void IProfiler::start(s32 id)
 	s32 idx = ProfileDatas.binary_search(SProfileData(id));
 	if ( idx >= 0 && Timer )
 	{
-		ProfileDatas[idx].LastTimeStarted = Timer->getRealTime();
+		++ProfileDatas[idx].StartStopCounter;
+		if (ProfileDatas[idx].StartStopCounter == 1 )
+			ProfileDatas[idx].LastTimeStarted = Timer->getRealTime();
 	}
 }
 
@@ -299,7 +298,8 @@ void IProfiler::stop(s32 id)
 		if ( idx >= 0 )
 		{
 			SProfileData &data = ProfileDatas[idx];
-			if ( data.LastTimeStarted != 0 )
+			--ProfileDatas[idx].StartStopCounter;
+			if ( data.LastTimeStarted != 0 && ProfileDatas[idx].StartStopCounter == 0)
 			{
 				// update data for this id
 				++data.CountCalls;
@@ -317,6 +317,11 @@ void IProfiler::stop(s32 id)
 					group.LongestTime = diffTime;
 				group.LastTimeStarted = 0;
 			}
+			else if ( ProfileDatas[idx].StartStopCounter < 0 )
+			{
+				// ignore additional stop calls
+				ProfileDatas[idx].StartStopCounter = 0;
+			}
 		}
 	}
 }
@@ -460,6 +465,16 @@ void IProfiler::resetAll()
     }
 }
 
+//! For internal engine use:
+//! Code inside IRR_PROFILE is only executed when _IRR_COMPILE_WITH_PROFILING_ is set
+//! This allows disabling all profiler code completely by changing that define.
+//! It's generally useful to wrap profiler-calls in application code with a similar macro.
+#ifdef _IRR_COMPILE_WITH_PROFILING_
+	#define IRR_PROFILE(X) X
+#else
+	#define IRR_PROFILE(X)
+#endif // IRR_PROFILE
+
 } // namespace irr
 
 #endif // __I_PROFILER_H_INCLUDED__

source/Irrlicht/CGUIProfiler.cpp

@@ -16,12 +16,14 @@ namespace gui
 {
 
 //! constructor
-CGUIProfiler::CGUIProfiler(IGUIEnvironment* environment, IGUIElement* parent, s32 id, core::rect<s32> rectangle)
+CGUIProfiler::CGUIProfiler(IGUIEnvironment* environment, IGUIElement* parent, s32 id, core::rect<s32> rectangle, IProfiler* profiler)
-	: IGUIProfiler(environment, parent, id, rectangle)
+	: IGUIProfiler(environment, parent, id, rectangle, profiler)
+	, Profiler(profiler)
 	, DisplayTable(0), CurrentGroupIdx(0), CurrentGroupPage(0), NumGroupPages(1), IgnoreUncalled(false)
 	, DrawBackground(false)
 {
-	Profiler = &getProfiler();
+	if ( !Profiler )
+		Profiler = &getProfiler();
 
 	core::recti r(0, 0, rectangle.getWidth(), rectangle.getHeight());
 

source/Irrlicht/CGUIProfiler.h

@@ -25,7 +25,7 @@ namespace gui
 	{
 	public:
 		//! constructor
-		CGUIProfiler(IGUIEnvironment* environment, IGUIElement* parent, s32 id, core::rect<s32> rectangle);
+		CGUIProfiler(IGUIEnvironment* environment, IGUIElement* parent, s32 id, core::rect<s32> rectangle, IProfiler* profiler = NULL);
 
 		//! Show first page of profile data
 		virtual void firstPage(bool includeOverview) _IRR_OVERRIDE_;