X-Git-Url: https://main.carlh.net/gitweb/?a=blobdiff_plain;f=libs%2Fardour%2Fbutler.cc;h=c33b6e333dc4e6e928d0c367c4cd8f9242cb7637;hb=b3e7c88988b6b3ade5872935b7c371cf3a6a1040;hp=1fe15246183c89575782e5e4f505c562bcbf6bb7;hpb=08371ae2cf6231bbb8522645d14add41ffa9c1c0;p=ardour.git diff --git a/libs/ardour/butler.cc b/libs/ardour/butler.cc index 1fe1524618..c33b6e333d 100644 --- a/libs/ardour/butler.cc +++ b/libs/ardour/butler.cc @@ -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 tr = boost::dynamic_pointer_cast (_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 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 tr = boost::dynamic_pointer_cast (*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); }