Add some debug code to time things in the process

thread(s).


git-svn-id: svn://localhost/ardour2/branches/3.0@11246 d708f5d6-7413-0410-9779-e7cbd77b26cf

5 files changed, 102 insertions, 5 deletions

diff --git a/libs/ardour/ardour/cycle_timer.h b/libs/ardour/ardour/cycle_timer.h
index dc70204e82..35cc2a4c73 100644
--- a/libs/ardour/ardour/cycle_timer.h
+++ b/libs/ardour/ardour/cycle_timer.h
@@ -22,10 +22,13 @@
 
 #include <string>
 #include <iostream>
+#include <cstdlib>
 
 #include "ardour/cycles.h"
 #include "ardour/debug.h"
 
+float get_mhz ();
+
 class CycleTimer {
   private:
 	static float cycles_per_usec;
@@ -56,8 +59,34 @@ class CycleTimer {
 		}
 #endif
 	}
+};
 
-	static float get_mhz ();
+class StoringTimer
+{
+public:
+	StoringTimer (int);
+	void ref ();
+	void check (int);
+	void dump (std::string const &);
+
+private:
+	cycles_t _current_ref;
+	int* _point;
+	cycles_t* _value;
+	cycles_t* _ref;
+	int _points;
+	int _max_points;
 };
 
+#ifdef PT_TIMING
+extern StoringTimer ST;
+#define PT_TIMING_REF ST.ref();
+#define PT_TIMING_CHECK(x) ST.check(x);
+#endif
+
+#ifndef PT_TIMING
+#define PT_TIMING_REF
+#define PT_TIMING_CHECK(x)
+#endif
+
 #endif /* __ardour_cycle_timer_h__ */
diff --git a/libs/ardour/audioengine.cc b/libs/ardour/audioengine.cc
index 34a79c35f8..06a1637382 100644
--- a/libs/ardour/audioengine.cc
+++ b/libs/ardour/audioengine.cc
@@ -446,9 +446,11 @@ int
 AudioEngine::process_callback (pframes_t nframes)
 {
 	GET_PRIVATE_JACK_POINTER_RET(_jack,0);
-	// CycleTimer ct ("AudioEngine::process");
 	Glib::Mutex::Lock tm (_process_lock, Glib::TRY_LOCK);
 
+	PT_TIMING_REF;
+	PT_TIMING_CHECK (1);
+
 	/// The number of frames that will have been processed when we've finished
 	pframes_t next_processed_frames;
 
@@ -504,7 +506,6 @@ AudioEngine::process_callback (pframes_t nframes)
 	} else {
 		if (_session) {
 			_session->process (nframes);
-
 		}
 	}
 
@@ -555,6 +556,9 @@ AudioEngine::process_callback (pframes_t nframes)
 	}
 
 	_processed_frames = next_processed_frames;
+
+	PT_TIMING_CHECK (2);
+	
 	return 0;
 }
 
diff --git a/libs/ardour/cycle_timer.cc b/libs/ardour/cycle_timer.cc
index 7a6b1fcab2..02d1abb930 100644
--- a/libs/ardour/cycle_timer.cc
+++ b/libs/ardour/cycle_timer.cc
@@ -18,17 +18,19 @@
 */
 
 #include <cstdio>
+#include <fstream>
 #include "pbd/error.h"
 #include "ardour/cycle_timer.h"
 
 #include "i18n.h"
 
+using namespace std;
 using namespace PBD;
 
 float CycleTimer::cycles_per_usec = 0;
 
 float
-CycleTimer::get_mhz()
+get_mhz()
 {
 	FILE *f;
 
@@ -72,3 +74,54 @@ CycleTimer::get_mhz()
 	/*NOTREACHED*/
 	return 0.0f;
 }
+
+StoringTimer::StoringTimer (int N)
+{
+	_point = new int[N];
+	_value = new cycles_t[N];
+	_ref = new cycles_t[N];
+	_max_points = N;
+	_points = 0;
+}
+	
+
+void
+StoringTimer::dump (string const & file)
+{
+	ofstream f (file.c_str ());
+
+	f << min (_points, _max_points) << "\n";
+	f << get_mhz () << "\n";
+	for (int i = 0; i < min (_points, _max_points); ++i) {
+		f << _point[i] << " " << _ref[i] << " " << _value[i] << "\n";
+	}
+}
+
+void
+StoringTimer::ref ()
+{
+	_current_ref = get_cycles ();
+}
+
+void
+StoringTimer::check (int p)
+{
+	if (_points == _max_points) {
+		++_points;
+		return;
+	} else if (_points > _max_points) {
+		return;
+	}
+	
+	_point[_points] = p;
+	_value[_points] = get_cycles ();
+	_ref[_points] = _current_ref;
+	
+	++_points;
+}
+
+#ifdef PT_TIMING
+StoringTimer ST (64 * 1024);
+#endif
+
+
diff --git a/libs/ardour/session.cc b/libs/ardour/session.cc
index 37349cc5fb..26b3d47b7e 100644
--- a/libs/ardour/session.cc
+++ b/libs/ardour/session.cc
@@ -217,6 +217,9 @@ Session::Session (AudioEngine &eng,
 
 Session::~Session ()
 {
+#ifdef PT_TIMING	
+	ST.dump ("ST.dump");
+#endif	
 	destroy ();
 }
 
diff --git a/libs/ardour/session_process.cc b/libs/ardour/session_process.cc
index 4876dc7931..80f922117d 100644
--- a/libs/ardour/session_process.cc
+++ b/libs/ardour/session_process.cc
@@ -39,6 +39,7 @@
 #include "ardour/graph.h"
 #include "ardour/audio_port.h"
 #include "ardour/tempo.h"
+#include "ardour/cycle_timer.h"
 
 #include "midi++/manager.h"
 #include "midi++/mmc.h"
@@ -103,6 +104,8 @@ Session::fail_roll (pframes_t nframes)
 int
 Session::no_roll (pframes_t nframes)
 {
+	PT_TIMING_CHECK (4);
+	
 	framepos_t end_frame = _transport_frame + nframes; // FIXME: varispeed + no_roll ??
 	int ret = 0;
 	bool declick = get_transport_declick_required();
@@ -112,10 +115,11 @@ Session::no_roll (pframes_t nframes)
 		_click_io->silence (nframes);
 	}
 
-	if (_process_graph->threads_in_use() > 0) {
+	if (1 || _process_graph->threads_in_use() > 0) {
 		DEBUG_TRACE(DEBUG::ProcessThreads,"calling graph/no-roll\n");
 		_process_graph->routes_no_roll( nframes, _transport_frame, end_frame, non_realtime_work_pending(), declick);
 	} else {
+		PT_TIMING_CHECK (10);
 		for (RouteList::iterator i = r->begin(); i != r->end(); ++i) {
 
 			if ((*i)->is_hidden()) {
@@ -130,8 +134,10 @@ Session::no_roll (pframes_t nframes)
 				break;
 			}
 		}
+		PT_TIMING_CHECK (11);
 	}
 
+	PT_TIMING_CHECK (5);
 	return ret;
 }
 
@@ -242,6 +248,8 @@ Session::get_track_statistics ()
 void
 Session::process_with_events (pframes_t nframes)
 {
+	PT_TIMING_CHECK (3);
+	
 	SessionEvent*  ev;
 	pframes_t      this_nframes;
 	framepos_t     end_frame;