Added a panel showing profiler timings

src/gui/profiler_window.cpp

+//+----------------------------------------------------------------------------+
+//| Description:  Magic Set Editor - Program to make Magic (tm) cards          |
+//| Copyright:    (C) 2001 - 2010 Twan van Laarhoven and Sean Hunt             |
+//| License:      GNU General Public License 2 or later (see file COPYING)     |
+//+----------------------------------------------------------------------------+
+
+// ----------------------------------------------------------------------------- : Includes
+
+#include <util/prec.hpp>
+#include <script/profiler.hpp>
+#include <wx/dcbuffer.h>
+
+DECLARE_TYPEOF_COLLECTION(FunctionProfileP);
+
+// -----------------------------------------------------------------------------
+// Profiler Panel : class
+// -----------------------------------------------------------------------------
+
+class ProfilerPanel : public wxPanel {
+  public:
+	ProfilerPanel(wxWindow* parent, bool fancy_effects);
+	~ProfilerPanel();
+	
+	virtual bool AcceptsFocus() const { return false; }
+	virtual wxSize DoGetBestSize() const;
+	
+  private:
+	bool        fancy_effects;
+	wxTimer     timer;
+	wxStopWatch stopwatch;
+	
+	typedef std::pair<int,long> NumCallsAndFadeTime;
+	typedef std::map<FunctionProfile const*,NumCallsAndFadeTime> PrevProfiles;
+	PrevProfiles prev_profiles;
+	
+	DECLARE_EVENT_TABLE();
+	void onPaint(wxPaintEvent&);
+	void onEraseBackground(wxEraseEvent&) {}
+	void onTimer(wxTimerEvent&);
+	void onSize(wxSizeEvent&);
+	void draw_profiler(wxDC& dc, int x, int y);
+};
+
+// -----------------------------------------------------------------------------
+// Drawing utilities
+// -----------------------------------------------------------------------------
+
+void clear_dc(wxDC& dc, wxColour const& color) {
+	dc.SetPen(*wxTRANSPARENT_PEN);
+	dc.SetBrush(color);
+	wxSize s = dc.GetSize();
+	dc.DrawRectangle(0,0,s.x,s.y);
+}
+
+void draw_right(wxDC& dc, wxString const& text, int x, int y) {
+	int w, h;
+	dc.GetTextExtent(text, &w, &h);
+	dc.DrawText(text, x-w, y);
+}
+
+// -----------------------------------------------------------------------------
+// Profiler Panel
+// -----------------------------------------------------------------------------
+
+ProfilerPanel::ProfilerPanel(wxWindow* parent, bool fancy_effects)
+	: wxPanel(parent, wxID_ANY)
+	, fancy_effects(fancy_effects)
+	, timer(this)
+{
+//	profiler::set_function_leave_callback(refresh_profiler_panel);
+}
+
+ProfilerPanel::~ProfilerPanel() {
+//	profiler::set_function_leave_callback(nullptr);
+}
+
+
+void ProfilerPanel::onPaint(wxPaintEvent&) {
+	#ifdef __WXMSW__
+		wxBufferedPaintDC dc(this);
+	#else
+		wxPaintDC dc(this);
+	#endif
+	// clear background
+	clear_dc(dc, wxSystemSettings::GetColour(wxSYS_COLOUR_3DFACE));
+	// draw table
+	dc.SetFont(*wxNORMAL_FONT);
+	draw_profiler(dc, 0, 0);
+}
+
+void ProfilerPanel::draw_profiler(wxDC& dc, int x0, int y0) {
+	#if USE_SCRIPT_PROFILING
+		// Get the profiles
+		const FunctionProfile& profile = profile_aggregated(1);
+		vector<FunctionProfileP> profiles;
+		profile.get_children(profiles);
+		// set up colors
+		wxColour fg(0,0,0);
+		wxColour fg_highlight(0,20,220);
+		dc.SetTextForeground(fg);
+		dc.SetPen(fg);
+		// set up positions/sizes
+		int line_height = dc.GetCharHeight() + 2;
+		int x1 = dc.GetSize().x - 2;
+		int pos[] = {x0+2, x1-124, x1-84, x1-44, x1-4 };
+		// fancy effects
+		bool any_active = false;
+		long now = stopwatch.Time();
+		// Draw table
+		dc.DrawText(_("Function"), pos[0], y0 + 2);
+		draw_right(dc,_("calls"),  pos[1], y0 + 2);
+		draw_right(dc,_("avg"),    pos[2], y0 + 2);
+		draw_right(dc,_("total"),  pos[3], y0 + 2);
+		draw_right(dc,_("max"),    pos[4], y0 + 2);
+		dc.DrawLine(x0, y0 + line_height + 2, x1, y0 + line_height + 2);
+		int i = 0;
+		FOR_EACH_REVERSE(prof, profiles) {
+			// recently changed?
+			if (fancy_effects) {
+				PrevProfiles::iterator prev = prev_profiles.find(prof.get());
+				float active = 0.f;
+				const int FADE_TIME = 1000;
+				if (prev == prev_profiles.end()) {
+					prev_profiles[prof.get()] = std::make_pair(prof->calls,0);
+				} else if (prev->second.first != prof->calls) {
+					prev->second = std::make_pair(prof->calls,now+FADE_TIME);
+					any_active = true;
+					active = 1.f;
+					dc.SetTextForeground(*wxRED);
+				} else if (now < prev->second.second) {
+					active = (prev->second.second - now) / (float)FADE_TIME;
+					any_active = true;
+				}
+				dc.SetTextForeground(lerp(fg,fg_highlight,active));
+			}
+			// draw line
+			int y = y0 + (++i) * line_height + 6;
+			dc.DrawText(prof->name,                                        pos[0], y);
+			draw_right(dc,wxString::Format(_("%d"),   prof->calls),        pos[1], y);
+			draw_right(dc,wxString::Format(_("%.2f"), prof->avg_time()),   pos[2], y);
+			draw_right(dc,wxString::Format(_("%.2f"), prof->total_time()), pos[3], y);
+			draw_right(dc,wxString::Format(_("%.2f"), prof->max_time()),   pos[4], y);
+		}
+		// are any fancy effects active?
+		if (fancy_effects && any_active && !timer.IsRunning()) {
+			timer.Start(40,wxTIMER_ONE_SHOT);
+		}
+//%		profiler_panel_refreshing = false;
+	#endif
+}
+
+void ProfilerPanel::onTimer(wxTimerEvent&) {
+	Refresh(false);
+}
+
+void ProfilerPanel::onSize(wxSizeEvent&) {
+	Refresh(true);
+}
+
+wxSize ProfilerPanel::DoGetBestSize() const {
+	return wxSize(300,500);
+}
+
+BEGIN_EVENT_TABLE(ProfilerPanel, wxPanel)
+	EVT_PAINT(          ProfilerPanel::onPaint)
+	EVT_SIZE(           ProfilerPanel::onSize)
+	EVT_TIMER(wxID_ANY, ProfilerPanel::onTimer)
+	EVT_ERASE_BACKGROUND(ProfilerPanel::onEraseBackground)
+END_EVENT_TABLE()
+
+
+void show_profiler_window(wxWindow* parent) {
+	wxDialog* dlg = new wxDialog(parent, wxID_ANY, _("Profiler"), wxDefaultPosition,wxSize(450,600), wxDEFAULT_DIALOG_STYLE|wxRESIZE_BORDER);
+	wxSizer* sizer = new wxBoxSizer(wxVERTICAL);
+	sizer->Add(new ProfilerPanel(dlg,true), 1, wxEXPAND | wxALL, 8);
+	sizer->Add(dlg->CreateButtonSizer(wxOK), 0, wxALIGN_CENTER | wxALL, 8);
+	dlg->SetSizer(sizer);
+	dlg->Show();
+}

src/main.cpp

@@ -48,6 +48,8 @@ class MSE : public wxApp {
 	int OnExit();
 	/// On exception: display error message
 	void HandleEvent(wxEvtHandler *handler, wxEventFunction func, wxEvent& event) const;
+	/// Hack around some wxWidget idiocies
+	int FilterEvent(wxEvent& ev);
 	/// Fancier assert
 	#if defined(_MSC_VER) && defined(_DEBUG)
 		void OnAssert(const wxChar *file, int line, const wxChar *cond, const wxChar *msg);
@@ -286,3 +288,13 @@ void MSE::HandleEvent(wxEvtHandler *handler, wxEventFunction func, wxEvent& even
 		#endif
 	}
 #endif
+
+// ----------------------------------------------------------------------------- : Events
+
+int MSE::FilterEvent(wxEvent& ev) {
+	if (ev.GetEventType() == wxEVT_MOUSE_CAPTURE_LOST) {
+		return 1;
+	} else {
+		return -1;
+	}
+}

src/mse.vcproj

@@ -1074,6 +1074,10 @@
 					RelativePath=".\gui\print_window.hpp"
 					>
 				</File>
+				<File
+					RelativePath=".\gui\profiler_window.cpp"
+					>
+				</File>
 				<File
 					RelativePath=".\gui\thumbnail_thread.cpp"
 					>

src/script/profiler.cpp

@@ -53,7 +53,7 @@ void FunctionProfile::get_children(vector<FunctionProfileP>& out) const {
 	sort(out.begin(), out.end(), compare_time);
 }
 
-
+// note: not thread safe
 FunctionProfile profile_aggr(_("everywhere"));
 
 void profile_aggregate(FunctionProfile& parent, int level, int max_level, const FunctionProfile& p);
@@ -135,6 +135,7 @@ Profiler::~Profiler() {
 	ProfileTime time = timer.time();
 	if (function == parent) return; // don't count
 	function->time_ticks += time;
+	function->time_ticks_max = max(function->time_ticks_max,time);
 	function->calls      += 1;
 	function = parent; // pop
 }

src/script/profiler.hpp

@@ -75,11 +75,15 @@ class Timer {
 /// 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) {}
+	FunctionProfile(const String& name)
+		: name(name), time_ticks(0), time_ticks_max(0), calls(0)
+	{}
 
 	String      name;
 	ProfileTime time_ticks;
-	UInt        calls;
+	ProfileTime time_ticks_max;
+	int         calls;
+	
 	/// for each id, called children
 	/** we (ab)use the fact that all pointers are even to store both pointers and ids */
 	map<size_t,FunctionProfileP> children;
@@ -88,13 +92,15 @@ class FunctionProfile : public IntrusivePtrBase<FunctionProfile> {
 	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; }
+	inline double total_time() const { return time_ticks / (double)timer_resolution(); }
+	inline double avg_time() const { return total_time() / calls; }
+	inline double max_time() const { return time_ticks_max / (double)timer_resolution(); }
 };
 
 /// The root profile
 extern FunctionProfile profile_root;
 
+/// Return a simplified profile, where all things beyond a cerrain level are agragated
 const FunctionProfile& profile_aggregated(int level = 1);
 
 // ----------------------------------------------------------------------------- : Profiler
@@ -119,6 +125,20 @@ class Profiler {
 	FunctionProfile*        parent;
 };
 
+// Profile the current function (all following code in the current block) under the given name
+#define PROFILER(name) \
+	Timer profile_timer; \
+	Profiler profiler(profile_timer, name)
+#define PROFILER2(name1,name2) \
+	Timer profile_timer; \
+	Profiler profiler(profile_timer, name1,name2)
+
+#else // USE_SCRIPT_PROFILING
+
+#define PROFILER(a)
+#define PROFILER2(a,b)
+
+#endif // USE_SCRIPT_PROFILING
+
 // ----------------------------------------------------------------------------- : EOF
 #endif
-#endif

src/script/script_manager.cpp

@@ -295,10 +295,7 @@ 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
+			PROFILER2( v->fieldP.get(), _("update set.") + v->fieldP->name );
 			v->update(ctx);
 		} catch (const ScriptError& e) {
 			handle_error(ScriptError(e.what() + _("\n  while updating set value '") + v->fieldP->name + _("'")), false, true);

src/util/prec.hpp

@@ -55,6 +55,12 @@ typedef wxDateTime DateTime;
 
 typedef wxOutputStream OutputStream;
 
+// ----------------------------------------------------------------------------- : Compatability fixes
+
+#if wxVERSION_NUMBER < 2805
+	#define wxBORDER_THEME wxSUNKEN_BORDER
+#endif
+
 // ----------------------------------------------------------------------------- : Other aliasses
 
 typedef unsigned char Byte;

src/util/window_id.hpp

@@ -42,6 +42,7 @@ enum MenuID {
 ,	ID_FILE_RECENT			= wxID_FILE1
 ,	ID_FILE_RECENT_MAX		= wxID_FILE9
 ,	ID_FILE_CHECK_UPDATES	= 10
+,	ID_FILE_PROFILER        = 11
 
 	// Edit menu
 ,	ID_EDIT_UNDO			= wxID_UNDO