From 5137b19407c95d8ecdb693efed31061876f874aa Mon Sep 17 00:00:00 2001 From: Chris Cannam Date: Wed, 22 Jun 2022 11:33:36 +0100 Subject: [PATCH] Wire up Log throughout --- src/common/Log.cpp | 23 +++ src/common/Log.h | 16 +- src/common/StretchCalculator.cpp | 236 +++++++++------------------- src/faster/R2Stretcher.cpp | 109 +++++-------- src/faster/StretcherChannelData.cpp | 8 - src/faster/StretcherProcess.cpp | 191 +++++++--------------- src/finer/R3Stretcher.cpp | 4 +- 7 files changed, 194 insertions(+), 393 deletions(-) diff --git a/src/common/Log.cpp b/src/common/Log.cpp index 03b3536..c2c944c 100644 --- a/src/common/Log.cpp +++ b/src/common/Log.cpp @@ -28,4 +28,27 @@ namespace RubberBand int Log::m_defaultDebugLevel = 0; +Log +Log::makeCoutLog() +{ + return Log( + [](const char *message) { + std::cout << "RubberBand: " << message << "\n"; + }, + [](const char *message, double arg0) { + auto prec = std::cout.precision(); + std::cout.precision(10); + std::cout << "RubberBand: " << message << ": " << arg0 << "\n"; + std::cout.precision(prec); + }, + [](const char *message, double arg0, double arg1) { + auto prec = std::cout.precision(); + std::cout.precision(10); + std::cout << "RubberBand: " << message + << ": (" << arg0 << ", " << arg1 << ")" << "\n"; + std::cout.precision(prec); + } + ); +} + } diff --git a/src/common/Log.h b/src/common/Log.h index d106270..1a9038c 100644 --- a/src/common/Log.h +++ b/src/common/Log.h @@ -68,21 +68,7 @@ public: if (level <= m_debugLevel) m_log2(message, arg0, arg1); } - static Log makeCoutLog() { - return Log( - [](const char *message) { - std::cout << "RubberBand: " << message << "\n"; - }, - [](const char *message, double arg0) { - std::cout << "RubberBand: " << message - << ": " << arg0 << "\n"; - }, - [](const char *message, double arg0, double arg1) { - std::cout << "RubberBand: " << message - << ": (" << arg0 << "," << arg1 << ")" << "\n"; - } - ); - } + static Log makeCoutLog(); private: std::function m_log0; diff --git a/src/common/StretchCalculator.cpp b/src/common/StretchCalculator.cpp index 204ccd3..7b98020 100644 --- a/src/common/StretchCalculator.cpp +++ b/src/common/StretchCalculator.cpp @@ -29,6 +29,7 @@ #include #include #include +#include #include "sysutils.h" @@ -53,7 +54,7 @@ StretchCalculator::StretchCalculator(size_t sampleRate, m_outFrameCounter(0), m_log(log) { -// std::cerr << "StretchCalculator::StretchCalculator: useHardPeaks = " << useHardPeaks << std::endl; + m_log.log(2, "StretchCalculator: useHardPeaks", useHardPeaks); } StretchCalculator::~StretchCalculator() @@ -85,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; @@ -124,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 { @@ -143,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; } @@ -197,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; } @@ -239,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; } @@ -276,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()) { @@ -318,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); @@ -391,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); @@ -404,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; @@ -438,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 @@ -453,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 = @@ -501,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); @@ -514,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; @@ -586,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) { @@ -602,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]); } } @@ -623,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]); } } @@ -637,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() && @@ -658,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); @@ -671,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) / @@ -722,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]); @@ -738,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] && @@ -768,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; @@ -795,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; @@ -829,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/faster/R2Stretcher.cpp b/src/faster/R2Stretcher.cpp index 9cf21e9..6aa41a0 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; @@ -112,9 +110,7 @@ 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); // Window size will vary according to the audio sample rate, but // we don't let it drop below the 48k default @@ -455,7 +451,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; @@ -464,7 +460,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); } } @@ -556,18 +553,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; @@ -621,9 +619,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) { @@ -713,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() { @@ -759,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 @@ -767,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 @@ -798,7 +794,7 @@ 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; @@ -824,12 +820,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"); } } @@ -844,7 +838,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 | @@ -862,7 +856,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 | @@ -911,7 +905,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; } @@ -933,14 +927,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; @@ -983,7 +975,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; @@ -1044,8 +1037,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); @@ -1059,7 +1052,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); } } @@ -1067,8 +1059,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; } @@ -1128,7 +1118,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; } } @@ -1145,10 +1135,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); } } @@ -1187,9 +1174,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 @@ -1226,7 +1211,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; } @@ -1239,9 +1224,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); @@ -1258,10 +1241,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 @@ -1293,12 +1274,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 @@ -1331,14 +1310,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/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..455092c 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]; @@ -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/R3Stretcher.cpp b/src/finer/R3Stretcher.cpp index 67bcaab..32ba055 100644 --- a/src/finer/R3Stretcher.cpp +++ b/src/finer/R3Stretcher.cpp @@ -134,15 +134,15 @@ R3Stretcher::R3Stretcher(Parameters parameters, // changes. if (!isRealTime()) { - m_log.log(1, "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_log.log(1, "RT mode: no internal pre-pad"); + m_log.log(1, "realtime mode: no prefill"); } }