From 015c31bf5df3c8ad302169da39fd2b314e5a5a4b Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Sat, 20 Nov 2021 01:08:01 +0100 Subject: [PATCH] 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 | 37 ++++++- common.mk | 1 - src/CMakeLists.txt | 3 +- src/sfizz.h | 37 ++++++- src/sfizz.hpp | 31 +++++- src/sfizz/FilePool.cpp | 12 +-- src/sfizz/FilePool.h | 13 +-- src/sfizz/Logger.cpp | 186 ------------------------------------ src/sfizz/Logger.h | 150 ----------------------------- src/sfizz/Resources.cpp | 9 +- src/sfizz/Resources.h | 2 - src/sfizz/Synth.cpp | 34 +++---- src/sfizz/Synth.h | 22 +++-- src/sfizz/SynthPrivate.h | 8 +- src/sfizz/Voice.cpp | 17 ++-- src/sfizz/Voice.h | 9 +- src/sfizz/sfizz.cpp | 18 +++- src/sfizz/sfizz_wrapper.cpp | 20 +++- src/sfizz/utility/Timing.h | 64 +++++++++++++ 19 files changed, 252 insertions(+), 421 deletions(-) delete mode 100644 src/sfizz/Logger.cpp delete mode 100644 src/sfizz/Logger.h create mode 100644 src/sfizz/utility/Timing.h diff --git a/clients/sfizz_render.cpp b/clients/sfizz_render.cpp index 8bb84ea3b..69464b1f6 100644 --- a/clients/sfizz_render.cpp +++ b/clients/sfizz_render.cpp @@ -8,6 +8,7 @@ #include #include #include +#include #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()); + bool logging = params.count("log") > 0; + std::string logFilename {}; + std::ofstream callbackLogFile {}; + if (logging) { + logFilename = params["log"].as(); + 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(interleavedBuffer); } } diff --git a/common.mk b/common.mk index fd81147dc..ebcdf76bd 100644 --- a/common.mk +++ b/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 \ diff --git a/src/CMakeLists.txt b/src/CMakeLists.txt index ad678666f..ad6dadcb7 100644 --- a/src/CMakeLists.txt +++ b/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 diff --git a/src/sfizz.h b/src/sfizz.h index 0e55ed93b..2ce5cae83 100644 --- a/src/sfizz.h +++ b/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. + */ +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 diff --git a/src/sfizz.hpp b/src/sfizz.hpp index 4ed458aea..589676a40 100644 --- a/src/sfizz.hpp +++ b/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. diff --git a/src/sfizz/FilePool.cpp b/src/sfizz/FilePool.cpp index 30955ed94..d9d5b0245 100644 --- a/src/sfizz/FilePool.cpp +++ b/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()), +sfz::FilePool::FilePool() + : filesToLoad(alignedNew()), threadPool(globalThreadPool()) { loadingJobs.reserve(config::maxVoices); @@ -396,7 +395,7 @@ sfz::FileDataHolder sfz::FilePool::getFilePromise(const std::shared_ptr& 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(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; diff --git a/src/sfizz/FilePool.h b/src/sfizz/FilePool.h index 48a75f973..03757c922 100644 --- a/src/sfizz/FilePool.h +++ b/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 @@ -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; QueuedFileData() noexcept {} - QueuedFileData(std::weak_ptr id, FileData* data, TimePoint queuedTime) noexcept - : id(id), data(data), queuedTime(queuedTime) {} + QueuedFileData(std::weak_ptr id, FileData* data) noexcept + : id(id), data(data) {} std::weak_ptr id; FileData* data { nullptr }; - TimePoint queuedTime {}; }; using FileQueue = atomic_queue::AtomicQueue2; diff --git a/src/sfizz/Logger.cpp b/src/sfizz/Logger.cpp deleted file mode 100644 index b0a767dbf..000000000 --- a/src/sfizz/Logger.cpp +++ /dev/null @@ -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 -#include -#include -#include -#include -#include - -template -void printStatistics(std::vector& data) -{ - absl::c_sort(data); - const auto maxToTake = std::min(data.size(), size_t(10)); - std::vector 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(data.size()); - const auto mean = sum / size; - std::cout << "Mean: " << mean << '\n'; - if (data.size() > 1) { - std::vector 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()), - fileTimeQueue(alignedNew()) -{ - 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 waitDuration, std::chrono::duration 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; - } -} diff --git a/src/sfizz/Logger.h b/src/sfizz/Logger.h deleted file mode 100644 index 3aee168a6..000000000 --- a/src/sfizz/Logger.h +++ /dev/null @@ -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 -#include -#include -#include -#include -#include -#include -#include - -namespace sfz -{ - -using Duration = std::chrono::duration; - -/** - * @brief Creates an RAII logger which fills or adds to a duration on destruction - * - */ -struct ScopedTiming -{ - using TimePoint = std::chrono::time_point; - 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; - using FileTimeQueue = atomic_queue::AtomicQueue2; - - aligned_unique_ptr callbackTimeQueue; - aligned_unique_ptr fileTimeQueue; - std::vector callbackTimes; - std::vector fileTimes; - - std::atomic_flag keepRunning; - std::atomic_flag clearFlag; - std::thread loggingThread; - LEAK_DETECTOR(Logger); -}; - -} diff --git a/src/sfizz/Resources.cpp b/src/sfizz/Resources.cpp index 1e52ccc7e..eb9e03406 100644 --- a/src/sfizz/Resources.cpp +++ b/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 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 { diff --git a/src/sfizz/Resources.h b/src/sfizz/Resources.h index 86cfe8ee6..1660854c3 100644 --- a/src/sfizz/Resources.h +++ b/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 @@ class Resources 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); diff --git a/src/sfizz/Synth.cpp b/src/sfizz/Synth.cpp index f5749ff62..c05c53fbe 100644 --- a/src/sfizz/Synth.cpp +++ b/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 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 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(now - impl.lastGarbageCollection_); @@ -1179,18 +1183,10 @@ void Synth::renderBlock(AudioSpan 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))); @@ -1410,7 +1406,7 @@ void Synth::Impl::performHdcc(int delay, int ccNumber, float normValue, bool asM ASSERT(ccNumber < config::numCCs); ASSERT(ccNumber >= 0); - ScopedTiming logger { dispatchDuration_, ScopedTiming::Operation::addToDuration }; + ScopedTiming logger { callbackBreakdown_.dispatch, ScopedTiming::Operation::addToDuration }; changedCCsThisCycle_.set(ccNumber); @@ -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 { diff --git a/src/sfizz/Synth.h b/src/sfizz/Synth.h index 59e846223..e4192164b 100644 --- a/src/sfizz/Synth.h +++ b/src/sfizz/Synth.h @@ -634,17 +634,23 @@ class Synth final { */ 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 - * many outputs so use with caution. - * - */ - void enableLogging(absl::string_view prefix = "") noexcept; - /** - * @brief Disable logging; + * @brief View the callback breakdown for the last frame. + * Call from the real-time thread after a renderBlock call. * + * @return const CallbackBreakdown& */ - void disableLogging() noexcept; + const CallbackBreakdown& getCallbackBreakdown() const noexcept; /** * @brief Shuts down the current processing, clear buffers and reset the voices. diff --git a/src/sfizz/SynthPrivate.h b/src/sfizz/SynthPrivate.h index 2fd072d97..e1cd5468c 100644 --- a/src/sfizz/SynthPrivate.h +++ b/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 lastGarbageCollection_; diff --git a/src/sfizz/Voice.cpp b/src/sfizz/Voice.cpp index 27a93566f..396ebcf57 100644 --- a/src/sfizz/Voice.cpp +++ b/src/sfizz/Voice.cpp @@ -33,6 +33,7 @@ #include "BufferPool.h" #include "SynthConfig.h" #include "utility/Macros.h" +#include "utility/Timing.h" #include #include #include @@ -285,10 +286,10 @@ struct Voice::Impl float waveLeftGain_[config::oscillatorsPerVoice] {}; float waveRightGain_[config::oscillatorsPerVoice] {}; - Duration dataDuration_; - Duration amplitudeDuration_; - Duration panningDuration_; - Duration filterDuration_; + double dataDuration_; + double amplitudeDuration_; + double panningDuration_; + double filterDuration_; fast_real_distribution uniformNoiseDist_ { -config::uniformNoiseBounds, config::uniformNoiseBounds }; fast_gaussian_generator 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_; diff --git a/src/sfizz/Voice.h b/src/sfizz/Voice.h index 94a6f3c43..58774562a 100644 --- a/src/sfizz/Voice.h +++ b/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 @@ -382,10 +381,10 @@ class Voice { */ int getAge() const noexcept; - Duration getLastDataDuration() const noexcept; - Duration getLastAmplitudeDuration() const noexcept; - Duration getLastFilterDuration() const noexcept; - Duration getLastPanningDuration() const noexcept; + double getLastDataDuration() const noexcept; + double getLastAmplitudeDuration() const noexcept; + double getLastFilterDuration() const noexcept; + double getLastPanningDuration() const noexcept; /** * @brief Get the SFZv1 amplitude LFO, if existing diff --git a/src/sfizz/sfizz.cpp b/src/sfizz/sfizz.cpp index be67cc064..089f35828 100644 --- a/src/sfizz/sfizz.cpp +++ b/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 diff --git a/src/sfizz/sfizz_wrapper.cpp b/src/sfizz/sfizz_wrapper.cpp index bfa0983a5..993275900 100644 --- a/src/sfizz/sfizz_wrapper.cpp +++ b/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) - synth->synth.enableLogging(prefix); - else - synth->synth.enableLogging(); + (void)synth; + (void)prefix; } 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) diff --git a/src/sfizz/utility/Timing.h b/src/sfizz/utility/Timing.h new file mode 100644 index 000000000..44a34b66e --- /dev/null +++ b/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 +#include + +namespace sfz +{ + +using Duration = std::chrono::duration; +using TimePoint = std::chrono::time_point; + +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() }; +}; + +}