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

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__ */

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;
 }
 

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
+
+

libs/ardour/session.cc

@@ -217,6 +217,9 @@ Session::Session (AudioEngine &eng,
 
 Session::~Session ()
 {
+#ifdef PT_TIMING	
+	ST.dump ("ST.dump");
+#endif	
 	destroy ();
 }
 

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;

wscript

@@ -391,6 +391,8 @@ def options(opt):
                     help='Build with debugging for the STL')
     opt.add_option('--rt-alloc-debug', action='store_true', default=False, dest='rt_alloc_debug',
                     help='Build with debugging for memory allocation in the real-time thread')
+    opt.add_option('--pt-timing', action='store_true', default=False, dest='pt_timing',
+                    help='Build with logging of timing in the process thread(s)')
     opt.add_option('--denormal-exception', action='store_true', default=False, dest='denormal_exception',
                     help='Raise a floating point exception if a denormal is detected')
     opt.add_option('--test', action='store_true', default=False, dest='build_tests',
@@ -589,6 +591,9 @@ def configure(conf):
     if opts.rt_alloc_debug:
         conf.define('DEBUG_RT_ALLOC', 1)
         conf.env['DEBUG_RT_ALLOC'] = True
+    if opts.pt_timing:
+        conf.define('PT_TIMING', 1)
+        conf.env['PT_TIMING'] = True
     if opts.denormal_exception:
         conf.define('DEBUG_DENORMAL_EXCEPTION', 1)
         conf.env['DEBUG_DENORMAL_EXCEPTION'] = True
@@ -621,6 +626,7 @@ const char* const ardour_config_info = "\\n\\
     write_config_text('Build target',          conf.env['build_target'])
     write_config_text('CoreAudio',             conf.is_defined('HAVE_COREAUDIO'))
     write_config_text('Debug RT allocations',  conf.is_defined('DEBUG_RT_ALLOC'))
+    write_config_text('Process thread timing', conf.is_defined('PT_TIMING'))
     write_config_text('Denormal exceptions',   conf.is_defined('DEBUG_DENORMAL_EXCEPTION'))
     write_config_text('FLAC',                  conf.is_defined('HAVE_FLAC'))
     write_config_text('FPU optimization',      opts.fpu_optimization)