Script profiler for finding slow scripts

src/cli/cli_main.cpp

@@ -161,6 +161,10 @@ void CLISetInterface::handleCommand(const String& command) {
 						system(arg.c_str());
 					#endif
 				}
+			#if USE_SCRIPT_PROFILING
+				} else if (before == _(":profile")) {
+					showProfilingStats();
+			#endif
 			} else {
 				cli.showError(_("Unknown command, type :help for help."));
 			}
@@ -187,3 +191,17 @@ void CLISetInterface::handleCommand(const String& command) {
 		cli.showError(e.what());
 	}
 }
+
+#if USE_SCRIPT_PROFILING
+	DECLARE_TYPEOF_COLLECTION(FunctionProfileItem);
+	void CLISetInterface::showProfilingStats() {
+		vector<FunctionProfileItem> stats;
+		get_profile(stats);
+		sort(stats.begin(), stats.end());
+		cli << GRAY << _("Time(s)   Avg (ms)  Calls   Function") << ENDL;
+		cli <<         _("========  ========  ======  ===============================") << NORMAL << ENDL;
+		FOR_EACH_REVERSE(s, stats) {
+			cli << String::Format(_("%8.5f  %8.5f  %6d  %s"), s.time, 1000 * s.time / s.calls, s.calls, s.name.c_str()) << ENDL;
+		}
+	}
+#endif

src/cli/cli_main.hpp

@@ -32,6 +32,9 @@ class CLISetInterface : public SetView {
 	void showWelcome();
 	void showUsage();
 	void handleCommand(const String& command);
+	#if USE_SCRIPT_PROFILING
+		void showProfilingStats();
+	#endif
 	
 	/// our own context, when no set is loaded
 	Context& getContext();

src/script/context.cpp

@@ -18,6 +18,95 @@ 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)
@@ -132,8 +221,21 @@ ScriptValueP Context::eval(const Script& script, bool useScope) {
 					}
 					instr += i.data; // skip arguments
 					try {
+						#if USE_SCRIPT_PROFILING
+							Timer timer;
+							const Instruction* instr_bt = script.backtraceSkip(instr - i.data - 2, i.data);
+							Variable function = instr_bt && instr_bt->instr == I_GET_VAR
+							                  ? (Variable)instr_bt->data
+							                  : (Variable)-1;
+							Profiler prof(timer, function);
+						#endif
 						// get function and call
 						stack.back() = stack.back()->eval(*this);
+						// finish profiling
+						#if USE_SCRIPT_PROFILING
+							//profile_add(function, timer.time());
+							//%timer.exclude_time();
+						#endif
 					} catch (const Error& e) {
 						// try to determine what named function was called
 						// the instructions for this look like:
@@ -258,6 +360,20 @@ int Context::getVariableScope(Variable var) {
 	else                      return -1;
 }
 
+Variable Context::lookupVariableValue(const ScriptValueP& value) {
+	const vector<VariableValue>& vars = variables.get();
+	for (size_t i = 0 ; i < vars.size() ; ++i) {
+		if (vars[i].value == value) {
+			return (Variable)i;
+		}
+	}
+	if (ScriptClosure* closure = dynamic_cast<ScriptClosure*>(value.get())) {
+		// look up the base function
+		return lookupVariableValue(closure->fun);
+	}
+	return (Variable)-1;
+}
+
 ScriptValueP Context::makeClosure(const ScriptValueP& fun) {
 	intrusive_ptr<ScriptClosure> closure(new ScriptClosure(fun));
 	// we can find out which variables are in the last level by looking at shadowed
@@ -331,8 +447,24 @@ class ScriptCompose : public ScriptValue {
 	virtual ScriptType type() const { return SCRIPT_FUNCTION; }
 	virtual String typeName() const { return _("function composition"); }
 	virtual ScriptValueP eval(Context& ctx) const {
-		ctx.setVariable(SCRIPT_VAR_input, a->eval(ctx));
-		return b->eval(ctx);
+		#if USE_SCRIPT_PROFILING
+			Timer timer;
+			{
+				// execute a
+				Variable fun = ctx.lookupVariableValue(a);
+				Profiler prof(timer,fun);
+				ctx.setVariable(SCRIPT_VAR_input, a->eval(ctx));
+			}
+			{
+				// execute b
+				Variable fun = ctx.lookupVariableValue(b);
+				Profiler prof(timer,fun);
+				return b->eval(ctx);
+			}
+		#else
+			ctx.setVariable(SCRIPT_VAR_input, a->eval(ctx));
+			return b->eval(ctx);
+		#endif
 	}
 	virtual ScriptValueP dependencies(Context& ctx, const Dependency& dep) const {
 		ctx.setVariable(SCRIPT_VAR_input, a->dependencies(ctx, dep));

src/script/context.hpp

@@ -13,6 +13,8 @@
 
 class Dependency;
 
+#define USE_SCRIPT_PROFILING 1 // TODO: Disable before release!
+
 // ----------------------------------------------------------------------------- : VectorIntMap
 
 /// A map like data structure that stores the elements in a vector.
@@ -26,6 +28,8 @@ class VectorIntMap {
 		}
 		return values[key];
 	}
+	/// Get access to the vector
+	inline const vector<V>& get() const { return values; }
   private:
 	vector<V> values;
 };
@@ -120,6 +124,12 @@ class Context {
 	void makeObject(size_t n);
 	/// Make a closure with n arguments
 	void makeClosure(size_t n, const Instruction*& instr);
+	
+	/// 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;
+	#endif
 };
 
 /// A class that creates a local scope
@@ -132,5 +142,20 @@ 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