Logging is not implicitely handled by the synth

You need a call to get the callback breakdown each frame.
sfizz_render has been updated to make use of this.

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)
-        synth.enableLogging(params["log"].as<std::string>());
+    bool logging = params.count("log") > 0;
+    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 \

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,31 +971,34 @@ 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.
  *
  * @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.
+ */
+struct sfizz_callback_breakdown_t
+{
+    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
+ *
+ * @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 @@ class SFIZZ_EXPORTED_API Sfizz
      * @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 @@ class SFIZZ_EXPORTED_API Sfizz
      * @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)
-    : logger(logger),
-      filesToLoad(alignedNew<FileQueue>()),
+sfz::FilePool::FilePool()
+    : 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 @@ class FileDataHolder {
             return;
 
         data->readerCount -= 1;
-        data->lastViewerLeftAt = std::chrono::high_resolution_clock::now();
+        data->lastViewerLeftAt = highResNow();
         data = nullptr;
     }
     ~FileDataHolder()
@@ -192,7 +192,7 @@ class FilePool {
      * 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 @@ class FilePool {
      */
     void triggerGarbageCollection() noexcept;
 private:
-    Logger& logger;
     fs::path rootDirectory;
 
     bool loadInRam { config::loadInRam };
@@ -340,13 +339,11 @@ class FilePool {
     // 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
-        : id(id), data(data), queuedTime(queuedTime) {}
+        QueuedFileData(std::weak_ptr<FileId> id, FileData* data) noexcept
+        : id(id), data(data) {}
         std::weak_ptr<FileId> id;
         FileData* data { nullptr };
-        TimePoint queuedTime {};
     };
 
     using FileQueue = atomic_queue::AtomicQueue2<QueuedFileData, config::maxVoices>;