From b087721d8aaf9470833414d01a72d826162946ab Mon Sep 17 00:00:00 2001 From: Carl Hetherington Date: Sat, 14 Jan 2012 22:02:59 +0000 Subject: [PATCH] Add some debug code to time things in the process thread(s). git-svn-id: svn://localhost/ardour2/branches/3.0@11246 d708f5d6-7413-0410-9779-e7cbd77b26cf --- libs/ardour/ardour/cycle_timer.h | 33 +++++++++++++++++-- libs/ardour/audioengine.cc | 8 +++-- libs/ardour/cycle_timer.cc | 55 +++++++++++++++++++++++++++++++- libs/ardour/session.cc | 3 ++ libs/ardour/session_process.cc | 10 +++++- wscript | 6 ++++ 6 files changed, 109 insertions(+), 6 deletions(-) diff --git a/libs/ardour/ardour/cycle_timer.h b/libs/ardour/ardour/cycle_timer.h index dc70204e82..35cc2a4c73 100644 --- a/libs/ardour/ardour/cycle_timer.h +++ b/libs/ardour/ardour/cycle_timer.h @@ -22,10 +22,13 @@ #include #include +#include #include "ardour/cycles.h" #include "ardour/debug.h" +float get_mhz (); + class CycleTimer { private: static float cycles_per_usec; @@ -56,8 +59,34 @@ class CycleTimer { } #endif } - - static float get_mhz (); }; +class StoringTimer +{ +public: + StoringTimer (int); + void ref (); + void check (int); + void dump (std::string const &); + +private: + cycles_t _current_ref; + int* _point; + cycles_t* _value; + cycles_t* _ref; + int _points; + int _max_points; +}; + +#ifdef PT_TIMING +extern StoringTimer ST; +#define PT_TIMING_REF ST.ref(); +#define PT_TIMING_CHECK(x) ST.check(x); +#endif + +#ifndef PT_TIMING +#define PT_TIMING_REF +#define PT_TIMING_CHECK(x) +#endif + #endif /* __ardour_cycle_timer_h__ */ diff --git a/libs/ardour/audioengine.cc b/libs/ardour/audioengine.cc index 34a79c35f8..06a1637382 100644 --- a/libs/ardour/audioengine.cc +++ b/libs/ardour/audioengine.cc @@ -446,9 +446,11 @@ int AudioEngine::process_callback (pframes_t nframes) { GET_PRIVATE_JACK_POINTER_RET(_jack,0); - // CycleTimer ct ("AudioEngine::process"); Glib::Mutex::Lock tm (_process_lock, Glib::TRY_LOCK); + PT_TIMING_REF; + PT_TIMING_CHECK (1); + /// The number of frames that will have been processed when we've finished pframes_t next_processed_frames; @@ -504,7 +506,6 @@ AudioEngine::process_callback (pframes_t nframes) } else { if (_session) { _session->process (nframes); - } } @@ -555,6 +556,9 @@ AudioEngine::process_callback (pframes_t nframes) } _processed_frames = next_processed_frames; + + PT_TIMING_CHECK (2); + return 0; } diff --git a/libs/ardour/cycle_timer.cc b/libs/ardour/cycle_timer.cc index 7a6b1fcab2..02d1abb930 100644 --- a/libs/ardour/cycle_timer.cc +++ b/libs/ardour/cycle_timer.cc @@ -18,17 +18,19 @@ */ #include +#include #include "pbd/error.h" #include "ardour/cycle_timer.h" #include "i18n.h" +using namespace std; using namespace PBD; float CycleTimer::cycles_per_usec = 0; float -CycleTimer::get_mhz() +get_mhz() { FILE *f; @@ -72,3 +74,54 @@ CycleTimer::get_mhz() /*NOTREACHED*/ return 0.0f; } + +StoringTimer::StoringTimer (int N) +{ + _point = new int[N]; + _value = new cycles_t[N]; + _ref = new cycles_t[N]; + _max_points = N; + _points = 0; +} + + +void +StoringTimer::dump (string const & file) +{ + ofstream f (file.c_str ()); + + f << min (_points, _max_points) << "\n"; + f << get_mhz () << "\n"; + for (int i = 0; i < min (_points, _max_points); ++i) { + f << _point[i] << " " << _ref[i] << " " << _value[i] << "\n"; + } +} + +void +StoringTimer::ref () +{ + _current_ref = get_cycles (); +} + +void +StoringTimer::check (int p) +{ + if (_points == _max_points) { + ++_points; + return; + } else if (_points > _max_points) { + return; + } + + _point[_points] = p; + _value[_points] = get_cycles (); + _ref[_points] = _current_ref; + + ++_points; +} + +#ifdef PT_TIMING +StoringTimer ST (64 * 1024); +#endif + + diff --git a/libs/ardour/session.cc b/libs/ardour/session.cc index 37349cc5fb..26b3d47b7e 100644 --- a/libs/ardour/session.cc +++ b/libs/ardour/session.cc @@ -217,6 +217,9 @@ Session::Session (AudioEngine &eng, Session::~Session () { +#ifdef PT_TIMING + ST.dump ("ST.dump"); +#endif destroy (); } diff --git a/libs/ardour/session_process.cc b/libs/ardour/session_process.cc index 4876dc7931..80f922117d 100644 --- a/libs/ardour/session_process.cc +++ b/libs/ardour/session_process.cc @@ -39,6 +39,7 @@ #include "ardour/graph.h" #include "ardour/audio_port.h" #include "ardour/tempo.h" +#include "ardour/cycle_timer.h" #include "midi++/manager.h" #include "midi++/mmc.h" @@ -103,6 +104,8 @@ Session::fail_roll (pframes_t nframes) int Session::no_roll (pframes_t nframes) { + PT_TIMING_CHECK (4); + framepos_t end_frame = _transport_frame + nframes; // FIXME: varispeed + no_roll ?? int ret = 0; bool declick = get_transport_declick_required(); @@ -112,10 +115,11 @@ Session::no_roll (pframes_t nframes) _click_io->silence (nframes); } - if (_process_graph->threads_in_use() > 0) { + if (1 || _process_graph->threads_in_use() > 0) { DEBUG_TRACE(DEBUG::ProcessThreads,"calling graph/no-roll\n"); _process_graph->routes_no_roll( nframes, _transport_frame, end_frame, non_realtime_work_pending(), declick); } else { + PT_TIMING_CHECK (10); for (RouteList::iterator i = r->begin(); i != r->end(); ++i) { if ((*i)->is_hidden()) { @@ -130,8 +134,10 @@ Session::no_roll (pframes_t nframes) break; } } + PT_TIMING_CHECK (11); } + PT_TIMING_CHECK (5); return ret; } @@ -242,6 +248,8 @@ Session::get_track_statistics () void Session::process_with_events (pframes_t nframes) { + PT_TIMING_CHECK (3); + SessionEvent* ev; pframes_t this_nframes; framepos_t end_frame; diff --git a/wscript b/wscript index 1569099666..4604b1d4bf 100644 --- a/wscript +++ b/wscript @@ -391,6 +391,8 @@ def options(opt): help='Build with debugging for the STL') opt.add_option('--rt-alloc-debug', action='store_true', default=False, dest='rt_alloc_debug', help='Build with debugging for memory allocation in the real-time thread') + opt.add_option('--pt-timing', action='store_true', default=False, dest='pt_timing', + help='Build with logging of timing in the process thread(s)') opt.add_option('--denormal-exception', action='store_true', default=False, dest='denormal_exception', help='Raise a floating point exception if a denormal is detected') opt.add_option('--test', action='store_true', default=False, dest='build_tests', @@ -589,6 +591,9 @@ def configure(conf): if opts.rt_alloc_debug: conf.define('DEBUG_RT_ALLOC', 1) conf.env['DEBUG_RT_ALLOC'] = True + if opts.pt_timing: + conf.define('PT_TIMING', 1) + conf.env['PT_TIMING'] = True if opts.denormal_exception: conf.define('DEBUG_DENORMAL_EXCEPTION', 1) conf.env['DEBUG_DENORMAL_EXCEPTION'] = True @@ -621,6 +626,7 @@ const char* const ardour_config_info = "\\n\\ write_config_text('Build target', conf.env['build_target']) write_config_text('CoreAudio', conf.is_defined('HAVE_COREAUDIO')) write_config_text('Debug RT allocations', conf.is_defined('DEBUG_RT_ALLOC')) + write_config_text('Process thread timing', conf.is_defined('PT_TIMING')) write_config_text('Denormal exceptions', conf.is_defined('DEBUG_DENORMAL_EXCEPTION')) write_config_text('FLAC', conf.is_defined('HAVE_FLAC')) write_config_text('FPU optimization', opts.fpu_optimization)