more DEBUG::Butler output, formatting corrections, and a warning on cerr if capture...

diff --git a/gtk2_ardour/ardour_ui.cc b/gtk2_ardour/ardour_ui.cc
index a94e77acc459b073686358754df994bfff50a1ff..f4c5bdd81c11cc8b799df8a7a21184e49f3f9b36 100644 (file)
--- 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 fefc1c235cc62eac6d7735176b130ab7fa811f9d..538faebc4f9375d9c24a9d78d201390a77921e35 100644 (file)
--- 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 5d4c47d5576f000a3b8e1ad9f7dca152f8e24db3..424312a8a4d8ec4d72e73574e6275e8a4a12da03 100644 (file)
--- 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<Track> tr = boost::dynamic_pointer_cast<Track> (*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 efe9ffb3513dce1c99826ff705bea37fe4a608a5..8d94fbb064807b9a1dc0e6cd3428a80b2c55b0d3 100644 (file)
--- 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();
        }