change StoringTimer to be thread safe and use fixed char strings to identify timing points

This may not be at all useful, but the existing implementation was completely useless because of a lack
of thread safety
This commit is contained in:
Paul Davis 2021-06-06 18:59:22 -06:00
parent 7ce43739e8
commit 0dddd75429
6 changed files with 72 additions and 36 deletions

View file

@ -21,6 +21,7 @@
#ifndef __ardour_cycle_timer_h__
#define __ardour_cycle_timer_h__
#include <atomic>
#include <string>
#include <iostream>
#include <cstdlib>
@ -68,31 +69,38 @@ class LIBARDOUR_API CycleTimer {
class LIBARDOUR_API StoringTimer
{
public:
StoringTimer (int);
StoringTimer ();
void ref ();
void check (int);
#ifndef NDEBUG
void dump (std::string const &);
#endif
void check (char const * const what);
void dump (std::ostream&);
static void dump_all (std::string const &);
static StoringTimer* thread_st();
static void dump_all ();
private:
cycles_t _current_ref;
int* _point;
char const * const thread;
char const ** _what;
cycles_t* _value;
cycles_t* _ref;
int _points;
int _max_points;
static int _max_points;
static StoringTimer* all_timers[2048]; /* size relates to thread count */
static std::atomic<int> st_cnt;
thread_local static int st_index;
};
#ifdef PT_TIMING
extern StoringTimer ST;
#define PT_TIMING_REF ST.ref();
#define PT_TIMING_CHECK(x) ST.check(x);
#define PT_TIMING_REF StoringTimer::thread_st()->ref();
#define PT_TIMING_CHECK(w) StoringTimer::thread_st()->check(w);
#endif
#ifndef PT_TIMING
#define PT_TIMING_REF
#define PT_TIMING_CHECK(x)
#define PT_TIMING_CHECK(w)
#endif
#endif /* __ardour_cycle_timer_h__ */

View file

@ -232,7 +232,7 @@ AudioEngine::process_callback (pframes_t nframes)
Port::set_speed_ratio (1.0);
PT_TIMING_REF;
PT_TIMING_CHECK (1);
PT_TIMING_CHECK ("process callback in");
/// The number of samples that will have been processed when we've finished
pframes_t next_processed_samples;
@ -588,7 +588,7 @@ AudioEngine::process_callback (pframes_t nframes)
_processed_samples = next_processed_samples;
PT_TIMING_CHECK (2);
PT_TIMING_CHECK ("process callback out");
return 0;
}

View file

@ -21,6 +21,7 @@
#include <cstdio>
#include <fstream>
#include "pbd/error.h"
#include "pbd/pthread_utils.h"
#include "ardour/cycle_timer.h"
#include "ardour/libardour_visibility.h"
@ -78,28 +79,45 @@ get_mhz()
return 0.0f;
}
StoringTimer::StoringTimer (int N)
int StoringTimer::_max_points = 64 * 1024;
StoringTimer* StoringTimer::all_timers[2048];
std::atomic<int> StoringTimer::st_cnt;
thread_local int StoringTimer::st_index = st_cnt.fetch_add (1);
StoringTimer::StoringTimer ()
: thread (strdup (pthread_name()))
{
_point = new int[N];
_value = new cycles_t[N];
_ref = new cycles_t[N];
_max_points = N;
_what = new char const *[_max_points];
_value = new cycles_t[_max_points];
_ref = new cycles_t[_max_points] ;
_points = 0;
}
#ifndef NDEBUG
void
StoringTimer::dump (string const & file)
StoringTimer::dump_all (string const & file)
{
ofstream f (file.c_str ());
f << min (_points, _max_points) << "\n";
f << get_mhz () << "\n";
f << "There were " << st_cnt.load() << " thread timers\n";
for (size_t i = 0; i < (sizeof (all_timers) / sizeof (all_timers[0])); ++i) {
if (all_timers[i]) {
all_timers[i]->dump (f);
}
}
}
void
StoringTimer::dump (std::ostream& f)
{
f << thread << ' ' << _points << "\n";
for (int i = 0; i < min (_points, _max_points); ++i) {
f << _point[i] << " " << _ref[i] << " " << _value[i] << "\n";
f << '\t' << _what[i] << " " << _ref[i] << " " << _value[i] << " delta " << _value[i] - _ref[i] << "\n";
}
}
#endif
void
StoringTimer::ref ()
@ -108,8 +126,10 @@ StoringTimer::ref ()
}
void
StoringTimer::check (int p)
StoringTimer::check (char const * const what)
{
cerr << pthread_name() << " @ " << pthread_self() << ' ' << thread << " check " << what << " @ " << _points << endl;
if (_points == _max_points) {
++_points;
return;
@ -117,15 +137,20 @@ StoringTimer::check (int p)
return;
}
_point[_points] = p;
_what[_points] = what;
_value[_points] = get_cycles ();
_ref[_points] = _current_ref;
++_points;
}
#ifdef PT_TIMING
StoringTimer ST (64 * 1024);
#endif
StoringTimer*
StoringTimer::thread_st()
{
if (all_timers[st_index] == 0) {
all_timers[st_index] = new StoringTimer;
}
return all_timers[st_index];
}

View file

@ -57,6 +57,7 @@
#include "ardour/buffer_set.h"
#include "ardour/capturing_processor.h"
#include "ardour/debug.h"
#include "ardour/cycle_timer.h"
#include "ardour/delivery.h"
#include "ardour/disk_reader.h"
#include "ardour/disk_writer.h"
@ -345,6 +346,7 @@ Route::process_output_buffers (BufferSet& bufs,
samplepos_t start_sample, samplepos_t end_sample, pframes_t nframes,
bool gain_automation_ok, bool run_disk_reader)
{
PT_TIMING_CHECK ("route-pob-in");
/* Caller must hold process lock */
assert (!AudioEngine::instance()->process_lock().trylock());

View file

@ -74,6 +74,7 @@
#include "ardour/butler.h"
#include "ardour/click.h"
#include "ardour/control_protocol_manager.h"
#include "ardour/cycle_timer.h"
#include "ardour/data_type.h"
#include "ardour/debug.h"
#include "ardour/disk_reader.h"
@ -502,7 +503,7 @@ Session::Session (AudioEngine &eng,
Session::~Session ()
{
#ifdef PT_TIMING
ST.dump ("ST.dump");
StoringTimer::dump_all ("ST.dump");
#endif
destroy ();
}

View file

@ -165,7 +165,7 @@ Session::fail_roll (pframes_t nframes)
int
Session::no_roll (pframes_t nframes)
{
PT_TIMING_CHECK (4);
PT_TIMING_CHECK ("no roll in");
samplepos_t end_sample = _transport_sample + floor (nframes * _transport_fsm->transport_speed());
int ret = 0;
@ -186,7 +186,7 @@ Session::no_roll (pframes_t nframes)
DEBUG_TRACE(DEBUG::ProcessThreads,"calling graph/no-roll\n");
_process_graph->routes_no_roll( nframes, _transport_sample, end_sample, non_realtime_work_pending());
} else {
PT_TIMING_CHECK (10);
PT_TIMING_CHECK ("nograph no roll in");
for (RouteList::iterator i = r->begin(); i != r->end(); ++i) {
if ((*i)->is_auditioner()) {
@ -199,10 +199,10 @@ Session::no_roll (pframes_t nframes)
break;
}
}
PT_TIMING_CHECK (11);
PT_TIMING_CHECK ("nograph no roll out");
}
PT_TIMING_CHECK (5);
PT_TIMING_CHECK ("no roll out");
return ret;
}
@ -330,7 +330,7 @@ Session::calc_preroll_subcycle (samplecnt_t ns) const
void
Session::process_with_events (pframes_t nframes)
{
PT_TIMING_CHECK (3);
PT_TIMING_CHECK ("p-with-e in");
SessionEvent* ev;
pframes_t this_nframes;