Remove common prefix for latency debugging

-DLatency now triggers all four:
  * LatencyCompensation (entry-points, overall flow)
  * LatencyIO (Port/IO query, set/get private/public)
  * LatencyDelayLine (Delaylines for internal sends and alignment)
  * LatencyRoute (route processor latency)

8 files changed, 48 insertions, 40 deletions

diff --git a/libs/ardour/ardour/debug.h b/libs/ardour/ardour/debug.h
index 2070ccea95..10bd90d8a8 100644
--- a/libs/ardour/ardour/debug.h
+++ b/libs/ardour/ardour/debug.h
@@ -58,8 +58,10 @@ namespace PBD {
 		LIBARDOUR_API extern DebugBits LTC;
 		LIBARDOUR_API extern DebugBits LV2;
 		LIBARDOUR_API extern DebugBits LV2Automate;
-		LIBARDOUR_API extern DebugBits Latency;
 		LIBARDOUR_API extern DebugBits LatencyCompensation;
+		LIBARDOUR_API extern DebugBits LatencyDelayLine;
+		LIBARDOUR_API extern DebugBits LatencyIO;
+		LIBARDOUR_API extern DebugBits LatencyRoute;
 		LIBARDOUR_API extern DebugBits LaunchControlXL;
 		LIBARDOUR_API extern DebugBits Layering;
 		LIBARDOUR_API extern DebugBits MTC;
diff --git a/libs/ardour/debug.cc b/libs/ardour/debug.cc
index 3adb2bab78..0de81ebf1c 100644
--- a/libs/ardour/debug.cc
+++ b/libs/ardour/debug.cc
@@ -53,8 +53,10 @@ PBD::DebugBits PBD::DEBUG::Graph = PBD::new_debug_bit ("graph");
 PBD::DebugBits PBD::DEBUG::LTC = PBD::new_debug_bit ("ltc");
 PBD::DebugBits PBD::DEBUG::LV2 = PBD::new_debug_bit ("lv2");
 PBD::DebugBits PBD::DEBUG::LV2Automate = PBD::new_debug_bit ("lv2automate");
-PBD::DebugBits PBD::DEBUG::Latency = PBD::new_debug_bit ("latency");
 PBD::DebugBits PBD::DEBUG::LatencyCompensation = PBD::new_debug_bit ("latencycompensation");
+PBD::DebugBits PBD::DEBUG::LatencyDelayLine = PBD::new_debug_bit ("latencydelayline");
+PBD::DebugBits PBD::DEBUG::LatencyIO = PBD::new_debug_bit ("latencyio");
+PBD::DebugBits PBD::DEBUG::LatencyRoute = PBD::new_debug_bit ("latencyroute");
 PBD::DebugBits PBD::DEBUG::LaunchControlXL = PBD::new_debug_bit("launchcontrolxl");
 PBD::DebugBits PBD::DEBUG::Layering = PBD::new_debug_bit ("layering");
 PBD::DebugBits PBD::DEBUG::MTC = PBD::new_debug_bit ("mtc");
diff --git a/libs/ardour/delayline.cc b/libs/ardour/delayline.cc
index 9d1f012870..91f6d56e32 100644
--- a/libs/ardour/delayline.cc
+++ b/libs/ardour/delayline.cc
@@ -298,13 +298,13 @@ DelayLine::set_delay (samplecnt_t signal_delay)
 	}
 
 	if (signal_delay == _pending_delay) {
-		DEBUG_TRACE (DEBUG::LatencyCompensation,
+		DEBUG_TRACE (DEBUG::LatencyDelayLine,
 				string_compose ("%1 set_delay - no change: %2 samples for %3 channels\n",
 					name (), signal_delay, _configured_output.n_audio ()));
 		return false;
 	}
 
-	DEBUG_TRACE (DEBUG::LatencyCompensation,
+	DEBUG_TRACE (DEBUG::LatencyDelayLine,
 			string_compose ("%1 set_delay to %2 samples for %3 channels\n",
 				name (), signal_delay, _configured_output.n_audio ()));
 
@@ -409,7 +409,7 @@ DelayLine::configure_io (ChanCount in, ChanCount out)
 		allocate_pending_buffers (_pending_delay, out);
 	}
 
-	DEBUG_TRACE (DEBUG::LatencyCompensation,
+	DEBUG_TRACE (DEBUG::LatencyDelayLine,
 			string_compose ("configure IO: %1 Ain: %2 Aout: %3 Min: %4 Mout: %5\n",
 				name (), in.n_audio (), out.n_audio (), in.n_midi (), out.n_midi ()));
 
diff --git a/libs/ardour/io.cc b/libs/ardour/io.cc
index b8e51ffd89..ae8a0a4854 100644
--- a/libs/ardour/io.cc
+++ b/libs/ardour/io.cc
@@ -1269,17 +1269,17 @@ IO::latency () const
 	for (PortSet::const_iterator i = _ports.begin(); i != _ports.end(); ++i) {
 		samplecnt_t latency;
 		if ((latency = i->private_latency_range (_direction == Output).max) > max_latency) {
-			DEBUG_TRACE (DEBUG::Latency, string_compose ("port %1 has %2 latency of %3 - use\n",
-			                                             name(),
-			                                             ((_direction == Output) ? "PLAYBACK" : "CAPTURE"),
-			                                             latency));
+			DEBUG_TRACE (DEBUG::LatencyIO, string_compose ("port %1 has %2 latency of %3 - use\n",
+			                                               name(),
+			                                               ((_direction == Output) ? "PLAYBACK" : "CAPTURE"),
+			                                               latency));
 			max_latency = latency;
 		}
 	}
 
-	DEBUG_TRACE (DEBUG::Latency, string_compose ("%1: max %4 latency from %2 ports = %3\n",
-	                                             name(), _ports.num_ports(), max_latency,
-	                                             ((_direction == Output) ? "PLAYBACK" : "CAPTURE")));
+	DEBUG_TRACE (DEBUG::LatencyIO, string_compose ("%1: max %4 latency from %2 ports = %3\n",
+	                                               name(), _ports.num_ports(), max_latency,
+	                                               ((_direction == Output) ? "PLAYBACK" : "CAPTURE")));
 	return max_latency;
 }
 
@@ -1293,17 +1293,17 @@ IO::public_latency () const
 	for (PortSet::const_iterator i = _ports.begin(); i != _ports.end(); ++i) {
 		samplecnt_t latency;
 		if ((latency = i->public_latency_range (_direction == Output).max) > max_latency) {
-			DEBUG_TRACE (DEBUG::Latency, string_compose ("port %1 has %2 latency of %3 - use\n",
-			                                             name(),
-			                                             ((_direction == Output) ? "PLAYBACK" : "CAPTURE"),
-			                                             latency));
+			DEBUG_TRACE (DEBUG::LatencyIO, string_compose ("port %1 has %2 latency of %3 - use\n",
+			                                               name(),
+			                                               ((_direction == Output) ? "PLAYBACK" : "CAPTURE"),
+			                                               latency));
 			max_latency = latency;
 		}
 	}
 
-	DEBUG_TRACE (DEBUG::Latency, string_compose ("%1: max %4 public latency from %2 ports = %3\n",
-	                                             name(), _ports.num_ports(), max_latency,
-	                                             ((_direction == Output) ? "PLAYBACK" : "CAPTURE")));
+	DEBUG_TRACE (DEBUG::LatencyIO, string_compose ("%1: max %4 public latency from %2 ports = %3\n",
+	                                               name(), _ports.num_ports(), max_latency,
+	                                               ((_direction == Output) ? "PLAYBACK" : "CAPTURE")));
 	return max_latency;
 }
 
diff --git a/libs/ardour/port.cc b/libs/ardour/port.cc
index c4fb6b7862..0822fd075f 100644
--- a/libs/ardour/port.cc
+++ b/libs/ardour/port.cc
@@ -363,7 +363,7 @@ Port::set_public_latency_range (LatencyRange const& range, bool playback) const
 	   port latency values are identical.
 	*/
 
-	DEBUG_TRACE (DEBUG::Latency,
+	DEBUG_TRACE (DEBUG::LatencyIO,
 	             string_compose ("SET PORT %1 %4 PUBLIC latency now [%2 - %3]\n",
 	                             name(), range.min, range.max,
 	                             (playback ? "PLAYBACK" : "CAPTURE")));;
@@ -389,14 +389,14 @@ Port::set_private_latency_range (LatencyRange& range, bool playback)
 {
 	if (playback) {
 		_private_playback_latency = range;
-		DEBUG_TRACE (DEBUG::Latency, string_compose (
+		DEBUG_TRACE (DEBUG::LatencyIO, string_compose (
 			             "SET PORT %1 playback PRIVATE latency now [%2 - %3]\n",
 			             name(),
 			             _private_playback_latency.min,
 			             _private_playback_latency.max));
 	} else {
 		_private_capture_latency = range;
-		DEBUG_TRACE (DEBUG::Latency, string_compose (
+		DEBUG_TRACE (DEBUG::LatencyIO, string_compose (
 			             "SET PORT %1 capture PRIVATE latency now [%2 - %3]\n",
 			             name(),
 			             _private_capture_latency.min,
@@ -412,14 +412,14 @@ const LatencyRange&
 Port::private_latency_range (bool playback) const
 {
 	if (playback) {
-		DEBUG_TRACE (DEBUG::Latency, string_compose (
+		DEBUG_TRACE (DEBUG::LatencyIO, string_compose (
 			             "GET PORT %1 playback PRIVATE latency now [%2 - %3]\n",
 			             name(),
 			             _private_playback_latency.min,
 			             _private_playback_latency.max));
 		return _private_playback_latency;
 	} else {
-		DEBUG_TRACE (DEBUG::Latency, string_compose (
+		DEBUG_TRACE (DEBUG::LatencyIO, string_compose (
 			             "GET PORT %1 capture PRIVATE latency now [%2 - %3]\n",
 			             name(),
 			             _private_playback_latency.min,
@@ -447,7 +447,7 @@ Port::public_latency_range (bool /*playback*/) const
 			}
 		}
 
-		DEBUG_TRACE (DEBUG::Latency, string_compose (
+		DEBUG_TRACE (DEBUG::LatencyIO, string_compose (
 				     "GET PORT %1: %4 PUBLIC latency range %2 .. %3\n",
 				     name(), r.min, r.max,
 				     sends_output() ? "PLAYBACK" : "CAPTURE"));
@@ -468,7 +468,7 @@ Port::get_connected_latency_range (LatencyRange& range, bool playback) const
 		range.min = ~((pframes_t) 0);
 		range.max = 0;
 
-		DEBUG_TRACE (DEBUG::Latency, string_compose ("%1: %2 connections to check for latency range\n", name(), connections.size()));
+		DEBUG_TRACE (DEBUG::LatencyIO, string_compose ("%1: %2 connections to check for latency range\n", name(), connections.size()));
 
 		for (vector<string>::const_iterator c = connections.begin();
 				c != connections.end(); ++c) {
@@ -496,7 +496,7 @@ Port::get_connected_latency_range (LatencyRange& range, bool playback) const
 						}
 					}
 
-					DEBUG_TRACE (DEBUG::Latency, string_compose (
+					DEBUG_TRACE (DEBUG::LatencyIO, string_compose (
 								"\t%1 <-> %2 : latter has latency range %3 .. %4\n",
 								name(), *c, lr.min, lr.max));
 
@@ -516,7 +516,7 @@ Port::get_connected_latency_range (LatencyRange& range, bool playback) const
 				boost::shared_ptr<Port> remote_port = AudioEngine::instance()->get_port_by_name (*c);
 				if (remote_port) {
 					lr = remote_port->private_latency_range ((playback ? true : false));
-					DEBUG_TRACE (DEBUG::Latency, string_compose (
+					DEBUG_TRACE (DEBUG::LatencyIO, string_compose (
 								"\t%1 <-LOCAL-> %2 : latter has latency range %3 .. %4\n",
 								name(), *c, lr.min, lr.max));
 
@@ -527,12 +527,12 @@ Port::get_connected_latency_range (LatencyRange& range, bool playback) const
 		}
 
 	} else {
-		DEBUG_TRACE (DEBUG::Latency, string_compose ("%1: not connected to anything\n", name()));
+		DEBUG_TRACE (DEBUG::LatencyIO, string_compose ("%1: not connected to anything\n", name()));
 		range.min = 0;
 		range.max = 0;
 	}
 
-	DEBUG_TRACE (DEBUG::Latency, string_compose ("%1: final connected latency range [ %2 .. %3 ] \n", name(), range.min, range.max));
+	DEBUG_TRACE (DEBUG::LatencyIO, string_compose ("%1: final connected latency range [ %2 .. %3 ] \n", name(), range.min, range.max));
 }
 
 int
diff --git a/libs/ardour/route.cc b/libs/ardour/route.cc
index d6cfec92e9..6d1dfab77d 100644
--- a/libs/ardour/route.cc
+++ b/libs/ardour/route.cc
@@ -4263,7 +4263,7 @@ Route::update_signal_latency (bool apply_to_delayline)
 		}
 	}
 
-	DEBUG_TRACE (DEBUG::Latency, string_compose ("%1: internal signal latency = %2\n", _name, l_out));
+	DEBUG_TRACE (DEBUG::LatencyRoute, string_compose ("%1: internal signal latency = %2\n", _name, l_out));
 
 	_signal_latency = l_out;
 
diff --git a/libs/ardour/send.cc b/libs/ardour/send.cc
index 524dc376ec..e0c92445f3 100644
--- a/libs/ardour/send.cc
+++ b/libs/ardour/send.cc
@@ -191,7 +191,7 @@ Send::set_delay_in (samplecnt_t delay)
 	}
 	_delay_in = delay;
 
-	DEBUG_TRACE (DEBUG::LatencyCompensation,
+	DEBUG_TRACE (DEBUG::LatencyDelayLine,
 			string_compose ("Send::set_delay_in %1: (%2) - %3 = %4\n",
 				name (), _delay_in, _delay_out, _delay_in - _delay_out));
 
@@ -205,7 +205,7 @@ Send::set_delay_out (samplecnt_t delay, size_t /*bus*/)
 		return;
 	}
 	_delay_out = delay;
-	DEBUG_TRACE (DEBUG::LatencyCompensation,
+	DEBUG_TRACE (DEBUG::LatencyDelayLine,
 			string_compose ("Send::set_delay_out %1: %2 - (%3) = %4\n",
 				name (), _delay_in, _delay_out, _delay_in - _delay_out));
 
diff --git a/libs/ardour/session.cc b/libs/ardour/session.cc
index 79638b718d..3c0945e033 100644
--- a/libs/ardour/session.cc
+++ b/libs/ardour/session.cc
@@ -6459,7 +6459,8 @@ Session::initialize_latencies ()
 void
 Session::set_worst_io_latencies_x (IOChange, void *)
 {
-		set_worst_io_latencies ();
+	DEBUG_TRACE (DEBUG::LatencyCompensation, "Session::set_worst_io_latencies_x\n");
+	set_worst_io_latencies ();
 }
 
 void
@@ -6487,6 +6488,8 @@ Session::update_route_latency (bool playback, bool apply_to_delayline)
 	 * caller must hold process lock when apply_to_delayline == true */
 	assert (!apply_to_delayline || !AudioEngine::instance()->process_lock().trylock());
 
+	DEBUG_TRACE (DEBUG::LatencyCompensation , string_compose ("update_route_latency: %1 apply_to_delayline? %2)\n", (playback ? "PLAYBACK" : "CAPTURE"), (apply_to_delayline ? "yes" : "no")));
+
 	/* Note: RouteList is process-graph sorted */
 	boost::shared_ptr<RouteList> r = routes.reader ();
 
@@ -6515,15 +6518,16 @@ restart:
 	}
 
 	if (_send_latency_changes > 0) {
-		// only 1 extra iteration is needed (we allow only 1 level of aux-sends)
-		// BUT..  jack'n'sends'n'bugs
+		/* One extra iteration might be needed since we allow u level of aux-sends.
+		 * Except mixbus that allows up to 3 (aux-sends, sends to mixbusses 1-8, sends to mixbusses 9-12,
+		 * and then there's JACK */
 		if (++bailout < 5) {
 			cerr << "restarting Session::update_latency. # of send changes: " << _send_latency_changes << " iteration: " << bailout << endl;
 			goto restart;
 		}
 	}
 
-	DEBUG_TRACE (DEBUG::Latency, string_compose ("worst signal processing latency: %1 (changed ? %2)\n", _worst_route_latency, (changed ? "yes" : "no")));
+	DEBUG_TRACE (DEBUG::LatencyCompensation , string_compose ("update_route_latency: worst proc latency: %1 (changed? %2) recursions: %3\n", _worst_route_latency, (changed ? "yes" : "no"), bailout));
 
 	return changed;
 }
@@ -6662,7 +6666,7 @@ Session::update_latency_compensation (bool force_whole_graph, bool called_from_b
 		return;
 	}
 
-	DEBUG_TRACE (DEBUG::LatencyCompensation, string_compose ("update_latency_compensation %1\n", (force_whole_graph ? "of whole graph" : "")));
+	DEBUG_TRACE (DEBUG::LatencyCompensation, string_compose ("update_latency_compensation%1.\n", (force_whole_graph ? " of whole graph" : "")));
 
 	bool some_track_latency_changed = update_route_latency (false, false);
 
@@ -6698,18 +6702,18 @@ Session::update_latency_compensation (bool force_whole_graph, bool called_from_b
 			DEBUG_TRACE (DEBUG::LatencyCompensation, "update_latency_compensation called from engine, don't call back into engine\n");
 		}
 	} else {
+		DEBUG_TRACE (DEBUG::LatencyCompensation, "update_latency_compensation: directly apply to routes\n");
 #ifndef MIXBUS
 		Glib::Threads::Mutex::Lock lm (AudioEngine::instance()->process_lock (), Glib::Threads::NOT_LOCK);
 #endif
 		lm.acquire ();
 
-		DEBUG_TRACE (DEBUG::LatencyCompensation, "update_latency_compensation: directly apply to routes\n");
 		boost::shared_ptr<RouteList> r = routes.reader ();
 		for (RouteList::iterator i = r->begin(); i != r->end(); ++i) {
 			(*i)->apply_latency_compensation ();
 		}
 	}
-	DEBUG_TRACE (DEBUG::LatencyCompensation, "update_latency_compensation: DONE\n");
+	DEBUG_TRACE (DEBUG::LatencyCompensation, "update_latency_compensation: complete\n");
 }
 
 char