From cb88fb4bb7ec5afcce45d5e8ec21dc7a9ac9b8e2 Mon Sep 17 00:00:00 2001 From: Paul Fd Date: Mon, 17 Feb 2020 00:01:15 +0100 Subject: [PATCH] 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 };