Split script profiler into a separate file

git-svn-id: svn://svn.code.sf.net/p/magicseteditor/code/trunk@1201 0fc631ac-6414-0410-93d0-97cfa31319b6

src/cli/cli_main.cpp

@@ -11,6 +11,7 @@
 #include <cli/cli_main.hpp>
 #include <cli/text_io_handler.hpp>
 #include <script/functions/functions.hpp>
+#include <script/profiler.hpp>
 #include <data/format/formats.hpp>
 #include <wx/process.h>
 
@@ -163,7 +164,11 @@ void CLISetInterface::handleCommand(const String& command) {
 				}
 			#if USE_SCRIPT_PROFILING
 				} else if (before == _(":profile")) {
-					showProfilingStats();
+					if (arg == _("full")) {
+						showProfilingStats(profile_root);
+					} else {
+						showProfilingStats(profile_aggregated());
+					}
 			#endif
 			} else {
 				cli.showError(_("Unknown command, type :help for help."));
@@ -193,15 +198,21 @@ void CLISetInterface::handleCommand(const String& command) {
 }
 
 #if USE_SCRIPT_PROFILING
-	DECLARE_TYPEOF_COLLECTION(FunctionProfileItem);
+	DECLARE_TYPEOF_COLLECTION(FunctionProfileP);
-	void CLISetInterface::showProfilingStats() {
+	void CLISetInterface::showProfilingStats(const FunctionProfile& item, int level) {
-		vector<FunctionProfileItem> stats;
+		// show parent
-		get_profile(stats);
+		if (level == 0) {
-		sort(stats.begin(), stats.end());
+			cli << GRAY << _("Time(s)   Avg (ms)  Calls   Function") << ENDL;
-		cli << GRAY << _("Time(s)   Avg (ms)  Calls   Function") << ENDL;
+			cli <<         _("========  ========  ======  ===============================") << NORMAL << ENDL;
-		cli <<         _("========  ========  ======  ===============================") << NORMAL << ENDL;
+		} else {
-		FOR_EACH_REVERSE(s, stats) {
+			for (int i = 1 ; i < level ; ++i) cli << _("  ");
-			cli << String::Format(_("%8.5f  %8.5f  %6d  %s"), s.time, 1000 * s.time / s.calls, s.calls, s.name.c_str()) << ENDL;
+			cli << String::Format(_("%8.5f  %8.5f  %6d  %s"), item.time(), 1000 * item.avg_time(), item.calls, item.name.c_str()) << ENDL;
+		}
+		// show children
+		vector<FunctionProfileP> children;
+		item.get_children(children);
+		FOR_EACH_REVERSE(c, children) {
+			showProfilingStats(*c, level + 1);
 		}
 	}
 #endif

src/cli/cli_main.hpp

@@ -12,6 +12,7 @@
 #include <util/prec.hpp>
 #include <data/set.hpp>
 #include <data/export_template.hpp>
+#include <script/profiler.hpp>
 
 // ----------------------------------------------------------------------------- : Command line interface
 
@@ -33,7 +34,7 @@ class CLISetInterface : public SetView {
 	void showUsage();
 	void handleCommand(const String& command);
 	#if USE_SCRIPT_PROFILING
-		void showProfilingStats();
+		void showProfilingStats(const FunctionProfile& parent, int level = 0);
 	#endif
 	
 	/// our own context, when no set is loaded

src/mse.vcproj

@@ -2791,6 +2791,12 @@
 				<File
 					RelativePath=".\script\parser.hpp">
 				</File>
+				<File
+					RelativePath=".\script\profiler.cpp">
+				</File>
+				<File
+					RelativePath=".\script\profiler.hpp">
+				</File>
 			</Filter>
 			<Filter
 				Name="use"

src/script/context.cpp

@@ -9,6 +9,7 @@
 #include <util/prec.hpp>
 #include <script/context.hpp>
 #include <script/to_value.hpp>
+#include <script/profiler.hpp>
 #include <util/error.hpp>
 #include <iostream>
 
@@ -18,95 +19,6 @@ Context::Context()
 	: level(0)
 {}
 
-// ----------------------------------------------------------------------------- : Profiler
-
-#if USE_SCRIPT_PROFILING
-
-	#ifndef UNICODE
-		#error "It looks like you are building the final release; disable USE_SCRIPT_PROFILING!"
-	#endif
-
-	#ifdef WIN32
-		typedef LONGLONG ProfileTime;
-		
-		ProfileTime timer_now() {
-			LARGE_INTEGER i;
-			QueryPerformanceCounter(&i);
-			return i.QuadPart;
-		}
-		ProfileTime timer_resolution() {
-			LARGE_INTEGER i;
-			QueryPerformanceFrequency(&i);
-			return i.QuadPart;
-		}
-	#else
-		#error "Can't use profiler"
-	#endif
-	
-	ProfileTime delta; ///< Time excluded
-	
-	class Timer {
-	  public:
-		Timer() {
-			start = timer_now() + delta;
-		}
-		ProfileTime time() {
-			ProfileTime end = timer_now() + delta;
-			ProfileTime diff = end - start;
-			start = end;
-			return diff;
-		}
-		void exclude_time() {
-			ProfileTime delta_delta = time();
-			delta -= delta_delta; // this time is not counted, even recursively
-			start -= delta_delta;
-		}
-	  private:
-		ProfileTime start;
-	};
-	
-	/// How much time was spent in each function?
-	struct FunctionProfile {
-		FunctionProfile() : time(0), calls(0) {}
-		ProfileTime time;
-		UInt        calls;
-	};
-	VectorIntMap<unsigned int, FunctionProfile> variable_timings;
-	
-	/// Profile a single function
-	struct Profiler {
-	  public:
-		inline Profiler(Timer& timer, Variable function)
-			: timer(timer), function(function)
-		{
-			timer.exclude_time();
-		}
-		inline ~Profiler() {
-			ProfileTime time = timer.time();
-			if ((int)function < 0) return;
-			// per function timing
-			FunctionProfile& funprof = variable_timings[function];
-			funprof.time  += time;
-			funprof.calls += 1;
-			timer.exclude_time();
-		}
-	  private:
-		Timer&   timer;
-		Variable function;
-	};
-	
-	/// Get profile time in seconds and function names
-	void get_profile(vector<FunctionProfileItem>& out) {
-		double resolution = timer_resolution();
-		const vector<FunctionProfile>& times = variable_timings.get();
-		for (size_t i = 0 ; i < times.size() ; ++i) {
-			if (times[i].calls == 0) continue;
-			out.push_back(FunctionProfileItem(variable_to_string((Variable)i), times[i].time / resolution, times[i].calls));
-		}
-	}
-	
-#endif
-
 // ----------------------------------------------------------------------------- : Evaluate
 
 // Perform a unary simple instruction, store the result in a (not in *a)

src/script/context.hpp

@@ -13,8 +13,6 @@
 
 class Dependency;
 
-#define USE_SCRIPT_PROFILING 1 // TODO: Disable before release!
-
 // ----------------------------------------------------------------------------- : VectorIntMap
 
 /// A map like data structure that stores the elements in a vector.
@@ -127,9 +125,7 @@ class Context {
 	
 	/// Get a variable name givin its value, returns (Variable)-1 if not found (slow!)
 	Variable lookupVariableValue(const ScriptValueP& value);
-	#if USE_SCRIPT_PROFILING
+	friend class ScriptCompose;
-		friend class ScriptCompose;
-	#endif
 };
 
 /// A class that creates a local scope
@@ -142,20 +138,5 @@ class LocalScope {
 	size_t scope;
 };
 
-// ----------------------------------------------------------------------------- : Profiler
-
-#if USE_SCRIPT_PROFILING
-	struct FunctionProfileItem {
-		FunctionProfileItem() {}
-		FunctionProfileItem(const String& name, double time, int calls) : name(name), time(time), calls(calls) {}
-		inline bool operator < (const FunctionProfileItem& that) { return time < that.time; }
-		
-		String name;
-		double time;
-		int    calls;
-	};
-	void get_profile(vector<FunctionProfileItem>& out);
-#endif
-
 // ----------------------------------------------------------------------------- : EOF
 #endif

src/script/profiler.cpp

@@ -0,0 +1,130 @@
+//+----------------------------------------------------------------------------+
+//| Description:  Magic Set Editor - Program to make Magic (tm) cards          |
+//| Copyright:    (C) 2001 - 2008 Twan van Laarhoven and "coppro"              |
+//| License:      GNU General Public License 2 or later (see file COPYING)     |
+//+----------------------------------------------------------------------------+
+
+// ----------------------------------------------------------------------------- : Includes
+
+#include <util/prec.hpp>
+#include <script/profiler.hpp>
+
+#if USE_SCRIPT_PROFILING
+
+// don't use script profiling in final build
+#ifndef UNICODE
+	#error "It looks like you are building the final release; disable USE_SCRIPT_PROFILING!"
+#endif
+
+DECLARE_TYPEOF(map<size_t COMMA FunctionProfileP>);
+
+// ----------------------------------------------------------------------------- : Timer
+
+Timer::Timer() {
+	start = timer_now() + delta;
+}
+
+ProfileTime Timer::time() {
+	ProfileTime end = timer_now() + delta;
+	ProfileTime diff = end - start;
+	start = end;
+	return diff;
+}
+
+void Timer::exclude_time() {
+	ProfileTime delta_delta = time();
+	delta -= delta_delta;
+	start -= delta_delta;
+}
+
+ProfileTime Timer::delta = 0;
+
+// ----------------------------------------------------------------------------- : FunctionProfile
+
+FunctionProfile profile_root(_("root"));
+
+inline bool compare_time(const FunctionProfileP& a, const FunctionProfileP& b) {
+	return a->time_ticks < b->time_ticks;
+}
+void FunctionProfile::get_children(vector<FunctionProfileP>& out) const {
+	FOR_EACH_CONST(c,children) {
+		out.push_back(c.second);
+	}
+	sort(out.begin(), out.end(), compare_time);
+}
+
+
+FunctionProfile profile_aggr(_("everywhere"));
+
+void profile_aggregate(FunctionProfile& parent, int level, int max_level, const FunctionProfile& p);
+void profile_aggregate(FunctionProfile& parent, int level, int max_level, size_t idx, const FunctionProfile& p) {
+	// add to item at idx
+	FunctionProfileP& fpp = parent.children[idx];
+	if (!fpp) {
+		fpp = new_intrusive1<FunctionProfile>(p.name);
+	}
+	fpp->time_ticks += p.time_ticks;
+	fpp->calls      += p.calls;
+	// recurse
+	if (level == 0) {
+		profile_aggregate(parent, level, max_level, p);
+	}
+	if (level < max_level) {
+		profile_aggregate(*fpp, level + 1, max_level, p);
+	}
+}
+void profile_aggregate(FunctionProfile& parent, int level, int max_level, const FunctionProfile& p) {
+	FOR_EACH_CONST(c, p.children) {
+		profile_aggregate(parent, level, max_level, c.first, *c.second);
+	}
+}
+
+const FunctionProfile& profile_aggregated(int max_level) {
+	profile_aggr.children.clear();
+	profile_aggregate(profile_aggr, 0, max_level, profile_root);
+	return profile_aggr;
+}
+
+// ----------------------------------------------------------------------------- : Profiler
+
+FunctionProfile* Profiler::function = &profile_root;
+
+// Enter a function
+Profiler::Profiler(Timer& timer, Variable function_name)
+	: timer(timer)
+	, parent(function) // push
+{
+	if ((int)function_name >= 0) {
+		FunctionProfileP& fpp = parent->children[(size_t)function_name << 1 | 1];
+		if (!fpp) {
+			fpp = new_intrusive1<FunctionProfile>(variable_to_string(function_name));
+		}
+		function = fpp.get();
+	}
+	timer.exclude_time();
+}
+
+// Enter a function
+Profiler::Profiler(Timer& timer, void* function_object, const String& function_name)
+	: timer(timer)
+	, parent(function) // push
+{
+	FunctionProfileP& fpp = parent->children[(size_t)function_object];
+	if (!fpp) {
+		fpp = new_intrusive1<FunctionProfile>(function_name);
+	}
+	function = fpp.get();
+	timer.exclude_time();
+}
+
+// Leave a function
+Profiler::~Profiler() {
+	ProfileTime time = timer.time();
+	if (function == parent) return; // don't count
+	function->time_ticks += time;
+	function->calls      += 1;
+	function = parent; // pop
+}
+
+// ----------------------------------------------------------------------------- : EOF
+#endif

src/script/profiler.hpp

@@ -0,0 +1,95 @@
+//+----------------------------------------------------------------------------+
+//| Description:  Magic Set Editor - Program to make Magic (tm) cards          |
+//| Copyright:    (C) 2001 - 2008 Twan van Laarhoven and "coppro"              |
+//| License:      GNU General Public License 2 or later (see file COPYING)     |
+//+----------------------------------------------------------------------------+
+
+#ifndef HEADER_SCRIPT_PROFILER
+#define HEADER_SCRIPT_PROFILER
+
+// ----------------------------------------------------------------------------- : Includes
+
+#include <util/prec.hpp>
+#include <script/script.hpp>
+#include <script/context.hpp>
+
+#define USE_SCRIPT_PROFILING 1
+
+#if USE_SCRIPT_PROFILING
+
+DECLARE_POINTER_TYPE(FunctionProfile);
+
+// ----------------------------------------------------------------------------- : Timer
+
+#ifdef WIN32
+	typedef LONGLONG ProfileTime;
+	
+	inline ProfileTime timer_now() {
+		LARGE_INTEGER i;
+		QueryPerformanceCounter(&i);
+		return i.QuadPart;
+	}
+	inline ProfileTime timer_resolution() {
+		LARGE_INTEGER i;
+		QueryPerformanceFrequency(&i);
+		return i.QuadPart;
+	}
+#else
+	#error "No Timer implementation, can't use profiler"
+#endif
+
+/// Simple execution timer
+class Timer {
+  public:
+	Timer();
+	/// The time the timer has been running, resets the timer
+	inline ProfileTime time();
+	/// Exclude the time since the last reset from ALL running timers
+	inline void exclude_time();
+  private:
+	ProfileTime start;
+	static ProfileTime delta; ///< Time excluded
+};
+
+// ----------------------------------------------------------------------------- : FunctionProfile
+
+/// How much time was spent in a function?
+class FunctionProfile : public IntrusivePtrBase<FunctionProfile> {
+  public:
+	FunctionProfile(const String& name) : name(name), time_ticks(0), calls(0) {}
+	
+	String      name;
+	ProfileTime time_ticks;
+	UInt        calls;
+	map<size_t,FunctionProfileP> children;
+	
+	/// The children, sorted by time
+	void get_children(vector<FunctionProfileP>& out) const;
+	
+	/// Time in seconds
+	inline double time() const { return time_ticks / (double)timer_resolution(); }
+	inline double avg_time() const { return time() / calls; }
+};
+
+/// The root profile
+extern FunctionProfile profile_root;
+
+const FunctionProfile& profile_aggregated(int level = 1);
+
+// ----------------------------------------------------------------------------- : Profiler
+
+/// Profile a single function call
+class Profiler {
+  public:
+	Profiler(Timer& timer, Variable function_name);
+	Profiler(Timer& timer, void* function_object, const String& function_name);
+	~Profiler();
+  private:
+	Timer&                  timer;
+	static FunctionProfile* function; ///< function we are in
+	FunctionProfile*        parent;
+};
+
+// ----------------------------------------------------------------------------- : EOF
+#endif
+#endif

src/script/script_manager.cpp

@@ -10,6 +10,7 @@
 #include <script/script_manager.hpp>
 #include <script/to_value.hpp>
 #include <script/functions/functions.hpp>
+#include <script/profiler.hpp>
 #include <data/set.hpp>
 #include <data/stylesheet.hpp>
 #include <data/game.hpp>
@@ -294,6 +295,10 @@ void SetScriptManager::updateAll() {
 	Context& ctx = getContext(set.stylesheet);
 	FOR_EACH(v, set.data) {
 		try {
+			#if USE_SCRIPT_PROFILING
+				Timer t;
+				Profiler prof(t, v->fieldP.get(), _("update set.") + v->fieldP->name);
+			#endif
 			v->update(ctx);
 		} catch (const ScriptError& e) {
 			handle_error(ScriptError(e.what() + _("\n  while updating set value '") + v->fieldP->name + _("'")), false, true);
@@ -304,6 +309,10 @@ void SetScriptManager::updateAll() {
 		Context& ctx = getContext(card);
 		FOR_EACH(v, card->data) {
 			try {
+				#if USE_SCRIPT_PROFILING
+					Timer t;
+					Profiler prof(t, v->fieldP.get(), _("update card.") + v->fieldP->name);
+				#endif
 				v->update(ctx);
 			} catch (const ScriptError& e) {
 				handle_error(ScriptError(e.what() + _("\n  while updating card value '") + v->fieldP->name + _("'")), false, true);