Add profile points; switch to microseconds

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",
+        snprintf(buffer, buflen, "\tReal: \t%12f %s      \t[%f %s total]\n",
-                (pp.second / pp.first),
+                 (pp.second / pp.first), mu_s,
-                (pp.second));
+                 (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<double, std::milli> ms = finish - m_start;
+    std::chrono::duration<double, std::micro> us = finish - m_start;
-    add(m_c, ms.count());
+    add(m_c, us.count());
     m_ended = true;
 }
  

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;

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 <vector>
 #include <memory>
@@ -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) {

src/finer/BinSegmenter.h

@@ -28,6 +28,7 @@
 
 #include "../common/HistogramFilter.h"
 #include "../common/mathmisc.h"
+#include "../common/Profiler.h"
 
 #include <vector>
 
@@ -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]) {

src/finer/Guide.h

@@ -25,6 +25,7 @@
 #define RUBBERBAND_GUIDE_H
 
 #include "../common/Log.h"
+#include "../common/Profiler.h"
 
 #include <functional>
 #include <sstream>
@@ -159,6 +160,8 @@ public:
                         bool tighterChannelLock,
                         Guidance &guidance) const {
 
+        Profiler profiler("Guide::updateGuidance");
+        
         bool hadPhaseReset = guidance.phaseReset.present;
 
         guidance.phaseReset.present = false;

src/finer/PhaseAdvance.h

@@ -28,6 +28,7 @@
 
 #include "../common/Log.h"
 #include "../common/mathmisc.h"
+#include "../common/Profiler.h"
 
 #include <sstream>
 #include <functional>
@@ -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) {

src/finer/R3Stretcher.cpp

@@ -24,6 +24,7 @@
 #include "R3Stretcher.h"
 
 #include "../common/VectorOpsComplex.h"
+#include "../common/Profiler.h"
 
 #include <array>
 
@@ -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<size_t, size_t> &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);