add slave,transport and event debugging traces

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

7 files changed, 96 insertions, 48 deletions

diff --git a/libs/ardour/ardour/debug.h b/libs/ardour/ardour/debug.h
index d90c82fcbe..f4170acfeb 100644
--- a/libs/ardour/ardour/debug.h
+++ b/libs/ardour/ardour/debug.h
@@ -47,7 +47,9 @@ namespace ARDOUR {
 			Graph = 0x80,
 			Destruction = 0x100,
 			MTC = 0x200,
-			Transport = 0x400
+			Transport = 0x400,
+			Slave = 0x800,
+			SessionEvents = 0x800,
 		};
 	}
 
diff --git a/libs/ardour/ardour/session.h b/libs/ardour/ardour/session.h
index da985d2ce7..06f6b5e505 100644
--- a/libs/ardour/ardour/session.h
+++ b/libs/ardour/ardour/session.h
@@ -117,6 +117,8 @@ class Source;
 class TempoMap;
 class VSTPlugin;
 
+extern void setup_enum_writer ();
+
 class Session : public PBD::StatefulDestructible, public boost::noncopyable
 {
   private:
@@ -960,15 +962,37 @@ class Session : public PBD::StatefulDestructible, public boost::noncopyable
 		return _exporting;
 	}
 
+	/* this is a private enum, but setup_enum_writer() needs it,
+	   and i can't find a way to give that function
+	   friend access. sigh.
+	*/
+
+	enum PostTransportWork {
+		PostTransportStop               = 0x1,
+		PostTransportDisableRecord      = 0x2,
+		PostTransportPosition           = 0x8,
+		PostTransportDidRecord          = 0x20,
+		PostTransportDuration           = 0x40,
+		PostTransportLocate             = 0x80,
+		PostTransportRoll               = 0x200,
+		PostTransportAbort              = 0x800,
+		PostTransportOverWrite          = 0x1000,
+		PostTransportSpeed              = 0x2000,
+		PostTransportAudition           = 0x4000,
+		PostTransportScrub              = 0x8000,
+		PostTransportReverse            = 0x10000,
+		PostTransportInputChange        = 0x20000,
+		PostTransportCurveRealloc       = 0x40000,
+		PostTransportClearSubstate      = 0x80000
+	};
+
+
   protected:
 	friend class AudioEngine;
 	void set_block_size (nframes_t nframes);
 	void set_frame_rate (nframes_t nframes);
 
   protected:
-	friend class Diskstream;
-
-  protected:
 	friend class Route;
 	void schedule_curve_reallocation ();
 	void update_latency_compensation (bool, bool);
@@ -1174,6 +1198,7 @@ class Session : public PBD::StatefulDestructible, public boost::noncopyable
 
 	Butler* _butler;
 
+#if 0 // these should be here, see comments in their other location above
 	enum PostTransportWork {
 		PostTransportStop               = 0x1,
 		PostTransportDisableRecord      = 0x2,
@@ -1192,7 +1217,7 @@ class Session : public PBD::StatefulDestructible, public boost::noncopyable
 		PostTransportCurveRealloc       = 0x40000,
 		PostTransportClearSubstate      = 0x80000
 	};
-
+#endif
 	static const PostTransportWork ProcessCannotProceedMask =
 		PostTransportWork (
 				PostTransportInputChange|
diff --git a/libs/ardour/debug.cc b/libs/ardour/debug.cc
index 0e9b7d8182..4677f696ae 100644
--- a/libs/ardour/debug.cc
+++ b/libs/ardour/debug.cc
@@ -84,6 +84,10 @@ ARDOUR::parse_debug_options (const char* str)
 			bits |= ARDOUR::DEBUG::MTC;
 		} else if (strncasecmp (p, "transport", strlen (p)) == 0) {
 			bits |= ARDOUR::DEBUG::Transport;
+		} else if (strncasecmp (p, "slave", strlen (p)) == 0) {
+			bits |= ARDOUR::DEBUG::Transport;
+		} else if (strncasecmp (p, "sessionevents", strlen (p)) == 0) {
+			bits |= ARDOUR::DEBUG::SessionEvents;
 		}
 
 		p = strtok_r (0, ",", &sp);
@@ -109,4 +113,6 @@ ARDOUR::list_debug_options ()
 	cerr << "\tDestruction" << endl;
 	cerr << "\tMTC" << endl;
 	cerr << "\tTransport" << endl;
+	cerr << "\tSlave" << endl;
+	cerr << "\tSessionEvents" << endl;
 }
diff --git a/libs/ardour/enums.cc b/libs/ardour/enums.cc
index 72aa5bef55..870c60eec7 100644
--- a/libs/ardour/enums.cc
+++ b/libs/ardour/enums.cc
@@ -114,7 +114,8 @@ setup_enum_writer ()
 	WaveformScale _WaveformScale;
 	WaveformShape _WaveformShape;
 	QuantizeType _QuantizeType;
-
+	Session::PostTransportWork _Session_PostTransportWork;
+		
 #define REGISTER(e) enum_writer->register_distinct (typeid(e).name(), i, s); i.clear(); s.clear()
 #define REGISTER_BITS(e) enum_writer->register_bits (typeid(e).name(), i, s); i.clear(); s.clear()
 #define REGISTER_ENUM(e) i.push_back (e); s.push_back (#e)
@@ -304,6 +305,24 @@ setup_enum_writer ()
 	REGISTER_CLASS_ENUM (Session::Event, AutoLoop);
 	REGISTER (_Session_Event_Type);
 
+	REGISTER_CLASS_ENUM (Session, PostTransportStop);
+	REGISTER_CLASS_ENUM (Session, PostTransportDisableRecord);
+	REGISTER_CLASS_ENUM (Session, PostTransportPosition);
+	REGISTER_CLASS_ENUM (Session, PostTransportDidRecord);
+	REGISTER_CLASS_ENUM (Session, PostTransportDuration);
+	REGISTER_CLASS_ENUM (Session, PostTransportLocate);
+	REGISTER_CLASS_ENUM (Session, PostTransportRoll);
+	REGISTER_CLASS_ENUM (Session, PostTransportAbort);
+	REGISTER_CLASS_ENUM (Session, PostTransportOverWrite);
+	REGISTER_CLASS_ENUM (Session, PostTransportSpeed);
+	REGISTER_CLASS_ENUM (Session, PostTransportAudition);
+	REGISTER_CLASS_ENUM (Session, PostTransportScrub);
+	REGISTER_CLASS_ENUM (Session, PostTransportReverse);
+	REGISTER_CLASS_ENUM (Session, PostTransportInputChange);
+	REGISTER_CLASS_ENUM (Session, PostTransportCurveRealloc);
+	REGISTER_CLASS_ENUM (Session, PostTransportClearSubstate);
+	REGISTER_BITS (_Session_PostTransportWork);
+
 	REGISTER_CLASS_ENUM (Session, Clean);
 	REGISTER_CLASS_ENUM (Session, Dirty);
 	REGISTER_CLASS_ENUM (Session, CannotSave);
diff --git a/libs/ardour/session_events.cc b/libs/ardour/session_events.cc
index 7304991948..b218bbdf85 100644
--- a/libs/ardour/session_events.cc
+++ b/libs/ardour/session_events.cc
@@ -29,6 +29,7 @@
 #include "ardour/ardour.h"
 #include "ardour/audio_diskstream.h"
 #include "ardour/butler.h"
+#include "ardour/debug.h"
 #include "ardour/session.h"
 
 #include "i18n.h"
@@ -296,7 +297,7 @@ Session::process_event (Event* ev)
 		}
 	}
 
-	//printf("Processing event: %s\n", event_names[ev->type]);
+	DEBUG_TRACE (DEBUG::SessionEvents, string_compose ("Processing event: %1 @ %2\n", enum_2_string (ev->type), _transport_frame));
 
 	switch (ev->type) {
 	case Event::SetLoop:
diff --git a/libs/ardour/session_process.cc b/libs/ardour/session_process.cc
index 6182927404..e277a2dbcc 100644
--- a/libs/ardour/session_process.cc
+++ b/libs/ardour/session_process.cc
@@ -31,8 +31,7 @@
 #include "ardour/audioengine.h"
 #include "ardour/auditioner.h"
 #include "ardour/butler.h"
-#include "ardour/cycle_timer.h"
-#include "ardour/cycles.h"
+#include "ardour/debug.h"
 #include "ardour/session.h"
 #include "ardour/slave.h"
 #include "ardour/timestamps.h"
@@ -494,6 +493,8 @@ Session::follow_slave (nframes_t nframes)
 
 	_slave->speed_and_position (slave_speed, slave_transport_frame);
 
+	DEBUG_TRACE (DEBUG::Slave, string_compose ("Slave @ %1 speed %2\n", slave_speed, slave_transport_frame));
+
 	if (!_slave->locked()) {
 		goto noroll;
 	}
@@ -561,14 +562,9 @@ Session::follow_slave (nframes_t nframes)
 				request_transport_speed(slave_speed);
 			} else {
 				request_transport_speed(adjusted_speed);
-				#ifdef DEBUG_SLAVES
-				cerr << "adjust using " << delta
-					 << " towards " << adjusted_speed
-					 << " ratio = " << adjusted_speed / slave_speed
-					 << " current = " << _transport_speed
-					 << " slave @ " << slave_speed
-					 << endl;
-				#endif
+				DEBUG_TRACE (DEBUG::Slave, string_compose ("adjust using %1 towards %2 ratio %3 current %4 slave @ %5\n",
+									   delta, adjusted_speed, adjusted_speed/slave_speed, _transport_speed,
+									   slave_speed));
 			}
 
 			if (abs(average_slave_delta) > (long) _slave->resolution()) {
@@ -578,15 +574,17 @@ Session::follow_slave (nframes_t nframes)
 		}
 	}
 
-	#ifdef DEBUG_SLAVES
-	if (slave_speed != 0.0)
-	cerr << "delta = " << (int) (dir * this_delta)
-		 << " speed = " << slave_speed
-		 << " ts = " << _transport_speed
-		 << " M@ "<< slave_transport_frame << " S@ " << _transport_frame
-		 << " avgdelta = " << average_slave_delta
-		 << endl;
-	#endif
+#ifndef NDEBUG
+	if (slave_speed != 0.0) {
+		DEBUG_TRACE (DEBUG::Slave, string_compose ("delta = %1 speed = %2 ts = %3 M@%4 S@%5 avgdelta %6\n",
+							   (int) (dir * this_delta),
+							   slave_speed,
+							   _transport_speed,
+							   slave_transport_frame, 
+							   _transport_frame,
+							   average_slave_delta));
+	}
+#endif
 
 	if (!starting && !non_realtime_work_pending()) {
 		/* speed is set, we're locked, and good to go */
@@ -594,17 +592,12 @@ Session::follow_slave (nframes_t nframes)
 	}
 
   silent_motion:
-	#ifdef DEBUG_SLAVES
-	cerr << "reached silent_motion:" <<endl;
-	#endif
-
+	DEBUG_TRACE (DEBUG::Slave, "silent motion\n")
 	follow_slave_silently (nframes, slave_speed);
 
   noroll:
 	/* don't move at all */
-	#ifdef DEBUG_SLAVES
-	cerr << "reached no_roll:" <<endl;
-	#endif
+	DEBUG_TRACE (DEBUG::Slave, "no roll\n")
 	no_roll (nframes);
 	return false;
 }
@@ -721,10 +714,7 @@ Session::track_slave_state(
 		}
 
 		if (slave_state == Running && _transport_speed == 0.0f) {
-
-        #ifdef DEBUG_SLAVES
-			cerr << "slave starts transport\n";
-        #endif
+			DEBUG_TRACE (DEBUG::Slave, "slave starts transport\n");
 			start_transport ();
 		}
 
@@ -733,19 +723,12 @@ Session::track_slave_state(
 		/* slave has stopped */
 
 		if (_transport_speed != 0.0f) {
-
-         #ifdef DEBUG_SLAVES
-			cerr << "slave stops transport: " << slave_speed << " frame: " << slave_transport_frame
-			     << " tf = " << _transport_frame << endl;
-         #endif
-
+			DEBUG_TRACE (DEBUG::Slave, string_compose ("slave stops transport: %1 frame %2 tf %3\n", slave_speed, slave_transport_frame, _transport_frame));
 			stop_transport();
 		}
 
 		if (slave_transport_frame != _transport_frame) {
-        #ifdef DEBUG_SLAVES
-			cerr << "slave stopped, move to " << slave_transport_frame << endl;
-        #endif
+			DEBUG_TRACE (DEBUG::Slave, string_compose ("slave stopped, move to %1\n", slave_transport_frame));
 			force_locate (slave_transport_frame, false);
 		}
 
diff --git a/libs/ardour/session_transport.cc b/libs/ardour/session_transport.cc
index 0eaf8125a4..f0fc5da6a1 100644
--- a/libs/ardour/session_transport.cc
+++ b/libs/ardour/session_transport.cc
@@ -26,10 +26,9 @@
 
 #include "pbd/undo.h"
 #include "pbd/error.h"
-#include <glibmm/thread.h>
+#include "pbd/enumwriter.h"
 #include "pbd/pthread_utils.h"
 #include "pbd/memento_command.h"
-#include "pbd/stacktrace.h"
 
 #include "midi++/mmc.h"
 #include "midi++/port.h"
@@ -39,6 +38,7 @@
 #include "ardour/audioengine.h"
 #include "ardour/auditioner.h"
 #include "ardour/butler.h"
+#include "ardour/debug.h"
 #include "ardour/location.h"
 #include "ardour/session.h"
 #include "ardour/slave.h"
@@ -105,6 +105,7 @@ void
 Session::request_transport_speed (double speed)
 {
 	Event* ev = new Event (Event::SetTransportSpeed, Event::Add, Event::Immediate, 0, speed);
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Request transport speed = %1\n", speed));
 	queue_event (ev);
 }
 
@@ -120,6 +121,7 @@ void
 Session::request_stop (bool abort, bool clear_state)
 {
 	Event* ev = new Event (Event::SetTransportSpeed, Event::Add, Event::Immediate, 0, 0.0, abort, clear_state);
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Request transport stop, abort = %1, clear state = %2\n", abort, clear_state));
 	queue_event (ev);
 }
 
@@ -127,6 +129,7 @@ void
 Session::request_locate (nframes_t target_frame, bool with_roll)
 {
 	Event *ev = new Event (with_roll ? Event::LocateRoll : Event::Locate, Event::Add, Event::Immediate, target_frame, 0, false);
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Request locate to %1\n", target_frame));
 	queue_event (ev);
 }
 
@@ -134,6 +137,7 @@ void
 Session::force_locate (nframes64_t target_frame, bool with_roll)
 {
 	Event *ev = new Event (with_roll ? Event::LocateRoll : Event::Locate, Event::Add, Event::Immediate, target_frame, 0, true);
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Request forced locate to %1\n", target_frame));
 	queue_event (ev);
 }
 
@@ -150,6 +154,7 @@ Session::request_play_loop (bool yn, bool leave_rolling)
 	}
 
 	ev = new Event (Event::SetLoop, Event::Add, Event::Immediate, 0, (leave_rolling ? 1.0 : 0.0), yn);
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Request set loop = %1, leave rolling ? %2\n", yn, leave_rolling));
 	queue_event (ev);
 
 	if (!leave_rolling && !yn && Config->get_seamless_loop() && transport_rolling()) {
@@ -168,12 +173,14 @@ Session::request_play_range (list<AudioRange>* range, bool leave_rolling)
 	} else {
 		ev->audio_range.clear ();
 	}
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Request play range, leave rolling ? %1\n", leave_rolling));
 	queue_event (ev);
 }
 
 void
 Session::realtime_stop (bool abort, bool clear_state)
 {
+	DEBUG_TRACE (DEBUG::Transport, "realtime stop\n");
 	PostTransportWork todo = PostTransportWork (0);
 
 	/* assume that when we start, we'll be moving forwards */
@@ -245,6 +252,9 @@ Session::butler_transport_work ()
 	int on_entry = g_atomic_int_get (&_butler->should_do_transport_work);
 	finished = true;
 	ptw = post_transport_work();
+
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Butler transport work, todo = %1\n", enum_2_string (ptw)));
+		     
 	if (ptw & PostTransportCurveRealloc) {
 		for (RouteList::iterator i = r->begin(); i != r->end(); ++i) {
 			(*i)->curve_reallocate();
@@ -873,6 +883,8 @@ Session::locate (nframes64_t target_frame, bool with_roll, bool with_flush, bool
 void
 Session::set_transport_speed (double speed, bool abort, bool clear_state)
 {
+	DEBUG_TRACE (DEBUG::Transport, string_compose ("Set transport speed to %1, abort = %2 clear_state = %3, current = %4\n", speed, abort, clear_state, _transport_speed));
+
 	if (_transport_speed == speed) {
 		return;
 	}