From cb88fb4bb7ec5afcce45d5e8ec21dc7a9ac9b8e2 Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Mon, 17 Feb 2020 00:01:15 +0100 Subject: [PATCH 1/8] Added logs for the processing time in voices --- src/sfizz/Config.h | 1 + src/sfizz/Logger.cpp | 32 ++++++++--- src/sfizz/Logger.h | 33 +++++++++-- src/sfizz/Synth.cpp | 22 ++++++- src/sfizz/Synth.h | 2 + src/sfizz/Voice.cpp | 133 +++++++++++++++++++++++++------------------ src/sfizz/Voice.h | 11 ++++ 7 files changed, 164 insertions(+), 70 deletions(-) diff --git a/src/sfizz/Config.h b/src/sfizz/Config.h index b9e62514..e404d9c3 100644 --- a/src/sfizz/Config.h +++ b/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 }; diff --git a/src/sfizz/Logger.cpp b/src/sfizz/Logger.cpp index 5e6c0fe7..b6a11135 100644 --- a/src/sfizz/Logger.cpp +++ b/src/sfizz/Logger.cpp @@ -66,7 +66,7 @@ sfz::Logger::~Logger() << "_file_log.csv"; fs::path fileLogPath{ fs::current_path() / fileLogFilename.str() }; DBG("Logging file times to " << fileLogPath.filename()); - std::ofstream loadLogFile { fileLogPath.string() }; + std::ofstream loadLogFile { fileLogPath.native() }; loadLogFile << "WaitDuration,LoadDuration,FileSize,FileName" << '\n'; for (auto& time: fileTimes) loadLogFile << time.waitDuration.count() << ',' @@ -82,22 +82,27 @@ sfz::Logger::~Logger() << "_callback_log.csv"; fs::path callbackLogPath{ fs::current_path() / callbackLogFilename.str() }; DBG("Logging callback times to " << callbackLogPath.filename()); - std::ofstream callbackLogFile { callbackLogPath.string() }; - callbackLogFile << "Duration,NumVoices,NumSamples" << '\n'; + std::ofstream callbackLogFile { callbackLogPath.native() }; + 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 duration, int numVoices, size_t numSamples) +void sfz::Logger::logCallbackTime(CallbackBreakdown&& breakdown, int numVoices, size_t numSamples) { if (!loggingEnabled) return; - callbackTimeQueue.try_push({ duration, numVoices, numSamples }); + callbackTimeQueue.try_push({ std::move(breakdown), numVoices, numSamples }); } void sfz::Logger::logFileTime(std::chrono::duration waitDuration, std::chrono::duration loadDuration, uint32_t fileSize, absl::string_view filename) @@ -126,7 +131,7 @@ void sfz::Logger::moveEvents() noexcept while (callbackTimeQueue.try_pop(callbackTime)) callbackTimes.push_back(callbackTime); - sfz::FileTime fileTime; + FileTime fileTime; while (fileTimeQueue.try_pop(fileTime)) fileTimes.push_back(fileTime); @@ -135,7 +140,7 @@ void sfz::Logger::moveEvents() noexcept callbackTimes.clear(); } - std::this_thread::sleep_for(50ms); + std::this_thread::sleep_for(10ms); } } @@ -149,3 +154,14 @@ void sfz::Logger::disableLogging() loggingEnabled = false; clearFlag.clear(); } + +sfz::ScopedLogger::ScopedLogger(std::function)> callback) +: callback(std::move(callback)) +{ + +} + +sfz::ScopedLogger::~ScopedLogger() +{ + callback(std::chrono::high_resolution_clock::now() - creationTime); +} diff --git a/src/sfizz/Logger.h b/src/sfizz/Logger.h index 3d16a541..dbc3cf49 100644 --- a/src/sfizz/Logger.h +++ b/src/sfizz/Logger.h @@ -10,23 +10,46 @@ #include #include #include +#include #include #include "absl/strings/string_view.h" namespace sfz { +using Duration = std::chrono::duration; + +struct ScopedLogger +{ + using TimePoint = std::chrono::time_point; + ScopedLogger() = delete; + ScopedLogger(std::function callback); + ~ScopedLogger(); + const std::function callback; + const TimePoint creationTime { std::chrono::high_resolution_clock::now() }; +}; + struct FileTime { - std::chrono::duration waitDuration; - std::chrono::duration 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 duration; + CallbackBreakdown breakdown; int numVoices; size_t numSamples; }; @@ -40,8 +63,8 @@ public: void clear(); void enableLogging(); void disableLogging(); - void logCallbackTime(std::chrono::duration duration, int numVoices, size_t numSamples); - void logFileTime(std::chrono::duration waitDuration, std::chrono::duration loadDuration, uint32_t fileSize, absl::string_view filename); + void logCallbackTime(CallbackBreakdown&& breakdown, int numVoices, size_t numSamples); + void logFileTime(Duration waitDuration, Duration loadDuration, uint32_t fileSize, absl::string_view filename); private: void moveEvents() noexcept; bool loggingEnabled { config::loggingEnabled }; diff --git a/src/sfizz/Synth.cpp b/src/sfizz/Synth.cpp index 8e17b7e2..c2ddb75e 100644 --- a/src/sfizz/Synth.cpp +++ b/src/sfizz/Synth.cpp @@ -411,6 +411,8 @@ void sfz::Synth::renderBlock(AudioSpan buffer) noexcept { ScopedFTZ ftz; const auto callbackStartTime = std::chrono::high_resolution_clock::now(); + CallbackBreakdown callbackBreakdown; + callbackBreakdown.dispatch = dispatchDuration; buffer.fill(0.0f); @@ -430,13 +432,20 @@ void sfz::Synth::renderBlock(AudioSpan buffer) noexcept numActiveVoices++; voice->renderBlock(tempSpan); buffer.add(tempSpan); + callbackBreakdown.data += voice->getLastDataDuration(); + callbackBreakdown.amplitude += voice->getLastAmplitudeDuration(); + callbackBreakdown.filters += voice->getLastFilterDuration(); + callbackBreakdown.panning += voice->getLastPanningDuration(); } } buffer.applyGain(db2mag(volume)); - const auto callbackDuration = std::chrono::high_resolution_clock::now() - callbackStartTime; - resources.logger.logCallbackTime(callbackDuration, numActiveVoices, buffer.getNumFrames()); + callbackBreakdown.renderMethod = std::chrono::high_resolution_clock::now() - callbackStartTime; + resources.logger.logCallbackTime(std::move(callbackBreakdown), numActiveVoices, buffer.getNumFrames()); + + // Reset the dispatch counter + dispatchDuration = Duration(0); } void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept @@ -444,6 +453,7 @@ void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept ASSERT(noteNumber < 128); ASSERT(noteNumber >= 0); + ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; resources.midiState.noteOnEvent(noteNumber, velocity); AtomicGuard callbackGuard { inCallback }; @@ -458,6 +468,7 @@ void sfz::Synth::noteOff(int delay, int noteNumber, uint8_t velocity [[maybe_unu ASSERT(noteNumber < 128); ASSERT(noteNumber >= 0); + ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; resources.midiState.noteOffEvent(noteNumber, velocity); AtomicGuard callbackGuard { inCallback }; @@ -513,6 +524,8 @@ void sfz::Synth::cc(int delay, int ccNumber, uint8_t ccValue) noexcept ASSERT(ccNumber < config::numCCs); ASSERT(ccNumber >= 0); + ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + resources.midiState.ccEvent(ccNumber, ccValue); AtomicGuard callbackGuard { inCallback }; @@ -543,6 +556,8 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept ASSERT(pitch <= 8192); ASSERT(pitch >= -8192); + ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + resources.midiState.pitchBendEvent(pitch); for (auto& region: regions) { @@ -555,10 +570,11 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept } void sfz::Synth::aftertouch(int /* delay */, uint8_t /* aftertouch */) noexcept { + ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; } void sfz::Synth::tempo(int /* delay */, float /* secondsPerQuarter */) noexcept { - + ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; } int sfz::Synth::getNumRegions() const noexcept diff --git a/src/sfizz/Synth.h b/src/sfizz/Synth.h index 28d6dde9..e0569aeb 100644 --- a/src/sfizz/Synth.h +++ b/src/sfizz/Synth.h @@ -456,6 +456,8 @@ private: int noteOffset { 0 }; int octaveOffset { 0 }; + Duration dispatchDuration { 0 }; + fs::file_time_type modificationTime { }; LEAK_DETECTOR(Synth); diff --git a/src/sfizz/Voice.cpp b/src/sfizz/Voice.cpp index 0ec124ee..308dfde6 100644 --- a/src/sfizz/Voice.cpp +++ b/src/sfizz/Voice.cpp @@ -250,10 +250,13 @@ void sfz::Voice::renderBlock(AudioSpan buffer) noexcept auto delayed_buffer = buffer.subspan(delay); initialDelay -= static_cast(delay); - if (region->isGenerator()) - fillWithGenerator(delayed_buffer); - else - fillWithData(delayed_buffer); + { // Fill buffer with raw data + ScopedLogger logger { [&](auto&& duration){ dataDuration = duration; } }; + if (region->isGenerator()) + fillWithGenerator(delayed_buffer); + else + fillWithData(delayed_buffer); + } if (region->isStereo) processStereo(buffer); @@ -275,39 +278,50 @@ void sfz::Voice::processMono(AudioSpan buffer) noexcept auto modulationSpan = tempSpan1.first(numSamples); - // Amplitude envelope - amplitudeEnvelope.getBlock(modulationSpan); - applyGain(modulationSpan, leftBuffer); + { // Amplitude processing + ScopedLogger logger { [&](auto&& duration){ amplitudeDuration = duration; } }; - // Crossfade envelope - crossfadeEnvelope.getBlock(modulationSpan); - applyGain(modulationSpan, leftBuffer); + // Amplitude envelope + amplitudeEnvelope.getBlock(modulationSpan); + applyGain(modulationSpan, leftBuffer); - // Volume envelope - volumeEnvelope.getBlock(modulationSpan); - applyGain(modulationSpan, leftBuffer); + // Crossfade envelope + crossfadeEnvelope.getBlock(modulationSpan); + applyGain(modulationSpan, leftBuffer); - // AmpEG envelope - egEnvelope.getBlock(modulationSpan); - applyGain(modulationSpan, leftBuffer); + // Volume envelope + volumeEnvelope.getBlock(modulationSpan); + applyGain(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(modulationSpan, leftBuffer); } - for (auto& eq: equalizers) { - eq->process(inputChannel, outputChannel, numSamples); + { // Filtering and EQ + ScopedLogger logger { [&](auto&& duration){ filterDuration = duration; } }; + + const float* inputChannel[1] { leftBuffer.data() }; + float* outputChannel[1] { leftBuffer.data() }; + for (auto& filter: filters) { + filter->process(inputChannel, outputChannel, numSamples); + } + + for (auto& eq: equalizers) { + eq->process(inputChannel, outputChannel, numSamples); + } } - // Prepare for stereo output - copy(leftBuffer, rightBuffer); + { // Panning and stereo processing + ScopedLogger logger { [&](auto&& duration){ panningDuration = duration; } }; - // Apply panning - panEnvelope.getBlock(modulationSpan); - pan(modulationSpan, leftBuffer, rightBuffer); + // Prepare for stereo output + copy(leftBuffer, rightBuffer); + + // Apply panning + panEnvelope.getBlock(modulationSpan); + pan(modulationSpan, leftBuffer, rightBuffer); + } } void sfz::Voice::processStereo(AudioSpan buffer) noexcept @@ -317,38 +331,49 @@ void sfz::Voice::processStereo(AudioSpan buffer) noexcept auto leftBuffer = buffer.getSpan(0); auto rightBuffer = buffer.getSpan(1); - // Amplitude envelope - amplitudeEnvelope.getBlock(modulationSpan); - buffer.applyGain(modulationSpan); + { // Amplitude processing + ScopedLogger logger { [&](auto&& duration){ amplitudeDuration = duration; } }; - // 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(modulationSpan, leftBuffer, rightBuffer); - positionEnvelope.getBlock(modulationSpan); - pan(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 + ScopedLogger logger { [&](auto&& duration){ panningDuration = duration; } }; + + // Apply the width/position process + widthEnvelope.getBlock(modulationSpan); + width(modulationSpan, leftBuffer, rightBuffer); + positionEnvelope.getBlock(modulationSpan); + pan(modulationSpan, leftBuffer, rightBuffer); + } + + { // Filtering and EQ + ScopedLogger logger { [&](auto&& duration){ filterDuration = duration; } }; + + const float* inputChannels[2] { leftBuffer.data(), rightBuffer.data() }; + float* outputChannels[2] { leftBuffer.data(), rightBuffer.data() }; + + for (auto& filter: filters) { + filter->process(inputChannels, outputChannels, numSamples); + } + + for (auto& eq: equalizers) { + eq->process(inputChannels, outputChannels, numSamples); + } } } diff --git a/src/sfizz/Voice.h b/src/sfizz/Voice.h index 51830ba0..d46c23fa 100644 --- a/src/sfizz/Voice.h +++ b/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 volumeEnvelope; float bendStepFactor { centsFactor(1) }; + Duration dataDuration; + Duration amplitudeDuration; + Duration panningDuration; + Duration filterDuration; + std::normal_distribution noiseDist { 0, config::noiseVariance }; HistoricalBuffer powerHistory { config::powerHistoryLength }; From 1461680e20069762de6d743490cadc1dc3165bfa Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Mon, 17 Feb 2020 09:22:46 +0100 Subject: [PATCH 2/8] Added a couple benchmarks Clocks are about 20 ns The queue is about 2 us --- benchmarks/BM_clock.cpp | 51 +++++++++++++++++++++++++++++++++++++++ benchmarks/BM_logger.cpp | 48 ++++++++++++++++++++++++++++++++++++ benchmarks/CMakeLists.txt | 6 +++++ 3 files changed, 105 insertions(+) create mode 100644 benchmarks/BM_clock.cpp create mode 100644 benchmarks/BM_logger.cpp diff --git a/benchmarks/BM_clock.cpp b/benchmarks/BM_clock.cpp new file mode 100644 index 00000000..e1a263a3 --- /dev/null +++ b/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 +#include + +class Clock : public benchmark::Fixture { +public: + void SetUp(const ::benchmark::State& state) { + + } + + void TearDown(const ::benchmark::State& state [[maybe_unused]]) { + + } + + std::chrono::time_point hires; + std::chrono::time_point 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(); diff --git a/benchmarks/BM_logger.cpp b/benchmarks/BM_logger.cpp new file mode 100644 index 00000000..a52bef57 --- /dev/null +++ b/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 +#include "Logger.h" +#include + +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(); diff --git a/benchmarks/CMakeLists.txt b/benchmarks/CMakeLists.txt index dd7bfb65..00bbd802 100644 --- a/benchmarks/CMakeLists.txt +++ b/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 From 1bb373cfa0bdab2a834f5d4d0ff57bb3d46c009c Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Tue, 18 Feb 2020 16:16:24 +0100 Subject: [PATCH 3/8] Added API functions to activate logging --- src/sfizz.h | 15 +++++++++++++++ src/sfizz.hpp | 11 +++++++++++ src/sfizz/Logger.cpp | 4 ++-- src/sfizz/Synth.cpp | 10 ++++++++++ src/sfizz/Synth.h | 11 +++++++++++ src/sfizz/sfizz.cpp | 10 ++++++++++ src/sfizz/sfizz_wrapper.cpp | 11 +++++++++++ 7 files changed, 70 insertions(+), 2 deletions(-) diff --git a/src/sfizz.h b/src/sfizz.h index 7b2a0c66..68c9a9e7 100644 --- a/src/sfizz.h +++ b/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 diff --git a/src/sfizz.hpp b/src/sfizz.hpp index 5437d6a8..e7f0f63d 100644 --- a/src/sfizz.hpp +++ b/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 synth; }; diff --git a/src/sfizz/Logger.cpp b/src/sfizz/Logger.cpp index b6a11135..5ecb4f3b 100644 --- a/src/sfizz/Logger.cpp +++ b/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 file times to " << fileLogPath.filename() << '\n'; std::ofstream loadLogFile { fileLogPath.native() }; loadLogFile << "WaitDuration,LoadDuration,FileSize,FileName" << '\n'; for (auto& time: fileTimes) @@ -81,7 +81,7 @@ 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 callback times to " << callbackLogPath.filename() << '\n'; std::ofstream callbackLogFile { callbackLogPath.native() }; callbackLogFile << "Dispatch,RenderMethod,Data,Amplitude,Filters,Panning,NumVoices,NumSamples" << '\n'; for (auto& time: callbackTimes) diff --git a/src/sfizz/Synth.cpp b/src/sfizz/Synth.cpp index c2ddb75e..63ef098f 100644 --- a/src/sfizz/Synth.cpp +++ b/src/sfizz/Synth.cpp @@ -822,3 +822,13 @@ bool sfz::Synth::shouldReloadFile() { return (checkModificationTime() > modificationTime); } + +void sfz::Synth::enableLogging() noexcept +{ + resources.logger.enableLogging(); +} + +void sfz::Synth::disableLogging() noexcept +{ + resources.logger.disableLogging(); +} diff --git a/src/sfizz/Synth.h b/src/sfizz/Synth.h index e0569aeb..f2c6fd11 100644 --- a/src/sfizz/Synth.h +++ b/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 diff --git a/src/sfizz/sfizz.cpp b/src/sfizz/sfizz.cpp index bf98af37..9115f318 100644 --- a/src/sfizz/sfizz.cpp +++ b/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(); +} diff --git a/src/sfizz/sfizz_wrapper.cpp b/src/sfizz/sfizz_wrapper.cpp index 8a29c1e8..7168e510 100644 --- a/src/sfizz/sfizz_wrapper.cpp +++ b/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(synth); + return self->enableLogging(); +} +void sfizz_disable_logging(sfizz_synth_t* synth) +{ + auto self = reinterpret_cast(synth); + return self->disableLogging(); +} + #ifdef __cplusplus } #endif From c9baf7671eb213076706578c01b31ff453045a93 Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Wed, 26 Feb 2020 21:49:26 +0100 Subject: [PATCH 4/8] Changed the scoped timing to have 1 of 2 possible behaviors --- src/sfizz/Logger.cpp | 14 +++++++-- src/sfizz/Logger.h | 10 +++++-- src/sfizz/Synth.cpp | 67 ++++++++++++++++++++++---------------------- src/sfizz/Voice.cpp | 14 ++++----- 4 files changed, 60 insertions(+), 45 deletions(-) diff --git a/src/sfizz/Logger.cpp b/src/sfizz/Logger.cpp index 5ecb4f3b..75f274fe 100644 --- a/src/sfizz/Logger.cpp +++ b/src/sfizz/Logger.cpp @@ -155,13 +155,21 @@ void sfz::Logger::disableLogging() clearFlag.clear(); } -sfz::ScopedLogger::ScopedLogger(std::function)> callback) -: callback(std::move(callback)) +sfz::ScopedLogger::ScopedLogger(Duration& targetDuration, Operation operation) +: targetDuration(targetDuration), operation(operation) { } sfz::ScopedLogger::~ScopedLogger() { - callback(std::chrono::high_resolution_clock::now() - creationTime); + 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 index dbc3cf49..f14f8438 100644 --- a/src/sfizz/Logger.h +++ b/src/sfizz/Logger.h @@ -22,10 +22,16 @@ using Duration = std::chrono::duration; struct ScopedLogger { using TimePoint = std::chrono::time_point; + enum class Operation + { + addToDuration, + replaceDuration + }; ScopedLogger() = delete; - ScopedLogger(std::function callback); + ScopedLogger(Duration& targetDuration, Operation op = Operation::replaceDuration); ~ScopedLogger(); - const std::function callback; + Duration& targetDuration; + const Operation operation; const TimePoint creationTime { std::chrono::high_resolution_clock::now() }; }; diff --git a/src/sfizz/Synth.cpp b/src/sfizz/Synth.cpp index 63ef098f..a96cfd1a 100644 --- a/src/sfizz/Synth.cpp +++ b/src/sfizz/Synth.cpp @@ -410,38 +410,39 @@ void sfz::Synth::setSampleRate(float sampleRate) noexcept void sfz::Synth::renderBlock(AudioSpan buffer) noexcept { ScopedFTZ ftz; - const auto callbackStartTime = std::chrono::high_resolution_clock::now(); CallbackBreakdown callbackBreakdown; - callbackBreakdown.dispatch = dispatchDuration; - - buffer.fill(0.0f); - - resources.filePool.cleanupPromises(); - - if (freeWheeling) - resources.filePool.waitForBackgroundLoading(); - - AtomicGuard callbackGuard { inCallback }; - if (!canEnterCallback) - return; - - auto tempSpan = AudioSpan(tempBuffer).first(buffer.getNumFrames()); int numActiveVoices { 0 }; - 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(); + + { // Main render block + ScopedLogger logger { callbackBreakdown.renderMethod }; + buffer.fill(0.0f); + + resources.filePool.cleanupPromises(); + + if (freeWheeling) + resources.filePool.waitForBackgroundLoading(); + + AtomicGuard callbackGuard { inCallback }; + if (!canEnterCallback) + return; + + auto tempSpan = AudioSpan(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.renderMethod = std::chrono::high_resolution_clock::now() - callbackStartTime; + callbackBreakdown.dispatch = dispatchDuration; resources.logger.logCallbackTime(std::move(callbackBreakdown), numActiveVoices, buffer.getNumFrames()); // Reset the dispatch counter @@ -453,7 +454,7 @@ void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept ASSERT(noteNumber < 128); ASSERT(noteNumber >= 0); - ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; resources.midiState.noteOnEvent(noteNumber, velocity); AtomicGuard callbackGuard { inCallback }; @@ -468,7 +469,7 @@ void sfz::Synth::noteOff(int delay, int noteNumber, uint8_t velocity [[maybe_unu ASSERT(noteNumber < 128); ASSERT(noteNumber >= 0); - ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; resources.midiState.noteOffEvent(noteNumber, velocity); AtomicGuard callbackGuard { inCallback }; @@ -524,7 +525,7 @@ void sfz::Synth::cc(int delay, int ccNumber, uint8_t ccValue) noexcept ASSERT(ccNumber < config::numCCs); ASSERT(ccNumber >= 0); - ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; resources.midiState.ccEvent(ccNumber, ccValue); @@ -556,7 +557,7 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept ASSERT(pitch <= 8192); ASSERT(pitch >= -8192); - ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; resources.midiState.pitchBendEvent(pitch); @@ -570,11 +571,11 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept } void sfz::Synth::aftertouch(int /* delay */, uint8_t /* aftertouch */) noexcept { - ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; } void sfz::Synth::tempo(int /* delay */, float /* secondsPerQuarter */) noexcept { - ScopedLogger logger { [this](auto&& duration){ dispatchDuration += duration; } }; + ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; } int sfz::Synth::getNumRegions() const noexcept diff --git a/src/sfizz/Voice.cpp b/src/sfizz/Voice.cpp index 308dfde6..3b47ff9c 100644 --- a/src/sfizz/Voice.cpp +++ b/src/sfizz/Voice.cpp @@ -251,7 +251,7 @@ void sfz::Voice::renderBlock(AudioSpan buffer) noexcept initialDelay -= static_cast(delay); { // Fill buffer with raw data - ScopedLogger logger { [&](auto&& duration){ dataDuration = duration; } }; + ScopedLogger logger { dataDuration }; if (region->isGenerator()) fillWithGenerator(delayed_buffer); else @@ -279,7 +279,7 @@ void sfz::Voice::processMono(AudioSpan buffer) noexcept auto modulationSpan = tempSpan1.first(numSamples); { // Amplitude processing - ScopedLogger logger { [&](auto&& duration){ amplitudeDuration = duration; } }; + ScopedLogger logger { amplitudeDuration }; // Amplitude envelope amplitudeEnvelope.getBlock(modulationSpan); @@ -299,7 +299,7 @@ void sfz::Voice::processMono(AudioSpan buffer) noexcept } { // Filtering and EQ - ScopedLogger logger { [&](auto&& duration){ filterDuration = duration; } }; + ScopedLogger logger { filterDuration }; const float* inputChannel[1] { leftBuffer.data() }; float* outputChannel[1] { leftBuffer.data() }; @@ -313,7 +313,7 @@ void sfz::Voice::processMono(AudioSpan buffer) noexcept } { // Panning and stereo processing - ScopedLogger logger { [&](auto&& duration){ panningDuration = duration; } }; + ScopedLogger logger { panningDuration }; // Prepare for stereo output copy(leftBuffer, rightBuffer); @@ -332,7 +332,7 @@ void sfz::Voice::processStereo(AudioSpan buffer) noexcept auto rightBuffer = buffer.getSpan(1); { // Amplitude processing - ScopedLogger logger { [&](auto&& duration){ amplitudeDuration = duration; } }; + ScopedLogger logger { amplitudeDuration }; // Amplitude envelope amplitudeEnvelope.getBlock(modulationSpan); @@ -352,7 +352,7 @@ void sfz::Voice::processStereo(AudioSpan buffer) noexcept } { // Panning and stereo processing - ScopedLogger logger { [&](auto&& duration){ panningDuration = duration; } }; + ScopedLogger logger { panningDuration }; // Apply the width/position process widthEnvelope.getBlock(modulationSpan); @@ -362,7 +362,7 @@ void sfz::Voice::processStereo(AudioSpan buffer) noexcept } { // Filtering and EQ - ScopedLogger logger { [&](auto&& duration){ filterDuration = duration; } }; + ScopedLogger logger { filterDuration }; const float* inputChannels[2] { leftBuffer.data(), rightBuffer.data() }; float* outputChannels[2] { leftBuffer.data(), rightBuffer.data() }; From 3b9683e66f46b41229f090dc0996e9950898f196 Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Wed, 26 Feb 2020 21:54:43 +0100 Subject: [PATCH 5/8] Added comments on the Logger --- src/sfizz/Logger.h | 50 ++++++++++++++++++++++++++++++++++++++++++++++ 1 file changed, 50 insertions(+) diff --git a/src/sfizz/Logger.h b/src/sfizz/Logger.h index f14f8438..5f777812 100644 --- a/src/sfizz/Logger.h +++ b/src/sfizz/Logger.h @@ -19,6 +19,10 @@ namespace sfz using Duration = std::chrono::duration; +/** + * @brief Creates an RAII logger which fills or adds to a duration on destruction + * + */ struct ScopedLogger { using TimePoint = std::chrono::time_point; @@ -28,6 +32,12 @@ struct ScopedLogger replaceDuration }; ScopedLogger() = delete; + /** + * @brief Construct a new Scoped Logger object + * + * @param targetDuration + * @param op + */ ScopedLogger(Duration& targetDuration, Operation op = Operation::replaceDuration); ~ScopedLogger(); Duration& targetDuration; @@ -65,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(); + + /** + * @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 { "" }; From 3346bbee285c8a9a06beca4053ba3966273f2c8e Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Thu, 27 Feb 2020 10:27:42 +0100 Subject: [PATCH 6/8] Added the number of log elements in the message --- src/sfizz/Logger.cpp | 4 ++-- src/sfizz/Synth.cpp | 17 +++++++++-------- 2 files changed, 11 insertions(+), 10 deletions(-) diff --git a/src/sfizz/Logger.cpp b/src/sfizz/Logger.cpp index 75f274fe..1fb60b8d 100644 --- a/src/sfizz/Logger.cpp +++ b/src/sfizz/Logger.cpp @@ -65,7 +65,7 @@ sfz::Logger::~Logger() << prefix << "_file_log.csv"; fs::path fileLogPath{ fs::current_path() / fileLogFilename.str() }; - std::cout << "Logging file times to " << fileLogPath.filename() << '\n'; + std::cout << "Logging " << fileTimes.size() << " file times to " << fileLogPath.filename() << '\n'; std::ofstream loadLogFile { fileLogPath.native() }; loadLogFile << "WaitDuration,LoadDuration,FileSize,FileName" << '\n'; for (auto& time: fileTimes) @@ -81,7 +81,7 @@ sfz::Logger::~Logger() << prefix << "_callback_log.csv"; fs::path callbackLogPath{ fs::current_path() / callbackLogFilename.str() }; - std::cout << "Logging callback times to " << callbackLogPath.filename() << '\n'; + std::cout << "Logging " << callbackTimes.size() << " callback times to " << callbackLogPath.filename() << '\n'; std::ofstream callbackLogFile { callbackLogPath.native() }; callbackLogFile << "Dispatch,RenderMethod,Data,Amplitude,Filters,Panning,NumVoices,NumSamples" << '\n'; for (auto& time: callbackTimes) diff --git a/src/sfizz/Synth.cpp b/src/sfizz/Synth.cpp index a96cfd1a..a9eef90e 100644 --- a/src/sfizz/Synth.cpp +++ b/src/sfizz/Synth.cpp @@ -410,21 +410,22 @@ void sfz::Synth::setSampleRate(float sampleRate) noexcept void sfz::Synth::renderBlock(AudioSpan buffer) noexcept { ScopedFTZ ftz; + + + if (freeWheeling) + resources.filePool.waitForBackgroundLoading(); + + AtomicGuard callbackGuard { inCallback }; + if (!canEnterCallback) + return; + CallbackBreakdown callbackBreakdown; int numActiveVoices { 0 }; - { // Main render block ScopedLogger logger { callbackBreakdown.renderMethod }; buffer.fill(0.0f); - resources.filePool.cleanupPromises(); - if (freeWheeling) - resources.filePool.waitForBackgroundLoading(); - - AtomicGuard callbackGuard { inCallback }; - if (!canEnterCallback) - return; auto tempSpan = AudioSpan(tempBuffer).first(buffer.getNumFrames()); for (auto& voice : voices) { From 805fd5a21c2d5d619f1c94027c73e375d6b61d7c Mon Sep 17 00:00:00 2001 From: Paul Ferrand Date: Thu, 27 Feb 2020 11:37:28 +0100 Subject: [PATCH 7/8] Trying to fix mingw builds --- src/sfizz/Logger.cpp | 4 ++-- 1 file changed, 2 insertions(+), 2 deletions(-) diff --git a/src/sfizz/Logger.cpp b/src/sfizz/Logger.cpp index 1fb60b8d..c2e5ed48 100644 --- a/src/sfizz/Logger.cpp +++ b/src/sfizz/Logger.cpp @@ -66,7 +66,7 @@ sfz::Logger::~Logger() << "_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.native() }; + std::ofstream loadLogFile { fileLogPath.string() }; loadLogFile << "WaitDuration,LoadDuration,FileSize,FileName" << '\n'; for (auto& time: fileTimes) loadLogFile << time.waitDuration.count() << ',' @@ -82,7 +82,7 @@ sfz::Logger::~Logger() << "_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.native() }; + std::ofstream callbackLogFile { callbackLogPath.string() }; callbackLogFile << "Dispatch,RenderMethod,Data,Amplitude,Filters,Panning,NumVoices,NumSamples" << '\n'; for (auto& time: callbackTimes) callbackLogFile << time.breakdown.dispatch.count() << ',' From 133885f085669f896b5703f778ca1168a91b5416 Mon Sep 17 00:00:00 2001 From: Paul Ferrand Date: Thu, 27 Feb 2020 12:29:29 +0100 Subject: [PATCH 8/8] Renamed the ScopedLogger as ScopedTiming --- src/sfizz/FilePool.cpp | 2 -- src/sfizz/Logger.cpp | 4 ++-- src/sfizz/Logger.h | 8 ++++---- src/sfizz/Synth.cpp | 14 +++++++------- src/sfizz/Voice.cpp | 14 +++++++------- 5 files changed, 20 insertions(+), 22 deletions(-) diff --git a/src/sfizz/FilePool.cpp b/src/sfizz/FilePool.cpp index f508ae80..89492265 100644 --- a/src/sfizz/FilePool.cpp +++ b/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); diff --git a/src/sfizz/Logger.cpp b/src/sfizz/Logger.cpp index c2e5ed48..35706167 100644 --- a/src/sfizz/Logger.cpp +++ b/src/sfizz/Logger.cpp @@ -155,13 +155,13 @@ void sfz::Logger::disableLogging() clearFlag.clear(); } -sfz::ScopedLogger::ScopedLogger(Duration& targetDuration, Operation operation) +sfz::ScopedTiming::ScopedTiming(Duration& targetDuration, Operation operation) : targetDuration(targetDuration), operation(operation) { } -sfz::ScopedLogger::~ScopedLogger() +sfz::ScopedTiming::~ScopedTiming() { switch(operation) { diff --git a/src/sfizz/Logger.h b/src/sfizz/Logger.h index 5f777812..9861ba87 100644 --- a/src/sfizz/Logger.h +++ b/src/sfizz/Logger.h @@ -23,7 +23,7 @@ using Duration = std::chrono::duration; * @brief Creates an RAII logger which fills or adds to a duration on destruction * */ -struct ScopedLogger +struct ScopedTiming { using TimePoint = std::chrono::time_point; enum class Operation @@ -31,15 +31,15 @@ struct ScopedLogger addToDuration, replaceDuration }; - ScopedLogger() = delete; + ScopedTiming() = delete; /** * @brief Construct a new Scoped Logger object * * @param targetDuration * @param op */ - ScopedLogger(Duration& targetDuration, Operation op = Operation::replaceDuration); - ~ScopedLogger(); + ScopedTiming(Duration& targetDuration, Operation op = Operation::replaceDuration); + ~ScopedTiming(); Duration& targetDuration; const Operation operation; const TimePoint creationTime { std::chrono::high_resolution_clock::now() }; diff --git a/src/sfizz/Synth.cpp b/src/sfizz/Synth.cpp index a9eef90e..0c3b3f87 100644 --- a/src/sfizz/Synth.cpp +++ b/src/sfizz/Synth.cpp @@ -422,7 +422,7 @@ void sfz::Synth::renderBlock(AudioSpan buffer) noexcept CallbackBreakdown callbackBreakdown; int numActiveVoices { 0 }; { // Main render block - ScopedLogger logger { callbackBreakdown.renderMethod }; + ScopedTiming logger { callbackBreakdown.renderMethod }; buffer.fill(0.0f); resources.filePool.cleanupPromises(); @@ -455,7 +455,7 @@ void sfz::Synth::noteOn(int delay, int noteNumber, uint8_t velocity) noexcept ASSERT(noteNumber < 128); ASSERT(noteNumber >= 0); - ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; + ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration }; resources.midiState.noteOnEvent(noteNumber, velocity); AtomicGuard callbackGuard { inCallback }; @@ -470,7 +470,7 @@ void sfz::Synth::noteOff(int delay, int noteNumber, uint8_t velocity [[maybe_unu ASSERT(noteNumber < 128); ASSERT(noteNumber >= 0); - ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; + ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration }; resources.midiState.noteOffEvent(noteNumber, velocity); AtomicGuard callbackGuard { inCallback }; @@ -526,7 +526,7 @@ void sfz::Synth::cc(int delay, int ccNumber, uint8_t ccValue) noexcept ASSERT(ccNumber < config::numCCs); ASSERT(ccNumber >= 0); - ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; + ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration }; resources.midiState.ccEvent(ccNumber, ccValue); @@ -558,7 +558,7 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept ASSERT(pitch <= 8192); ASSERT(pitch >= -8192); - ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; + ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration }; resources.midiState.pitchBendEvent(pitch); @@ -572,11 +572,11 @@ void sfz::Synth::pitchWheel(int delay, int pitch) noexcept } void sfz::Synth::aftertouch(int /* delay */, uint8_t /* aftertouch */) noexcept { - ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; + ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration }; } void sfz::Synth::tempo(int /* delay */, float /* secondsPerQuarter */) noexcept { - ScopedLogger logger { dispatchDuration, ScopedLogger::Operation::addToDuration }; + ScopedTiming logger { dispatchDuration, ScopedTiming::Operation::addToDuration }; } int sfz::Synth::getNumRegions() const noexcept diff --git a/src/sfizz/Voice.cpp b/src/sfizz/Voice.cpp index 3b47ff9c..64bac0f2 100644 --- a/src/sfizz/Voice.cpp +++ b/src/sfizz/Voice.cpp @@ -251,7 +251,7 @@ void sfz::Voice::renderBlock(AudioSpan buffer) noexcept initialDelay -= static_cast(delay); { // Fill buffer with raw data - ScopedLogger logger { dataDuration }; + ScopedTiming logger { dataDuration }; if (region->isGenerator()) fillWithGenerator(delayed_buffer); else @@ -279,7 +279,7 @@ void sfz::Voice::processMono(AudioSpan buffer) noexcept auto modulationSpan = tempSpan1.first(numSamples); { // Amplitude processing - ScopedLogger logger { amplitudeDuration }; + ScopedTiming logger { amplitudeDuration }; // Amplitude envelope amplitudeEnvelope.getBlock(modulationSpan); @@ -299,7 +299,7 @@ void sfz::Voice::processMono(AudioSpan buffer) noexcept } { // Filtering and EQ - ScopedLogger logger { filterDuration }; + ScopedTiming logger { filterDuration }; const float* inputChannel[1] { leftBuffer.data() }; float* outputChannel[1] { leftBuffer.data() }; @@ -313,7 +313,7 @@ void sfz::Voice::processMono(AudioSpan buffer) noexcept } { // Panning and stereo processing - ScopedLogger logger { panningDuration }; + ScopedTiming logger { panningDuration }; // Prepare for stereo output copy(leftBuffer, rightBuffer); @@ -332,7 +332,7 @@ void sfz::Voice::processStereo(AudioSpan buffer) noexcept auto rightBuffer = buffer.getSpan(1); { // Amplitude processing - ScopedLogger logger { amplitudeDuration }; + ScopedTiming logger { amplitudeDuration }; // Amplitude envelope amplitudeEnvelope.getBlock(modulationSpan); @@ -352,7 +352,7 @@ void sfz::Voice::processStereo(AudioSpan buffer) noexcept } { // Panning and stereo processing - ScopedLogger logger { panningDuration }; + ScopedTiming logger { panningDuration }; // Apply the width/position process widthEnvelope.getBlock(modulationSpan); @@ -362,7 +362,7 @@ void sfz::Voice::processStereo(AudioSpan buffer) noexcept } { // Filtering and EQ - ScopedLogger logger { filterDuration }; + ScopedTiming logger { filterDuration }; const float* inputChannels[2] { leftBuffer.data(), rightBuffer.data() }; float* outputChannels[2] { leftBuffer.data(), rightBuffer.data() };