diff --git a/meson.build b/meson.build index 442e274..6aa8677 100644 --- a/meson.build +++ b/meson.build @@ -42,10 +42,11 @@ library_sources = [ 'src/faster/R2Stretcher.cpp', 'src/faster/StretcherChannelData.cpp', 'src/faster/StretcherProcess.cpp', + 'src/common/Allocators.cpp', + 'src/common/FFT.cpp', + 'src/common/Log.cpp', 'src/common/Profiler.cpp', 'src/common/Resampler.cpp', - 'src/common/FFT.cpp', - 'src/common/Allocators.cpp', 'src/common/StretchCalculator.cpp', 'src/common/sysutils.cpp', 'src/common/Thread.cpp', diff --git a/rubberband/RubberBandStretcher.h b/rubberband/RubberBandStretcher.h index 60fc9d9..b806e48 100644 --- a/rubberband/RubberBandStretcher.h +++ b/rubberband/RubberBandStretcher.h @@ -37,6 +37,8 @@ #include #include +#include +#include #include /** @@ -277,7 +279,6 @@ public: * provided for backward compatibility only. They are ignored by * the stretcher. */ - enum Option { OptionProcessOffline = 0x00000000, @@ -331,6 +332,13 @@ public: PercussiveOptions = 0x00102000 }; + struct Logger { + virtual void log(const char *) = 0; + virtual void log(const char *, double) = 0; + virtual void log(const char *, double, double) = 0; + virtual ~Logger() { } + }; + /** * Construct a time and pitch stretcher object to run at the given * sample rate, with the given number of channels. @@ -361,6 +369,30 @@ public: Options options = DefaultOptions, double initialTimeRatio = 1.0, double initialPitchScale = 1.0); + + /** + * Construct a time and pitch stretcher object with a custom debug + * logger. This may be useful for debugging if the default logger + * output (which simply goes to cout) is not visible in the + * runtime environment, or if the application has a standard or + * more realtime-appropriate logging mechanism. + * + * See the documentation for the other constructor above for + * details of the arguments other than the logger. + * + * Note that although the supplied logger gets to decide what to + * do with log messages, the separately-set debug level (see + * setDebugLevel() and setDefaultDebugLevel()) still determines + * whether any given debug message is sent to the logger in the + * first place. + */ + RubberBandStretcher(size_t sampleRate, + size_t channels, + std::shared_ptr logger, + Options options = DefaultOptions, + double initialTimeRatio = 1.0, + double initialPitchScale = 1.0); + ~RubberBandStretcher(); /** diff --git a/src/RubberBandStretcher.cpp b/src/RubberBandStretcher.cpp index 6043217..2202832 100644 --- a/src/RubberBandStretcher.cpp +++ b/src/RubberBandStretcher.cpp @@ -24,24 +24,68 @@ #include "faster/R2Stretcher.h" #include "finer/R3Stretcher.h" +#include + namespace RubberBand { class RubberBandStretcher::Impl { R2Stretcher *m_r2; R3Stretcher *m_r3; - + + class CerrLogger : public RubberBandStretcher::Logger { + public: + void log(const char *message) override { + std::cerr << "RubberBand: " << message << "\n"; + } + void log(const char *message, double arg0) override { + auto prec = std::cerr.precision(); + std::cerr.precision(10); + std::cerr << "RubberBand: " << message << ": " << arg0 << "\n"; + std::cerr.precision(prec); + } + void log(const char *message, double arg0, double arg1) override { + auto prec = std::cerr.precision(); + std::cerr.precision(10); + std::cerr << "RubberBand: " << message + << ": (" << arg0 << ", " << arg1 << ")" << "\n"; + std::cerr.precision(prec); + } + }; + + Log makeRBLog(std::shared_ptr logger) { + if (logger) { + return Log( + [=](const char *message) { + logger->log(message); + }, + [=](const char *message, double arg0) { + logger->log(message, arg0); + }, + [=](const char *message, double arg0, double arg1) { + logger->log(message, arg0, arg1); + } + ); + } else { + return makeRBLog(std::shared_ptr + (new CerrLogger())); + } + } + public: Impl(size_t sampleRate, size_t channels, Options options, + std::shared_ptr logger, double initialTimeRatio, double initialPitchScale) : m_r2 (!(options & OptionEngineFiner) ? new R2Stretcher(sampleRate, channels, options, - initialTimeRatio, initialPitchScale) + initialTimeRatio, initialPitchScale, + makeRBLog(logger)) : nullptr), m_r3 ((options & OptionEngineFiner) ? new R3Stretcher(R3Stretcher::Parameters (double(sampleRate), channels, options), - initialTimeRatio, initialPitchScale) + initialTimeRatio, initialPitchScale, + makeRBLog(logger)) : nullptr) { } @@ -272,13 +316,13 @@ public: setDebugLevel(int level) { if (m_r2) m_r2->setDebugLevel(level); + else m_r3->setDebugLevel(level); } static void setDefaultDebugLevel(int level) { - R2Stretcher::setDefaultDebugLevel(level); -//!!! R3Stretcher::setDefaultDebugLevel(level); + Log::setDefaultDebugLevel(level); } }; @@ -287,7 +331,18 @@ RubberBandStretcher::RubberBandStretcher(size_t sampleRate, Options options, double initialTimeRatio, double initialPitchScale) : - m_d(new Impl(sampleRate, channels, options, + m_d(new Impl(sampleRate, channels, options, nullptr, + initialTimeRatio, initialPitchScale)) +{ +} + +RubberBandStretcher::RubberBandStretcher(size_t sampleRate, + size_t channels, + std::shared_ptr logger, + Options options, + double initialTimeRatio, + double initialPitchScale) : + m_d(new Impl(sampleRate, channels, options, logger, initialTimeRatio, initialPitchScale)) { } diff --git a/src/common/Log.cpp b/src/common/Log.cpp new file mode 100644 index 0000000..03b3536 --- /dev/null +++ b/src/common/Log.cpp @@ -0,0 +1,31 @@ +/* -*- c-basic-offset: 4 indent-tabs-mode: nil -*- vi:set ts=8 sts=4 sw=4: */ + +/* + Rubber Band Library + An audio time-stretching and pitch-shifting library. + Copyright 2007-2022 Particular Programs Ltd. + + This program is free software; you can redistribute it and/or + modify it under the terms of the GNU General Public License as + published by the Free Software Foundation; either version 2 of the + License, or (at your option) any later version. See the file + COPYING included with this distribution for more information. + + Alternatively, if you have a valid commercial licence for the + Rubber Band Library obtained by agreement with the copyright + holders, you may redistribute and/or modify it under the terms + described in that licence. + + If you wish to distribute code using the Rubber Band Library + under terms other than those of the GNU General Public License, + you must obtain a valid commercial licence before doing so. +*/ + +#include "Log.h" + +namespace RubberBand +{ + +int Log::m_defaultDebugLevel = 0; + +} diff --git a/src/common/Log.h b/src/common/Log.h new file mode 100644 index 0000000..b78315e --- /dev/null +++ b/src/common/Log.h @@ -0,0 +1,72 @@ +/* -*- c-basic-offset: 4 indent-tabs-mode: nil -*- vi:set ts=8 sts=4 sw=4: */ + +/* + Rubber Band Library + An audio time-stretching and pitch-shifting library. + Copyright 2007-2022 Particular Programs Ltd. + + This program is free software; you can redistribute it and/or + modify it under the terms of the GNU General Public License as + published by the Free Software Foundation; either version 2 of the + License, or (at your option) any later version. See the file + COPYING included with this distribution for more information. + + Alternatively, if you have a valid commercial licence for the + Rubber Band Library obtained by agreement with the copyright + holders, you may redistribute and/or modify it under the terms + described in that licence. + + If you wish to distribute code using the Rubber Band Library + under terms other than those of the GNU General Public License, + you must obtain a valid commercial licence before doing so. +*/ + +#ifndef RUBBERBAND_LOG_H +#define RUBBERBAND_LOG_H + +#include +#include + +namespace RubberBand { + +class Log { +public: + Log(std::function _log0, + std::function _log1, + std::function _log2) : + m_log0(_log0), + m_log1(_log1), + m_log2(_log2), + m_debugLevel(m_defaultDebugLevel) { } + + Log(const Log &other) =default; + Log(Log &&other) =default; + Log &operator=(const Log &other) =default; + Log &operator=(Log &&other) =default; + + void setDebugLevel(int level) { m_debugLevel = level; } + int getDebugLevel() const { return m_debugLevel; } + + static void setDefaultDebugLevel(int level) { m_defaultDebugLevel = level; } + + void log(int level, const char *message) const { + if (level <= m_debugLevel) m_log0(message); + } + void log(int level, const char *message, double arg0) const { + if (level <= m_debugLevel) m_log1(message, arg0); + } + void log(int level, const char *message, double arg0, double arg1) const { + if (level <= m_debugLevel) m_log2(message, arg0, arg1); + } + +private: + std::function m_log0; + std::function m_log1; + std::function m_log2; + int m_debugLevel; + static int m_defaultDebugLevel; +}; + +} + +#endif diff --git a/src/common/StretchCalculator.cpp b/src/common/StretchCalculator.cpp index 25c440f..7b98020 100644 --- a/src/common/StretchCalculator.cpp +++ b/src/common/StretchCalculator.cpp @@ -29,6 +29,7 @@ #include #include #include +#include #include "sysutils.h" @@ -37,7 +38,8 @@ namespace RubberBand StretchCalculator::StretchCalculator(size_t sampleRate, size_t inputIncrement, - bool useHardPeaks) : + bool useHardPeaks, + Log log) : m_sampleRate(sampleRate), m_increment(inputIncrement), m_prevDf(0), @@ -49,9 +51,10 @@ StretchCalculator::StretchCalculator(size_t sampleRate, m_useHardPeaks(useHardPeaks), m_inFrameCounter(0), m_frameCheckpoint(0, 0), - m_outFrameCounter(0) + m_outFrameCounter(0), + m_log(log) { -// std::cerr << "StretchCalculator::StretchCalculator: useHardPeaks = " << useHardPeaks << std::endl; + m_log.log(2, "StretchCalculator: useHardPeaks", useHardPeaks); } StretchCalculator::~StretchCalculator() @@ -83,25 +86,18 @@ StretchCalculator::calculate(double ratio, size_t inputDuration, size_t outputDuration = lrint(inputDuration * ratio); - if (m_debugLevel > 0) { - std::cerr << "StretchCalculator::calculate(): inputDuration " << inputDuration << ", ratio " << ratio << ", outputDuration " << outputDuration; - } + m_log.log(1, "StretchCalculator::calculate: inputDuration and ratio", inputDuration, ratio); outputDuration = lrint((phaseResetDf.size() * m_increment) * ratio); - if (m_debugLevel > 0) { - std::cerr << " (rounded up to " << outputDuration << ")"; - std::cerr << ", df size " << phaseResetDf.size() << ", increment " - << m_increment << std::endl; - } - + m_log.log(1, "StretchCalculator::calculate: outputDuration rounds up from and to", inputDuration * ratio, outputDuration); + m_log.log(1, "StretchCalculator::calculate: df size and increment", phaseResetDf.size(), m_increment); + std::vector peaks; // peak position (in chunks) and hardness std::vector targets; // targets for mapping peaks (in samples) mapPeaks(peaks, targets, outputDuration, totalCount); - if (m_debugLevel > 1) { - std::cerr << "have " << peaks.size() << " fixed positions" << std::endl; - } + m_log.log(2, "have fixed positions", peaks.size()); size_t totalInput = 0, totalOutput = 0; @@ -122,7 +118,6 @@ StretchCalculator::calculate(double ratio, size_t inputDuration, } if (i == peaks.size()) { -// std::cerr << "note: i (=" << i << ") == peaks.size(); regionEndChunk " << regionEndChunk << " -> " << totalCount << ", regionEnd " << regionEnd << " -> " << outputDuration << std::endl; regionEndChunk = totalCount; regionEnd = outputDuration; } else { @@ -141,15 +136,12 @@ StretchCalculator::calculate(double ratio, size_t inputDuration, size_t regionDuration = regionEnd - regionStart; size_t nchunks = regionEndChunk - regionStartChunk; - - if (m_debugLevel > 1) { - std::cerr << "region from " << regionStartChunk << " to " << regionEndChunk << " (samples " << regionStart << " to " << regionEnd << ")" << std::endl; - } + + m_log.log(2, "region from and to (chunks)", regionStartChunk, regionEndChunk); + m_log.log(2, "region from and to (samples)", regionStart, regionEnd); if (nchunks == 0) { - if (m_debugLevel > 1) { - std::cerr << "note: nchunks == 0" << std::endl; - } + m_log.log(2, "note: nchunks == 0"); continue; } @@ -195,10 +187,10 @@ StretchCalculator::calculate(double ratio, size_t inputDuration, totalOutput += totalForRegion; } - if (m_debugLevel > 0) { - std::cerr << "total input increment = " << totalInput << " (= " << totalInput / m_increment << " chunks), output = " << totalOutput << ", ratio = " << double(totalOutput)/double(totalInput) << ", ideal output " << size_t(ceil(totalInput * ratio)) << std::endl; - } - + m_log.log(1, "total input (frames, chunks)", totalInput, totalInput / m_increment); + m_log.log(1, "total output and achieved ratio", totalOutput, double(totalOutput)/double(totalInput)); + m_log.log(1, "ideal output", totalInput * ratio); + return increments; } @@ -237,8 +229,6 @@ StretchCalculator::mapPeaks(std::vector &peaks, while (mi != m_keyFrameMap.end()) { -// std::cerr << "mi->first is " << mi->first << ", second is " << mi->second < &peaks, sourceStartChunk >= sourceEndChunk || targetStartSample >= outputDuration || targetStartSample >= targetEndSample) { - std::cerr << "NOTE: ignoring mapping from chunk " << sourceStartChunk << " to sample " << targetStartSample << "\n(source or target chunk exceeds total count, or end is not later than start)" << std::endl; + m_log.log(0, "NOTE: ignoring key-frame mapping from chunk to sample", sourceStartChunk, targetStartSample); + m_log.log(0, "(source or target chunk exceeds total count, or end is not later than start)"); continue; } @@ -274,9 +265,7 @@ StretchCalculator::mapPeaks(std::vector &peaks, peaks.push_back(p); targets.push_back(targetStartSample); - if (m_debugLevel > 1) { - std::cerr << "mapped chunk " << sourceStartChunk << " (frame " << sourceStartChunk * m_increment << ") -> " << targetStartSample << std::endl; - } + m_log.log(2, "mapped key-frame chunk to frame", sourceStartChunk, targetStartSample); while (peakidx < m_peaks.size()) { @@ -316,9 +305,7 @@ StretchCalculator::mapPeaks(std::vector &peaks, continue; } - if (m_debugLevel > 1) { - std::cerr << " peak chunk " << pchunk << " (frame " << pchunk * m_increment << ") -> " << target << std::endl; - } + m_log.log(2, "mapped peak chunk to frame", pchunk, target); peaks.push_back(p); targets.push_back(target); @@ -389,9 +376,7 @@ StretchCalculator::calculateSingle(double timeRatio, // this function, which normally precedes resampling - hence // the use of timeRatio rather than ratio here - if (m_debugLevel > 1) { - std::cerr << "StretchCalculator: ratio changed from " << m_prevRatio << " to " << ratio << std::endl; - } + m_log.log(2, "StretchCalculator: ratio changed from and to", m_prevRatio, ratio); int64_t toCheckpoint = expectedOutFrame (m_inFrameCounter, m_prevTimeRatio); @@ -402,23 +387,25 @@ StretchCalculator::calculateSingle(double timeRatio, m_prevRatio = ratio; m_prevTimeRatio = timeRatio; - if (m_debugLevel > 2) { - std::cerr << "StretchCalculator::calculateSingle: timeRatio = " - << timeRatio << ", effectivePitchRatio = " - << effectivePitchRatio << " (that's 1.0 / " - << (1.0 / effectivePitchRatio) - << "), ratio = " << ratio << ", df = " << df - << ", inIncrement = " << inIncrement - << ", default outIncrement = " << outIncrement - << ", analysisWindowSize = " << analysisWindowSize - << ", synthesisWindowSize = " << synthesisWindowSize - << std::endl; + if (m_log.getDebugLevel() > 2) { + std::ostringstream os; + os << "StretchCalculator::calculateSingle: timeRatio = " + << timeRatio << ", effectivePitchRatio = " + << effectivePitchRatio << " (that's 1.0 / " + << (1.0 / effectivePitchRatio) + << "), ratio = " << ratio << ", df = " << df + << ", inIncrement = " << inIncrement + << ", default outIncrement = " << outIncrement + << ", analysisWindowSize = " << analysisWindowSize + << ", synthesisWindowSize = " << synthesisWindowSize + << "\n"; - std::cerr << "inFrameCounter = " << m_inFrameCounter - << ", outFrameCounter = " << m_outFrameCounter - << std::endl; + os << "inFrameCounter = " << m_inFrameCounter + << ", outFrameCounter = " << m_outFrameCounter + << "\n"; - std::cerr << "The next sample out is input sample " << m_inFrameCounter << std::endl; + os << "The next sample out is input sample " << m_inFrameCounter << "\n"; + m_log.log(3, os.str().c_str()); } int64_t intended, projected; @@ -436,9 +423,8 @@ StretchCalculator::calculateSingle(double timeRatio, int64_t divergence = projected - intended; - if (m_debugLevel > 2) { - std::cerr << "for current frame + quarter frame: intended " << intended << ", projected " << projected << ", divergence " << divergence << std::endl; - } + m_log.log(3, "for current frame + quarter frame: intended vs projected", intended, projected); + m_log.log(3, "divergence", divergence); // In principle, the threshold depends on chunk size: larger chunk // sizes need higher thresholds. Since chunk size depends on @@ -451,35 +437,26 @@ StretchCalculator::calculateSingle(double timeRatio, if (m_useHardPeaks && df > m_prevDf * 1.1f && df > transientThreshold) { if (divergence > 1000 || divergence < -1000) { - if (m_debugLevel > 1) { - std::cerr << "StretchCalculator::calculateSingle: transient, but we're not permitting it because the divergence (" << divergence << ") is too great" << std::endl; - } + m_log.log(2, "StretchCalculator::calculateSingle: transient, but we're not permitting it because the divergence is too great", divergence); } else { isTransient = true; } } - if (m_debugLevel > 2) { - std::cerr << "df = " << df << ", prevDf = " << m_prevDf - << ", thresh = " << transientThreshold << std::endl; - } + m_log.log(3, "df and prevDf", df, m_prevDf); m_prevDf = df; if (m_transientAmnesty > 0) { if (isTransient) { - if (m_debugLevel > 1) { - std::cerr << "StretchCalculator::calculateSingle: transient, but we have an amnesty (df " << df << ", threshold " << transientThreshold << ")" << std::endl; - } + m_log.log(2, "StretchCalculator::calculateSingle: transient, but we have an amnesty: df and threshold", df, transientThreshold); isTransient = false; } --m_transientAmnesty; } if (isTransient) { - if (m_debugLevel > 1) { - std::cerr << "StretchCalculator::calculateSingle: transient at (df " << df << ", threshold " << transientThreshold << ")" << std::endl; - } + m_log.log(2, "StretchCalculator::calculateSingle: transient: df and threshold", df, transientThreshold); // as in offline mode, 0.05 sec approx min between transients m_transientAmnesty = @@ -499,9 +476,10 @@ StretchCalculator::calculateSingle(double timeRatio, } int incr = lrint(outIncrement - recovery); - if (m_debugLevel > 2 || (m_debugLevel > 1 && divergence != 0)) { - std::cerr << "divergence = " << divergence << ", recovery = " << recovery << ", incr = " << incr << ", "; - } + + int level = (divergence != 0 ? 2 : 3); + m_log.log(level, "divergence and recovery", divergence, recovery); + m_log.log(level, "outIncrement and adjusted incr", outIncrement, incr); int minIncr = lrint(increment * ratio * 0.3); int maxIncr = lrint(increment * ratio * 2); @@ -512,25 +490,18 @@ StretchCalculator::calculateSingle(double timeRatio, incr = maxIncr; } - if (m_debugLevel > 2 || (m_debugLevel > 1 && divergence != 0)) { - std::cerr << "clamped into [" << minIncr << ", " << maxIncr - << "] becomes " << incr << std::endl; - } + m_log.log(level, "clamped into", minIncr, maxIncr); + m_log.log(level, "giving incr", incr); if (incr < 0) { - std::cerr << "WARNING: internal error: incr < 0 in calculateSingle" - << std::endl; + m_log.log(0, "WARNING: internal error: incr < 0 in calculateSingle"); outIncrement = 0; } else { outIncrement = incr; } } - if (m_debugLevel > 1) { - std::cerr << "StretchCalculator::calculateSingle: returning isTransient = " - << isTransient << ", outIncrement = " << outIncrement - << std::endl; - } + m_log.log(2, "StretchCalculator::calculateSingle: returning isTransient and outIncrement", isTransient, outIncrement); m_inFrameCounter += inIncrement; m_outFrameCounter += outIncrement * effectivePitchRatio; @@ -584,9 +555,7 @@ StretchCalculator::findPeaks(const std::vector &rawDf) (20 * double(m_increment)))); size_t prevHardPeak = 0; - if (m_debugLevel > 1) { - std::cerr << "hardPeakAmnesty = " << hardPeakAmnesty << std::endl; - } + m_log.log(2, "hardPeakAmnesty", hardPeakAmnesty); for (size_t i = 1; i + 1 < df.size(); ++i) { @@ -600,20 +569,16 @@ StretchCalculator::findPeaks(const std::vector &rawDf) } bool hard = (df[i] > 0.4); - - if (hard && (m_debugLevel > 1)) { - std::cerr << "hard peak at " << i << ": " << df[i] - << " > absolute " << 0.4 - << std::endl; + + if (hard) { + m_log.log(2, "hard peak, df > absolute 0.4: chunk and df", i, df[i]); } if (!hard) { hard = (df[i] > df[i-1] * 1.4); - if (hard && (m_debugLevel > 1)) { - std::cerr << "hard peak at " << i << ": " << df[i] - << " > prev " << df[i-1] << " * 1.4" - << std::endl; + if (hard) { + m_log.log(2, "hard peak, single rise of 40%: chunk and df", i, df[i]); } } @@ -621,11 +586,8 @@ StretchCalculator::findPeaks(const std::vector &rawDf) hard = (df[i] > df[i-1] * 1.2 && df[i-1] > df[i-2] * 1.2); - if (hard && (m_debugLevel > 1)) { - std::cerr << "hard peak at " << i << ": " << df[i] - << " > prev " << df[i-1] << " * 1.2 and " - << df[i-1] << " > prev " << df[i-2] << " * 1.2" - << std::endl; + if (hard) { + m_log.log(2, "hard peak, two rises of 20%: chunk and df", i, df[i]); } } @@ -635,20 +597,13 @@ StretchCalculator::findPeaks(const std::vector &rawDf) df[i-1] > df[i-2] * 1.1 && df[i-2] > df[i-3] * 1.1); - if (hard && (m_debugLevel > 1)) { - std::cerr << "hard peak at " << i << ": " << df[i] - << " > prev " << df[i-1] << " * 1.1 and " - << df[i-1] << " > prev " << df[i-2] << " * 1.1 and " - << df[i-2] << " > prev " << df[i-3] << " * 1.1" - << std::endl; + if (hard) { + m_log.log(2, "hard peak, three rises of 10%: chunk and df", i, df[i]); } } if (!hard) continue; -// (df[i+1] > df[i] && df[i+1] > df[i-1] * 1.8) || -// df[i] > 0.4) { - size_t peakLocation = i; if (i + 1 < rawDf.size() && @@ -656,9 +611,7 @@ StretchCalculator::findPeaks(const std::vector &rawDf) ++peakLocation; - if (m_debugLevel > 1) { - std::cerr << "pushing hard peak forward to " << peakLocation << ": " << df[peakLocation] << " > " << df[peakLocation-1] << " * " << 1.4 << std::endl; - } + m_log.log(2, "big rise next, pushing hard peak forward to", peakLocation); } hardPeakCandidates.insert(peakLocation); @@ -669,14 +622,10 @@ StretchCalculator::findPeaks(const std::vector &rawDf) size_t medianmaxsize = lrint(ceil(double(m_sampleRate) / double(m_increment))); // 1 sec ish - if (m_debugLevel > 1) { - std::cerr << "mediansize = " << medianmaxsize << std::endl; - } + m_log.log(2, "mediansize", medianmaxsize); if (medianmaxsize < 7) { medianmaxsize = 7; - if (m_debugLevel > 1) { - std::cerr << "adjusted mediansize = " << medianmaxsize << std::endl; - } + m_log.log(2, "adjusted mediansize", medianmaxsize); } int minspacing = lrint(ceil(double(m_sampleRate) / @@ -720,10 +669,6 @@ StretchCalculator::findPeaks(const std::vector &rawDf) continue; } - if (m_debugLevel > 2) { -// std::cerr << "have " << mediansize << " in median buffer" << std::endl; - } - sorted.clear(); for (size_t j = 0; j < mediansize; ++j) { sorted.push_back(medianwin[j]); @@ -736,17 +681,6 @@ StretchCalculator::findPeaks(const std::vector &rawDf) if (index == sorted.size()-1 && index > 0) --index; float thresh = sorted[index]; -// if (m_debugLevel > 2) { -// std::cerr << "medianwin[" << middle << "] = " << medianwin[middle] << ", thresh = " << thresh << std::endl; -// if (medianwin[middle] == 0.f) { -// std::cerr << "contents: "; -// for (size_t j = 0; j < medianwin.size(); ++j) { -// std::cerr << medianwin[j] << " "; -// } -// std::cerr << std::endl; -// } -// } - if (medianwin[middle] > thresh && medianwin[middle] > medianwin[middle-1] && medianwin[middle] > medianwin[middle+1] && @@ -766,26 +700,10 @@ StretchCalculator::findPeaks(const std::vector &rawDf) size_t peak = i + maxindex - middle; -// std::cerr << "i = " << i << ", maxindex = " << maxindex << ", middle = " << middle << ", so peak at " << peak << std::endl; - if (softPeakCandidates.empty() || lastSoftPeak != peak) { - - if (m_debugLevel > 1) { - std::cerr << "soft peak at " << peak << " (" - << peak * m_increment << "): " - << medianwin[middle] << " > " - << thresh << " and " - << medianwin[middle] - << " > " << medianwin[middle-1] << " and " - << medianwin[middle] - << " > " << medianwin[middle+1] - << std::endl; - } - + m_log.log(2, "soft peak: chunk and median df", peak, medianwin[middle]); if (peak >= df.size()) { - if (m_debugLevel > 2) { - std::cerr << "peak is beyond end" << std::endl; - } + m_log.log(2, "peak is beyond end"); } else { softPeakCandidates.insert(peak); lastSoftPeak = peak; @@ -793,9 +711,7 @@ StretchCalculator::findPeaks(const std::vector &rawDf) } softPeakAmnesty = minspacing + maxindex - middle; - if (m_debugLevel > 2) { - std::cerr << "amnesty = " << softPeakAmnesty << std::endl; - } + m_log.log(3, "amnesty", softPeakAmnesty); } else if (softPeakAmnesty > 0) --softPeakAmnesty; @@ -827,26 +743,16 @@ StretchCalculator::findPeaks(const std::vector &rawDf) if (haveHardPeak && (!haveSoftPeak || hardPeak <= softPeak)) { - - if (m_debugLevel > 2) { - std::cerr << "Hard peak: " << hardPeak << std::endl; - } - + m_log.log(3, "hard peak", hardPeak); peak.hard = true; peak.chunk = hardPeak; hardPeakCandidates.erase(hardPeakCandidates.begin()); - } else { - if (m_debugLevel > 2) { - std::cerr << "Soft peak: " << softPeak << std::endl; - } + m_log.log(3, "soft peak", softPeak); if (!peaks.empty() && peaks[peaks.size()-1].hard && peaks[peaks.size()-1].chunk + 3 >= softPeak) { - if (m_debugLevel > 2) { - std::cerr << "(ignoring, as we just had a hard peak)" - << std::endl; - } + m_log.log(3, "ignoring, as we just had a hard peak"); ignore = true; } } diff --git a/src/common/StretchCalculator.h b/src/common/StretchCalculator.h index e1f91fc..af12780 100644 --- a/src/common/StretchCalculator.h +++ b/src/common/StretchCalculator.h @@ -30,13 +30,18 @@ #include #include +#include "Log.h" + namespace RubberBand { class StretchCalculator { public: - StretchCalculator(size_t sampleRate, size_t inputIncrement, bool useHardPeaks); + StretchCalculator(size_t sampleRate, + size_t inputIncrement, + bool useHardPeaks, + Log log); virtual ~StretchCalculator(); /** @@ -107,6 +112,7 @@ protected: std::pair m_frameCheckpoint; int64_t expectedOutFrame(int64_t inFrame, double timeRatio); double m_outFrameCounter; + Log m_log; std::map m_keyFrameMap; std::vector m_peaks; diff --git a/src/faster/R2Stretcher.cpp b/src/faster/R2Stretcher.cpp index 202f69a..46e044c 100644 --- a/src/faster/R2Stretcher.cpp +++ b/src/faster/R2Stretcher.cpp @@ -40,8 +40,6 @@ #include #include -using std::cerr; -using std::endl; using std::vector; using std::map; using std::set; @@ -56,16 +54,14 @@ R2Stretcher::m_defaultIncrement = 256; const size_t R2Stretcher::m_defaultFftSize = 2048; -int -R2Stretcher::m_defaultDebugLevel = 0; - static bool _initialised = false; R2Stretcher::R2Stretcher(size_t sampleRate, size_t channels, RubberBandStretcher::Options options, double initialTimeRatio, - double initialPitchScale) : + double initialPitchScale, + Log log) : m_sampleRate(sampleRate), m_channels(channels), m_timeRatio(initialTimeRatio), @@ -82,7 +78,7 @@ R2Stretcher::R2Stretcher(size_t sampleRate, #endif m_realtime(false), m_options(options), - m_debugLevel(m_defaultDebugLevel), + m_log(log), m_mode(JustCreated), m_awindow(0), m_afilter(0), @@ -110,9 +106,10 @@ R2Stretcher::R2Stretcher(size_t sampleRate, _initialised = true; } - if (m_debugLevel > 0) { - cerr << "R2Stretcher::R2Stretcher: rate = " << m_sampleRate << ", options = " << options << endl; - } + m_log.log(1, "R2Stretcher::R2Stretcher: rate, options", + m_sampleRate, options); + m_log.log(1, "R2Stretcher::R2Stretcher: initial time ratio and pitch scale", + m_timeRatio, m_pitchScale); // Window size will vary according to the audio sample rate, but // we don't let it drop below the 48k default @@ -124,17 +121,13 @@ R2Stretcher::R2Stretcher(size_t sampleRate, (options & RubberBandStretcher::OptionWindowLong)) { if ((options & RubberBandStretcher::OptionWindowShort) && (options & RubberBandStretcher::OptionWindowLong)) { - cerr << "R2Stretcher::R2Stretcher: Cannot specify OptionWindowLong and OptionWindowShort together; falling back to OptionWindowStandard" << endl; + m_log.log(0, "R2Stretcher::R2Stretcher: Cannot specify OptionWindowLong and OptionWindowShort together; falling back to OptionWindowStandard"); } else if (options & RubberBandStretcher::OptionWindowShort) { m_baseFftSize = m_baseFftSize / 2; - if (m_debugLevel > 0) { - cerr << "setting baseFftSize to " << m_baseFftSize << endl; - } + m_log.log(1, "setting baseFftSize", m_baseFftSize); } else if (options & RubberBandStretcher::OptionWindowLong) { m_baseFftSize = m_baseFftSize * 2; - if (m_debugLevel > 0) { - cerr << "setting baseFftSize to " << m_baseFftSize << endl; - } + m_log.log(1, "setting baseFftSize", m_baseFftSize); } m_fftSize = m_baseFftSize; m_aWindowSize = m_baseFftSize; @@ -161,8 +154,8 @@ R2Stretcher::R2Stretcher(size_t sampleRate, m_threaded = false; } - if (m_threaded && m_debugLevel > 0) { - cerr << "Going multithreaded..." << endl; + if (m_threaded) { + m_log.log(1, "Going multithreaded..."); } } #endif @@ -177,9 +170,7 @@ R2Stretcher::~R2Stretcher() MutexLocker locker(&m_threadSetMutex); for (set::iterator i = m_threadSet.begin(); i != m_threadSet.end(); ++i) { - if (m_debugLevel > 0) { - cerr << "RubberBandStretcher::~RubberBandStretcher: joining (channel " << *i << ")" << endl; - } + m_log.log(1, "RubberBandStretcher::~RubberBandStretcher: joining for channel", (*i)->channel()); (*i)->abandon(); (*i)->wait(); delete *i; @@ -214,9 +205,7 @@ R2Stretcher::reset() m_threadSetMutex.lock(); for (set::iterator i = m_threadSet.begin(); i != m_threadSet.end(); ++i) { - if (m_debugLevel > 0) { - cerr << "RubberBandStretcher::~RubberBandStretcher: joining (channel " << *i << ")" << endl; - } + m_log.log(1, "RubberBandStretcher::~RubberBandStretcher: joining for channel", (*i)->channel()); (*i)->abandon(); (*i)->wait(); delete *i; @@ -253,7 +242,7 @@ R2Stretcher::setTimeRatio(double ratio) { if (!m_realtime) { if (m_mode == Studying || m_mode == Processing) { - cerr << "R2Stretcher::setTimeRatio: Cannot set ratio while studying or processing in non-RT mode" << endl; + m_log.log(0, "R2Stretcher::setTimeRatio: Cannot set ratio while studying or processing in non-RT mode"); return; } } @@ -269,7 +258,7 @@ R2Stretcher::setPitchScale(double fs) { if (!m_realtime) { if (m_mode == Studying || m_mode == Processing) { - cerr << "R2Stretcher::setPitchScale: Cannot set ratio while studying or processing in non-RT mode" << endl; + m_log.log(0, "R2Stretcher::setPitchScale: Cannot set ratio while studying or processing in non-RT mode"); return; } } @@ -331,11 +320,11 @@ R2Stretcher::setKeyFrameMap(const std::map & mapping) { if (m_realtime) { - cerr << "R2Stretcher::setKeyFrameMap: Cannot specify key frame map in RT mode" << endl; + m_log.log(0, "R2Stretcher::setKeyFrameMap: Cannot specify key frame map in RT mode"); return; } if (m_mode == Processing) { - cerr << "R2Stretcher::setKeyFrameMap: Cannot specify key frame map after process() has begun" << endl; + m_log.log(0, "R2Stretcher::setKeyFrameMap: Cannot specify key frame map after process() has begun"); return; } @@ -403,12 +392,12 @@ R2Stretcher::calculateSizes() // This special case is likelier than one might hope, because // of naive initialisations in programs that set it from a // variable - std::cerr << "RubberBandStretcher: WARNING: Pitch scale must be greater than zero!\nResetting it from " << m_pitchScale << " to the default of 1.0: no pitch change will occur" << std::endl; + m_log.log(0, "WARNING: Pitch scale must be greater than zero! Resetting it to default, no pitch shift will happen", m_pitchScale); m_pitchScale = 1.0; } if (m_timeRatio <= 0.0) { // Likewise - std::cerr << "RubberBandStretcher: WARNING: Time ratio must be greater than zero!\nResetting it from " << m_timeRatio << " to the default of 1.0: no time stretch will occur" << std::endl; + m_log.log(0, "WARNING: Time ratio must be greater than zero! Resetting it to default, no time stretch will happen", m_timeRatio); m_timeRatio = 1.0; } @@ -461,7 +450,7 @@ R2Stretcher::calculateSizes() if (windowSize < minwin) windowSize = minwin; if (rsb) { -// cerr << "adjusting window size from " << windowSize; + size_t oldWindowSize = windowSize; size_t newWindowSize = roundUp(lrint(windowSize / m_pitchScale)); if (newWindowSize < 512) newWindowSize = 512; size_t div = windowSize / newWindowSize; @@ -470,7 +459,8 @@ R2Stretcher::calculateSizes() outputIncrement /= div; windowSize /= div; } -// cerr << " to " << windowSize << " (inputIncrement = " << inputIncrement << ", outputIncrement = " << outputIncrement << ")" << endl; + m_log.log(2, "adjusting window size from/to", oldWindowSize, windowSize); + m_log.log(2, "input and output increments", inputIncrement, outputIncrement); } } @@ -530,10 +520,11 @@ R2Stretcher::calculateSizes() // twice the basic output increment (i.e. input increment times // ratio) for any chunk. - if (m_debugLevel > 0) { - cerr << "calculateSizes: time ratio = " << m_timeRatio << ", pitch scale = " << m_pitchScale << ", effective ratio = " << getEffectiveRatio() << endl; - cerr << "calculateSizes: analysis window size = " << m_aWindowSize << ", synthesis window size = " << m_sWindowSize << ", fft size = " << m_fftSize << ", increment = " << m_increment << " (approx output increment = " << int(lrint(m_increment * getEffectiveRatio())) << ")" << endl; - } + m_log.log(1, "calculateSizes: time ratio and pitch scale", m_timeRatio, m_pitchScale); + m_log.log(1, "effective ratio", getEffectiveRatio()); + m_log.log(1, "analysis and synthesis window sizes", m_aWindowSize, m_sWindowSize); + m_log.log(1, "fft size", m_fftSize); + m_log.log(1, "input increment and mean output increment", m_increment, m_increment * getEffectiveRatio()); if (std::max(m_aWindowSize, m_sWindowSize) > m_maxProcessSize) { m_maxProcessSize = std::max(m_aWindowSize, m_sWindowSize); @@ -561,18 +552,19 @@ R2Stretcher::calculateSizes() #endif } - if (m_debugLevel > 0) { - cerr << "calculateSizes: outbuf size = " << m_outbufSize << endl; - } + m_log.log(1, "calculateSizes: outbuf size", m_outbufSize); } void R2Stretcher::configure() { - if (m_debugLevel > 0) { - std::cerr << "configure[" << this << "]: realtime = " << m_realtime << ", pitch scale = " - << m_pitchScale << ", channels = " << m_channels << std::endl; - } + if (m_realtime) { + m_log.log(1, "configure, realtime: pitch scale and channels", + m_pitchScale, m_channels); + } else { + m_log.log(1, "configure, offline: pitch scale and channels", + m_pitchScale, m_channels); + } size_t prevFftSize = m_fftSize; size_t prevAWindowSize = m_aWindowSize; @@ -626,9 +618,8 @@ R2Stretcher::configure() m_afilter = m_sincs[m_aWindowSize]; m_swindow = m_windows[m_sWindowSize]; - if (m_debugLevel > 0) { - cerr << "Window area: " << m_awindow->getArea() << "; synthesis window area: " << m_swindow->getArea() << endl; - } + m_log.log(1, "analysis and synthesis window areas", + m_awindow->getArea(), m_swindow->getArea()); } if (windowSizeChanged || outbufSizeChanged) { @@ -649,7 +640,7 @@ R2Stretcher::configure() if (!m_realtime && fftSizeChanged) { delete m_studyFFT; - m_studyFFT = new FFT(m_fftSize, m_debugLevel); + m_studyFFT = new FFT(m_fftSize, m_log.getDebugLevel()); m_studyFFT->initFloat(); } @@ -674,7 +665,8 @@ R2Stretcher::configure() } params.maxBufferSize = 4096 * 16; - params.debugLevel = (m_debugLevel > 0 ? m_debugLevel-1 : 0); + int myLevel = m_log.getDebugLevel(); + params.debugLevel = (myLevel > 0 ? myLevel-1 : 0); m_channelData[c]->resampler = new Resampler(params, 1); @@ -700,9 +692,10 @@ R2Stretcher::configure() delete m_stretchCalculator; m_stretchCalculator = new StretchCalculator (m_sampleRate, m_increment, - !(m_options & RubberBandStretcher::OptionTransientsSmooth)); + !(m_options & RubberBandStretcher::OptionTransientsSmooth), + m_log); - m_stretchCalculator->setDebugLevel(m_debugLevel); + m_stretchCalculator->setDebugLevel(m_log.getDebugLevel()); m_inputDuration = 0; // Prepare the inbufs with half a chunk of emptiness. The centre @@ -717,17 +710,16 @@ R2Stretcher::configure() // want gaps when the ratio changes. if (!m_realtime) { - if (m_debugLevel > 1) { - cerr << "Not real time mode: prefilling with " << m_aWindowSize/2 << " samples" << endl; - } + m_log.log(1, "offline mode: prefilling with", m_aWindowSize/2); for (size_t c = 0; c < m_channels; ++c) { m_channelData[c]->reset(); m_channelData[c]->inbuf->zero(m_aWindowSize/2); } + } else { + m_log.log(1, "realtime mode: no prefill"); } } - void R2Stretcher::reconfigure() { @@ -763,7 +755,7 @@ R2Stretcher::reconfigure() m_sWindowSize != prevSWindowSize) { if (m_windows.find(m_aWindowSize) == m_windows.end()) { - std::cerr << "WARNING: reconfigure(): window allocation (size " << m_aWindowSize << ") required in RT mode" << std::endl; + m_log.log(0, "WARNING: reconfigure(): window allocation required in realtime mode, size", m_aWindowSize); m_windows[m_aWindowSize] = new Window (HannWindow, m_aWindowSize); m_sincs[m_aWindowSize] = new SincWindow @@ -771,7 +763,7 @@ R2Stretcher::reconfigure() } if (m_windows.find(m_sWindowSize) == m_windows.end()) { - std::cerr << "WARNING: reconfigure(): window allocation (size " << m_sWindowSize << ") required in RT mode" << std::endl; + m_log.log(0, "WARNING: reconfigure(): window allocation required in realtime mode, size", m_sWindowSize); m_windows[m_sWindowSize] = new Window (HannWindow, m_sWindowSize); m_sincs[m_sWindowSize] = new SincWindow @@ -802,14 +794,15 @@ R2Stretcher::reconfigure() if (m_channelData[c]->resampler) continue; - std::cerr << "WARNING: reconfigure(): resampler construction required in RT mode" << std::endl; + m_log.log(0, "WARNING: reconfigure(): resampler construction required in RT mode"); Resampler::Parameters params; params.quality = Resampler::FastestTolerable; params.dynamism = Resampler::RatioOftenChanging; params.ratioChange = Resampler::SmoothRatioChange; params.maxBufferSize = m_sWindowSize; - params.debugLevel = (m_debugLevel > 0 ? m_debugLevel-1 : 0); + int myLevel = m_log.getDebugLevel(); + params.debugLevel = (myLevel > 0 ? myLevel-1 : 0); m_channelData[c]->resampler = new Resampler(params, 1); @@ -828,12 +821,10 @@ R2Stretcher::reconfigure() somethingChanged = true; } - if (m_debugLevel > 0) { - if (somethingChanged) { - std::cerr << "reconfigure: at least one parameter changed" << std::endl; - } else { - std::cerr << "reconfigure: nothing changed" << std::endl; - } + if (somethingChanged) { + m_log.log(1, "reconfigure: at least one parameter changed"); + } else { + m_log.log(1, "reconfigure: nothing changed"); } } @@ -848,7 +839,7 @@ void R2Stretcher::setTransientsOption(RubberBandStretcher::Options options) { if (!m_realtime) { - cerr << "R2Stretcher::setTransientsOption: Not permissible in non-realtime mode" << endl; + m_log.log(0, "R2Stretcher::setTransientsOption: Not permissible in non-realtime mode"); return; } int mask = (RubberBandStretcher::OptionTransientsMixed | @@ -866,7 +857,7 @@ void R2Stretcher::setDetectorOption(RubberBandStretcher::Options options) { if (!m_realtime) { - cerr << "R2Stretcher::setDetectorOption: Not permissible in non-realtime mode" << endl; + m_log.log(0, "R2Stretcher::setDetectorOption: Not permissible in non-realtime mode"); return; } int mask = (RubberBandStretcher::OptionDetectorPercussive | @@ -915,7 +906,7 @@ void R2Stretcher::setPitchOption(RubberBandStretcher::Options options) { if (!m_realtime) { - cerr << "R2Stretcher::setPitchOption: Pitch option is not used in non-RT mode" << endl; + m_log.log(0, "R2Stretcher::setPitchOption: Pitch option is not used in non-RT mode"); return; } @@ -937,14 +928,12 @@ R2Stretcher::study(const float *const *input, size_t samples, bool final) Profiler profiler("R2Stretcher::study"); if (m_realtime) { - if (m_debugLevel > 1) { - cerr << "R2Stretcher::study: Not meaningful in realtime mode" << endl; - } + m_log.log(0, "R2Stretcher::study: Not meaningful in realtime mode"); return; } if (m_mode == Processing || m_mode == Finished) { - cerr << "R2Stretcher::study: Cannot study after processing" << endl; + m_log.log(0, "R2Stretcher::study: Cannot study after processing"); return; } m_mode = Studying; @@ -987,7 +976,8 @@ R2Stretcher::study(const float *const *input, size_t samples, bool final) if (writable == 0) { // warn - cerr << "WARNING: writable == 0 (consumed = " << consumed << ", samples = " << samples << ")" << endl; + m_log.log(0, "WARNING: writable == 0: consumed, samples", + consumed, samples); } else { inbuf.write(mixdown + consumed, writable); consumed += writable; @@ -1048,8 +1038,8 @@ R2Stretcher::study(const float *const *input, size_t samples, bool final) df = m_silentAudioCurve->processFloat(cd.fltbuf, m_increment); bool silent = (df > 0.f); - if (silent && m_debugLevel > 1) { - cerr << "silence found at " << m_inputDuration << endl; + if (silent) { + m_log.log(2, "silence at", m_inputDuration); } m_silence.push_back(silent); @@ -1063,7 +1053,6 @@ R2Stretcher::study(const float *const *input, size_t samples, bool final) // extra afterwards. m_inputDuration += m_increment; -// cerr << "incr input duration by increment: " << m_increment << " -> " << m_inputDuration << endl; inbuf.skip(m_increment); } } @@ -1071,8 +1060,6 @@ R2Stretcher::study(const float *const *input, size_t samples, bool final) if (final) { int rs = inbuf.getReadSpace(); m_inputDuration += rs; -// cerr << "incr input duration by read space: " << rs << " -> " << m_inputDuration << endl; - if (m_inputDuration > m_aWindowSize/2) { // deducting the extra m_inputDuration -= m_aWindowSize/2; } @@ -1132,7 +1119,7 @@ R2Stretcher::calculateStretch() if (!m_realtime && m_expectedInputDuration > 0) { if (m_expectedInputDuration != inputDuration) { - std::cerr << "RubberBandStretcher: WARNING: Actual study() duration differs from duration set by setExpectedInputDuration (" << m_inputDuration << " vs " << m_expectedInputDuration << ", diff = " << (m_expectedInputDuration - m_inputDuration) << "), using the latter for calculation" << std::endl; + m_log.log(0, "WARNING: Actual study() duration differs from duration set by setExpectedInputDuration - using the latter for calculation", m_inputDuration, m_expectedInputDuration); inputDuration = m_expectedInputDuration; } } @@ -1149,10 +1136,7 @@ R2Stretcher::calculateStretch() else history = 0; if (history >= int(m_aWindowSize / m_increment) && increments[i] >= 0) { increments[i] = -increments[i]; - if (m_debugLevel > 1) { - std::cerr << "phase reset on silence (silent history == " - << history << ")" << std::endl; - } + m_log.log(2, "phase reset on silence: silent history", history); } } @@ -1169,8 +1153,10 @@ R2Stretcher::calculateStretch() void R2Stretcher::setDebugLevel(int level) { - m_debugLevel = level; - if (m_stretchCalculator) m_stretchCalculator->setDebugLevel(level); + m_log.setDebugLevel(level); + if (m_stretchCalculator) { + m_stretchCalculator->setDebugLevel(level); + } } size_t @@ -1191,9 +1177,7 @@ R2Stretcher::getSamplesRequired() const size_t rs = inbuf.getReadSpace(); size_t ws = outbuf.getReadSpace(); - if (m_debugLevel > 2) { - cerr << "getSamplesRequired: ws = " << ws << ", rs = " << rs << ", m_aWindowSize = " << m_aWindowSize << endl; - } + m_log.log(3, "getSamplesRequired: ws and rs ", ws, rs); // We should never return zero in non-threaded modes if // available() would also return zero, i.e. if ws == 0. If we @@ -1230,7 +1214,7 @@ R2Stretcher::process(const float *const *input, size_t samples, bool final) Profiler profiler("R2Stretcher::process"); if (m_mode == Finished) { - cerr << "R2Stretcher::process: Cannot process again after final chunk" << endl; + m_log.log(0, "R2Stretcher::process: Cannot process again after final chunk"); return; } @@ -1243,9 +1227,7 @@ R2Stretcher::process(const float *const *input, size_t samples, bool final) if (!m_realtime) { // See note in configure() above. Of course, we should // never enter Studying unless we are non-RT anyway - if (m_debugLevel > 1) { - cerr << "Not real time mode: prefilling" << endl; - } + m_log.log(1, "offline mode: prefilling with", m_aWindowSize/2); for (size_t c = 0; c < m_channels; ++c) { m_channelData[c]->reset(); m_channelData[c]->inbuf->zero(m_aWindowSize/2); @@ -1262,10 +1244,8 @@ R2Stretcher::process(const float *const *input, size_t samples, bool final) m_threadSet.insert(thread); thread->start(); } - - if (m_debugLevel > 0) { - cerr << m_channels << " threads created" << endl; - } + + m_log.log(1, "created threads", m_channels); } #endif @@ -1297,12 +1277,10 @@ R2Stretcher::process(const float *const *input, size_t samples, bool final) final); if (consumed[c] < samples) { allConsumed = false; -// cerr << "process: waiting on input consumption for channel " << c << endl; } else { if (final) { m_channelData[c]->inputSize = m_channelData[c]->inCount; } -// cerr << "process: happy with channel " << c << endl; } if ( #ifndef NO_THREADING @@ -1335,14 +1313,10 @@ R2Stretcher::process(const float *const *input, size_t samples, bool final) } #endif - if (m_debugLevel > 1) { - if (!allConsumed) cerr << "process looping" << endl; - } + m_log.log(2, "process looping"); } - if (m_debugLevel > 1) { - cerr << "process returning" << endl; - } + m_log.log(2, "process returning"); if (final) m_mode = Finished; } diff --git a/src/faster/R2Stretcher.h b/src/faster/R2Stretcher.h index 06efbcb..b9e1709 100644 --- a/src/faster/R2Stretcher.h +++ b/src/faster/R2Stretcher.h @@ -31,6 +31,7 @@ #include "../common/RingBuffer.h" #include "../common/Scavenger.h" #include "../common/Thread.h" +#include "../common/Log.h" #include "../common/sysutils.h" #include "SincWindow.h" @@ -50,7 +51,8 @@ class R2Stretcher public: R2Stretcher(size_t sampleRate, size_t channels, RubberBandStretcher::Options options, - double initialTimeRatio, double initialPitchScale); + double initialTimeRatio, double initialPitchScale, + Log log); ~R2Stretcher(); void reset(); @@ -98,7 +100,6 @@ public: void calculateStretch(); void setDebugLevel(int level); - static void setDefaultDebugLevel(int level) { m_defaultDebugLevel = level; } protected: size_t m_sampleRate; @@ -174,7 +175,7 @@ protected: bool m_realtime; RubberBandStretcher::Options m_options; - int m_debugLevel; + Log m_log; enum ProcessMode { JustCreated, @@ -202,6 +203,7 @@ protected: void run(); void signalDataAvailable(); void abandon(); + size_t channel() { return m_channel; } private: R2Stretcher *m_s; size_t m_channel; @@ -251,7 +253,6 @@ protected: void writeOutput(RingBuffer &to, float *from, size_t qty, size_t &outCount, size_t theoreticalOut); - static int m_defaultDebugLevel; static const size_t m_defaultIncrement; static const size_t m_defaultFftSize; }; diff --git a/src/faster/StretcherChannelData.cpp b/src/faster/StretcherChannelData.cpp index 43af2d2..81c47d2 100644 --- a/src/faster/StretcherChannelData.cpp +++ b/src/faster/StretcherChannelData.cpp @@ -56,8 +56,6 @@ R2Stretcher::ChannelData::construct(const std::set &sizes, size_t maxSize = initialWindowSize * 2; if (initialFftSize > maxSize) maxSize = initialFftSize; -// std::cerr << "ChannelData::construct: initialWindowSize = " << initialWindowSize << ", initialFftSize = " << initialFftSize << ", outbufSize = " << outbufSize << std::endl; - // std::set is ordered by value std::set::const_iterator i = sizes.end(); if (i != sizes.begin()) { @@ -68,8 +66,6 @@ R2Stretcher::ChannelData::construct(const std::set &sizes, // max possible size of the real "half" of freq data size_t realSize = maxSize / 2 + 1; -// std::cerr << "ChannelData::construct([" << sizes.size() << "], " << maxSize << ", " << realSize << ", " << outbufSize << ")" << std::endl; - if (outbufSize < maxSize) outbufSize = maxSize; inbuf = new RingBuffer(maxSize); @@ -117,8 +113,6 @@ void R2Stretcher::ChannelData::setSizes(size_t windowSize, size_t fftSize) { -// std::cerr << "ChannelData::setSizes: windowSize = " << windowSize << ", fftSize = " << fftSize << std::endl; - size_t maxSize = 2 * std::max(windowSize, fftSize); size_t realSize = maxSize / 2 + 1; size_t oldMax = inbuf->getSize(); @@ -210,8 +204,6 @@ R2Stretcher::ChannelData::setOutbufSize(size_t outbufSize) { size_t oldSize = outbuf->getSize(); -// std::cerr << "ChannelData::setOutbufSize(" << outbufSize << ") [from " << oldSize << "]" << std::endl; - if (oldSize < outbufSize) { //!!! at this point we need a lock in case a different client diff --git a/src/faster/StretcherProcess.cpp b/src/faster/StretcherProcess.cpp index 64ebd07..7044c7a 100644 --- a/src/faster/StretcherProcess.cpp +++ b/src/faster/StretcherProcess.cpp @@ -40,9 +40,6 @@ using namespace RubberBand; -using std::cerr; -using std::endl; - namespace RubberBand { #ifndef NO_THREADING @@ -57,20 +54,13 @@ R2Stretcher::ProcessThread::ProcessThread(R2Stretcher *s, size_t c) : void R2Stretcher::ProcessThread::run() { - if (m_s->m_debugLevel > 1) { - cerr << "thread " << m_channel << " getting going" << endl; - } + m_s->m_log.log(2, "thread getting going for channel", m_channel); ChannelData &cd = *m_s->m_channelData[m_channel]; while (cd.inputSize == -1 || cd.inbuf->getReadSpace() > 0) { -// if (cd.inputSize != -1) { -// cerr << "inputSize == " << cd.inputSize -// << ", readSpace == " << cd.inbuf->getReadSpace() << endl; -// } - bool any = false, last = false; m_s->processChunks(m_channel, any, last); @@ -89,9 +79,7 @@ R2Stretcher::ProcessThread::run() m_dataAvailable.unlock(); if (m_abandoning) { - if (m_s->m_debugLevel > 1) { - cerr << "thread " << m_channel << " abandoning" << endl; - } + m_s->m_log.log(2, "thread abandoning for channel", m_channel); return; } } @@ -102,9 +90,7 @@ R2Stretcher::ProcessThread::run() m_s->m_spaceAvailable.signal(); m_s->m_spaceAvailable.unlock(); - if (m_s->m_debugLevel > 1) { - cerr << "thread " << m_channel << " done" << endl; - } + m_s->m_log.log(2, "thread done for channel", m_channel); } void @@ -205,8 +191,7 @@ R2Stretcher::consumeChannel(size_t c, size_t reqSize = int(ceil(samples / m_pitchScale)); if (reqSize > cd.resamplebufSize) { - cerr << "WARNING: R2Stretcher::consumeChannel: resizing resampler buffer from " - << cd.resamplebufSize << " to " << reqSize << endl; + m_log.log(0, "WARNING: R2Stretcher::consumeChannel: resizing resampler buffer from and to", cd.resamplebufSize, reqSize); cd.setResampleBufSize(reqSize); } @@ -286,9 +271,7 @@ R2Stretcher::processChunks(size_t c, bool &any, bool &last) while (!last) { if (!testInbufReadSpace(c)) { - if (m_debugLevel > 1) { - cerr << "processChunks: out of input" << endl; - } + m_log.log(2, "processChunks: out of input"); break; } @@ -311,9 +294,7 @@ R2Stretcher::processChunks(size_t c, bool &any, bool &last) (c, phaseIncrement, shiftIncrement, phaseReset); } else { size_t bit = m_aWindowSize/4; - if (m_debugLevel > 1) { - cerr << "channel " << c << " breaking down overlong increment " << shiftIncrement << " into " << bit << "-size bits" << endl; - } + m_log.log(2, "breaking down overlong increment into chunks from and to", shiftIncrement, bit); if (!tmp) tmp = allocate(m_aWindowSize); analyseChunk(c); v_copy(tmp, cd.fltbuf, m_aWindowSize); @@ -330,9 +311,8 @@ R2Stretcher::processChunks(size_t c, bool &any, bool &last) } cd.chunkCount++; - if (m_debugLevel > 2) { - cerr << "channel " << c << ": last = " << last << ", chunkCount = " << cd.chunkCount << endl; - } + m_log.log(3, "channel/last", c, last); + m_log.log(3, "channel/chunkCount", c, cd.chunkCount); } if (tmp) deallocate(tmp); @@ -351,9 +331,7 @@ R2Stretcher::processOneChunk() for (size_t c = 0; c < m_channels; ++c) { if (!testInbufReadSpace(c)) { - if (m_debugLevel > 1) { - cerr << "processOneChunk: out of input" << endl; - } + m_log.log(2, "processOneChunk: out of input"); return false; } ChannelData &cd = *m_channelData[c]; @@ -405,11 +383,7 @@ R2Stretcher::testInbufReadSpace(size_t c) #ifndef NO_THREADING if (!m_threaded) { #endif - if (m_debugLevel > 1) { - cerr << "Note: RubberBandStretcher: read space < chunk size (" - << inbuf.getReadSpace() << " < " << m_aWindowSize - << ") when not all input written, on processChunks for channel " << c << endl; - } + m_log.log(2, "Note: read space < chunk size when not all input written", inbuf.getReadSpace(), m_aWindowSize); #ifndef NO_THREADING } @@ -418,18 +392,10 @@ R2Stretcher::testInbufReadSpace(size_t c) } if (rs == 0) { - - if (m_debugLevel > 1) { - cerr << "read space = 0, giving up" << endl; - } + m_log.log(2, "read space = 0, giving up"); return false; - } else if (rs < m_aWindowSize/2) { - - if (m_debugLevel > 1) { - cerr << "read space = " << rs << ", setting draining true" << endl; - } - + m_log.log(2, "setting draining true with read space", rs); cd.draining = true; } } @@ -450,9 +416,9 @@ R2Stretcher::processChunkForChannel(size_t c, // using e.g. testInbufReadSpace first. Return true if this is // the last chunk on the channel. - if (phaseReset && (m_debugLevel > 1)) { - cerr << "processChunkForChannel: phase reset found, incrs " - << phaseIncrement << ":" << shiftIncrement << endl; + if (phaseReset) { + m_log.log(2, "processChunkForChannel: phase reset found, increments", + phaseIncrement, shiftIncrement); } ChannelData &cd = *m_channelData[c]; @@ -475,7 +441,7 @@ R2Stretcher::processChunkForChannel(size_t c, modifyChunk(c, phaseIncrement, phaseReset); synthesiseChunk(c, shiftIncrement); // reads from cd.mag, cd.phase - if (m_debugLevel > 2) { + if (m_log.getDebugLevel() > 2) { if (phaseReset) { for (int i = 0; i < 10; ++i) { cd.accumulator[i] = 1.2f - (i % 3) * 1.2f; @@ -487,19 +453,13 @@ R2Stretcher::processChunkForChannel(size_t c, bool last = false; if (cd.draining) { - if (m_debugLevel > 1) { - cerr << "draining: accumulator fill = " << cd.accumulatorFill << " (shiftIncrement = " << shiftIncrement << ")" << endl; - } + m_log.log(2, "draining: accumulator fill and shift increment", cd.accumulatorFill, shiftIncrement); if (shiftIncrement == 0) { - cerr << "WARNING: draining: shiftIncrement == 0, can't handle that in this context: setting to " << m_increment << endl; + m_log.log(0, "WARNING: draining: shiftIncrement == 0, can't handle that in this context: setting to", m_increment); shiftIncrement = m_increment; } if (cd.accumulatorFill <= shiftIncrement) { - if (m_debugLevel > 1) { - cerr << "reducing shift increment from " << shiftIncrement - << " to " << cd.accumulatorFill - << " and marking as last" << endl; - } + m_log.log(2, "draining: marking as last and reducing shift increment from and to", shiftIncrement, cd.accumulatorFill); shiftIncrement = cd.accumulatorFill; last = true; } @@ -513,9 +473,7 @@ R2Stretcher::processChunkForChannel(size_t c, int ws = cd.outbuf->getWriteSpace(); if (ws < required) { - if (m_debugLevel > 0) { - cerr << "Buffer overrun on output for channel " << c << endl; - } + m_log.log(1, "Buffer overrun on output for channel", c); // The only correct thing we can do here is resize the buffer. // We can't wait for the client thread to read some data out @@ -528,12 +486,10 @@ R2Stretcher::processChunkForChannel(size_t c, RingBuffer *oldbuf = cd.outbuf; cd.outbuf = oldbuf->resized(oldbuf->getSize() * 2); - if (m_debugLevel > 1) { - cerr << "(Write space was " << ws << ", needed " << required - << ": resized output buffer from " << oldbuf->getSize() - << " to " << cd.outbuf->getSize() << ")" << endl; - } - + m_log.log(2, "write space and space needed", ws, required); + m_log.log(2, "resized output buffer from and to", oldbuf->getSize(), + cd.outbuf->getSize()); + m_emergencyScavenger.claim(oldbuf); } @@ -548,8 +504,6 @@ R2Stretcher::calculateIncrements(size_t &phaseIncrementRtn, { Profiler profiler("R2Stretcher::calculateIncrements"); -// cerr << "calculateIncrements" << endl; - // Calculate the next upcoming phase and shift increment, on the // basis that both channels are in sync. This is in contrast to // getIncrements, which requires that all the increments have been @@ -572,7 +526,7 @@ R2Stretcher::calculateIncrements(size_t &phaseIncrementRtn, size_t bc = cd.chunkCount; for (size_t c = 1; c < m_channels; ++c) { if (m_channelData[c]->chunkCount != bc) { - cerr << "ERROR: R2Stretcher::calculateIncrements: Channels are not in sync" << endl; + m_log.log(0, "ERROR: R2Stretcher::calculateIncrements: Channels are not in sync"); return; } } @@ -669,10 +623,7 @@ R2Stretcher::calculateIncrements(size_t &phaseIncrementRtn, if (m_silentHistory >= int(m_aWindowSize / m_increment) && !phaseReset) { phaseReset = true; - if (m_debugLevel > 1) { - cerr << "calculateIncrements: phase reset on silence (silent history == " - << m_silentHistory << ")" << endl; - } + m_log.log(2, "calculateIncrements: phase reset on silence: silent history", m_silentHistory); } } @@ -711,9 +662,6 @@ R2Stretcher::getIncrements(size_t channel, bool gotData = true; if (cd.chunkCount >= m_outputIncrements.size()) { -// cerr << "WARNING: R2Stretcher::getIncrements:" -// << " chunk count " << cd.chunkCount << " >= " -// << m_outputIncrements.size() << endl; if (m_outputIncrements.size() == 0) { phaseIncrementRtn = m_increment; shiftIncrementRtn = m_increment; @@ -740,12 +688,12 @@ R2Stretcher::getIncrements(size_t channel, if (shiftIncrement < 0) { shiftIncrement = -shiftIncrement; } - /* - if (shiftIncrement >= int(m_windowSize)) { - cerr << "*** ERROR: R2Stretcher::processChunks: shiftIncrement " << shiftIncrement << " >= windowSize " << m_windowSize << " at " << cd.chunkCount << " (of " << m_outputIncrements.size() << ")" << endl; - shiftIncrement = m_windowSize; + + if (shiftIncrement >= int(m_aWindowSize)) { + m_log.log(1, "WARNING: shiftIncrement >= analysis window size", shiftIncrement, m_aWindowSize); + m_log.log(1, "at chunk of total", cd.chunkCount, m_outputIncrements.size()); } - */ + phaseIncrementRtn = phaseIncrement; shiftIncrementRtn = shiftIncrement; if (cd.chunkCount == 0) phaseReset = true; // don't mess with the first chunk @@ -782,8 +730,8 @@ R2Stretcher::modifyChunk(size_t channel, ChannelData &cd = *m_channelData[channel]; - if (phaseReset && m_debugLevel > 1) { - cerr << "phase reset: leaving phases unmodified" << endl; + if (phaseReset) { + m_log.log(2, "phase reset: leaving phases unmodified"); } const process_t rate = process_t(m_sampleRate); @@ -904,15 +852,13 @@ R2Stretcher::modifyChunk(size_t channel, cd.unwrappedPhase[i] = outphase; } - if (m_debugLevel > 2) { - cerr << "mean inheritance distance = " << distacc / count << endl; - } + m_log.log(3, "mean inheritance distance", distacc / count); if (fullReset) unchanged = true; cd.unchanged = unchanged; - if (unchanged && m_debugLevel > 1) { - cerr << "frame unchanged on channel " << channel << endl; + if (unchanged) { + m_log.log(2, "frame unchanged on channel", channel); } } @@ -936,8 +882,6 @@ R2Stretcher::formantShiftChunk(size_t channel) const int cutoff = m_sampleRate / 700; -// cerr <<"cutoff = "<< cutoff << ", m_sampleRate/cutoff = " << m_sampleRate/cutoff << endl; - dblbuf[0] /= 2; dblbuf[cutoff-1] /= 2; @@ -1061,8 +1005,10 @@ R2Stretcher::writeChunk(size_t channel, size_t shiftIncrement, bool last) const int sz = cd.accumulatorFill; const int si = shiftIncrement; - if (m_debugLevel > 2) { - cerr << "writeChunk(" << channel << ", " << shiftIncrement << ", " << last << ")" << endl; + m_log.log(3, "writeChunk: channel and shiftIncrement", + channel, shiftIncrement); + if (last) { + m_log.log(3, "writeChunk: last true"); } v_divide(accumulator, windowAccumulator, si); @@ -1090,12 +1036,10 @@ R2Stretcher::writeChunk(size_t channel, size_t shiftIncrement, bool last) // first place. But we retain this check in case the // pitch scale has changed since then, or the stretch // calculator has gone mad, or something. - cerr << "WARNING: R2Stretcher::writeChunk: resizing resampler buffer from " - << cd.resamplebufSize << " to " << reqSize << endl; + m_log.log(0, "WARNING: R2Stretcher::writeChunk: resizing resampler buffer from and to", cd.resamplebufSize, reqSize); cd.setResampleBufSize(reqSize); } - #if defined(STRETCHER_IMPL_RESAMPLER_MUTEX_REQUIRED) if (m_threaded) { m_resamplerMutex.lock(); @@ -1134,9 +1078,7 @@ R2Stretcher::writeChunk(size_t channel, size_t shiftIncrement, bool last) } else { cd.accumulatorFill = 0; if (cd.draining) { - if (m_debugLevel > 1) { - cerr << "R2Stretcher::processChunks: setting outputComplete to true" << endl; - } + m_log.log(2, "processChunks: setting outputComplete to true"); cd.outputComplete = true; } } @@ -1162,31 +1104,23 @@ R2Stretcher::writeOutput(RingBuffer &to, float *from, size_t qty, size_t // this is the normal case if (theoreticalOut > 0) { - if (m_debugLevel > 1) { - cerr << "theoreticalOut = " << theoreticalOut - << ", outCount = " << outCount - << ", startSkip = " << startSkip - << ", qty = " << qty << endl; - } + m_log.log(2, "theoreticalOut and outCount", + theoreticalOut, outCount); + m_log.log(2, "startSkip and qty", + startSkip, qty); if (outCount - startSkip <= theoreticalOut && outCount - startSkip + qty > theoreticalOut) { qty = theoreticalOut - (outCount - startSkip); - if (m_debugLevel > 1) { - cerr << "reduce qty to " << qty << endl; - } + m_log.log(2, "reducing qty to", qty); } } - if (m_debugLevel > 2) { - cerr << "writing " << qty << endl; - } + m_log.log(3, "writing", qty); size_t written = to.write(from, qty); if (written < qty) { - cerr << "WARNING: R2Stretcher::writeOutput: " - << "Buffer overrun on output: wrote " << written - << " of " << qty << " samples" << endl; + m_log.log(0, "WARNING: writeOutput: buffer overrun: wanted to write and able to write", qty, written); } outCount += written; @@ -1196,22 +1130,16 @@ R2Stretcher::writeOutput(RingBuffer &to, float *from, size_t qty, size_t // the rest of this is only used during the first startSkip samples if (outCount + qty <= startSkip) { - if (m_debugLevel > 1) { - cerr << "qty = " << qty << ", startSkip = " - << startSkip << ", outCount = " << outCount - << ", discarding" << endl; - } + m_log.log(2, "discarding with startSkip", startSkip); + m_log.log(2, "qty and outCount", qty, outCount); outCount += qty; return; } size_t off = startSkip - outCount; - if (m_debugLevel > 1) { - cerr << "qty = " << qty << ", startSkip = " - << startSkip << ", outCount = " << outCount - << ", writing " << qty - off - << " from start offset " << off << endl; - } + m_log.log(2, "shortening with startSkip", startSkip); + m_log.log(2, "qty and outCount", qty, outCount); + m_log.log(2, "start offset and number written", off, qty - off); to.write(from + off, qty - off); outCount += qty; } @@ -1235,11 +1163,8 @@ R2Stretcher::available() const #endif for (size_t c = 0; c < m_channels; ++c) { if (m_channelData[c]->inputSize >= 0) { -// cerr << "available: m_done true" << endl; if (m_channelData[c]->inbuf->getReadSpace() > 0) { - if (m_debugLevel > 1) { - cerr << "calling processChunks(" << c << ") from available" << endl; - } + m_log.log(2, "calling processChunks from available, channel" , c); //!!! do we ever actually do this? if so, this method should not be const // ^^^ yes, we do sometimes -- e.g. when fed a very short file bool any = false, last = false; @@ -1258,9 +1183,7 @@ R2Stretcher::available() const for (size_t i = 0; i < m_channels; ++i) { size_t availIn = m_channelData[i]->inbuf->getReadSpace(); size_t availOut = m_channelData[i]->outbuf->getReadSpace(); - if (m_debugLevel > 2) { - cerr << "available on channel " << i << ": " << availOut << " (waiting: " << availIn << ")" << endl; - } + m_log.log(3, "available in and out", availIn, availOut); if (i == 0 || availOut < min) min = availOut; if (!m_channelData[i]->outputComplete) consumed = false; if (m_channelData[i]->resampler) haveResamplers = true; @@ -1284,9 +1207,7 @@ R2Stretcher::retrieve(float *const *output, size_t samples) const size_t gotHere = m_channelData[c]->outbuf->read(output[c], got); if (gotHere < got) { if (c > 0) { - if (m_debugLevel > 0) { - cerr << "R2Stretcher::retrieve: WARNING: channel imbalance detected" << endl; - } + m_log.log(0, "R2Stretcher::retrieve: WARNING: channel imbalance detected"); } got = gotHere; } diff --git a/src/finer/Guide.h b/src/finer/Guide.h index f71148b..54d2599 100644 --- a/src/finer/Guide.h +++ b/src/finer/Guide.h @@ -24,6 +24,8 @@ #ifndef RUBBERBAND_GUIDE_H #define RUBBERBAND_GUIDE_H +#include "../common/Log.h" + #include #include @@ -102,15 +104,12 @@ public: struct Parameters { double sampleRate; - std::function logger; - Parameters(double _sampleRate, - std::function _log) : - sampleRate(_sampleRate), - logger(_log) { } + Parameters(double _sampleRate) : sampleRate(_sampleRate) { } }; - Guide(Parameters parameters) : + Guide(Parameters parameters, Log log) : m_parameters(parameters), + m_log(log), m_configuration(roundUp(int(ceil(parameters.sampleRate / 16.0))), roundUp(int(ceil(parameters.sampleRate / 64.0))), roundUp(int(ceil(parameters.sampleRate / 32.0)))), @@ -120,10 +119,12 @@ public: { double rate = m_parameters.sampleRate; + m_log.log(1, "Guide: rate", rate); + int bandFftSize = roundUp(int(ceil(rate/16.0))); m_configuration.fftBandLimits[0] = BandLimits(bandFftSize, rate, 0.0, m_maxLower); - + // This is the classification and fallback FFT: we need it to // go up to Nyquist so we can seamlessly switch to it for // longer stretches @@ -134,6 +135,9 @@ public: bandFftSize = roundUp(int(ceil(rate/64.0))); m_configuration.fftBandLimits[2] = BandLimits(bandFftSize, rate, m_minHigher, rate/2.0); + + m_log.log(1, "Guide: classification FFT size", + m_configuration.classificationFftSize); } const Configuration &getConfiguration() const { @@ -332,8 +336,13 @@ public: */ } + void setDebugLevel(int level) { + m_log.setDebugLevel(level); + } + protected: Parameters m_parameters; + Log m_log; Configuration m_configuration; double m_minLower; diff --git a/src/finer/PhaseAdvance.h b/src/finer/PhaseAdvance.h index 5fc6f99..b2dd33c 100644 --- a/src/finer/PhaseAdvance.h +++ b/src/finer/PhaseAdvance.h @@ -26,6 +26,7 @@ #include "Guide.h" +#include "../common/Log.h" #include "../common/mathmisc.h" #include @@ -41,15 +42,13 @@ public: int fftSize; double sampleRate; int channels; - std::function logger; - Parameters(int _fftSize, double _sampleRate, int _channels, - std::function _log) : - fftSize(_fftSize), sampleRate(_sampleRate), - channels(_channels), logger(_log) { } + Parameters(int _fftSize, double _sampleRate, int _channels) : + fftSize(_fftSize), sampleRate(_sampleRate), channels(_channels) { } }; - GuidedPhaseAdvance(Parameters parameters) : + GuidedPhaseAdvance(Parameters parameters, Log log) : m_parameters(parameters), + m_log(log), m_binCount(parameters.fftSize / 2 + 1), m_peakPicker(m_binCount), m_reported(false) { @@ -111,18 +110,18 @@ public: int lowest = configuration.fftBandLimits[myFftBand].b0min; int highest = configuration.fftBandLimits[myFftBand].b1max; - if (!m_reported) { - std::ostringstream ostr; - ostr << "PhaseAdvance: fftSize = " << m_parameters.fftSize - << ": bins = " << bs << ", channels = " << channels - << ", inhop = "<< inhop << ", outhop = " << outhop - << ", ratio = " << ratio << std::endl; - ostr << "PhaseAdvance: lowest possible bin = " << lowest - << " (" << configuration.fftBandLimits[myFftBand].f0min - << "Hz), highest = " << highest - << " (" << configuration.fftBandLimits[myFftBand].f1max - << "Hz)" << std::endl; - m_parameters.logger(ostr.str()); + if (m_log.getDebugLevel() > 0 && !m_reported) { + m_log.log(1, "PhaseAdvance: for fftSize and bins", + m_parameters.fftSize, bs); + m_log.log(1, "PhaseAdvance: channels", channels); + m_log.log(1, "PhaseAdvance: widest bin range for this size", + lowest, highest); + m_log.log(1, "PhaseAdvance: widest freq range for this size", + configuration.fftBandLimits[myFftBand].f0min, + configuration.fftBandLimits[myFftBand].f1max); + m_log.log(1, "PhaseAdvance: initial inhop and outhop", + inhop, outhop); + m_log.log(1, "PhaseAdvance: initial ratio", ratio); m_reported = true; } @@ -231,8 +230,13 @@ public: } } + void setDebugLevel(int debugLevel) { + m_log.setDebugLevel(debugLevel); + } + protected: Parameters m_parameters; + Log m_log; int m_binCount; Peak m_peakPicker; int **m_currentPeaks; diff --git a/src/finer/R3Stretcher.cpp b/src/finer/R3Stretcher.cpp index 57b8f6a..1fe3bb7 100644 --- a/src/finer/R3Stretcher.cpp +++ b/src/finer/R3Stretcher.cpp @@ -31,12 +31,14 @@ namespace RubberBand { R3Stretcher::R3Stretcher(Parameters parameters, double initialTimeRatio, - double initialPitchScale) : + double initialPitchScale, + Log log) : m_parameters(parameters), + m_log(log), m_timeRatio(initialTimeRatio), m_pitchScale(initialPitchScale), m_formantScale(0.0), - m_guide(Guide::Parameters(m_parameters.sampleRate, parameters.logger)), + m_guide(Guide::Parameters(m_parameters.sampleRate), m_log), m_guideConfiguration(m_guide.getConfiguration()), m_channelAssembly(m_parameters.channels), m_inhop(1), @@ -51,6 +53,11 @@ R3Stretcher::R3Stretcher(Parameters parameters, m_totalOutputDuration(0), m_mode(ProcessMode::JustCreated) { + m_log.log(1, "R3Stretcher::R3Stretcher: rate, options", + m_parameters.sampleRate, m_parameters.options); + m_log.log(1, "R3Stretcher::R3Stretcher: initial time ratio and pitch scale", + m_timeRatio, m_pitchScale); + double maxClassifierFrequency = 16000.0; if (maxClassifierFrequency > m_parameters.sampleRate/2) { maxClassifierFrequency = m_parameters.sampleRate/2; @@ -83,18 +90,19 @@ R3Stretcher::R3Stretcher(Parameters parameters, (fftSize, m_guideConfiguration.longestFftSize); } } - + for (auto band: m_guideConfiguration.fftBandLimits) { int fftSize = band.fftSize; GuidedPhaseAdvance::Parameters guidedParameters - (fftSize, m_parameters.sampleRate, m_parameters.channels, - m_parameters.logger); - m_scaleData[fftSize] = std::make_shared(guidedParameters); + (fftSize, m_parameters.sampleRate, m_parameters.channels); + m_scaleData[fftSize] = std::make_shared + (guidedParameters, m_log); } m_calculator = std::unique_ptr (new StretchCalculator(int(round(m_parameters.sampleRate)), //!!! which is a double... - 1, false)); // no fixed inputIncrement + 1, false, // no fixed inputIncrement + m_log)); Resampler::Parameters resamplerParameters; resamplerParameters.quality = Resampler::FastestTolerable; @@ -119,10 +127,10 @@ R3Stretcher::R3Stretcher(Parameters parameters, m_prevOuthop = int(round(m_inhop * getEffectiveRatio())); if (!m_inhop.is_lock_free()) { - m_parameters.logger("WARNING: std::atomic is not lock-free"); + m_log.log(0, "WARNING: std::atomic is not lock-free"); } if (!m_timeRatio.is_lock_free()) { - m_parameters.logger("WARNING: std::atomic is not lock-free"); + m_log.log(0, "WARNING: std::atomic is not lock-free"); } // Pad to half of the longest frame. As with R2, in real-time mode @@ -131,15 +139,15 @@ R3Stretcher::R3Stretcher(Parameters parameters, // changes. if (!isRealTime()) { - m_parameters.logger("Offline mode: pre-padding"); int pad = m_guideConfiguration.longestFftSize / 2; + m_log.log(1, "offline mode: prefilling with", pad); for (int c = 0; c < m_parameters.channels; ++c) { m_channelData[c]->inbuf->zero(pad); } // By the time we skip this later we will have resampled m_startSkip = int(round(pad / m_pitchScale)); } else { - m_parameters.logger("RT mode: no internal pre-pad"); + m_log.log(1, "realtime mode: no prefill"); } } @@ -176,7 +184,7 @@ R3Stretcher::setTimeRatio(double ratio) if (!isRealTime()) { if (m_mode == ProcessMode::Studying || m_mode == ProcessMode::Processing) { - m_parameters.logger("R3Stretcher::setTimeRatio: Cannot set time ratio while studying or processing in non-RT mode"); + m_log.log(0, "R3Stretcher::setTimeRatio: Cannot set time ratio while studying or processing in non-RT mode"); return; } } @@ -192,7 +200,7 @@ R3Stretcher::setPitchScale(double scale) if (!isRealTime()) { if (m_mode == ProcessMode::Studying || m_mode == ProcessMode::Processing) { - m_parameters.logger("R3Stretcher::setTimeRatio: Cannot set pitch scale while studying or processing in non-RT mode"); + m_log.log(0, "R3Stretcher::setTimeRatio: Cannot set pitch scale while studying or processing in non-RT mode"); return; } } @@ -208,7 +216,7 @@ R3Stretcher::setFormantScale(double scale) if (!isRealTime()) { if (m_mode == ProcessMode::Studying || m_mode == ProcessMode::Processing) { - m_parameters.logger("R3Stretcher::setTimeRatio: Cannot set formant scale while studying or processing in non-RT mode"); + m_log.log(0, "R3Stretcher::setTimeRatio: Cannot set formant scale while studying or processing in non-RT mode"); return; } } @@ -230,11 +238,11 @@ void R3Stretcher::setKeyFrameMap(const std::map &mapping) { if (isRealTime()) { - m_parameters.logger("R3Stretcher::setKeyFrameMap: Cannot specify key frame map in RT mode"); + m_log.log(0, "R3Stretcher::setKeyFrameMap: Cannot specify key frame map in RT mode"); return; } if (m_mode == ProcessMode::Processing || m_mode == ProcessMode::Finished) { - m_parameters.logger("R3Stretcher::setKeyFrameMap: Cannot specify key frame map after process() has begun"); + m_log.log(0, "R3Stretcher::setKeyFrameMap: Cannot specify key frame map after process() has begun"); return; } @@ -266,22 +274,21 @@ R3Stretcher::calculateHop() if (proposedOuthop > 512.0) proposedOuthop = 512.0; if (proposedOuthop < 128.0) proposedOuthop = 128.0; - std::cout << "calculateHop: for ratio " << ratio << " proposedOuthop = " - << proposedOuthop << std::endl; + m_log.log(1, "calculateHop: ratio and proposed outhop", ratio, proposedOuthop); double inhop = proposedOuthop / ratio; if (inhop < 1.0) { - m_parameters.logger("WARNING: Extreme ratio yields ideal inhop < 1, results may be suspect"); + m_log.log(0, "WARNING: Extreme ratio yields ideal inhop < 1, results may be suspect", ratio, inhop); inhop = 1.0; } if (inhop > 768.0) { - m_parameters.logger("WARNING: Extreme ratio yields ideal inhop > 768, results may be suspect"); + m_log.log(0, "WARNING: Extreme ratio yields ideal inhop > 768, results may be suspect", ratio, inhop); inhop = 768.0; } m_inhop = int(floor(inhop)); - std::cout << "R3Stretcher::calculateHop: inhop = " << m_inhop << ", proposed outhop = " << proposedOuthop << ", mean outhop = " << m_inhop * ratio << std::endl; + m_log.log(1, "calculateHop: inhop and mean outhop", m_inhop, m_inhop * ratio); } void @@ -292,7 +299,12 @@ R3Stretcher::updateRatioFromMap() if (m_processInputDuration == 0) { m_timeRatio = double(m_keyFrameMap.begin()->second) / double(m_keyFrameMap.begin()->first); - std::cout << "initial key-frame map entry " << m_keyFrameMap.begin()->first << " -> " << m_keyFrameMap.begin()->second << " gives initial ratio " << m_timeRatio << std::endl; + + m_log.log(1, "initial key-frame map entry ", + double(m_keyFrameMap.begin()->first), + double(m_keyFrameMap.begin()->second)); + m_log.log(1, "giving initial ratio ", m_timeRatio); + calculateHop(); m_lastKeyFrameSurpassed = 0; return; @@ -306,7 +318,8 @@ R3Stretcher::updateRatioFromMap() if (m_processInputDuration >= i0->first) { - std::cout << "at " << m_processInputDuration << " (output = " << m_totalOutputDuration << ") we have passed " << i0->first << ", looking ahead to next key frame" << std::endl; + m_log.log(2, "input duration surpasses pending key frame", + double(m_processInputDuration), double(i0->first)); auto i1 = m_keyFrameMap.upper_bound(m_processInputDuration); @@ -331,10 +344,13 @@ R3Stretcher::updateRatioFromMap() double ratio = double(toKeyFrameAtOutput) / double(toKeyFrameAtInput); - std::cout << "keyFrameAtInput = " << keyFrameAtInput << ", keyFrameAtOutput = " << keyFrameAtOutput << std::endl; - std::cout << "currently at input = " << m_processInputDuration << ", currently at output = " << m_totalOutputDuration << std::endl; - std::cout << "toKeyFrameAtInput = " << toKeyFrameAtInput << ", toKeyFrameAtOutput = " << toKeyFrameAtOutput << std::endl; - std::cout << "ratio = " << ratio << std::endl; + m_log.log(2, "next key frame input and output", + double(keyFrameAtInput), double(keyFrameAtOutput)); + m_log.log(2, "current input and output", + double(m_processInputDuration), double(m_totalOutputDuration)); + m_log.log(2, "to next key frame input and output", + double(toKeyFrameAtInput), double(toKeyFrameAtOutput)); + m_log.log(2, "new ratio", ratio); m_timeRatio = ratio; calculateHop(); @@ -409,12 +425,12 @@ void R3Stretcher::study(const float *const *, size_t samples, bool) { if (isRealTime()) { - m_parameters.logger("R3Stretcher::study: Not meaningful in realtime mode"); + m_log.log(0, "R3Stretcher::study: Not meaningful in realtime mode"); return; } if (m_mode == ProcessMode::Processing || m_mode == ProcessMode::Finished) { - m_parameters.logger("R3Stretcher::study: Cannot study after processing"); + m_log.log(0, "R3Stretcher::study: Cannot study after processing"); return; } @@ -443,7 +459,7 @@ void R3Stretcher::process(const float *const *input, size_t samples, bool final) { if (m_mode == ProcessMode::Finished) { - m_parameters.logger("R3Stretcher::process: Cannot process again after final chunk"); + m_log.log(0, "R3Stretcher::process: Cannot process again after final chunk"); return; } @@ -468,7 +484,7 @@ R3Stretcher::process(const float *const *input, size_t samples, bool final) size_t ws = m_channelData[0]->inbuf->getWriteSpace(); if (samples > ws) { //!!! check this - m_parameters.logger("R3Stretcher::process: WARNING: Forced to increase input buffer size. Either setMaxProcessSize was not properly called or process is being called repeatedly without retrieve."); + m_log.log(0, "R3Stretcher::process: WARNING: Forced to increase input buffer size. Either setMaxProcessSize was not properly called or process is being called repeatedly without retrieve."); size_t newSize = m_channelData[0]->inbuf->getSize() - ws + samples; for (int c = 0; c < m_parameters.channels; ++c) { auto newBuf = m_channelData[c]->inbuf->resized(newSize); @@ -505,7 +521,7 @@ R3Stretcher::retrieve(float *const *output, size_t samples) const int gotHere = m_channelData[c]->outbuf->read(output[c], got); if (gotHere < got) { if (c > 0) { - m_parameters.logger("R3Stretcher::retrieve: WARNING: channel imbalance detected"); + m_log.log(0, "R3Stretcher::retrieve: WARNING: channel imbalance detected"); } got = std::min(got, std::max(gotHere, 0)); } @@ -550,16 +566,14 @@ R3Stretcher::consume() // advanced the input and output since the previous frame, not the // distances we are about to advance them, so they use the m_prev // values. -/* + if (inhop != m_prevInhop) { - std::cout << "Note: inhop has changed from " << m_prevInhop - << " to " << inhop << std::endl; + m_log.log(2, "change in inhop", double(m_prevInhop), double(inhop)); } if (outhop != m_prevOuthop) { - std::cout << "Note: outhop has changed from " << m_prevOuthop - << " to " << outhop << std::endl; + m_log.log(2, "change in outhop", double(m_prevOuthop), double(outhop)); } -*/ + while (m_channelData.at(0)->outbuf->getWriteSpace() >= outhop) { // NB our ChannelData, ScaleData, and ChannelScaleData maps diff --git a/src/finer/R3Stretcher.h b/src/finer/R3Stretcher.h index 6ba2944..161c2b0 100644 --- a/src/finer/R3Stretcher.h +++ b/src/finer/R3Stretcher.h @@ -36,12 +36,12 @@ #include "../common/Allocators.h" #include "../common/Window.h" #include "../common/VectorOpsComplex.h" +#include "../common/Log.h" #include "../../rubberband/RubberBandStretcher.h" #include #include -#include namespace RubberBand { @@ -53,17 +53,15 @@ public: double sampleRate; int channels; RubberBandStretcher::Options options; - std::function logger; Parameters(double _sampleRate, int _channels, - RubberBandStretcher::Options _options, - std::function _log = &logCout) : - sampleRate(_sampleRate), channels(_channels), options(_options), - logger(_log) { } + RubberBandStretcher::Options _options) : + sampleRate(_sampleRate), channels(_channels), options(_options) { } }; R3Stretcher(Parameters parameters, double initialTimeRatio, - double initialPitchScale); + double initialPitchScale, + Log log); ~R3Stretcher() { } void reset(); @@ -89,6 +87,15 @@ public: size_t getLatency() const; size_t getChannelCount() const; + void setDebugLevel(int level) { + m_log.setDebugLevel(level); + for (auto &sd : m_scaleData) { + sd.second->guided.setDebugLevel(level); + } + m_guide.setDebugLevel(level); + m_calculator->setDebugLevel(level); + } + protected: struct ClassificationReadaheadData { FixedVector timeDomain; @@ -242,7 +249,8 @@ protected: Window synthesisWindow; double windowScaleFactor; GuidedPhaseAdvance guided; - ScaleData(GuidedPhaseAdvance::Parameters guidedParameters) : + ScaleData(GuidedPhaseAdvance::Parameters guidedParameters, + Log log) : fftSize(guidedParameters.fftSize), fft(fftSize), analysisWindow(analysisWindowShape(fftSize), @@ -250,7 +258,7 @@ protected: synthesisWindow(synthesisWindowShape(fftSize), synthesisWindowLength(fftSize)), windowScaleFactor(0.0), - guided(guidedParameters) + guided(guidedParameters, log) { int asz = analysisWindow.getSize(), ssz = synthesisWindow.getSize(); int off = (asz - ssz) / 2; @@ -267,6 +275,7 @@ protected: }; Parameters m_parameters; + Log m_log; std::atomic m_timeRatio; std::atomic m_pitchScale; @@ -347,10 +356,6 @@ protected: return m_parameters.options & RubberBandStretcher::OptionProcessRealTime; } - - static void logCout(const std::string &message) { - std::cout << "RubberBandStretcher: " << message << std::endl; - } }; } diff --git a/vamp/RubberBandVampPlugin.cpp b/vamp/RubberBandVampPlugin.cpp index 6a8ca3a..028ee81 100644 --- a/vamp/RubberBandVampPlugin.cpp +++ b/vamp/RubberBandVampPlugin.cpp @@ -454,6 +454,28 @@ RubberBandVampPlugin::Impl::processOffline(const float *const *inputBuffers, return FeatureSet(); } +static RubberBand::Log makeCerrLog() +{ + auto log0 = [](const char *message) { + std::cerr << "RubberBand: " << message << "\n"; + }; + auto log1 = [](const char *message, double arg0) { + auto prec = std::cerr.precision(); + std::cerr.precision(10); + std::cerr << "RubberBand: " << message << ": " << arg0 << "\n"; + std::cerr.precision(prec); + }; + auto log2 = [](const char *message, double arg0, double arg1) { + auto prec = std::cerr.precision(); + std::cerr.precision(10); + std::cerr << "RubberBand: " << message + << ": (" << arg0 << ", " << arg1 << ")" << "\n"; + std::cerr.precision(prec); + }; + + return RubberBand::Log(log0, log1, log2); +} + RubberBandVampPlugin::FeatureSet RubberBandVampPlugin::Impl::getRemainingFeaturesOffline() { @@ -463,7 +485,8 @@ RubberBandVampPlugin::Impl::getRemainingFeaturesOffline() int rate = m_sampleRate; - RubberBand::StretchCalculator sc(rate, m_stretcher->getInputIncrement(), true); + RubberBand::StretchCalculator sc + (rate, m_stretcher->getInputIncrement(), true, makeCerrLog()); size_t inputIncrement = m_stretcher->getInputIncrement(); std::vector outputIncrements = m_stretcher->getOutputIncrements();