From 9709364ee798b187b3b22ebe52238fe156b7d1c0 Mon Sep 17 00:00:00 2001 From: twanvl Date: Tue, 2 Sep 2008 16:27:47 +0000 Subject: [PATCH] Script profiler for finding slow scripts git-svn-id: svn://svn.code.sf.net/p/magicseteditor/code/trunk@1191 0fc631ac-6414-0410-93d0-97cfa31319b6 --- src/cli/cli_main.cpp | 18 ++++++ src/cli/cli_main.hpp | 3 + src/script/context.cpp | 136 ++++++++++++++++++++++++++++++++++++++++- src/script/context.hpp | 25 ++++++++ 4 files changed, 180 insertions(+), 2 deletions(-) diff --git a/src/cli/cli_main.cpp b/src/cli/cli_main.cpp index e0490a07..2a56de98 100644 --- a/src/cli/cli_main.cpp +++ b/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 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 diff --git a/src/cli/cli_main.hpp b/src/cli/cli_main.hpp index 7c203ae3..9866ae17 100644 --- a/src/cli/cli_main.hpp +++ b/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(); diff --git a/src/script/context.cpp b/src/script/context.cpp index fd9292ca..b61ebce8 100644 --- a/src/script/context.cpp +++ b/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 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& out) { + double resolution = timer_resolution(); + const vector& 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& 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(value.get())) { + // look up the base function + return lookupVariableValue(closure->fun); + } + return (Variable)-1; +} + ScriptValueP Context::makeClosure(const ScriptValueP& fun) { intrusive_ptr 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)); diff --git a/src/script/context.hpp b/src/script/context.hpp index 81da61a9..cf0b9a04 100644 --- a/src/script/context.hpp +++ b/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& get() const { return values; } private: vector 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& out); +#endif + // ----------------------------------------------------------------------------- : EOF #endif