Add some very basic timing of the player.

8 files changed, 194 insertions, 17 deletions

diff --git a/src/lib/timer.cc b/src/lib/timer.cc
index e0cd93d7a..2e138aabf 100644
--- a/src/lib/timer.cc
+++ b/src/lib/timer.cc
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2012 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2012-2019 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -30,6 +30,7 @@
 #include "i18n.h"
 
 using namespace std;
+using boost::optional;
 
 /** @param n Name to use when giving output */
 PeriodTimer::PeriodTimer (string n)
@@ -58,34 +59,55 @@ StateTimer::StateTimer (string n, string s)
 	_state = s;
 }
 
+StateTimer::StateTimer (string n)
+	: _name (n)
+{
+
+}
+
+void
+StateTimer::set (string s)
+{
+	set_internal (s);
+}
+
 /** @param s New state that the caller is in */
 void
-StateTimer::set_state (string s)
+StateTimer::set_internal (optional<string> s)
 {
 	double const last = _time;
 	struct timeval t;
 	gettimeofday (&t, 0);
 	_time = seconds (t);
 
-	if (_totals.find (s) == _totals.end ()) {
-		_totals[s] = 0;
+	if (s && _counts.find(*s) == _counts.end()) {
+		_counts[*s] = Counts();
 	}
 
-	_totals[_state] += _time - last;
+	if (_state) {
+		_counts[*_state].total_time += _time - last;
+		_counts[*_state].number++;
+	}
 	_state = s;
 }
 
+void
+StateTimer::unset ()
+{
+	set_internal (optional<string>());
+}
+
 /** Destroy StateTimer and generate a summary of the state timings on cout */
 StateTimer::~StateTimer ()
 {
-	if (_state.empty ()) {
+	if (!_state) {
 		return;
 	}
 
-	set_state (N_(""));
+	unset ();
 
 	cout << _name << N_(":\n");
-	for (map<string, double>::iterator i = _totals.begin(); i != _totals.end(); ++i) {
-		cout << N_("\t") << i->first << " " << i->second << N_("\n");
+	for (map<string, Counts>::iterator i = _counts.begin(); i != _counts.end(); ++i) {
+		cout << N_("\t") << i->first << " " << i->second.total_time << " " << i->second.number << " " << (i->second.total_time / i->second.number) << N_("\n");
 	}
 }
diff --git a/src/lib/timer.h b/src/lib/timer.h
index 9ea95c720..bd4e652f8 100644
--- a/src/lib/timer.h
+++ b/src/lib/timer.h
@@ -1,6 +1,6 @@
 /*
-    Copyright (C) 2012 Carl Hetherington <cth@carlh.net>
-    Copyright (C) 2000-2007 Paul Davis
+    Copyright (C) 2012-2019 Carl Hetherington <cth@carlh.net>
+
     This file is part of DCP-o-matic.
 
     DCP-o-matic is free software; you can redistribute it and/or modify
@@ -26,6 +26,7 @@
 #define DCPOMATIC_TIMER_H
 
 #include <sys/time.h>
+#include <boost/optional.hpp>
 #include <string>
 #include <map>
 
@@ -59,20 +60,44 @@ private:
 class StateTimer
 {
 public:
+	explicit StateTimer (std::string n);
 	StateTimer (std::string n, std::string s);
 	~StateTimer ();
 
-	void set_state (std::string s);
+	void set (std::string s);
+	void unset ();
+
+	std::string name () const {
+		return _name;
+	}
+
+	class Counts
+	{
+	public:
+		Counts ()
+			: total_time (0)
+			, number (0)
+		{}
+
+		double total_time;
+		int number;
+	};
+
+	std::map<std::string, Counts> counts () const {
+		return _counts;
+	}
 
 private:
+	void set_internal (boost::optional<std::string> s);
+
 	/** name to add to the output */
 	std::string _name;
 	/** current state */
-	std::string _state;
+	boost::optional<std::string> _state;
 	/** time that _state was entered */
 	double _time;
-	/** time that has been spent in each state so far */
-	std::map<std::string, double> _totals;
+	/** total time and number of entries for each state */
+	std::map<std::string, Counts> _counts;
 };
 
 #endif
diff --git a/src/tools/dcpomatic_player.cc b/src/tools/dcpomatic_player.cc
index 7abc7c921..8422df28e 100644
--- a/src/tools/dcpomatic_player.cc
+++ b/src/tools/dcpomatic_player.cc
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2017-2018 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2017-2019 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -29,6 +29,7 @@
 #include "wx/verify_dcp_dialog.h"
 #include "wx/standard_controls.h"
 #include "wx/swaroop_controls.h"
+#include "wx/timer_display.h"
 #include "lib/cross.h"
 #include "lib/config.h"
 #include "lib/util.h"
@@ -108,6 +109,7 @@ enum {
 	ID_help_report_a_problem,
 	ID_tools_verify,
 	ID_tools_check_for_updates,
+	ID_tools_timing,
 	/* IDs for shortcuts (with no associated menu item) */
 	ID_start_stop,
 	ID_back_frame,
@@ -168,6 +170,7 @@ public:
 		Bind (wxEVT_MENU, boost::bind (&DOMFrame::help_report_a_problem, this), ID_help_report_a_problem);
 		Bind (wxEVT_MENU, boost::bind (&DOMFrame::tools_verify, this), ID_tools_verify);
 		Bind (wxEVT_MENU, boost::bind (&DOMFrame::tools_check_for_updates, this), ID_tools_check_for_updates);
+		Bind (wxEVT_MENU, boost::bind (&DOMFrame::tools_timing, this), ID_tools_timing);
 
 		/* Use a panel as the only child of the Frame so that we avoid
 		   the dark-grey background on Windows.
@@ -498,6 +501,7 @@ private:
 		_tools_verify = tools->Append (ID_tools_verify, _("Verify DCP"));
 		tools->AppendSeparator ();
 		tools->Append (ID_tools_check_for_updates, _("Check for updates"));
+		tools->Append (ID_tools_timing, _("Timing..."));
 
 		wxMenu* help = new wxMenu;
 #ifdef __WXOSX__
@@ -768,6 +772,13 @@ private:
 		_update_news_requested = true;
 	}
 
+	void tools_timing ()
+	{
+		TimerDisplay* d = new TimerDisplay (this, _viewer->state_timer(), _viewer->gets());
+		d->ShowModal ();
+		d->Destroy ();
+	}
+
 	void help_about ()
 	{
 		AboutDialog* d = new AboutDialog (this);
diff --git a/src/wx/film_viewer.cc b/src/wx/film_viewer.cc
index 6d050157c..a803eeda1 100644
--- a/src/wx/film_viewer.cc
+++ b/src/wx/film_viewer.cc
@@ -92,6 +92,8 @@ FilmViewer::FilmViewer (wxWindow* p)
 	, _in_watermark (false)
 	, _background_image (false)
 #endif
+	, _state_timer ("viewer")
+	, _gets (0)
 {
 #ifndef __WXOSX__
 	_panel->SetDoubleBuffered (true);
@@ -211,14 +213,17 @@ FilmViewer::recreate_butler ()
 void
 FilmViewer::refresh_panel ()
 {
+	_state_timer.set ("refresh-panel");
 	_panel->Refresh ();
 	_panel->Update ();
+	_state_timer.unset ();
 }
 
 void
 FilmViewer::get ()
 {
 	DCPOMATIC_ASSERT (_butler);
+	++_gets;
 
 	do {
 		Butler::Error e;
@@ -275,9 +280,12 @@ FilmViewer::display_player_video ()
 	 * image and convert it (from whatever the user has said it is) to RGB.
 	 */
 
+	_state_timer.set ("get image");
 	_frame = _player_video.first->image (bind(&PlayerVideo::force, _1, AV_PIX_FMT_RGB24), false, true);
 
+	_state_timer.set ("ImageChanged");
 	ImageChanged (_player_video.first);
+	_state_timer.unset ();
 
 	_video_position = _player_video.second;
 	_inter_position = _player_video.first->inter_position ();
@@ -337,12 +345,15 @@ FilmViewer::maybe_draw_background_image (wxPaintDC &)
 void
 FilmViewer::paint_panel ()
 {
+	_state_timer.set ("paint-panel");
+
 	wxPaintDC dc (_panel);
 
 #ifdef DCPOMATIC_VARIANT_SWAROOP
 	if (_background_image) {
 		dc.Clear ();
 		maybe_draw_background_image (dc);
+		_state_timer.unset ();
 		return;
 	}
 #endif
@@ -402,6 +413,8 @@ FilmViewer::paint_panel ()
 		dc.SetBrush (*wxTRANSPARENT_BRUSH);
 		dc.DrawRectangle (_inter_position.x, _inter_position.y + (_panel_size.height - _out_size.height) / 2, _inter_size.width, _inter_size.height);
 	}
+
+	_state_timer.unset ();
 }
 
 void
diff --git a/src/wx/film_viewer.h b/src/wx/film_viewer.h
index 972a88a5a..97da5f591 100644
--- a/src/wx/film_viewer.h
+++ b/src/wx/film_viewer.h
@@ -1,5 +1,5 @@
 /*
-    Copyright (C) 2012-2018 Carl Hetherington <cth@carlh.net>
+    Copyright (C) 2012-2019 Carl Hetherington <cth@carlh.net>
 
     This file is part of DCP-o-matic.
 
@@ -25,6 +25,7 @@
 #include "lib/film.h"
 #include "lib/config.h"
 #include "lib/player_text.h"
+#include "lib/timer.h"
 #include <RtAudio.h>
 #include <wx/wx.h>
 
@@ -95,6 +96,14 @@ public:
 	}
 #endif
 
+	StateTimer const & state_timer () const {
+		return _state_timer;
+	}
+
+	int gets () const {
+		return _gets;
+	}
+
 	boost::signals2::signal<void (boost::weak_ptr<PlayerVideo>)> ImageChanged;
 	boost::signals2::signal<void ()> PositionChanged;
 	boost::signals2::signal<void (DCPTime)> Started;
@@ -174,5 +183,8 @@ private:
 	bool _background_image;
 #endif
 
+	StateTimer _state_timer;
+	int _gets;
+
 	boost::signals2::scoped_connection _config_changed_connection;
 };
diff --git a/src/wx/timer_display.cc b/src/wx/timer_display.cc
new file mode 100644
index 000000000..7d43a3307
--- /dev/null
+++ b/src/wx/timer_display.cc
@@ -0,0 +1,64 @@
+/*
+    Copyright (C) 2019 Carl Hetherington <cth@carlh.net>
+
+    This file is part of DCP-o-matic.
+
+    DCP-o-matic is free software; you can redistribute it and/or modify
+    it under the terms of the GNU General Public License as published by
+    the Free Software Foundation; either version 2 of the License, or
+    (at your option) any later version.
+
+    DCP-o-matic is distributed in the hope that it will be useful,
+    but WITHOUT ANY WARRANTY; without even the implied warranty of
+    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+    GNU General Public License for more details.
+
+    You should have received a copy of the GNU General Public License
+    along with DCP-o-matic.  If not, see <http://www.gnu.org/licenses/>.
+
+*/
+
+#include "timer_display.h"
+#include "wx_util.h"
+#include "lib/timer.h"
+#include <dcp/locale_convert.h>
+#include <list>
+
+using std::map;
+using std::list;
+using std::pair;
+using std::make_pair;
+using std::string;
+
+static
+bool
+comparator (pair<string, StateTimer::Counts> const & a, pair<string, StateTimer::Counts> const & b)
+{
+	return a.second.total_time > b.second.total_time;
+}
+
+TimerDisplay::TimerDisplay (wxWindow* parent, StateTimer const & timer, int gets)
+	: TableDialog (parent, std_to_wx(timer.name()), 4, 0, false)
+{
+	map<string, StateTimer::Counts> counts = timer.counts ();
+	list<pair<string, StateTimer::Counts> > sorted;
+	for (map<string, StateTimer::Counts>::const_iterator i = counts.begin(); i != counts.end(); ++i) {
+		sorted.push_back (make_pair(i->first, i->second));
+	}
+
+	sorted.sort (comparator);
+
+	add (wxString("get() calls"), true);
+	add (std_to_wx(dcp::locale_convert<string>(gets)), false);
+	add_spacer ();
+	add_spacer ();
+
+	for (list<pair<string, StateTimer::Counts> >::const_iterator i = sorted.begin(); i != sorted.end(); ++i) {
+		add (std_to_wx(i->first), true);
+		add (std_to_wx(dcp::locale_convert<string>(i->second.total_time)), false);
+		add (std_to_wx(dcp::locale_convert<string>(i->second.number)), false);
+		add (std_to_wx(dcp::locale_convert<string>(i->second.total_time / i->second.number)), false);
+	}
+
+	layout ();
+}
diff --git a/src/wx/timer_display.h b/src/wx/timer_display.h
new file mode 100644
index 000000000..5ee72bff5
--- /dev/null
+++ b/src/wx/timer_display.h
@@ -0,0 +1,29 @@
+/*
+    Copyright (C) 2019 Carl Hetherington <cth@carlh.net>
+
+    This file is part of DCP-o-matic.
+
+    DCP-o-matic is free software; you can redistribute it and/or modify
+    it under the terms of the GNU General Public License as published by
+    the Free Software Foundation; either version 2 of the License, or
+    (at your option) any later version.
+
+    DCP-o-matic is distributed in the hope that it will be useful,
+    but WITHOUT ANY WARRANTY; without even the implied warranty of
+    MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE.  See the
+    GNU General Public License for more details.
+
+    You should have received a copy of the GNU General Public License
+    along with DCP-o-matic.  If not, see <http://www.gnu.org/licenses/>.
+
+*/
+
+#include "table_dialog.h"
+
+class StateTimer;
+
+class TimerDisplay : public TableDialog
+{
+public:
+	TimerDisplay (wxWindow* parent, StateTimer const & timer, int gets);
+};
diff --git a/src/wx/wscript b/src/wx/wscript
index 0985423bc..816f5a63f 100644
--- a/src/wx/wscript
+++ b/src/wx/wscript
@@ -123,6 +123,7 @@ sources = """
           text_panel.cc
           text_view.cc
           time_picker.cc
+          timer_display.cc
           timecode.cc
           timeline.cc
           timeline_atmos_content_view.cc