fixes for desirable playback when using seamless looping.
[ardour.git] / libs / ardour / butler.cc
index 1fe15246183c89575782e5e4f505c562bcbf6bb7..c33b6e333dc4e6e928d0c367c4cd8f9242cb7637 100644 (file)
@@ -27,6 +27,7 @@
 
 #include "pbd/error.h"
 #include "pbd/pthread_utils.h"
+#include "ardour/debug.h"
 #include "ardour/butler.h"
 #include "ardour/io.h"
 #include "ardour/midi_diskstream.h"
@@ -43,6 +44,7 @@ namespace ARDOUR {
 Butler::Butler(Session& s)
        : SessionHandleRef (s)
        , thread()
+       , have_thread (false)
        , audio_dstream_capture_buffer_size(0)
        , audio_dstream_playback_buffer_size(0)
        , midi_dstream_buffer_size(0)
@@ -126,16 +128,19 @@ Butler::start_thread()
        }
 
        //pthread_detach (thread);
-
+       have_thread = true;
        return 0;
 }
 
 void
 Butler::terminate_thread ()
 {
-       void* status;
-       queue_request (Request::Quit);
-       pthread_join (thread, &status);
+       if (have_thread) {
+               void* status;
+                DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: ask butler to quit @ %2\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
+               queue_request (Request::Quit);
+               pthread_join (thread, &status);
+       }
 }
 
 void *
@@ -168,6 +173,8 @@ Butler::wait_for_requests ()
                        break;
                }
 
+               DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: butler awake at @ %2\n", DEBUG_THREAD_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;
                        break;
@@ -199,7 +206,7 @@ Butler::dequeue_request (Request::Type& r)
                return false;
        } else {
                fatal << _("Error reading from butler request pipe") << endmsg;
-               /*NOTREACHED*/
+               abort(); /*NOTREACHED*/
        }
 #else
        r = (Request::Type) m_request_state.get();
@@ -207,7 +214,7 @@ Butler::dequeue_request (Request::Type& r)
        return false;
 }
 
-       void *
+void *
 Butler::thread_work ()
 {
        uint32_t err = 0;
@@ -216,45 +223,64 @@ Butler::thread_work ()
        RouteList::iterator i;
 
        while (true) {
+               DEBUG_TRACE (DEBUG::Butler, string_compose ("%1 butler main loop, disk work outstanding ? %2 @ %3\n", DEBUG_THREAD_SELF, disk_work_outstanding, g_get_monotonic_time()));
+
                if(!disk_work_outstanding) {
+                       DEBUG_TRACE (DEBUG::Butler, string_compose ("%1 butler waits for requests @ %2\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
                        if (wait_for_requests ()) {
                                Request::Type req;
 
                                /* empty the pipe of all current requests */
 #ifdef PLATFORM_WINDOWS
                                dequeue_request (req);
-                               {
 #else
-                               while(dequeue_request(req)) {
+                               while (dequeue_request(req)) {
 #endif
                                        switch (req) {
 
                                        case Request::Run:
+                                               DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: butler asked to run @ %2\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
                                                should_run = true;
                                                break;
 
                                        case Request::Pause:
+                                               DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: butler asked to pause @ %2\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
                                                should_run = false;
                                                break;
 
                                        case Request::Quit:
+                                               DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: butler asked to quit @ %2\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
                                                return 0;
-                                               /*NOTREACHED*/
+                                               abort(); /*NOTREACHED*/
                                                break;
 
                                        default:
                                                break;
                                        }
+#ifndef PLATFORM_WINDOWS
                                }
+#endif
                        }
                }
 
-
-restart:
+               
+         restart:
+               DEBUG_TRACE (DEBUG::Butler, "at restart for disk work\n");
                disk_work_outstanding = false;
 
                if (transport_work_requested()) {
+                       DEBUG_TRACE (DEBUG::Butler, string_compose ("do transport work @ %1\n", g_get_monotonic_time()));
                        _session.butler_transport_work ();
+                       DEBUG_TRACE (DEBUG::Butler, string_compose ("\ttransport work complete @ %1\n", g_get_monotonic_time()));
+               }
+
+               frameoffset_t audition_seek;
+               if (should_run && _session.is_auditioning()
+                               && (audition_seek = _session.the_auditioner()->seek_frame()) >= 0) {
+                       boost::shared_ptr<Track> tr = boost::dynamic_pointer_cast<Track> (_session.the_auditioner());
+                       DEBUG_TRACE (DEBUG::Butler, "seek the auditioner\n");
+                       tr->seek(audition_seek);
+                       _session.the_auditioner()->seek_response(audition_seek);
                }
 
                boost::shared_ptr<RouteList> rl = _session.get_routes();
@@ -262,10 +288,6 @@ restart:
                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);
@@ -278,19 +300,23 @@ restart:
 
                        if (io && !io->active()) {
                                /* don't read inactive tracks */
+                               DEBUG_TRACE (DEBUG::Butler, string_compose ("butler skips inactive track %1\n", tr->name()));
                                continue;
                        }
-
+                       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()));
                                break;
                                
                        case 1:
+                               DEBUG_TRACE (DEBUG::Butler, string_compose ("\ttrack refill unfinished %1\n", tr->name()));
                                disk_work_outstanding = true;
                                break;
 
                        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;
                        }
 
@@ -302,6 +328,7 @@ restart:
                }
 
                if (!err && transport_work_requested()) {
+                       DEBUG_TRACE (DEBUG::Butler, "transport work requested during refill, back to restart\n");
                        goto restart;
                }
 
@@ -317,17 +344,27 @@ restart:
                        /* note that we still try to flush diskstreams attached to inactive routes
                         */
 
-                       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, %2 usecs\n", tr->name(), after - before));
                                break;
                                
                        case 1:
+                               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.
                                */
@@ -338,15 +375,18 @@ restart:
                        /* stop the transport and try to catch as much possible
                           captured state as we can.
                        */
+                       DEBUG_TRACE (DEBUG::Butler, "error occurred during recording - stop transport\n");
                        _session.request_stop ();
                }
 
                if (i != rl->begin() && i != rl->end()) {
                        /* we didn't get to all the streams */
+                       DEBUG_TRACE (DEBUG::Butler, "not all tracks processed, will need to go back for more\n");
                        disk_work_outstanding = true;
                }
 
                if (!err && transport_work_requested()) {
+                       DEBUG_TRACE (DEBUG::Butler, "transport work requested during flush, back to restart\n");
                        goto restart;
                }
 
@@ -359,16 +399,16 @@ restart:
                        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", DEBUG_THREAD_SELF, g_get_monotonic_time()));
                        paused.signal();
                }
 
+               DEBUG_TRACE (DEBUG::Butler, "butler emptying pool trash\n");
                empty_pool_trash ();
        }
 
@@ -397,6 +437,7 @@ Butler::queue_request (Request::Type r)
 void
 Butler::summon ()
 {
+       DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: summon butler to run @ %2\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
        queue_request (Request::Run);
 }
 
@@ -404,6 +445,7 @@ void
 Butler::stop ()
 {
        Glib::Threads::Mutex::Lock lm (request_lock);
+       DEBUG_TRACE (DEBUG::Butler, string_compose ("%1: asking butler to stop @ %2\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
        queue_request (Request::Pause);
        paused.wait(request_lock);
 }
@@ -412,6 +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\n", DEBUG_THREAD_SELF, g_get_monotonic_time()));
        queue_request (Request::Pause);
        paused.wait(request_lock);
 }
@@ -455,7 +498,7 @@ Butler::empty_pool_trash ()
 void
 Butler::drop_references ()
 {
-       cerr << "Butler drops pool trash\n";
+       std::cerr << "Butler drops pool trash\n";
        SessionEvent::pool->set_trash (0);
 }