From dc74c993cf1d93dc7c870ec5523bf1b9951ff4e2 Mon Sep 17 00:00:00 2001 From: Chris Cannam Date: Thu, 14 Jul 2022 10:02:39 +0100 Subject: [PATCH] Add profile points; switch to microseconds --- src/common/Profiler.cpp | 88 +++++++++++++++++++------------------- src/faster/R2Stretcher.cpp | 2 + src/finer/BinClassifier.h | 3 ++ src/finer/BinSegmenter.h | 4 ++ src/finer/Guide.h | 3 ++ src/finer/PhaseAdvance.h | 3 ++ src/finer/R3Stretcher.cpp | 25 +++++++++++ 7 files changed, 85 insertions(+), 43 deletions(-) diff --git a/src/common/Profiler.cpp b/src/common/Profiler.cpp index 142f0ee..b0466e2 100644 --- a/src/common/Profiler.cpp +++ b/src/common/Profiler.cpp @@ -50,23 +50,23 @@ Profiler::m_worstCalls; static Mutex profileMutex; void -Profiler::add(const char *id, double ms) +Profiler::add(const char *id, double us) { profileMutex.lock(); ProfileMap::iterator pmi = m_profiles.find(id); if (pmi != m_profiles.end()) { ++pmi->second.first; - pmi->second.second += ms; + pmi->second.second += us; } else { - m_profiles[id] = TimePair(1, ms); + m_profiles[id] = TimePair(1, us); } WorstCallMap::iterator wci = m_worstCalls.find(id); if (wci != m_worstCalls.end()) { - if (ms > wci->second) wci->second = ms; + if (us > wci->second) wci->second = us; } else { - m_worstCalls[id] = ms; + m_worstCalls[id] = us; } profileMutex.unlock(); @@ -100,6 +100,8 @@ Profiler::getReport() TimeRMap totmap, avgmap, worstmap; IntRMap ncallmap; + const unsigned char mu_s[] = { 0xce, 0xbc, 's', 0x0 }; + for (ProfileMap::const_iterator i = m_profiles.begin(); i != m_profiles.end(); ++i) { totmap.insert(TimeRMap::value_type(i->second.second, i->first)); @@ -113,38 +115,6 @@ Profiler::getReport() worstmap.insert(TimeRMap::value_type(i->second, i->first)); } - snprintf(buffer, buflen, "\nBy total:\n"); - report += buffer; - for (TimeRMap::const_iterator i = totmap.end(); i != totmap.begin(); ) { - --i; - snprintf(buffer, buflen, "%-40s %f ms\n", i->second, i->first); - report += buffer; - } - - snprintf(buffer, buflen, "\nBy average:\n"); - report += buffer; - for (TimeRMap::const_iterator i = avgmap.end(); i != avgmap.begin(); ) { - --i; - snprintf(buffer, buflen, "%-40s %f ms\n", i->second, i->first); - report += buffer; - } - - snprintf(buffer, buflen, "\nBy worst case:\n"); - report += buffer; - for (TimeRMap::const_iterator i = worstmap.end(); i != worstmap.begin(); ) { - --i; - snprintf(buffer, buflen, "%-40s %f ms\n", i->second, i->first); - report += buffer; - } - - snprintf(buffer, buflen, "\nBy number of calls:\n"); - report += buffer; - for (IntRMap::const_iterator i = ncallmap.end(); i != ncallmap.begin(); ) { - --i; - snprintf(buffer, buflen, "%-40s %d\n", i->second, i->first); - report += buffer; - } - snprintf(buffer, buflen, "\nBy name:\n"); report += buffer; @@ -165,15 +135,47 @@ Profiler::getReport() const TimePair &pp(j->second); snprintf(buffer, buflen, "%s(%d):\n", *i, pp.first); report += buffer; - snprintf(buffer, buflen, "\tReal: \t%f ms \t[%f ms total]\n", - (pp.second / pp.first), - (pp.second)); + snprintf(buffer, buflen, "\tReal: \t%12f %s \t[%f %s total]\n", + (pp.second / pp.first), mu_s, + (pp.second), mu_s); report += buffer; WorstCallMap::const_iterator k = m_worstCalls.find(*i); if (k == m_worstCalls.end()) continue; - snprintf(buffer, buflen, "\tWorst:\t%f ms/call\n", k->second); + snprintf(buffer, buflen, "\tWorst:\t%14f %s/call\n", k->second, mu_s); + report += buffer; + } + + snprintf(buffer, buflen, "\nBy total:\n"); + report += buffer; + for (TimeRMap::const_iterator i = totmap.end(); i != totmap.begin(); ) { + --i; + snprintf(buffer, buflen, "%-40s %14f %s\n", i->second, i->first, mu_s); + report += buffer; + } + + snprintf(buffer, buflen, "\nBy average:\n"); + report += buffer; + for (TimeRMap::const_iterator i = avgmap.end(); i != avgmap.begin(); ) { + --i; + snprintf(buffer, buflen, "%-40s %14f %s\n", i->second, i->first, mu_s); + report += buffer; + } + + snprintf(buffer, buflen, "\nBy worst case:\n"); + report += buffer; + for (TimeRMap::const_iterator i = worstmap.end(); i != worstmap.begin(); ) { + --i; + snprintf(buffer, buflen, "%-40s %14f %s\n", i->second, i->first, mu_s); + report += buffer; + } + + snprintf(buffer, buflen, "\nBy number of calls:\n"); + report += buffer; + for (IntRMap::const_iterator i = ncallmap.end(); i != ncallmap.begin(); ) { + --i; + snprintf(buffer, buflen, "%-40s %14d\n", i->second, i->first); report += buffer; } @@ -198,8 +200,8 @@ void Profiler::end() { auto finish = std::chrono::steady_clock::now(); - std::chrono::duration ms = finish - m_start; - add(m_c, ms.count()); + std::chrono::duration us = finish - m_start; + add(m_c, us.count()); m_ended = true; } diff --git a/src/faster/R2Stretcher.cpp b/src/faster/R2Stretcher.cpp index 4546895..4033c11 100644 --- a/src/faster/R2Stretcher.cpp +++ b/src/faster/R2Stretcher.cpp @@ -101,6 +101,8 @@ R2Stretcher::R2Stretcher(size_t sampleRate, m_freq2(12000), m_baseFftSize(m_defaultFftSize) { + Profiler profiler("R2Stretcher::R2Stretcher"); + if (!_initialised) { system_specific_initialise(); _initialised = true; diff --git a/src/finer/BinClassifier.h b/src/finer/BinClassifier.h index 2c58d29..d0431cb 100644 --- a/src/finer/BinClassifier.h +++ b/src/finer/BinClassifier.h @@ -27,6 +27,7 @@ #include "../common/Allocators.h" #include "../common/MovingMedian.h" #include "../common/RingBuffer.h" +#include "../common/Profiler.h" #include #include @@ -97,6 +98,8 @@ public: void classify(const process_t *const mag, // input, of at least binCount bins Classification *classification) // output, of binCount bins { + Profiler profiler("BinClassifier::classify"); + const int n = m_parameters.binCount; for (int i = 0; i < n; ++i) { diff --git a/src/finer/BinSegmenter.h b/src/finer/BinSegmenter.h index 705d255..90c29b7 100644 --- a/src/finer/BinSegmenter.h +++ b/src/finer/BinSegmenter.h @@ -28,6 +28,7 @@ #include "../common/HistogramFilter.h" #include "../common/mathmisc.h" +#include "../common/Profiler.h" #include @@ -65,6 +66,9 @@ public: } Segmentation segment(const BinClassifier::Classification *classification) { + + Profiler profiler("BinSegmenter::segment"); + int n = m_parameters.binCount; for (int i = 0; i < n; ++i) { switch (classification[i]) { diff --git a/src/finer/Guide.h b/src/finer/Guide.h index 108fd27..f14b24b 100644 --- a/src/finer/Guide.h +++ b/src/finer/Guide.h @@ -25,6 +25,7 @@ #define RUBBERBAND_GUIDE_H #include "../common/Log.h" +#include "../common/Profiler.h" #include #include @@ -159,6 +160,8 @@ public: bool tighterChannelLock, Guidance &guidance) const { + Profiler profiler("Guide::updateGuidance"); + bool hadPhaseReset = guidance.phaseReset.present; guidance.phaseReset.present = false; diff --git a/src/finer/PhaseAdvance.h b/src/finer/PhaseAdvance.h index aec35b9..ba200bb 100644 --- a/src/finer/PhaseAdvance.h +++ b/src/finer/PhaseAdvance.h @@ -28,6 +28,7 @@ #include "../common/Log.h" #include "../common/mathmisc.h" +#include "../common/Profiler.h" #include #include @@ -93,6 +94,8 @@ public: int inhop, int outhop) { + Profiler profiler("GuidedPhaseAdvance::advance"); + int myFftBand = 0; int i = 0; for (const auto &fband : guidance[0]->fftBands) { diff --git a/src/finer/R3Stretcher.cpp b/src/finer/R3Stretcher.cpp index dd2f947..f7be7bc 100644 --- a/src/finer/R3Stretcher.cpp +++ b/src/finer/R3Stretcher.cpp @@ -24,6 +24,7 @@ #include "R3Stretcher.h" #include "../common/VectorOpsComplex.h" +#include "../common/Profiler.h" #include @@ -54,6 +55,8 @@ R3Stretcher::R3Stretcher(Parameters parameters, m_totalOutputDuration(0), m_mode(ProcessMode::JustCreated) { + Profiler profiler("R3Stretcher::R3Stretcher"); + m_log.log(1, "R3Stretcher::R3Stretcher: rate, options", m_parameters.sampleRate, m_parameters.options); m_log.log(1, "R3Stretcher::R3Stretcher: initial time ratio and pitch scale", @@ -233,6 +236,8 @@ R3Stretcher::setKeyFrameMap(const std::map &mapping) void R3Stretcher::createResampler() { + Profiler profiler("R3Stretcher::createResampler"); + Resampler::Parameters resamplerParameters; if (m_parameters.options & RubberBandStretcher::OptionPitchHighQuality) { @@ -463,6 +468,8 @@ R3Stretcher::reset() void R3Stretcher::study(const float *const *, size_t samples, bool) { + Profiler profiler("R3Stretcher::study"); + if (isRealTime()) { m_log.log(0, "R3Stretcher::study: Not meaningful in realtime mode"); return; @@ -520,6 +527,8 @@ R3Stretcher::setMaxProcessSize(size_t n) void R3Stretcher::process(const float *const *input, size_t samples, bool final) { + Profiler profiler("R3Stretcher::process"); + if (m_mode == ProcessMode::Finished) { m_log.log(0, "R3Stretcher::process: Cannot process again after final chunk"); return; @@ -615,6 +624,8 @@ R3Stretcher::available() const size_t R3Stretcher::retrieve(float *const *output, size_t samples) const { + Profiler profiler("R3Stretcher::retrieve"); + int got = samples; for (int c = 0; c < m_parameters.channels; ++c) { @@ -633,6 +644,8 @@ R3Stretcher::retrieve(float *const *output, size_t samples) const void R3Stretcher::consume() { + Profiler profiler("R3Stretcher::consume"); + int longest = m_guideConfiguration.longestFftSize; int channels = m_parameters.channels; int inhop = m_inhop; @@ -680,6 +693,8 @@ R3Stretcher::consume() while (cd0->outbuf->getWriteSpace() >= outhop) { + Profiler profiler("R3Stretcher::consume/loop"); + // NB our ChannelData, ScaleData, and ChannelScaleData maps // contain shared_ptrs; whenever we retain one of them in a // variable, we do so by reference to avoid copying the @@ -827,6 +842,8 @@ R3Stretcher::consume() void R3Stretcher::analyseChannel(int c, int inhop, int prevInhop, int prevOuthop) { + Profiler profiler("R3Stretcher::analyseChannel"); + int longest = m_guideConfiguration.longestFftSize; int classify = m_guideConfiguration.classificationFftSize; @@ -1067,6 +1084,8 @@ R3Stretcher::analyseChannel(int c, int inhop, int prevInhop, int prevOuthop) void R3Stretcher::analyseFormant(int c) { + Profiler profiler("R3Stretcher::analyseFormant"); + auto &cd = m_channelData.at(c); auto &f = *cd->formant; @@ -1101,6 +1120,8 @@ R3Stretcher::analyseFormant(int c) void R3Stretcher::adjustFormant(int c) { + Profiler profiler("R3Stretcher::adjustFormant"); + auto &cd = m_channelData.at(c); for (auto &it : cd->scales) { @@ -1135,6 +1156,8 @@ R3Stretcher::adjustFormant(int c) void R3Stretcher::adjustPreKick(int c) { + Profiler profiler("R3Stretcher::adjustPreKick"); + auto &cd = m_channelData.at(c); auto fftSize = cd->guidance.fftBands[0].fftSize; if (cd->guidance.preKick.present) { @@ -1166,6 +1189,8 @@ R3Stretcher::adjustPreKick(int c) void R3Stretcher::synthesiseChannel(int c, int outhop, bool draining) { + Profiler profiler("R3Stretcher::synthesiseChannel"); + int longest = m_guideConfiguration.longestFftSize; auto &cd = m_channelData.at(c);