Added logs for the processing time in voices

src/sfizz/Config.h

@@ -30,6 +30,7 @@ namespace config {
     constexpr int maxBlockSize { 8192 };
     constexpr int preloadSize { 8192 };
     constexpr int loggerQueueSize { 16 };
+    constexpr int voiceLoggerQueueSize { 256 };
     constexpr bool loggingEnabled { false };
     constexpr size_t numChannels { 2 };
     constexpr int numBackgroundThreads { 4 };

src/sfizz/Logger.cpp

@@ -66,7 +66,7 @@ sfz::Logger::~Logger()
                         << "_file_log.csv";
         fs::path fileLogPath{ fs::current_path() / fileLogFilename.str() };
         DBG("Logging file times to " << fileLogPath.filename());
-        std::ofstream loadLogFile { fileLogPath.string() };
+        std::ofstream loadLogFile { fileLogPath.native() };
         loadLogFile << "WaitDuration,LoadDuration,FileSize,FileName" << '\n';
         for (auto& time: fileTimes)
             loadLogFile << time.waitDuration.count() << ','
@@ -82,22 +82,27 @@ sfz::Logger::~Logger()
                             << "_callback_log.csv";
         fs::path callbackLogPath{ fs::current_path() / callbackLogFilename.str() };
         DBG("Logging callback times to " << callbackLogPath.filename());
-        std::ofstream callbackLogFile { callbackLogPath.string() };
+        std::ofstream callbackLogFile { callbackLogPath.native() };
-        callbackLogFile << "Duration,NumVoices,NumSamples" << '\n';
+        callbackLogFile << "Dispatch,RenderMethod,Data,Amplitude,Filters,Panning,NumVoices,NumSamples" << '\n';
         for (auto& time: callbackTimes)
-            callbackLogFile << time.duration.count() << ','
+            callbackLogFile << time.breakdown.dispatch.count() << ','
+                            << time.breakdown.renderMethod.count() << ','
+                            << time.breakdown.data.count() << ','
+                            << time.breakdown.amplitude.count() << ','
+                            << time.breakdown.filters.count() << ','
+                            << time.breakdown.panning.count() << ','
                             << time.numVoices << ','
                             << time.numSamples << '\n';
     }
 }
 
 
-void sfz::Logger::logCallbackTime(std::chrono::duration<double> duration, int numVoices, size_t numSamples)
+void sfz::Logger::logCallbackTime(CallbackBreakdown&& breakdown, int numVoices, size_t numSamples)
 {
     if (!loggingEnabled)
         return;
 
-    callbackTimeQueue.try_push<CallbackTime>({ duration, numVoices, numSamples });
+    callbackTimeQueue.try_push<CallbackTime>({ std::move(breakdown), numVoices, numSamples });
 }
 
 void sfz::Logger::logFileTime(std::chrono::duration<double> waitDuration, std::chrono::duration<double> loadDuration, uint32_t fileSize, absl::string_view filename)
@@ -126,7 +131,7 @@ void sfz::Logger::moveEvents() noexcept
         while (callbackTimeQueue.try_pop(callbackTime))
             callbackTimes.push_back(callbackTime);
 
-        sfz::FileTime fileTime;
+        FileTime fileTime;
         while (fileTimeQueue.try_pop(fileTime))
             fileTimes.push_back(fileTime);
 
@@ -135,7 +140,7 @@ void sfz::Logger::moveEvents() noexcept
             callbackTimes.clear();
         }
 
-        std::this_thread::sleep_for(50ms);
+        std::this_thread::sleep_for(10ms);
     }
 }
 
@@ -149,3 +154,14 @@ void sfz::Logger::disableLogging()
     loggingEnabled = false;
     clearFlag.clear();
 }
+
+sfz::ScopedLogger::ScopedLogger(std::function<void(std::chrono::duration<double>)> callback)
+: callback(std::move(callback))
+{
+
+}
+
+sfz::ScopedLogger::~ScopedLogger()
+{
+    callback(std::chrono::high_resolution_clock::now() - creationTime);
+}

src/sfizz/Logger.h

@@ -10,23 +10,46 @@
 #include <vector>
 #include <string>
 #include <chrono>
+#include <functional>
 #include <thread>
 #include "absl/strings/string_view.h"
 
 namespace sfz
 {
 
+using Duration = std::chrono::duration<double>;
+
+struct ScopedLogger
+{
+    using TimePoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
+    ScopedLogger() = delete;
+    ScopedLogger(std::function<void(Duration)> callback);
+    ~ScopedLogger();
+    const std::function<void(Duration)> callback;
+    const TimePoint creationTime { std::chrono::high_resolution_clock::now() };
+};
+
 struct FileTime
 {
-    std::chrono::duration<double> waitDuration;
+    Duration waitDuration;
-    std::chrono::duration<double> loadDuration;
+    Duration loadDuration;
     uint32_t fileSize;
     absl::string_view filename;
 };
 
+struct CallbackBreakdown
+{
+    Duration dispatch { 0 };
+    Duration renderMethod { 0 };
+    Duration data { 0 };
+    Duration amplitude { 0 };
+    Duration filters { 0 };
+    Duration panning { 0 };
+};
+
 struct CallbackTime
 {
-    std::chrono::duration<double> duration;
+    CallbackBreakdown breakdown;
     int numVoices;
     size_t numSamples;
 };
@@ -40,8 +63,8 @@ public:
     void clear();
     void enableLogging();
     void disableLogging();
-    void logCallbackTime(std::chrono::duration<double> duration, int numVoices, size_t numSamples);
+    void logCallbackTime(CallbackBreakdown&& breakdown, int numVoices, size_t numSamples);
-    void logFileTime(std::chrono::duration<double> waitDuration, std::chrono::duration<double> loadDuration, uint32_t fileSize, absl::string_view filename);
+    void logFileTime(Duration waitDuration, Duration loadDuration, uint32_t fileSize, absl::string_view filename);
 private:
     void moveEvents() noexcept;
     bool loggingEnabled { config::loggingEnabled };

src/sfizz/Synth.cpp

@@ -411,6 +411,8 @@ void sfz::Synth::renderBlock(AudioSpan<float> buffer) noexcept
 {
     ScopedFTZ ftz;
     const auto callbackStartTime = std::chrono::high_resolution_clock::now();
+    CallbackBreakdown callbackBreakdown;
+    callbackBreakdown.dispatch = dispatchDuration;
 
     buffer.fill(0.0f);
 
@@ -430,13 +432,20 @@ void sfz::Synth::renderBlock(AudioSpan<float> buffer) noexcept
             numActiveVoices++;
             voice->renderBlock(tempSpan);
             buffer.add(tempSpan);
+            callbackBreakdown.data += voice->getLastDataDuration();
+            callbackBreakdown.amplitude += voice->getLastAmplitudeDuration();
+            callbackBreakdown.filters += voice->getLastFilterDuration();
+            callbackBreakdown.panning += voice->getLastPanningDuration();
         }
     }
 
     buffer.applyGain(db2mag(volume));
 
-    const auto callbackDuration = std::chrono::high_resolution_clock::now() - callbackStartTime;
+    callbackBreakdown.renderMethod = std::chrono::high_resolution_clock::now() - callbackStartTime;
-    resources.logger.logCallbackTime(callbackDuration, numActiveVoices, buffer.getNumFrames());
+    resources.logger.logCallbackTime(std::move(callbackBreakdown), numActiveVoices, buffer.getNumFrames());
+
+    // Reset the dispatch counter
+    dispatchDuration = Duration(0);
 }
 
 void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept
@@ -444,6 +453,7 @@ void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept
     ASSERT(noteNumber < 128);
     ASSERT(noteNumber >= 0);
 
+    ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } };
     resources.midiState.noteOnEvent(noteNumber, velocity);
 
     AtomicGuard callbackGuard { inCallback };
@@ -458,6 +468,7 @@ void sfz::Synth::noteOff(int delay, int noteNumber, uint8_t velocity [[maybe_unu
     ASSERT(noteNumber < 128);
     ASSERT(noteNumber >= 0);
 
+    ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } };
     resources.midiState.noteOffEvent(noteNumber, velocity);
 
     AtomicGuard callbackGuard { inCallback };
@@ -513,6 +524,8 @@ void sfz::Synth::cc(int delay, int ccNumber, uint8_t ccValue) noexcept
     ASSERT(ccNumber < config::numCCs);
     ASSERT(ccNumber >= 0);
 
+    ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } };
+
     resources.midiState.ccEvent(ccNumber, ccValue);
 
     AtomicGuard callbackGuard { inCallback };
@@ -543,6 +556,8 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept
     ASSERT(pitch <= 8192);
     ASSERT(pitch >= -8192);
 
+    ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } };
+
     resources.midiState.pitchBendEvent(pitch);
 
     for (auto& region: regions) {
@@ -555,10 +570,11 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept
 }
 void sfz::Synth::aftertouch(int /* delay */, uint8_t /* aftertouch */) noexcept
 {
+    ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } };
 }
 void sfz::Synth::tempo(int /* delay */, float /* secondsPerQuarter */) noexcept
 {
-
+    ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } };
 }
 
 int sfz::Synth::getNumRegions() const noexcept

src/sfizz/Synth.h

@@ -456,6 +456,8 @@ private:
     int noteOffset { 0 };
     int octaveOffset { 0 };
 
+    Duration dispatchDuration { 0 };
+
     fs::file_time_type modificationTime { };
 
     LEAK_DETECTOR(Synth);

src/sfizz/Voice.cpp

@@ -250,10 +250,13 @@ void sfz::Voice::renderBlock(AudioSpan<float> buffer) noexcept
     auto delayed_buffer = buffer.subspan(delay);
     initialDelay -= static_cast<int>(delay);
 
-    if (region->isGenerator())
+    { // Fill buffer with raw data
-        fillWithGenerator(delayed_buffer);
+        ScopedLogger logger { [&](auto&& duration){ dataDuration = duration; } };
-    else
+        if (region->isGenerator())
-        fillWithData(delayed_buffer);
+            fillWithGenerator(delayed_buffer);
+        else
+            fillWithData(delayed_buffer);
+    }
 
     if (region->isStereo)
         processStereo(buffer);
@@ -275,39 +278,50 @@ void sfz::Voice::processMono(AudioSpan<float> buffer) noexcept
 
     auto modulationSpan = tempSpan1.first(numSamples);
 
-    // Amplitude envelope
+    { // Amplitude processing
-    amplitudeEnvelope.getBlock(modulationSpan);
+        ScopedLogger logger { [&](auto&& duration){ amplitudeDuration = duration; } };
-    applyGain<float>(modulationSpan, leftBuffer);
 
-    // Crossfade envelope
+        // Amplitude envelope
-    crossfadeEnvelope.getBlock(modulationSpan);
+        amplitudeEnvelope.getBlock(modulationSpan);
-    applyGain<float>(modulationSpan, leftBuffer);
+        applyGain<float>(modulationSpan, leftBuffer);
 
-    // Volume envelope
+        // Crossfade envelope
-    volumeEnvelope.getBlock(modulationSpan);
+        crossfadeEnvelope.getBlock(modulationSpan);
-    applyGain<float>(modulationSpan, leftBuffer);
+        applyGain<float>(modulationSpan, leftBuffer);
 
-    // AmpEG envelope
+        // Volume envelope
-    egEnvelope.getBlock(modulationSpan);
+        volumeEnvelope.getBlock(modulationSpan);
-    applyGain<float>(modulationSpan, leftBuffer);
+        applyGain<float>(modulationSpan, leftBuffer);
 
-    // Filtering and EQ
+        // AmpEG envelope
-    const float* inputChannel[1] { leftBuffer.data() };
+        egEnvelope.getBlock(modulationSpan);
-    float* outputChannel[1] { leftBuffer.data() };
+        applyGain<float>(modulationSpan, leftBuffer);
-    for (auto& filter: filters) {
-        filter->process(inputChannel, outputChannel, numSamples);
     }
 
-    for (auto& eq: equalizers) {
+    { // Filtering and EQ
-        eq->process(inputChannel, outputChannel, numSamples);
+        ScopedLogger logger { [&](auto&& duration){ filterDuration = duration; } };
+
+        const float* inputChannel[1] { leftBuffer.data() };
+        float* outputChannel[1] { leftBuffer.data() };
+        for (auto& filter: filters) {
+            filter->process(inputChannel, outputChannel, numSamples);
+        }
+
+        for (auto& eq: equalizers) {
+            eq->process(inputChannel, outputChannel, numSamples);
+        }
     }
 
-    // Prepare for stereo output
+    { // Panning and stereo processing
-    copy<float>(leftBuffer, rightBuffer);
+        ScopedLogger logger { [&](auto&& duration){ panningDuration = duration; } };
 
-    // Apply panning
+        // Prepare for stereo output
-    panEnvelope.getBlock(modulationSpan);
+        copy<float>(leftBuffer, rightBuffer);
-    pan<float>(modulationSpan, leftBuffer, rightBuffer);
+
+        // Apply panning
+        panEnvelope.getBlock(modulationSpan);
+        pan<float>(modulationSpan, leftBuffer, rightBuffer);
+    }
 }
 
 void sfz::Voice::processStereo(AudioSpan<float> buffer) noexcept
@@ -317,38 +331,49 @@ void sfz::Voice::processStereo(AudioSpan<float> buffer) noexcept
     auto leftBuffer = buffer.getSpan(0);
     auto rightBuffer = buffer.getSpan(1);
 
-    // Amplitude envelope
+    { // Amplitude processing
-    amplitudeEnvelope.getBlock(modulationSpan);
+        ScopedLogger logger { [&](auto&& duration){ amplitudeDuration = duration; } };
-    buffer.applyGain(modulationSpan);
 
-    // Crossfade envelope
+        // Amplitude envelope
-    crossfadeEnvelope.getBlock(modulationSpan);
+        amplitudeEnvelope.getBlock(modulationSpan);
-    buffer.applyGain(modulationSpan);
+        buffer.applyGain(modulationSpan);
 
-    // Volume envelope
+        // Crossfade envelope
-    volumeEnvelope.getBlock(modulationSpan);
+        crossfadeEnvelope.getBlock(modulationSpan);
-    buffer.applyGain(modulationSpan);
+        buffer.applyGain(modulationSpan);
 
-    // AmpEG envelope
+        // Volume envelope
-    egEnvelope.getBlock(modulationSpan);
+        volumeEnvelope.getBlock(modulationSpan);
-    buffer.applyGain(modulationSpan);
+        buffer.applyGain(modulationSpan);
 
-    // Apply the width/position process
+        // AmpEG envelope
-    widthEnvelope.getBlock(modulationSpan);
+        egEnvelope.getBlock(modulationSpan);
-    width<float>(modulationSpan, leftBuffer, rightBuffer);
+        buffer.applyGain(modulationSpan);
-    positionEnvelope.getBlock(modulationSpan);
-    pan<float>(modulationSpan, leftBuffer, rightBuffer);
-
-    // Filtering and EQ
-    const float* inputChannels[2] { leftBuffer.data(), rightBuffer.data() };
-    float* outputChannels[2] { leftBuffer.data(), rightBuffer.data() };
-
-    for (auto& filter: filters) {
-        filter->process(inputChannels, outputChannels, numSamples);
     }
 
-    for (auto& eq: equalizers) {
+    { // Panning and stereo processing
-        eq->process(inputChannels, outputChannels, numSamples);
+        ScopedLogger logger { [&](auto&& duration){ panningDuration = duration; } };
+
+        // Apply the width/position process
+        widthEnvelope.getBlock(modulationSpan);
+        width<float>(modulationSpan, leftBuffer, rightBuffer);
+        positionEnvelope.getBlock(modulationSpan);
+        pan<float>(modulationSpan, leftBuffer, rightBuffer);
+    }
+
+    { // Filtering and EQ
+        ScopedLogger logger { [&](auto&& duration){ filterDuration = duration; } };
+
+        const float* inputChannels[2] { leftBuffer.data(), rightBuffer.data() };
+        float* outputChannels[2] { leftBuffer.data(), rightBuffer.data() };
+
+        for (auto& filter: filters) {
+            filter->process(inputChannels, outputChannels, numSamples);
+        }
+
+        for (auto& eq: equalizers) {
+            eq->process(inputChannels, outputChannels, numSamples);
+        }
     }
 }
 

src/sfizz/Voice.h

@@ -209,6 +209,12 @@ public:
      * @param numFilters
      */
     void setMaxEQsPerVoice(size_t numEQs);
+
+    Duration getLastDataDuration() const noexcept { return dataDuration; }
+    Duration getLastAmplitudeDuration() const noexcept { return amplitudeDuration; }
+    Duration getLastFilterDuration() const noexcept { return filterDuration; }
+    Duration getLastPanningDuration() const noexcept { return panningDuration; }
+
 private:
     /**
      * @brief Fill a span with data from a file source. This is the first step
@@ -301,6 +307,11 @@ private:
     MultiplicativeEnvelope<float> volumeEnvelope;
     float bendStepFactor { centsFactor(1) };
 
+    Duration dataDuration;
+    Duration amplitudeDuration;
+    Duration panningDuration;
+    Duration filterDuration;
+
     std::normal_distribution<float> noiseDist { 0, config::noiseVariance };
 
     HistoricalBuffer<float> powerHistory { config::powerHistoryLength };