From 1e0c1751a53999a8b9ac6978393486afbf317529 Mon Sep 17 00:00:00 2001 From: Paul Davis Date: Tue, 9 Dec 2014 16:36:37 -0500 Subject: [PATCH] more DEBUG::Butler output, formatting corrections, and a warning on cerr if capture/playback buffers are too full/empty --- gtk2_ardour/ardour_ui.cc | 4 ++-- libs/ardour/audio_diskstream.cc | 8 ++++++- libs/ardour/butler.cc | 38 ++++++++++++++++++--------------- libs/ardour/session_process.cc | 6 ++++++ 4 files changed, 36 insertions(+), 20 deletions(-) diff --git a/gtk2_ardour/ardour_ui.cc b/gtk2_ardour/ardour_ui.cc index a94e77acc4..f4c5bdd81c 100644 --- a/gtk2_ardour/ardour_ui.cc +++ b/gtk2_ardour/ardour_ui.cc @@ -3897,8 +3897,8 @@ ARDOUR_UI::create_xrun_marker (framepos_t where) void ARDOUR_UI::halt_on_xrun_message () { - MessageDialog msg (*editor, - _("Recording was stopped because your system could not keep up.")); + cerr << "HALT on xrun\n"; + MessageDialog msg (*editor, _("Recording was stopped because your system could not keep up.")); msg.run (); } diff --git a/libs/ardour/audio_diskstream.cc b/libs/ardour/audio_diskstream.cc index fefc1c235c..538faebc4f 100644 --- a/libs/ardour/audio_diskstream.cc +++ b/libs/ardour/audio_diskstream.cc @@ -513,6 +513,8 @@ AudioDiskstream::process (BufferSet& bufs, framepos_t transport_frame, pframes_t framecnt_t total = chaninfo->capture_vector.len[0] + chaninfo->capture_vector.len[1]; if (rec_nframes > total) { + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1 overrun in %2, rec_nframes = %3 total space = %4\n", + pthread_self(), name(), rec_nframes, total)); DiskOverrun (); return -1; } @@ -619,6 +621,8 @@ AudioDiskstream::process (BufferSet& bufs, framepos_t transport_frame, pframes_t if (necessary_samples > total) { cerr << _name << " Need " << necessary_samples << " total = " << total << endl; cerr << "underrun for " << _name << endl; + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1 underrun in %2, rec_nframes = %3 total space = %4\n", + pthread_self(), name(), rec_nframes, total)); DiskUnderrun (); return -1; @@ -1394,7 +1398,7 @@ AudioDiskstream::do_flush (RunContext /*context*/, bool force_flush) error << string_compose(_("AudioDiskstream %1: cannot write to disk"), id()) << endmsg; return -1; } - + (*chan)->capture_buf->increment_read_ptr (to_write); (*chan)->curr_capture_cnt += to_write; @@ -1407,6 +1411,8 @@ AudioDiskstream::do_flush (RunContext /*context*/, bool force_flush) to_write = min ((framecnt_t)(disk_io_chunk_frames - to_write), (framecnt_t) vector.len[1]); + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1 additional write of %2\n", name(), to_write)); + if ((*chan)->write_source->write (vector.buf[1], to_write) != to_write) { error << string_compose(_("AudioDiskstream %1: cannot write to disk"), id()) << endmsg; return -1; diff --git a/libs/ardour/butler.cc b/libs/ardour/butler.cc index 5d4c47d557..424312a8a4 100644 --- a/libs/ardour/butler.cc +++ b/libs/ardour/butler.cc @@ -137,6 +137,7 @@ Butler::terminate_thread () { if (have_thread) { void* status; + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: ask butler to quit @ %2\n", pthread_self(), g_get_monotonic_time())); queue_request (Request::Quit); pthread_join (thread, &status); } @@ -172,7 +173,7 @@ Butler::wait_for_requests () break; } - DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: butler awake at @ %2", pthread_self(), g_get_monotonic_time())); + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: butler awake at @ %2\n", pthread_self(), g_get_monotonic_time())); if (pfd[0].revents & ~POLLIN) { error << string_compose (_("Error on butler thread request pipe: fd=%1 err=%2"), pfd[0].fd, pfd[0].revents) << endmsg; @@ -287,10 +288,6 @@ Butler::thread_work () RouteList rl_with_auditioner = *rl; rl_with_auditioner.push_back (_session.the_auditioner()); -// for (i = dsl->begin(); i != dsl->end(); ++i) { -// cerr << "BEFORE " << (*i)->name() << ": pb = " << (*i)->playback_buffer_load() << " cp = " << (*i)->capture_buffer_load() << endl; -// } - for (i = rl_with_auditioner.begin(); !transport_work_requested() && should_run && i != rl_with_auditioner.end(); ++i) { boost::shared_ptr tr = boost::dynamic_pointer_cast (*i); @@ -306,7 +303,7 @@ Butler::thread_work () DEBUG_TRACE (DEBUG::Butler, string_compose ("butler skips inactive track %1\n", tr->name())); continue; } - DEBUG_TRACE (DEBUG::Butler, string_compose ("butler refills %1\n", tr->name())); + DEBUG_TRACE (DEBUG::Butler, string_compose ("butler refills %1, playback load = %2\n", tr->name(), tr->playback_buffer_load())); switch (tr->do_refill ()) { case 0: DEBUG_TRACE (DEBUG::Butler, string_compose ("\ttrack refill done %1\n", tr->name())); @@ -319,6 +316,7 @@ Butler::thread_work () default: error << string_compose(_("Butler read ahead failure on dstream %1"), (*i)->name()) << endmsg; + std::cerr << string_compose(_("Butler read ahead failure on dstream %1"), (*i)->name()) << std::endl; break; } @@ -346,20 +344,27 @@ Butler::thread_work () /* note that we still try to flush diskstreams attached to inactive routes */ - DEBUG_TRACE (DEBUG::Butler, string_compose ("butler flushes track %1\n", tr->name())); - switch (tr->do_flush (ButlerContext)) { + gint64 before, after; + int ret; + + DEBUG_TRACE (DEBUG::Butler, string_compose ("butler flushes track %1 capture load %2\n", tr->name(), tr->capture_buffer_load())); + before = g_get_monotonic_time (); + ret = tr->do_flush (ButlerContext); + after = g_get_monotonic_time (); + switch (ret) { case 0: - DEBUG_TRACE (DEBUG::Butler, string_compose ("\tflush complete for %1\n", tr->name())); + DEBUG_TRACE (DEBUG::Butler, string_compose ("\tflush complete for %1, %2 usecs\n", tr->name(), after - before)); break; case 1: - DEBUG_TRACE (DEBUG::Butler, string_compose ("\tflush not finished for %1\n", tr->name())); + DEBUG_TRACE (DEBUG::Butler, string_compose ("\tflush not finished for %1, %2 usecs\n", tr->name(), after - before)); disk_work_outstanding = true; break; default: err++; error << string_compose(_("Butler write-behind failure on dstream %1"), (*i)->name()) << endmsg; + std::cerr << string_compose(_("Butler write-behind failure on dstream %1"), (*i)->name()) << std::endl; /* don't break - try to flush all streams in case they are split across disks. */ @@ -394,13 +399,12 @@ Butler::thread_work () Glib::Threads::Mutex::Lock lm (request_lock); if (should_run && (disk_work_outstanding || transport_work_requested())) { -// for (DiskstreamList::iterator i = dsl->begin(); i != dsl->end(); ++i) { -// cerr << "AFTER " << (*i)->name() << ": pb = " << (*i)->playback_buffer_load() << " cp = " << (*i)->capture_buffer_load() << endl; -// } - + DEBUG_TRACE (DEBUG::Butler, string_compose ("at end, should run %1 disk work %2 transport work %3 ... goto restart\n", + should_run, disk_work_outstanding, transport_work_requested())); goto restart; } + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: butler signals pause @ %2\n", pthread_self(), g_get_monotonic_time())); paused.signal(); } @@ -433,7 +437,7 @@ Butler::queue_request (Request::Type r) void Butler::summon () { - DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: summon butler to run @ %2", pthread_self(), g_get_monotonic_time())); + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: summon butler to run @ %2\n", pthread_self(), g_get_monotonic_time())); queue_request (Request::Run); } @@ -441,7 +445,7 @@ void Butler::stop () { Glib::Threads::Mutex::Lock lm (request_lock); - DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: asking butler to stop @ %2", pthread_self(), g_get_monotonic_time())); + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: asking butler to stop @ %2\n", pthread_self(), g_get_monotonic_time())); queue_request (Request::Pause); paused.wait(request_lock); } @@ -450,7 +454,7 @@ void Butler::wait_until_finished () { Glib::Threads::Mutex::Lock lm (request_lock); - DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: waiting for butler to finish @ %2", pthread_self(), g_get_monotonic_time())); + DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: waiting for butler to finish @ %2\n", pthread_self(), g_get_monotonic_time())); queue_request (Request::Pause); paused.wait(request_lock); } diff --git a/libs/ardour/session_process.cc b/libs/ardour/session_process.cc index efe9ffb351..8d94fbb064 100644 --- a/libs/ardour/session_process.cc +++ b/libs/ardour/session_process.cc @@ -248,6 +248,12 @@ Session::get_track_statistics () g_atomic_int_set (&_playback_load, (uint32_t) floor (pworst * 100.0f)); g_atomic_int_set (&_capture_load, (uint32_t) floor (cworst * 100.0f)); + if (cworst < 0.4 || pworst < 0.4) { + GTimeVal now; + g_get_current_time (&now); + std::cerr << g_time_val_to_iso8601 (&now) << " *** WARNING *** CAPTURE BUFFERS (WORST): " << cworst << "PLAYBACK BUFFERS (WORST): " << pworst << endl; + } + if (actively_recording()) { set_dirty(); } -- 2.30.2