Merge pull request #1034 from paulfd/logger-api

Logging is not implicitely handled by the synth

clients/sfizz_render.cpp

@@ -8,6 +8,7 @@
 #include <cxxopts.hpp>
 #include <fmidi/fmidi.h>
 #include <iostream>
+#include <fstream>
 
 #define LOG_ERROR(ostream) std::cerr  << ostream << '\n'
 #define LOG_INFO(ostream) if (verbose) { std::cout << ostream << '\n'; }
@@ -125,8 +126,38 @@ int main(int argc, char** argv)
     synth.setNumVoices(polyphony);
     synth.enableFreeWheeling();
 
-    if (params.count("log") > 0)
+    bool logging = params.count("log") > 0;
-        synth.enableLogging(params["log"].as<std::string>());
+    std::string logFilename {};
+    std::ofstream callbackLogFile {};
+    if (logging) {
+        logFilename = params["log"].as<std::string>();
+        fs::path logPath{ fs::current_path() / logFilename };
+        callbackLogFile.open(logPath.string());
+
+        if (callbackLogFile.is_open()) {
+            callbackLogFile << "Dispatch,RenderMethod,Data,Amplitude,Filters,Panning,Effects,NumVoices,NumSamples" << '\n';
+        } else {
+            logging = false;
+            LOG_INFO("Error opening log file " << logPath.string() << "; logging will be disabled");
+        }
+    }
+
+    auto writeLogLine = [&] {
+        if (!logging)
+            return;
+
+        auto breakdown = synth.getCallbackBreakdown();
+        auto numVoices = synth.getNumActiveVoices();
+        callbackLogFile << breakdown.dispatch << ','
+                        << breakdown.renderMethod << ','
+                        << breakdown.data << ','
+                        << breakdown.amplitude << ','
+                        << breakdown.filters << ','
+                        << breakdown.panning << ','
+                        << breakdown.effects << ','
+                        << numVoices << ','
+                        << blockSize << '\n';
+    };
 
     ERROR_IF(!synth.loadSfzFile(sfzPath), "There was an error loading the SFZ file.");
     LOG_INFO(synth.getNumRegions() << " regions in the SFZ.");
@@ -178,6 +209,7 @@ int main(int argc, char** argv)
         sfz::writeInterleaved(audioBuffer.getConstSpan(0), audioBuffer.getConstSpan(1), absl::MakeSpan(interleavedBuffer));
         drwav_f32_to_s16(interleavedPcm.data(), interleavedBuffer.data(), 2 * blockSize);
         numFramesWritten += drwav_write_pcm_frames(&outputFile, blockSize, interleavedPcm.data());
+        writeLogLine();
     }
 
     if (!useEOT) {
@@ -187,6 +219,7 @@ int main(int argc, char** argv)
             sfz::writeInterleaved(audioBuffer.getConstSpan(0), audioBuffer.getConstSpan(1), absl::MakeSpan(interleavedBuffer));
             drwav_f32_to_s16(interleavedPcm.data(), interleavedBuffer.data(), 2 * blockSize);
             numFramesWritten += drwav_write_pcm_frames(&outputFile, blockSize, interleavedPcm.data());
+            writeLogLine();
             averagePower = sfz::meanSquared<float>(interleavedBuffer);
         }
     }

common.mk

@@ -91,7 +91,6 @@ SFIZZ_SOURCES = \
 	src/sfizz/FlexEnvelope.cpp \
 	src/sfizz/Interpolators.cpp \
 	src/sfizz/Layer.cpp \
-	src/sfizz/Logger.cpp \
 	src/sfizz/LFO.cpp \
 	src/sfizz/LFODescription.cpp \
 	src/sfizz/Messaging.cpp \

scripts/run_clang_tidy.sh

@@ -7,7 +7,6 @@ clang-tidy \
   src/sfizz/EQPool.cpp \
   src/sfizz/FilePool.cpp \
   src/sfizz/FilterPool.cpp \
-  src/sfizz/Logger.cpp \
   src/sfizz/MidiState.cpp \
   src/sfizz/Opcode.cpp \
   src/sfizz/Oversampler.cpp \

src/CMakeLists.txt

@@ -29,6 +29,7 @@ set(SFIZZ_HEADERS
     sfizz/utility/NumericId.h
     sfizz/utility/StringViewHelpers.h
     sfizz/utility/SwapAndPop.h
+    sfizz/utility/Timing.h
     sfizz/utility/XmlHelpers.h
     sfizz/modulations/ModId.h
     sfizz/modulations/ModKey.h
@@ -76,7 +77,6 @@ set(SFIZZ_HEADERS
     sfizz/Interpolators.h
     sfizz/Interpolators.hpp
     sfizz/Layer.h
-    sfizz/Logger.h
     sfizz/LFO.h
     sfizz/LFOCommon.h
     sfizz/LFOCommon.hpp
@@ -137,7 +137,6 @@ set(SFIZZ_SOURCES
     sfizz/MidiState.cpp
     sfizz/Oversampler.cpp
     sfizz/ADSREnvelope.cpp
-    sfizz/Logger.cpp
     sfizz/SfzFilter.cpp
     sfizz/Curve.cpp
     sfizz/Smoothers.cpp

src/sfizz.h

@@ -971,6 +971,7 @@ SFIZZ_EXPORTED_API bool sfizz_should_reload_scala(sfizz_synth_t* synth);
  * @since 0.3.0
  *
  * @note This can produce many outputs so use with caution.
+ *  Deprecated since 1.2.0.
  *
  * @param synth  The synth.
  * @param prefix The prefix.
@@ -978,24 +979,26 @@ SFIZZ_EXPORTED_API bool sfizz_should_reload_scala(sfizz_synth_t* synth);
  * @par Thread-safety constraints
  * - TBD ?
  */
-SFIZZ_EXPORTED_API void sfizz_enable_logging(sfizz_synth_t* synth, const char* prefix);
+SFIZZ_EXPORTED_API SFIZZ_DEPRECATED_API void sfizz_enable_logging(sfizz_synth_t* synth, const char* prefix);
 
 /**
  * @brief Disable logging.
  * @since 0.3.0
  *
  * @param synth  The synth.
+ *  Deprecated since 1.2.0.
  *
  * @par Thread-safety constraints
  * - TBD ?
  */
-SFIZZ_EXPORTED_API void sfizz_disable_logging(sfizz_synth_t* synth);
+SFIZZ_EXPORTED_API SFIZZ_DEPRECATED_API void sfizz_disable_logging(sfizz_synth_t* synth);
 
 /**
  * @brief Enable logging of timings to sidecar CSV files.
  * @since 0.3.2
  *
  * @note This can produce many outputs so use with caution.
+ *  Deprecated since 1.2.0.
  *
  * @param synth  The synth.
  * @param prefix The prefix.
@@ -1005,6 +1008,36 @@ SFIZZ_EXPORTED_API void sfizz_disable_logging(sfizz_synth_t* synth);
  */
 SFIZZ_EXPORTED_API SFIZZ_DEPRECATED_API void sfizz_set_logging_prefix(sfizz_synth_t* synth, const char* prefix);
 
+/**
+ * @brief The callback breakdown structure.
+ * @note Times are in seconds.
+ */
+typedef struct
+{
+    double dispatch;
+    double renderMethod;
+    double data;
+    double amplitude;
+    double filters;
+    double panning;
+    double effects;
+} sfizz_callback_breakdown_t;
+
+/**
+ * @brief Get the last callback breakdown. Call after a render method.
+ *
+ * @since 1.2.0
+ *
+ * @param synth
+ * @param breakdown
+ *
+ * @return CallbackBreakdown
+ *
+ * @par Thread-safety constraints
+ * - @b RT: the function must be invoked from the Real-time thread
+ */
+SFIZZ_EXPORTED_API void sfizz_get_callback_breakdown(sfizz_synth_t* synth, sfizz_callback_breakdown_t* breakdown);
+
 /**
  * @brief Shuts down the current processing, clear buffers and reset the voices.
  * @since 0.3.2

src/sfizz.hpp

@@ -910,21 +910,24 @@ public:
      * @since 0.3.2
      *
      * @note This can produce many outputs so use with caution.
+     * Deprecated since 1.2.0
      *
      * @param prefix the file prefix to use for logging.
      *
      * @par Thread-safety constraints
      * - TBD ?
      */
-    void enableLogging(const std::string& prefix) noexcept;
+    SFIZZ_DEPRECATED_API void enableLogging(const std::string& prefix) noexcept;
 
     /**
      * @brief Set the logging prefix.
      *
      * @since 0.3.2
+     * @note Deprecated since 1.2.0
      *
      * @param prefix
      *
+     *
      * @par Thread-safety constraints
      * - TBD ?
      */
@@ -934,11 +937,35 @@ public:
      * @brief Disable logging of timings to sidecar CSV files.
      *
      * @since 0.3.0
+     * @note Deprecated since 1.2.0
      *
      * @par Thread-safety constraints
      * - TBD ?
      */
-    void disableLogging() noexcept;
+    SFIZZ_DEPRECATED_API void disableLogging() noexcept;
+
+    struct CallbackBreakdown
+    {
+        double dispatch;
+        double renderMethod;
+        double data;
+        double amplitude;
+        double filters;
+        double panning;
+        double effects;
+    };
+
+    /**
+     * @brief Get the last callback breakdown. Call after a render method.
+     *
+     * @since 1.2.0
+     *
+     * @par Thread-safety constraints
+     * - @b RT: the function must be invoked from the Real-time thread
+     *
+     * @return CallbackBreakdown
+     */
+    CallbackBreakdown getCallbackBreakdown() noexcept;
 
     /**
      * @brief Shuts down the current processing, clear buffers and reset the voices.

src/sfizz/FilePool.cpp

@@ -140,9 +140,8 @@ void streamFromFile(sfz::AudioReader& reader, sfz::FileAudioBuffer& output, std:
     }
 }
 
-sfz::FilePool::FilePool(sfz::Logger& logger)
+sfz::FilePool::FilePool()
-    : logger(logger),
+    : filesToLoad(alignedNew<FileQueue>()),
-      filesToLoad(alignedNew<FileQueue>()),
       threadPool(globalThreadPool())
 {
     loadingJobs.reserve(config::maxVoices);
@@ -396,7 +395,7 @@ sfz::FileDataHolder sfz::FilePool::getFilePromise(const std::shared_ptr<FileId>&
         DBG("[sfizz] File not found in the preloaded files: " << fileId->filename());
         return {};
     }
-    QueuedFileData queuedData { fileId, &preloaded->second, std::chrono::high_resolution_clock::now() };
+    QueuedFileData queuedData { fileId, &preloaded->second };
     if (!filesToLoad->try_push(queuedData)) {
         DBG("[sfizz] Could not enqueue the file to load for " << fileId << " (queue capacity " << filesToLoad->capacity() << ")");
         return {};
@@ -434,8 +433,6 @@ void sfz::FilePool::loadingJob(const QueuedFileData& data) noexcept
         return;
     }
 
-    const auto loadStartTime = std::chrono::high_resolution_clock::now();
-    const auto waitDuration = loadStartTime - data.queuedTime;
     const fs::path file { rootDirectory / id->filename() };
     std::error_code readError;
     AudioReaderPtr reader = createAudioReader(file, id->isReverse(), &readError);
@@ -468,10 +465,7 @@ void sfz::FilePool::loadingJob(const QueuedFileData& data) noexcept
     if (!data.data->status.compare_exchange_strong(currentStatus, FileData::Status::Streaming))
         return;
 
-    const auto frames = static_cast<uint32_t>(reader->frames());
     streamFromFile(*reader, data.data->fileData, &data.data->availableFrames);
-    const auto loadDuration = std::chrono::high_resolution_clock::now() - loadStartTime;
-    logger.logFileTime(waitDuration, loadDuration, frames, id->filename());
 
     data.data->status = FileData::Status::Done;
 

src/sfizz/FilePool.h

@@ -32,8 +32,8 @@
 #include "FileId.h"
 #include "FileMetadata.h"
 #include "SIMDHelpers.h"
-#include "Logger.h"
 #include "SpinMutex.h"
+#include "utility/Timing.h"
 #include "utility/LeakDetector.h"
 #include "utility/MemoryHelpers.h"
 #include <ghc/fs_std.hpp>
@@ -148,7 +148,7 @@ public:
             return;
 
         data->readerCount -= 1;
-        data->lastViewerLeftAt = std::chrono::high_resolution_clock::now();
+        data->lastViewerLeftAt = highResNow();
         data = nullptr;
     }
     ~FileDataHolder()
@@ -192,7 +192,7 @@ public:
      * This creates the background threads based on config::numBackgroundThreads
      * as well as the garbage collection thread.
      */
-    FilePool(Logger& logger);
+    FilePool();
 
     ~FilePool();
     /**
@@ -325,7 +325,6 @@ public:
      */
     void triggerGarbageCollection() noexcept;
 private:
-    Logger& logger;
     fs::path rootDirectory;
 
     bool loadInRam { config::loadInRam };
@@ -340,13 +339,11 @@ private:
     // Structures for the background loaders
     struct QueuedFileData
     {
-        using TimePoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
         QueuedFileData() noexcept {}
-        QueuedFileData(std::weak_ptr<FileId> id, FileData* data, TimePoint queuedTime) noexcept
+        QueuedFileData(std::weak_ptr<FileId> id, FileData* data) noexcept
-        : id(id), data(data), queuedTime(queuedTime) {}
+        : id(id), data(data) {}
         std::weak_ptr<FileId> id;
         FileData* data { nullptr };
-        TimePoint queuedTime {};
     };
 
     using FileQueue = atomic_queue::AtomicQueue2<QueuedFileData, config::maxVoices>;

src/sfizz/Logger.cpp

@@ -1,186 +0,0 @@
-// 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 "Logger.h"
-#include "utility/Debug.h"
-#include <ghc/fs_std.hpp>
-#include <absl/algorithm/container.h>
-#include <iostream>
-#include <fstream>
-#include <sstream>
-#include <cmath>
-
-template<class T>
-void printStatistics(std::vector<T>& data)
-{
-    absl::c_sort(data);
-    const auto maxToTake = std::min(data.size(), size_t(10));
-    std::vector<T> maxValues;
-    auto it = data.rbegin();
-    for (size_t i = 0; i < maxToTake; ++i)
-        maxValues.push_back(*it++);
-
-    const auto sum = absl::c_accumulate(data, 0.0);
-    const auto size = static_cast<T>(data.size());
-    const auto mean = sum / size;
-    std::cout << "Mean: " << mean << '\n';
-    if (data.size() > 1) {
-        std::vector<T> squares;
-        absl::c_transform(data, std::back_inserter(squares), [mean](T x) { return x * x; });
-        const auto sumOfSquares = absl::c_accumulate(squares, 0.0);
-        const auto variance = sumOfSquares / (size - 1.0) - (mean * mean) / size / (size - 1.0);
-        std::cout << "Variance: " << variance << '\n';
-        std::cout << "(Biased) deviation: " << std::sqrt(variance) << '\n';
-    }
-
-    std::cout << "Maximum values:";
-    for (auto& value: maxValues)
-        std::cout << value << ' ';
-    std::cout << '\n';
-}
-
-sfz::Logger::Logger()
-    : callbackTimeQueue(alignedNew<CallbackTimeQueue>()),
-      fileTimeQueue(alignedNew<FileTimeQueue>())
-{
-    keepRunning.test_and_set();
-    clearFlag.test_and_set();
-    loggingThread = std::thread(&Logger::moveEvents, this);
-}
-
-sfz::Logger::~Logger()
-{
-    keepRunning.clear();
-    loggingThread.join();
-
-    if (!loggingEnabled)
-        return;
-
-    if (!fileTimes.empty()) {
-        std::stringstream fileLogFilename;
-        fileLogFilename << this << "_"
-                        << prefix
-                        << "_file_log.csv";
-        fs::path fileLogPath{ fs::current_path() / fileLogFilename.str() };
-        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)
-            loadLogFile << time.waitDuration.count() << ','
-                        << time.loadDuration.count() << ','
-                        << time.fileSize << ','
-                        << "disabled" << '\n';
-                        // << time.filename << '\n';
-    }
-
-    if (!callbackTimes.empty()) {
-        std::stringstream callbackLogFilename;
-        callbackLogFilename << this << "_"
-                            << prefix
-                            << "_callback_log.csv";
-        fs::path callbackLogPath{ fs::current_path() / callbackLogFilename.str() };
-        std::cout << "Logging " << callbackTimes.size() << " callback times to " << callbackLogPath.filename() << '\n';
-        std::ofstream callbackLogFile { callbackLogPath.string() };
-        callbackLogFile << "Dispatch,RenderMethod,Data,Amplitude,Filters,Panning,Effects,NumVoices,NumSamples" << '\n';
-        for (auto& time: callbackTimes)
-            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.breakdown.effects.count() << ','
-                            << time.numVoices << ','
-                            << time.numSamples << '\n';
-    }
-}
-
-
-void sfz::Logger::logCallbackTime(const CallbackBreakdown& breakdown, int numVoices, size_t numSamples)
-{
-    if (!loggingEnabled)
-        return;
-
-    CallbackTime callbackTime;
-    callbackTime.breakdown = breakdown;
-    callbackTime.numVoices = numVoices;
-    callbackTime.numSamples = numSamples;
-    callbackTimeQueue->try_push(callbackTime);
-}
-
-void sfz::Logger::logFileTime(std::chrono::duration<double> waitDuration, std::chrono::duration<double> loadDuration, uint32_t fileSize, absl::string_view filename)
-{
-    if (!loggingEnabled)
-        return;
-
-    FileTime fileTime;
-    fileTime.waitDuration = waitDuration;
-    fileTime.loadDuration = loadDuration;
-    fileTime.fileSize = fileSize;
-    fileTime.filename = filename;
-    fileTimeQueue->try_push(fileTime);
-}
-
-void sfz::Logger::setPrefix(absl::string_view prefix)
-{
-    this->prefix = std::string(prefix);
-}
-
-void sfz::Logger::clear()
-{
-    clearFlag.clear();
-}
-
-void sfz::Logger::moveEvents() noexcept
-{
-    while(keepRunning.test_and_set()) {
-        CallbackTime callbackTime;
-        while (callbackTimeQueue->try_pop(callbackTime))
-            callbackTimes.push_back(callbackTime);
-
-        FileTime fileTime;
-        while (fileTimeQueue->try_pop(fileTime))
-            fileTimes.push_back(fileTime);
-
-        if (!clearFlag.test_and_set()) {
-            fileTimes.clear();
-            callbackTimes.clear();
-        }
-
-        std::this_thread::sleep_for(std::chrono::milliseconds(10));
-    }
-}
-
-void sfz::Logger::enableLogging(absl::string_view prefix)
-{
-    setPrefix(prefix);
-    loggingEnabled = true;
-}
-
-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

@@ -1,150 +0,0 @@
-// 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
-
-#pragma once
-#include "Config.h"
-#include "utility/LeakDetector.h"
-#include "utility/MemoryHelpers.h"
-#include <atomic_queue/atomic_queue.h>
-#include <absl/strings/string_view.h>
-#include <vector>
-#include <string>
-#include <chrono>
-#include <functional>
-#include <thread>
-#include <memory>
-
-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
-{
-    Duration waitDuration { 0 };
-    Duration loadDuration { 0 };
-    uint32_t fileSize { 0 };
-    absl::string_view filename {};
-    LEAK_DETECTOR(FileTime);
-};
-
-struct CallbackBreakdown
-{
-    Duration dispatch { 0 };
-    Duration renderMethod { 0 };
-    Duration data { 0 };
-    Duration amplitude { 0 };
-    Duration filters { 0 };
-    Duration panning { 0 };
-    Duration effects { 0 };
-    LEAK_DETECTOR(CallbackBreakdown);
-};
-
-struct CallbackTime
-{
-    CallbackBreakdown breakdown {};
-    int numVoices { 0 };
-    size_t numSamples { 0 };
-    LEAK_DETECTOR(CallbackTime);
-};
-
-class Logger
-{
-public:
-    Logger();
-    ~Logger();
-    /**
-     * @brief Set the prefix for the output log files
-     *
-     * @param prefix
-     */
-    void setPrefix(absl::string_view prefix);
-
-    /**
-     * @brief Removes all logged data
-     *
-     */
-    void clear();
-
-    /**
-     * @brief Enables logging and writing to log files on destruction
-     *
-     */
-    void enableLogging(absl::string_view prefix);
-
-    /**
-     * @brief Disables logging and writing to log files on destruction
-     *
-     */
-    void disableLogging();
-
-    /**
-     * @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(const 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 { "" };
-
-    using CallbackTimeQueue = atomic_queue::AtomicQueue2<CallbackTime, config::loggerQueueSize, true, true, false, true>;
-    using FileTimeQueue = atomic_queue::AtomicQueue2<FileTime, config::loggerQueueSize, true, true, false, true>;
-
-    aligned_unique_ptr<CallbackTimeQueue> callbackTimeQueue;
-    aligned_unique_ptr<FileTimeQueue> fileTimeQueue;
-    std::vector<CallbackTime> callbackTimes;
-    std::vector<FileTime> fileTimes;
-
-    std::atomic_flag keepRunning;
-    std::atomic_flag clearFlag;
-    std::thread loggingThread;
-    LEAK_DETECTOR(Logger);
-};
-
-}

src/sfizz/Resources.cpp

@@ -9,7 +9,6 @@
 #include "MidiState.h"
 #include "FilePool.h"
 #include "BufferPool.h"
-#include "Logger.h"
 #include "Wavetables.h"
 #include "Curve.h"
 #include "Tuning.h"
@@ -23,9 +22,8 @@ struct Resources::Impl {
     SynthConfig synthConfig;
     BufferPool bufferPool;
     MidiState midiState;
-    Logger logger;
     CurveSet curves;
-    FilePool filePool { logger };
+    FilePool filePool;
     WavetablePool wavePool;
     Tuning tuning;
     absl::optional<StretchTuning> stretch;
@@ -67,7 +65,6 @@ void Resources::clearNonState()
     impl.curves = CurveSet::createPredefined();
     impl.filePool.clear();
     impl.wavePool.clearFileWaves();
-    impl.logger.clear();
     impl.modMatrix.clear();
     impl.metronome.clear();
 }
@@ -95,10 +92,6 @@ const MidiState& Resources::getMidiState() const noexcept
     return impl_->midiState;
 }
 
-const Logger& Resources::getLogger() const noexcept
-{
-    return impl_->logger;
-}
 
 const CurveSet& Resources::getCurves() const noexcept
 {

src/sfizz/Resources.h

@@ -13,7 +13,6 @@ namespace sfz {
 struct SynthConfig;
 class BufferPool;
 class MidiState;
-class Logger;
 class CurveSet;
 class FilePool;
 struct WavetablePool;
@@ -50,7 +49,6 @@ public:
     ACCESSOR_RW(getSynthConfig, SynthConfig);
     ACCESSOR_RW(getBufferPool, BufferPool);
     ACCESSOR_RW(getMidiState, MidiState);
-    ACCESSOR_RW(getLogger, Logger);
     ACCESSOR_RW(getCurves, CurveSet);
     ACCESSOR_RW(getFilePool, FilePool);
     ACCESSOR_RW(getWavePool, WavetablePool);

src/sfizz/Synth.cpp

@@ -25,6 +25,7 @@
 #include "SynthConfig.h"
 #include "ScopedFTZ.h"
 #include "utility/StringViewHelpers.h"
+#include "utility/Timing.h"
 #include "utility/XmlHelpers.h"
 #include "Voice.h"
 #include "Interpolators.h"
@@ -1037,7 +1038,10 @@ void Synth::renderBlock(AudioSpan<float> buffer) noexcept
 {
     Impl& impl = *impl_;
     ScopedFTZ ftz;
-    CallbackBreakdown callbackBreakdown;
+    auto& callbackBreakdown = impl.callbackBreakdown_;
+    impl.resetCallbackBreakdown();
+    callbackBreakdown.dispatch = impl.dispatchDuration_;
+    impl.dispatchDuration_ = 0.0;
 
     { // Silence buffer
         ScopedTiming logger { callbackBreakdown.renderMethod };
@@ -1057,7 +1061,7 @@ void Synth::renderBlock(AudioSpan<float> buffer) noexcept
     if (synthConfig.freeWheeling)
         filePool.waitForBackgroundLoading();
 
-    const auto now = std::chrono::high_resolution_clock::now();
+    const auto now = highResNow();
     const auto timeSinceLastCollection =
         std::chrono::duration_cast<std::chrono::seconds>(now - impl.lastGarbageCollection_);
 
@@ -1179,18 +1183,10 @@ void Synth::renderBlock(AudioSpan<float> buffer) noexcept
     impl.changedCCsThisCycle_.clear();
 
     { // Clear events and advance midi time
-        ScopedTiming logger { impl.dispatchDuration_, ScopedTiming::Operation::addToDuration };
+        ScopedTiming logger { impl.callbackBreakdown_.dispatch, ScopedTiming::Operation::addToDuration };
         midiState.advanceTime(buffer.getNumFrames());
     }
 
-    callbackBreakdown.dispatch = impl.dispatchDuration_;
-    Logger& logger = impl.resources_.getLogger();
-    logger.logCallbackTime(
-        callbackBreakdown, impl.voiceManager_.getNumActiveVoices(), numFrames);
-
-    // Reset the dispatch counter
-    impl.dispatchDuration_ = Duration(0);
-
     ASSERT(!hasNanInf(buffer.getConstSpan(0)));
     ASSERT(!hasNanInf(buffer.getConstSpan(1)));
     SFIZZ_CHECK(isReasonableAudio(buffer.getConstSpan(0)));
@@ -1906,6 +1902,11 @@ void Synth::Impl::resetVoices(int numVoices)
     applySettingsPerVoice();
 }
 
+void Synth::Impl::resetCallbackBreakdown()
+{
+    callbackBreakdown_ = CallbackBreakdown();
+}
+
 void Synth::Impl::applySettingsPerVoice()
 {
     for (auto& voice : voiceManager_) {
@@ -2093,17 +2094,12 @@ bool Synth::shouldReloadScala()
     return impl.resources_.getTuning().shouldReloadScala();
 }
 
-void Synth::enableLogging(absl::string_view prefix) noexcept
+const Synth::CallbackBreakdown& Synth::getCallbackBreakdown() const noexcept
 {
     Impl& impl = *impl_;
-    impl.resources_.getLogger().enableLogging(prefix);
+    return impl.callbackBreakdown_;
 }
 
-void Synth::disableLogging() noexcept
-{
-    Impl& impl = *impl_;
-    impl.resources_.getLogger().disableLogging();
-}
 
 void Synth::allSoundOff() noexcept
 {

src/sfizz/Synth.h

@@ -634,17 +634,23 @@ public:
      */
     bool shouldReloadScala();
 
+    struct CallbackBreakdown
+    {
+        double dispatch { 0 };
+        double renderMethod { 0 };
+        double data { 0 };
+        double amplitude { 0 };
+        double filters { 0 };
+        double panning { 0 };
+        double effects { 0 };
+    };
     /**
-     * @brief Enable logging of timings to sidecar CSV files. This can produce
+     * @brief View the callback breakdown for the last frame.
-     * many outputs so use with caution.
+     * Call from the real-time thread after a renderBlock call.
      *
+     * @return const CallbackBreakdown&
      */
-    void enableLogging(absl::string_view prefix = "") noexcept;
+    const CallbackBreakdown& getCallbackBreakdown() const noexcept;
-    /**
-     * @brief Disable logging;
-     *
-     */
-    void disableLogging() noexcept;
 
     /**
      * @brief Shuts down the current processing, clear buffers and reset the voices.

src/sfizz/SynthPrivate.h

@@ -247,6 +247,11 @@ struct Synth::Impl final: public Parser::Listener {
      */
     void checkOffGroups(const Region* region, int delay, int number);
 
+    /**
+     * @brief Resets the callback duration breakdown to 0
+     */
+    void resetCallbackBreakdown();
+
     int numGroups_ { 0 };
     int numMasters_ { 0 };
     int numOutputs_ { 1 };
@@ -340,7 +345,8 @@ struct Synth::Impl final: public Parser::Listener {
         bool haveFilterLFO { false };
     } settingsPerVoice_;
 
-    Duration dispatchDuration_ { 0 };
+    CallbackBreakdown callbackBreakdown_;
+    double dispatchDuration_ { 0 };
 
     std::chrono::time_point<std::chrono::high_resolution_clock> lastGarbageCollection_;
 

src/sfizz/Voice.cpp

@@ -33,6 +33,7 @@
 #include "BufferPool.h"
 #include "SynthConfig.h"
 #include "utility/Macros.h"
+#include "utility/Timing.h"
 #include <absl/algorithm/container.h>
 #include <absl/types/span.h>
 #include <random>
@@ -285,10 +286,10 @@ struct Voice::Impl
     float waveLeftGain_[config::oscillatorsPerVoice] {};
     float waveRightGain_[config::oscillatorsPerVoice] {};
 
-    Duration dataDuration_;
+    double dataDuration_;
-    Duration amplitudeDuration_;
+    double amplitudeDuration_;
-    Duration panningDuration_;
+    double panningDuration_;
-    Duration filterDuration_;
+    double filterDuration_;
 
     fast_real_distribution<float> uniformNoiseDist_ { -config::uniformNoiseBounds, config::uniformNoiseBounds };
     fast_gaussian_generator<float> gaussianNoiseDist_ { 0.0f, config::noiseVariance };
@@ -2091,25 +2092,25 @@ int Voice::getAge() const noexcept
     return impl.age_;
 }
 
-Duration Voice::getLastDataDuration() const noexcept
+double Voice::getLastDataDuration() const noexcept
 {
     Impl& impl = *impl_;
     return impl.dataDuration_;
 }
 
-Duration Voice::getLastAmplitudeDuration() const noexcept
+double Voice::getLastAmplitudeDuration() const noexcept
 {
     Impl& impl = *impl_;
     return impl.amplitudeDuration_;
 }
 
-Duration Voice::getLastFilterDuration() const noexcept
+double Voice::getLastFilterDuration() const noexcept
 {
     Impl& impl = *impl_;
     return impl.filterDuration_;
 }
 
-Duration Voice::getLastPanningDuration() const noexcept
+double Voice::getLastPanningDuration() const noexcept
 {
     Impl& impl = *impl_;
     return impl.panningDuration_;

src/sfizz/Voice.h

@@ -10,7 +10,6 @@
 #include "Region.h"
 #include "Resources.h"
 #include "AudioSpan.h"
-#include "Logger.h"
 #include "utility/NumericId.h"
 #include "utility/LeakDetector.h"
 #include <memory>
@@ -382,10 +381,10 @@ public:
      */
     int getAge() const noexcept;
 
-    Duration getLastDataDuration() const noexcept;
+    double getLastDataDuration() const noexcept;
-    Duration getLastAmplitudeDuration() const noexcept;
+    double getLastAmplitudeDuration() const noexcept;
-    Duration getLastFilterDuration() const noexcept;
+    double getLastFilterDuration() const noexcept;
-    Duration getLastPanningDuration() const noexcept;
+    double getLastPanningDuration() const noexcept;
 
     /**
      * @brief Get the SFZv1 amplitude LFO, if existing

src/sfizz/sfizz.cpp

@@ -334,12 +334,11 @@ bool sfz::Sfizz::shouldReloadScala()
 
 void sfz::Sfizz::enableLogging() noexcept
 {
-    synth->synth.enableLogging();
 }
 
 void sfz::Sfizz::enableLogging(const std::string& prefix) noexcept
 {
-    synth->synth.enableLogging(prefix);
+    (void)prefix;
 }
 
 void sfz::Sfizz::setLoggingPrefix(const std::string& prefix) noexcept
@@ -349,7 +348,20 @@ void sfz::Sfizz::setLoggingPrefix(const std::string& prefix) noexcept
 
 void sfz::Sfizz::disableLogging() noexcept
 {
-    synth->synth.disableLogging();
+}
+
+sfz::Sfizz::CallbackBreakdown sfz::Sfizz::getCallbackBreakdown() noexcept
+{
+    CallbackBreakdown breakdown;
+    const auto& bd = synth->synth.getCallbackBreakdown();
+    breakdown.amplitude = bd.amplitude;
+    breakdown.panning = bd.panning;
+    breakdown.renderMethod = bd.renderMethod;
+    breakdown.data = bd.data;
+    breakdown.dispatch = bd.dispatch;
+    breakdown.filters = bd.filters;
+    breakdown.effects = bd.effects;
+    return breakdown;
 }
 
 void sfz::Sfizz::allSoundOff() noexcept

src/sfizz/sfizz_wrapper.cpp

@@ -314,10 +314,8 @@ bool sfizz_should_reload_scala(sfizz_synth_t* synth)
 
 void sfizz_enable_logging(sfizz_synth_t* synth, const char* prefix)
 {
-    if (prefix)
+    (void)synth;
-        synth->synth.enableLogging(prefix);
+    (void)prefix;
-    else
-        synth->synth.enableLogging();
 }
 
 void sfizz_set_logging_prefix(sfizz_synth_t* synth, const char* prefix)
@@ -328,7 +326,19 @@ void sfizz_set_logging_prefix(sfizz_synth_t* synth, const char* prefix)
 
 void sfizz_disable_logging(sfizz_synth_t* synth)
 {
-    synth->synth.disableLogging();
+    (void)synth;
+}
+
+void sfizz_get_callback_breakdown(sfizz_synth_t* synth, sfizz_callback_breakdown_t* breakdown)
+{
+    const auto& bd = synth->synth.getCallbackBreakdown();
+    breakdown->amplitude = bd.amplitude;
+    breakdown->panning = bd.panning;
+    breakdown->renderMethod = bd.renderMethod;
+    breakdown->data = bd.data;
+    breakdown->dispatch = bd.dispatch;
+    breakdown->filters = bd.filters;
+    breakdown->effects = bd.effects;
 }
 
 void sfizz_all_sound_off(sfizz_synth_t* synth)

src/sfizz/utility/Timing.h

@@ -0,0 +1,64 @@
+// 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
+#pragma once
+
+#include <chrono>
+#include <type_traits>
+
+namespace sfz
+{
+
+using Duration = std::chrono::duration<double>;
+using TimePoint = std::chrono::time_point<std::chrono::high_resolution_clock>;
+
+static TimePoint highResNow()
+{
+#ifdef EMSCRIPTEN
+    return {};
+#else
+    return std::chrono::high_resolution_clock::now();
+#endif
+}
+
+/**
+ * @brief Creates an RAII logger which fills or adds to a duration on destruction
+ *
+ */
+struct ScopedTiming
+{
+    enum class Operation
+    {
+        addToDuration,
+        replaceDuration
+    };
+    ScopedTiming() = delete;
+    /**
+     * @brief Construct a new Scoped Logger object
+     *
+     * @param targetDuration
+     * @param op
+     */
+    ScopedTiming(double& targetDuration, Operation op = Operation::replaceDuration)
+    : targetDuration(targetDuration), operation(op) {}
+    ~ScopedTiming()
+    {
+        switch(operation)
+        {
+        case(Operation::replaceDuration):
+            targetDuration = (highResNow() - creationTime).count();
+            break;
+        case(Operation::addToDuration):
+            targetDuration += (highResNow() - creationTime).count();
+            break;
+        }
+    }
+
+    double& targetDuration;
+    const Operation operation;
+    const TimePoint creationTime { highResNow() };
+};
+
+}