Merge pull request #65 from paulfd/processing-logs

Processing logs

benchmarks/BM_clock.cpp

@@ -0,0 +1,51 @@
+// SPDX-License-Identifier: BSD-2-Clause
+
+// This code is part of the sfizz library and is licensed under a BSD 2-clause
+// license. You should have receive a LICENSE.md file along with the code.
+// If not, contact the sfizz maintainers at https://github.com/sfztools/sfizz
+
+#include <benchmark/benchmark.h>
+#include <chrono>
+
+class Clock : public benchmark::Fixture {
+public:
+  void SetUp(const ::benchmark::State& state) {
+
+  }
+
+  void TearDown(const ::benchmark::State& state [[maybe_unused]]) {
+
+  }
+
+  std::chrono::time_point<std::chrono::high_resolution_clock> hires;
+  std::chrono::time_point<std::chrono::steady_clock> steady;
+};
+
+
+BENCHMARK_DEFINE_F(Clock, HighRes)(benchmark::State& state) {
+    for (auto _ : state)
+    {
+        hires = std::chrono::high_resolution_clock::now();
+    }
+}
+
+BENCHMARK_DEFINE_F(Clock, Steady)(benchmark::State& state) {
+    for (auto _ : state)
+    {
+        steady = std::chrono::steady_clock::now();
+    }
+}
+
+// Just checking that stuff happens..
+BENCHMARK_DEFINE_F(Clock, Both)(benchmark::State& state) {
+    for (auto _ : state)
+    {
+        hires = std::chrono::high_resolution_clock::now();
+        steady = std::chrono::steady_clock::now();
+    }
+}
+
+BENCHMARK_REGISTER_F(Clock, HighRes);
+BENCHMARK_REGISTER_F(Clock, Steady);
+BENCHMARK_REGISTER_F(Clock, Both);
+BENCHMARK_MAIN();

benchmarks/BM_logger.cpp

@@ -0,0 +1,48 @@
+// SPDX-License-Identifier: BSD-2-Clause
+
+// This code is part of the sfizz library and is licensed under a BSD 2-clause
+// license. You should have receive a LICENSE.md file along with the code.
+// If not, contact the sfizz maintainers at https://github.com/sfztools/sfizz
+
+#include <benchmark/benchmark.h>
+#include "Logger.h"
+#include <chrono>
+
+class Logger : public benchmark::Fixture {
+public:
+  void SetUp(const ::benchmark::State& state) {
+
+  }
+
+  void TearDown(const ::benchmark::State& state [[maybe_unused]]) {
+
+  }
+
+};
+
+BENCHMARK_DEFINE_F(Logger, Baseline)(benchmark::State& state) {
+    for (auto _ : state)
+    {
+        sfz::Logger logger {};
+        benchmark::DoNotOptimize(logger);
+    }
+}
+
+BENCHMARK_DEFINE_F(Logger, ProcessingTime)(benchmark::State& state) {
+    for (auto _ : state)
+    {
+        sfz::Logger logger {};
+        sfz::CallbackBreakdown breakdown;
+        breakdown.data = sfz::Duration(1);
+        breakdown.renderMethod = sfz::Duration(1);
+        breakdown.dispatch = sfz::Duration(1);
+        breakdown.panning = sfz::Duration(1);
+        breakdown.filters = sfz::Duration(1);
+        breakdown.amplitude = sfz::Duration(1);
+        logger.logCallbackTime(std::move(breakdown), 16, 16);
+    }
+}
+
+BENCHMARK_REGISTER_F(Logger, Baseline);
+BENCHMARK_REGISTER_F(Logger, ProcessingTime);
+BENCHMARK_MAIN();

benchmarks/CMakeLists.txt

@@ -32,6 +32,7 @@ macro(sfizz_add_benchmark TARGET)
 endmacro()
 
 sfizz_add_benchmark(bm_opf_high_vs_low BM_OPF_high_vs_low.cpp)
+sfizz_add_benchmark(bm_clock BM_clock.cpp)
 sfizz_add_benchmark(bm_write BM_writeInterleaved.cpp)
 sfizz_add_benchmark(bm_read BM_readInterleaved.cpp)
 sfizz_add_benchmark(bm_fill BM_fill.cpp)
@@ -57,6 +58,9 @@ sfizz_add_benchmark(bm_widthPos BM_widthPos.cpp)
 sfizz_add_benchmark(bm_interpolationCast BM_interpolationCast.cpp)
 sfizz_add_benchmark(bm_pointerIterationOrOffsets BM_pointerIterationOrOffsets.cpp)
 
+sfizz_add_benchmark(bm_logger BM_logger.cpp)
+target_link_libraries(bm_logger PRIVATE sfizz::sfizz)
+
 if (TARGET sfizz-samplerate)
 	sfizz_add_benchmark(bm_resample BM_resample.cpp ${BENCHMARK_SIMD_SOURCES})
 	target_link_libraries(bm_resample PRIVATE sfizz-samplerate sfizz-sndfile)
@@ -86,6 +90,7 @@ add_custom_target(sfizz_benchmarks)
 add_dependencies(sfizz_benchmarks
 	bm_opf_high_vs_low
 	bm_write
+	bm_clock
 	bm_pointerIterationOrOffsets
 	bm_read
 	bm_mean
@@ -102,6 +107,7 @@ add_dependencies(sfizz_benchmarks
 	bm_ramp
 	bm_ADSR
 	bm_add
+	bm_logger
 	bm_pan
 	bm_subtract
 	bm_multiplyAdd

src/sfizz.h

@@ -361,6 +361,21 @@ SFIZZ_EXPORTED_API char* sfizz_get_unknown_opcodes(sfizz_synth_t* synth);
  */
 SFIZZ_EXPORTED_API bool sfizz_should_reload_file(sfizz_synth_t* synth);
 
+/**
+ * @brief Enable logging of timings to sidecar CSV files. This can produce
+ * many outputs so use with caution.
+ *
+ * @param synth
+ */
+SFIZZ_EXPORTED_API void sfizz_enable_logging(sfizz_synth_t* synth);
+
+/**
+ * @brief Disable logging
+ *
+ * @param synth
+ */
+SFIZZ_EXPORTED_API void sfizz_disable_logging(sfizz_synth_t* synth);
+
 #ifdef __cplusplus
 }
 #endif

src/sfizz.hpp

@@ -248,6 +248,17 @@ public:
      * @return false
      */
     bool shouldReloadFile();
+    /**
+     * @brief Enable logging of timings to sidecar CSV files. This can produce
+     * many outputs so use with caution.
+     *
+     */
+    void enableLogging() noexcept;
+    /**
+     * @brief Disable logging;
+     *
+     */
+    void disableLogging() noexcept;
 private:
     std::unique_ptr<sfz::Synth> synth;
 };

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/FilePool.cpp

@@ -324,8 +324,6 @@ void sfz::FilePool::loadingThread() noexcept
 
         threadsLoading--;
 
-
-
         while (!filledPromiseQueue.try_push(promise)) {
             DBG("[sfizz] Error enqueuing the promise for " << promise->filename << " in the filledPromiseQueue");
             std::this_thread::sleep_for(1ms);

src/sfizz/Logger.cpp

@@ -65,7 +65,7 @@ sfz::Logger::~Logger()
                         << prefix
                         << "_file_log.csv";
         fs::path fileLogPath{ fs::current_path() / fileLogFilename.str() };
-        DBG("Logging file times to " << fileLogPath.filename());
+        std::cout << "Logging " << fileTimes.size() << " file times to " << fileLogPath.filename() << '\n';
         std::ofstream loadLogFile { fileLogPath.string() };
         loadLogFile << "WaitDuration,LoadDuration,FileSize,FileName" << '\n';
         for (auto& time: fileTimes)
@@ -81,23 +81,28 @@ sfz::Logger::~Logger()
                             << prefix
                             << "_callback_log.csv";
         fs::path callbackLogPath{ fs::current_path() / callbackLogFilename.str() };
-        DBG("Logging callback times to " << callbackLogPath.filename());
+        std::cout << "Logging " << callbackTimes.size() << " callback times to " << callbackLogPath.filename() << '\n';
         std::ofstream callbackLogFile { callbackLogPath.string() };
-        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,22 @@ void sfz::Logger::disableLogging()
     loggingEnabled = false;
     clearFlag.clear();
 }
+
+sfz::ScopedTiming::ScopedTiming(Duration& targetDuration, Operation operation)
+: targetDuration(targetDuration), operation(operation)
+{
+
+}
+
+sfz::ScopedTiming::~ScopedTiming()
+{
+    switch(operation)
+    {
+    case(Operation::replaceDuration):
+        targetDuration = std::chrono::high_resolution_clock::now() - creationTime;
+        break;
+    case(Operation::addToDuration):
+        targetDuration += std::chrono::high_resolution_clock::now() - creationTime;
+        break;
+    }
+}

src/sfizz/Logger.h

@@ -10,23 +10,62 @@
 #include <vector>
 #include <string>
 #include <chrono>
+#include <functional>
 #include <thread>
 #include "absl/strings/string_view.h"
 
 namespace sfz
 {
 
+using Duration = std::chrono::duration<double>;
+
+/**
+ * @brief Creates an RAII logger which fills or adds to a duration on destruction
+ *
+ */
+struct ScopedTiming
+{
+    using TimePoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
+    enum class Operation
+    {
+        addToDuration,
+        replaceDuration
+    };
+    ScopedTiming() = delete;
+    /**
+     * @brief Construct a new Scoped Logger object
+     *
+     * @param targetDuration
+     * @param op
+     */
+    ScopedTiming(Duration& targetDuration, Operation op = Operation::replaceDuration);
+    ~ScopedTiming();
+    Duration& targetDuration;
+    const Operation operation;
+    const TimePoint creationTime { std::chrono::high_resolution_clock::now() };
+};
+
 struct FileTime
 {
-    std::chrono::duration<double> waitDuration;
-    std::chrono::duration<double> loadDuration;
+    Duration waitDuration;
+    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;
 };
@@ -36,13 +75,53 @@ class Logger
 public:
     Logger();
     ~Logger();
+    /**
+     * @brief Set the prefix for the output log files
+     *
+     * @param prefix
+     */
     void setPrefix(const std::string& prefix);
+
+    /**
+     * @brief Removes all logged data
+     *
+     */
     void clear();
+
+    /**
+     * @brief Enables logging and writing to log files on destruction
+     *
+     */
     void enableLogging();
+
+    /**
+     * @brief Disables logging and writing to log files on destruction
+     *
+     */
     void disableLogging();
-    void logCallbackTime(std::chrono::duration<double> duration, int numVoices, size_t numSamples);
-    void logFileTime(std::chrono::duration<double> waitDuration, std::chrono::duration<double> loadDuration, uint32_t fileSize, absl::string_view filename);
+
+    /**
+     * @brief Logs the callback duration, with breakdown per operations
+     *
+     * @param breakdown The different timings for the callback
+     * @param numVoices The number of active voices
+     * @param numSamples The number of samples in the callback
+     */
+    void logCallbackTime(CallbackBreakdown&& breakdown, int numVoices, size_t numSamples);
+
+    /**
+     * @brief Log a file loading and waiting duration
+     *
+     * @param waitDuration The time spent waiting before loading the file
+     * @param loadDuration The time it took to load the file
+     * @param fileSize The file size
+     * @param filename The file name
+     */
+    void logFileTime(Duration waitDuration, Duration loadDuration, uint32_t fileSize, absl::string_view filename);
 private:
+    /**
+     * @brief Move all events from the real time queues to the non-realtime vectors
+     */
     void moveEvents() noexcept;
     bool loggingEnabled { config::loggingEnabled };
     std::string prefix { "" };

src/sfizz/Synth.cpp

@@ -410,11 +410,7 @@ void sfz::Synth::setSampleRate(float sampleRate) noexcept
 void sfz::Synth::renderBlock(AudioSpan<float> buffer) noexcept
 {
     ScopedFTZ ftz;
-    const auto callbackStartTime = std::chrono::high_resolution_clock::now();
 
-    buffer.fill(0.0f);
-
-    resources.filePool.cleanupPromises();
 
     if (freeWheeling)
         resources.filePool.waitForBackgroundLoading();
@@ -423,20 +419,35 @@ void sfz::Synth::renderBlock(AudioSpan<float> buffer) noexcept
     if (!canEnterCallback)
         return;
 
-    auto tempSpan = AudioSpan<float>(tempBuffer).first(buffer.getNumFrames());
+    CallbackBreakdown callbackBreakdown;
     int numActiveVoices { 0 };
-    for (auto& voice : voices) {
-        if (!voice->isFree()) {
-            numActiveVoices++;
-            voice->renderBlock(tempSpan);
-            buffer.add(tempSpan);
+    { // Main render block
+        ScopedTiming logger { callbackBreakdown.renderMethod };
+        buffer.fill(0.0f);
+        resources.filePool.cleanupPromises();
+
+
+        auto tempSpan = AudioSpan<float>(tempBuffer).first(buffer.getNumFrames());
+        for (auto& voice : voices) {
+            if (!voice->isFree()) {
+                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));
     }
 
-    buffer.applyGain(db2mag(volume));
+    callbackBreakdown.dispatch = dispatchDuration;
+    resources.logger.logCallbackTime(std::move(callbackBreakdown), numActiveVoices, buffer.getNumFrames());
 
-    const auto callbackDuration = std::chrono::high_resolution_clock::now() - callbackStartTime;
-    resources.logger.logCallbackTime(callbackDuration, numActiveVoices, buffer.getNumFrames());
+    // Reset the dispatch counter
+    dispatchDuration = Duration(0);
 }
 
 void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept
@@ -444,6 +455,7 @@ void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept
     ASSERT(noteNumber < 128);
     ASSERT(noteNumber >= 0);
 
+    ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration };
     resources.midiState.noteOnEvent(noteNumber, velocity);
 
     AtomicGuard callbackGuard { inCallback };
@@ -458,6 +470,7 @@ void sfz::Synth::noteOff(int delay, int noteNumber, uint8_t velocity [[maybe_unu
     ASSERT(noteNumber < 128);
     ASSERT(noteNumber >= 0);
 
+    ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration };
     resources.midiState.noteOffEvent(noteNumber, velocity);
 
     AtomicGuard callbackGuard { inCallback };
@@ -513,6 +526,8 @@ void sfz::Synth::cc(int delay, int ccNumber, uint8_t ccValue) noexcept
     ASSERT(ccNumber < config::numCCs);
     ASSERT(ccNumber >= 0);
 
+    ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration };
+
     resources.midiState.ccEvent(ccNumber, ccValue);
 
     AtomicGuard callbackGuard { inCallback };
@@ -543,6 +558,8 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept
     ASSERT(pitch <= 8192);
     ASSERT(pitch >= -8192);
 
+    ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration };
+
     resources.midiState.pitchBendEvent(pitch);
 
     for (auto& region: regions) {
@@ -555,10 +572,11 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept
 }
 void sfz::Synth::aftertouch(int /* delay */, uint8_t /* aftertouch */) noexcept
 {
+    ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration };
 }
 void sfz::Synth::tempo(int /* delay */, float /* secondsPerQuarter */) noexcept
 {
-
+    ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration };
 }
 
 int sfz::Synth::getNumRegions() const noexcept
@@ -806,3 +824,13 @@ bool sfz::Synth::shouldReloadFile()
 {
     return (checkModificationTime() > modificationTime);
 }
+
+void sfz::Synth::enableLogging() noexcept
+{
+    resources.logger.enableLogging();
+}
+
+void sfz::Synth::disableLogging() noexcept
+{
+    resources.logger.disableLogging();
+}

src/sfizz/Synth.h

@@ -340,6 +340,17 @@ public:
      * @return false
      */
     bool shouldReloadFile();
+    /**
+     * @brief Enable logging of timings to sidecar CSV files. This can produce
+     * many outputs so use with caution.
+     *
+     */
+    void enableLogging() noexcept;
+    /**
+     * @brief Disable logging;
+     *
+     */
+    void disableLogging() noexcept;
 protected:
     /**
      * @brief The parser callback; this is called by the parent object each time
@@ -456,6 +467,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())
-        fillWithGenerator(delayed_buffer);
-    else
-        fillWithData(delayed_buffer);
+    { // Fill buffer with raw data
+        ScopedTiming logger { dataDuration };
+        if (region->isGenerator())
+            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
-    amplitudeEnvelope.getBlock(modulationSpan);
-    applyGain<float>(modulationSpan, leftBuffer);
+    { // Amplitude processing
+        ScopedTiming logger { amplitudeDuration };
 
-    // Crossfade envelope
-    crossfadeEnvelope.getBlock(modulationSpan);
-    applyGain<float>(modulationSpan, leftBuffer);
+        // Amplitude envelope
+        amplitudeEnvelope.getBlock(modulationSpan);
+        applyGain<float>(modulationSpan, leftBuffer);
 
-    // Volume envelope
-    volumeEnvelope.getBlock(modulationSpan);
-    applyGain<float>(modulationSpan, leftBuffer);
+        // Crossfade envelope
+        crossfadeEnvelope.getBlock(modulationSpan);
+        applyGain<float>(modulationSpan, leftBuffer);
 
-    // AmpEG envelope
-    egEnvelope.getBlock(modulationSpan);
-    applyGain<float>(modulationSpan, leftBuffer);
+        // Volume envelope
+        volumeEnvelope.getBlock(modulationSpan);
+        applyGain<float>(modulationSpan, leftBuffer);
 
-    // Filtering and EQ
-    const float* inputChannel[1] { leftBuffer.data() };
-    float* outputChannel[1] { leftBuffer.data() };
-    for (auto& filter: filters) {
-        filter->process(inputChannel, outputChannel, numSamples);
+        // AmpEG envelope
+        egEnvelope.getBlock(modulationSpan);
+        applyGain<float>(modulationSpan, leftBuffer);
     }
 
-    for (auto& eq: equalizers) {
-        eq->process(inputChannel, outputChannel, numSamples);
+    { // Filtering and EQ
+        ScopedTiming logger { filterDuration };
+
+        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
-    copy<float>(leftBuffer, rightBuffer);
+    { // Panning and stereo processing
+        ScopedTiming logger { panningDuration };
 
-    // Apply panning
-    panEnvelope.getBlock(modulationSpan);
-    pan<float>(modulationSpan, leftBuffer, rightBuffer);
+        // Prepare for stereo output
+        copy<float>(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
-    amplitudeEnvelope.getBlock(modulationSpan);
-    buffer.applyGain(modulationSpan);
+    { // Amplitude processing
+        ScopedTiming logger { amplitudeDuration };
 
-    // Crossfade envelope
-    crossfadeEnvelope.getBlock(modulationSpan);
-    buffer.applyGain(modulationSpan);
+        // Amplitude envelope
+        amplitudeEnvelope.getBlock(modulationSpan);
+        buffer.applyGain(modulationSpan);
 
-    // Volume envelope
-    volumeEnvelope.getBlock(modulationSpan);
-    buffer.applyGain(modulationSpan);
+        // Crossfade envelope
+        crossfadeEnvelope.getBlock(modulationSpan);
+        buffer.applyGain(modulationSpan);
 
-    // AmpEG envelope
-    egEnvelope.getBlock(modulationSpan);
-    buffer.applyGain(modulationSpan);
+        // Volume envelope
+        volumeEnvelope.getBlock(modulationSpan);
+        buffer.applyGain(modulationSpan);
 
-    // Apply the width/position process
-    widthEnvelope.getBlock(modulationSpan);
-    width<float>(modulationSpan, leftBuffer, rightBuffer);
-    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);
+        // AmpEG envelope
+        egEnvelope.getBlock(modulationSpan);
+        buffer.applyGain(modulationSpan);
     }
 
-    for (auto& eq: equalizers) {
-        eq->process(inputChannels, outputChannels, numSamples);
+    { // Panning and stereo processing
+        ScopedTiming logger { panningDuration };
+
+        // Apply the width/position process
+        widthEnvelope.getBlock(modulationSpan);
+        width<float>(modulationSpan, leftBuffer, rightBuffer);
+        positionEnvelope.getBlock(modulationSpan);
+        pan<float>(modulationSpan, leftBuffer, rightBuffer);
+    }
+
+    { // Filtering and EQ
+        ScopedTiming logger { filterDuration };
+
+        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 };

src/sfizz/sfizz.cpp

@@ -184,3 +184,13 @@ bool sfz::Sfizz::shouldReloadFile()
 {
     return synth->shouldReloadFile();
 }
+
+void sfz::Sfizz::enableLogging() noexcept
+{
+    synth->enableLogging();
+}
+
+void sfz::Sfizz::disableLogging() noexcept
+{
+    synth->disableLogging();
+}

src/sfizz/sfizz_wrapper.cpp

@@ -232,6 +232,17 @@ bool sfizz_should_reload_file(sfizz_synth_t* synth)
     return self->shouldReloadFile();
 }
 
+void sfizz_enable_logging(sfizz_synth_t* synth)
+{
+    auto self = reinterpret_cast<sfz::Synth*>(synth);
+    return self->enableLogging();
+}
+void sfizz_disable_logging(sfizz_synth_t* synth)
+{
+    auto self = reinterpret_cast<sfz::Synth*>(synth);
+    return self->disableLogging();
+}
+
 #ifdef __cplusplus
 }
 #endif