smokephil/ardour
1
0
Fork 0
mirror of https://github.com/Ardour/ardour.git synced 2026-01-30 08:53:08 +01:00
Code Issues Projects Releases Wiki Activity

NO-OP: improve butler and disk-i/o debug messages

Browse source
This commit is contained in:
Robin Gareus 2024-09-26 03:14:18 +02:00
parent 75e6a77c3e
commit e1f465a952
No known key found for this signature in database
GPG key ID: A090BCE02CF57F04
3 changed files with 25 additions and 22 deletions
Download patch file Download diff file Expand all files Collapse all files

4
libs/ardour/butler.cc
View file

@ -273,7 +273,7 @@ Butler::thread_work ()
RouteList rl_with_auditioner = *rl;
rl_with_auditioner.push_back (_session.the_auditioner ());
DEBUG_TRACE (DEBUG::Butler, string_compose ("butler starts refill loop, twr = %1\n", transport_work_requested ()));
DEBUG_TRACE (DEBUG::Butler, string_compose ("butler starts refill loop, twr = %1\n", should_do_transport_work.load ()));
std::shared_ptr<IOTaskList> tl = _session.io_tasklist ();
@ -413,8 +413,8 @@ Butler::flush_tracks_to_disk_normal (std::shared_ptr<RouteList const> rl, uint32
void
Butler::schedule_transport_work ()
{
DEBUG_TRACE (DEBUG::Butler, "requesting more transport work\n");
should_do_transport_work.fetch_add (1);
DEBUG_TRACE (DEBUG::Butler, string_compose ("requesting more transport work (now %1)\n", should_do_transport_work.load ()));
summon ();
}

34
libs/ardour/disk_reader.cc
View file

@ -115,7 +115,7 @@ DiskReader::add_channel_to (std::shared_ptr<ChannelList> c, uint32_t how_many)
{
while (how_many--) {
c->push_back (new ReaderChannelInfo (_session.butler ()->audio_playback_buffer_size (), loop_fade_length));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1: new reader channel, write space = %2 read = %3\n",
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': new reader channel, write space = %2 read = %3\n",
name (),
c->back ()->rbuf->write_space (),
c->back ()->rbuf->read_space ()));
@ -422,7 +422,7 @@ DiskReader::run (BufferSet& bufs, samplepos_t start_sample, samplepos_t end_samp
#ifndef NDEBUG // not rt-safe to print here
cerr << "underrun for " << _name << " Available samples: " << available << " required: " << disk_samples_to_consume << endl;
#endif
DEBUG_TRACE (DEBUG::Butler, string_compose ("%1 underrun in %2, total space = %3 vs %4\n", DEBUG_THREAD_SELF, name (), available, disk_samples_to_consume));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': underrun in thread %2, available = %3 need = %4\n", owner ()->name (), DEBUG_THREAD_SELF, available, disk_samples_to_consume));
DEBUG_TRACE (DEBUG::AudioCacheRefill, string_compose ("DR '%1' underrun have %2 need %3 samples at pos %4\n",
name (), available, disk_samples_to_consume,
std::setprecision (3), std::fixed,
@ -503,13 +503,14 @@ midi:
if (!c->empty ()) {
if (_slaved) {
if (c->front ()->rbuf->write_space () >= c->front ()->rbuf->bufsize () / 2) {
DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: slaved, write space = %2 of %3\n", name (), c->front ()->rbuf->write_space (), c->front ()->rbuf->bufsize ()));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': slaved, write space = %2 of %3\n",
_owner->name (), c->front ()->rbuf->write_space (), c->front ()->rbuf->bufsize ()));
butler_required = true;
}
} else {
if ((samplecnt_t)c->front ()->rbuf->write_space () >= _chunk_samples) {
DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: write space = %2 chunk size = %3\n", name (), c->front ()->rbuf->write_space (),
_chunk_samples));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1: write space = %2 chunk size = %3\n",
_owner->name (), c->front ()->rbuf->write_space (), _chunk_samples));
butler_required = true;
}
}
@ -524,7 +525,7 @@ midi:
}
if (_need_butler) {
DEBUG_TRACE (DEBUG::Butler, string_compose ("%1 reader run, needs butler = %2\n", name (), _need_butler));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1' reader run, needs butler = %2\n", _owner->name (), _need_butler));
}
}
@ -560,7 +561,7 @@ DiskReader::pending_overwrite () const
void
DiskReader::set_pending_overwrite (OverwriteReason why)
{
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1 set_pending_overwrite because %2%3%4\n", owner ()->name (), std::hex, why, std::dec));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': set_pending_overwrite because %2%3%4)\n", owner ()->name (), std::hex, why, std::dec));
std::shared_ptr<ChannelList const> c = channels.reader ();
/* called from audio thread, so we can use the read ptr and playback sample as we wish */
@ -699,6 +700,8 @@ DiskReader::overwrite_existing_audio ()
const size_t to_overwrite = c->front ()->rbuf->overwritable_at (overwrite_offset);
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': overwrite_existing_audio at %2 offset = %2 to_ovrwrt = %3\n", owner ()->name (), overwrite_sample, overwrite_offset, to_overwrite));
chunk1_offset = overwrite_offset;
chunk1_cnt = min (c->front ()->rbuf->bufsize () - (size_t)overwrite_offset, to_overwrite);
@ -763,7 +766,7 @@ DiskReader::overwrite_existing_audio ()
}
if (!rci->initialized) {
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("Init ReaderChannel '%1' overwriting at: %2, avail: %3\n", name (), overwrite_sample, chan->rbuf->read_space ()));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'1': Init ReaderChannel overwriting at: %2, avail: %3\n", name (), overwrite_sample, chan->rbuf->read_space ()));
if (chan->rbuf->read_space () > 0) {
rci->initialized = true;
}
@ -807,7 +810,7 @@ DiskReader::overwrite_existing_buffers ()
{
/* called from butler thread */
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1 overwriting existing buffers at %2 (because %3%4%5\n", owner ()->name (), overwrite_sample, std::hex, _pending_overwrite.load (), std::dec));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': overwriting existing buffers at %2 (because %3%4%5)\n", owner ()->name (), overwrite_sample, std::hex, _pending_overwrite.load (), std::dec));
bool ret = true;
@ -823,6 +826,7 @@ DiskReader::overwrite_existing_buffers ()
}
}
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': Clear _pending_overwrite\n", owner ()->name ()));
_pending_overwrite.store (OverwriteReason (0));
return ret;
@ -863,7 +867,7 @@ DiskReader::seek (samplepos_t sample, bool complete_refill)
}
}
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("DiskReader::seek %1 %2 -> %3 refill=%4 pending_overwrite = %5\n",
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': seek %2 -> %3 refill = %4 pending_overwrite = %5\n",
owner ()->name (), playback_sample, sample, complete_refill, _pending_overwrite.load ()));
_pending_overwrite.store (OverwriteReason (0));
@ -1194,7 +1198,7 @@ DiskReader::refill_audio (Sample* sum_buffer, Sample* mixdown_buffer, float* gai
samplecnt_t total_space = c->front ()->rbuf->write_space ();
if (total_space == 0) {
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1: no space to refill\n", name ()));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': no space to refill\n", name ()));
/* nowhere to write to */
return 0;
}
@ -1219,7 +1223,7 @@ DiskReader::refill_audio (Sample* sum_buffer, Sample* mixdown_buffer, float* gai
* the playback buffer is empty.
*/
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1: space to refill %2 vs. chunk %3 (speed = %4)\n", name (), total_space, _chunk_samples, _session.transport_speed ()));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': space to refill %2 vs. chunk %3 (speed = %4)\n", name (), total_space, _chunk_samples, _session.transport_speed ()));
if ((total_space < _chunk_samples) && fabs (_session.transport_speed ()) < 2.0f) {
return 0;
}
@ -1230,7 +1234,7 @@ DiskReader::refill_audio (Sample* sum_buffer, Sample* mixdown_buffer, float* gai
*/
if (_slaved && total_space < (samplecnt_t) (c->front ()->rbuf->bufsize () / 2)) {
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1: not enough to refill while slaved\n", this));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': not enough to refill while slaved\n", this));
return 0;
}
@ -1288,7 +1292,7 @@ DiskReader::refill_audio (Sample* sum_buffer, Sample* mixdown_buffer, float* gai
/* now back to samples */
samplecnt_t samples_to_read = byte_size_for_read / (bits_per_sample / 8);
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("%1: will refill %2 channels with %3 samples\n", name (), c->size (), total_space));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1': will refill %2 channels with %3 samples\n", name (), c->size (), total_space));
samplepos_t file_sample_tmp = fsa;
@ -1334,7 +1338,7 @@ DiskReader::refill_audio (Sample* sum_buffer, Sample* mixdown_buffer, float* gai
}
}
if (!rci->initialized) {
DEBUG_TRACE (DEBUG::DiskIO, string_compose (" -- Init ReaderChannel '%1' read: %2 samples, at: %4, avail: %5\n", name (), to_read, file_sample_tmp, rci->rbuf->read_space ()));
DEBUG_TRACE (DEBUG::DiskIO, string_compose ("'%1' Init ReaderChannel read: %2 samples, at: %4, avail: %5\n", name (), to_read, file_sample_tmp, rci->rbuf->read_space ()));
rci->initialized = true;
}
}

9
libs/ardour/session_transport.cc
View file

@ -674,7 +674,7 @@ Session::butler_completed_transport_work ()
ENSURE_PROCESS_THREAD;
PostTransportWork ptw = post_transport_work ();
DEBUG_TRACE (DEBUG::Transport, string_compose ("Butler done, RT cleanup for %1\n", enum_2_string (ptw)));
DEBUG_TRACE (DEBUG::Butler, string_compose ("Butler done, RT cleanup for %1\n", enum_2_string (ptw)));
if (ptw & PostTransportAudition) {
if (auditioner && auditioner->auditioning()) {
@ -1149,7 +1149,7 @@ Session::butler_transport_work (bool have_process_lock)
uint64_t before = g_get_monotonic_time();
#endif
DEBUG_TRACE (DEBUG::Transport, string_compose ("Butler transport work, todo = [%1] (0x%3%4%5) at %2\n", enum_2_string (ptw), before, std::hex, ptw, std::dec));
DEBUG_TRACE (DEBUG::Butler, string_compose ("Butler transport work, todo = [%1] (0x%3%4%5) twr = %6 @ %2\n", enum_2_string (ptw), before, std::hex, ptw, std::dec, on_entry));
if (ptw & PostTransportAdjustPlaybackBuffering) {
/* need to prevent concurrency with ARDOUR::Reader::run(),
@ -1203,9 +1203,8 @@ Session::butler_transport_work (bool have_process_lock)
}
}
if (will_locate) {
DEBUG_TRACE (DEBUG::Transport, string_compose ("nonrealtime locate invoked from BTW (butler has done %1, rtlocs %2)\n", butler, rtlocates));
DEBUG_TRACE (DEBUG::Butler, string_compose ("nonrealtime locate invoked from BTW (butler has done %1, rtlocs %2)\n", butler, rtlocates));
non_realtime_locate ();
}
@ -1226,7 +1225,7 @@ Session::butler_transport_work (bool have_process_lock)
(void) PBD::atomic_dec_and_test (_butler->should_do_transport_work);
DEBUG_TRACE (DEBUG::Transport, string_compose (X_("Butler transport work all done after %1 usecs @ %2 ptw %3 trw = %4\n"), g_get_monotonic_time() - before, _transport_sample, enum_2_string (post_transport_work()), _butler->transport_work_requested()));
DEBUG_TRACE (DEBUG::Butler, string_compose (X_("Butler transport work all done after %1 usecs tsp = %2 ptw [%3] trw = %4\n"), g_get_monotonic_time() - before, _transport_sample, enum_2_string (post_transport_work()), _butler->should_do_transport_work.load ()));
}
void