From 5b0b8cd5cbd0ce5e99623fd02ded1d6cd10766e5 Mon Sep 17 00:00:00 2001 From: Christian Speckner Date: Fri, 14 Dec 2018 23:57:12 +0100 Subject: [PATCH] Summarize audio buffer errors and log them to the main log. --- src/common/AudioQueue.cxx | 7 +- src/common/AudioQueue.hxx | 5 +- src/common/SoundSDL2.cxx | 9 +- src/common/StaggeredLogger.cxx | 142 ++++++++++++++++++++++++++ src/common/StaggeredLogger.hxx | 77 ++++++++++++++ src/common/audio/LanczosResampler.cxx | 7 +- src/common/audio/LanczosResampler.hxx | 3 +- src/common/audio/Resampler.hxx | 8 +- src/common/audio/SimpleResampler.cxx | 7 +- src/common/audio/SimpleResampler.hxx | 3 +- src/common/module.mk | 3 +- src/emucore/Console.cxx | 3 +- 12 files changed, 255 insertions(+), 19 deletions(-) create mode 100644 src/common/StaggeredLogger.cxx create mode 100644 src/common/StaggeredLogger.hxx diff --git a/src/common/AudioQueue.cxx b/src/common/AudioQueue.cxx index 9c1429d22..58923387e 100644 --- a/src/common/AudioQueue.cxx +++ b/src/common/AudioQueue.cxx @@ -21,14 +21,15 @@ using std::mutex; using std::lock_guard; // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -AudioQueue::AudioQueue(uInt32 fragmentSize, uInt32 capacity, bool isStereo) +AudioQueue::AudioQueue(uInt32 fragmentSize, uInt32 capacity, bool isStereo, StaggeredLogger::Logger logger) : myFragmentSize(fragmentSize), myIsStereo(isStereo), myFragmentQueue(capacity), myAllFragments(capacity + 2), mySize(0), myNextFragment(0), - myIgnoreOverflows(true) + myIgnoreOverflows(true), + myOverflowLogger("audio buffer overflow", logger) { const uInt8 sampleSize = myIsStereo ? 2 : 1; @@ -95,7 +96,7 @@ Int16* AudioQueue::enqueue(Int16* fragment) if (mySize < capacity) ++mySize; else { myNextFragment = (myNextFragment + 1) % capacity; - if (!myIgnoreOverflows) (cerr << "audio buffer overflow\n").flush(); + if (!myIgnoreOverflows) myOverflowLogger.log(); } return newFragment; diff --git a/src/common/AudioQueue.hxx b/src/common/AudioQueue.hxx index 98998b240..af0aaacad 100644 --- a/src/common/AudioQueue.hxx +++ b/src/common/AudioQueue.hxx @@ -21,6 +21,7 @@ #include #include "bspf.hxx" +#include "StaggeredLogger.hxx" /** This class implements a an audio queue that acts both like a ring buffer @@ -44,7 +45,7 @@ class AudioQueue @param capacity The number of fragments that can be queued before wrapping. @param isStereo Whether samples are stereo or mono. */ - AudioQueue(uInt32 fragmentSize, uInt32 capacity, bool isStereo); + AudioQueue(uInt32 fragmentSize, uInt32 capacity, bool isStereo, StaggeredLogger::Logger logger); /** Capacity getter. @@ -129,6 +130,8 @@ class AudioQueue // Log overflows? bool myIgnoreOverflows; + StaggeredLogger myOverflowLogger; + private: AudioQueue() = delete; diff --git a/src/common/SoundSDL2.cxx b/src/common/SoundSDL2.cxx index a6dd518fb..194090ecf 100644 --- a/src/common/SoundSDL2.cxx +++ b/src/common/SoundSDL2.cxx @@ -33,6 +33,7 @@ #include "AudioSettings.hxx" #include "audio/SimpleResampler.hxx" #include "audio/LanczosResampler.hxx" +#include "StaggeredLogger.hxx" #include "ThreadDebugging.hxx" @@ -304,6 +305,8 @@ void SoundSDL2::initResampler() return nextFragment; }; + StaggeredLogger::Logger logger = [this](string msg) { myOSystem.logMessage(msg, 0); }; + Resampler::Format formatFrom = Resampler::Format(myEmulationTiming->audioSampleRate(), myAudioQueue->fragmentSize(), myAudioQueue->isStereo()); Resampler::Format formatTo = @@ -311,15 +314,15 @@ void SoundSDL2::initResampler() switch (myAudioSettings.resamplingQuality()) { case AudioSettings::ResamplingQuality::nearestNeightbour: - myResampler = make_unique(formatFrom, formatTo, nextFragmentCallback); + myResampler = make_unique(formatFrom, formatTo, nextFragmentCallback, logger); break; case AudioSettings::ResamplingQuality::lanczos_2: - myResampler = make_unique(formatFrom, formatTo, nextFragmentCallback, 2); + myResampler = make_unique(formatFrom, formatTo, nextFragmentCallback, 2, logger); break; case AudioSettings::ResamplingQuality::lanczos_3: - myResampler = make_unique(formatFrom, formatTo, nextFragmentCallback, 3); + myResampler = make_unique(formatFrom, formatTo, nextFragmentCallback, 3, logger); break; default: diff --git a/src/common/StaggeredLogger.cxx b/src/common/StaggeredLogger.cxx new file mode 100644 index 000000000..f0b508769 --- /dev/null +++ b/src/common/StaggeredLogger.cxx @@ -0,0 +1,142 @@ +//============================================================================ +// +// SSSS tt lll lll +// SS SS tt ll ll +// SS tttttt eeee ll ll aaaa +// SSSS tt ee ee ll ll aa +// SS tt eeeeee ll ll aaaaa -- "An Atari 2600 VCS Emulator" +// SS SS tt ee ll ll aa aa +// SSSS ttt eeeee llll llll aaaaa +// +// Copyright (c) 1995-2018 by Bradford W. Mott, Stephen Anthony +// and the Stella Team +// +// See the file "License.txt" for information on usage and redistribution of +// this file, and for a DISCLAIMER OF ALL WARRANTIES. +//============================================================================ + +#include "StaggeredLogger.hxx" + +#include + +using namespace std::chrono; + +namespace { + string currentTimestamp() + { + std::tm now = BSPF::localTime(); + + char formattedTime[100]; + formattedTime[99] = 0; + std::strftime(formattedTime, 99, "%H:%M:%S", &now); + + return formattedTime; + } +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +StaggeredLogger::StaggeredLogger(const string& message, Logger logger) + : myMessage(message), + myCurrentEventCount(0), + myIsCurrentlyCollecting(false), + myCurrentIntervalSize(100), + myMaxIntervalFactor(9), + myCurrentIntervalFactor(1), + myCooldownTime(1000) +{ + if (logger) myLogger = logger; +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::setLogger(Logger logger) +{ + myLogger = logger; +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::log() +{ + std::lock_guard lock(myMutex); + + _log(); +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::advance() +{ + std::lock_guard lock(myMutex); + + _advance(); +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::_log() +{ + _advance(); + + if (!myIsCurrentlyCollecting) { + myCurrentEventCount = 0; + myIsCurrentlyCollecting = true; + myCurrentIntervalStartTimestamp = high_resolution_clock::now(); + } + + myCurrentEventCount++; + myLastLogEventTimestamp = high_resolution_clock::now(); +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::logLine() +{ + stringstream ss; + ss + << currentTimestamp() << ": " + << myMessage + << " (" << myCurrentEventCount << " times in " + << myCurrentIntervalSize << " milliseconds" + << ")"; + + myLogger(ss.str()); + + myIsCurrentlyCollecting = false; + + increaseInterval(); +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::increaseInterval() +{ + if (myCurrentIntervalFactor >= myMaxIntervalFactor) return; + + myCurrentIntervalFactor++; + myCurrentIntervalSize *= 2; +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::decreaseInterval() +{ + if (myCurrentIntervalFactor <= 1) return; + + myCurrentIntervalFactor--; + myCurrentIntervalSize /= 2; +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::_advance() +{ + high_resolution_clock::time_point now = high_resolution_clock::now(); + + if (myIsCurrentlyCollecting) { + Int64 msecSinceIntervalStart = + duration_cast>(now - myCurrentIntervalStartTimestamp).count(); + + if (msecSinceIntervalStart > myCurrentIntervalSize) logLine(); + } + + Int64 msec = + duration_cast>(now - myLastLogEventTimestamp).count(); + + while (msec > myCooldownTime && myCurrentIntervalFactor > 1) { + msec -= myCooldownTime; + decreaseInterval(); + } +} diff --git a/src/common/StaggeredLogger.hxx b/src/common/StaggeredLogger.hxx new file mode 100644 index 000000000..597df4b82 --- /dev/null +++ b/src/common/StaggeredLogger.hxx @@ -0,0 +1,77 @@ +//============================================================================ +// +// SSSS tt lll lll +// SS SS tt ll ll +// SS tttttt eeee ll ll aaaa +// SSSS tt ee ee ll ll aa +// SS tt eeeeee ll ll aaaaa -- "An Atari 2600 VCS Emulator" +// SS SS tt ee ll ll aa aa +// SSSS ttt eeeee llll llll aaaaa +// +// Copyright (c) 1995-2018 by Bradford W. Mott, Stephen Anthony +// and the Stella Team +// +// See the file "License.txt" for information on usage and redistribution of +// this file, and for a DISCLAIMER OF ALL WARRANTIES. +//============================================================================ + +#ifndef STAGGERED_LOGGER +#define STAGGERED_LOGGER + +#include +#include +#include + +#include "bspf.hxx" + +/** + * This class buffers log events and logs them after a certain time window has expired. + * The timout increases after every log line by a factor of two until a maximum is reached. + * If no events are reported, the window size decreases again. + */ + +class StaggeredLogger { + public: + + typedef std::function Logger; + + public: + + StaggeredLogger(const string& message, Logger logger = Logger()); + + void log(); + + void advance(); + + void setLogger(Logger logger); + + private: + + void _log(); + + void _advance(); + + void increaseInterval(); + + void decreaseInterval(); + + void logLine(); + + Logger myLogger; + string myMessage; + + uInt32 myCurrentEventCount; + bool myIsCurrentlyCollecting; + + std::chrono::high_resolution_clock::time_point myCurrentIntervalStartTimestamp; + std::chrono::high_resolution_clock::time_point myLastLogEventTimestamp; + + uInt32 myCurrentIntervalSize; + uInt32 myMaxIntervalFactor; + uInt32 myCurrentIntervalFactor; + uInt32 myCooldownTime; + + std::mutex myMutex; +}; + +#endif // STAGGERED_LOGGER diff --git a/src/common/audio/LanczosResampler.cxx b/src/common/audio/LanczosResampler.cxx index cb57a1ed0..5b5b88279 100644 --- a/src/common/audio/LanczosResampler.cxx +++ b/src/common/audio/LanczosResampler.cxx @@ -60,9 +60,10 @@ LanczosResampler::LanczosResampler( Resampler::Format formatFrom, Resampler::Format formatTo, Resampler::NextFragmentCallback nextFragmentCallback, - uInt32 kernelParameter) + uInt32 kernelParameter, + StaggeredLogger::Logger logger) : - Resampler(formatFrom, formatTo, nextFragmentCallback), + Resampler(formatFrom, formatTo, nextFragmentCallback, logger), // In order to find the number of kernels we need to precompute, we need to find N minimal such that // // N / formatTo.sampleRate = M / formatFrom.sampleRate @@ -204,7 +205,7 @@ inline void LanczosResampler::shiftSamples(uInt32 samplesToShift) myCurrentFragment = nextFragment; myIsUnderrun = false; } else { - (cerr << "audio buffer underrun\n").flush(); + myUnderrunLogger.log(); myIsUnderrun = true; } } diff --git a/src/common/audio/LanczosResampler.hxx b/src/common/audio/LanczosResampler.hxx index 5581d48d8..a433bf0bf 100644 --- a/src/common/audio/LanczosResampler.hxx +++ b/src/common/audio/LanczosResampler.hxx @@ -30,7 +30,8 @@ class LanczosResampler : public Resampler Resampler::Format formatFrom, Resampler::Format formatTo, Resampler::NextFragmentCallback nextFragmentCallback, - uInt32 kernelParameter + uInt32 kernelParameter, + StaggeredLogger::Logger logger ); void fillFragment(float* fragment, uInt32 length) override; diff --git a/src/common/audio/Resampler.hxx b/src/common/audio/Resampler.hxx index cd39818e4..f962537fb 100644 --- a/src/common/audio/Resampler.hxx +++ b/src/common/audio/Resampler.hxx @@ -21,6 +21,7 @@ #include #include "bspf.hxx" +#include "StaggeredLogger.hxx" class Resampler { public: @@ -49,10 +50,11 @@ class Resampler { public: - Resampler(Format formatFrom, Format formatTo, NextFragmentCallback nextFragmentCallback) : + Resampler(Format formatFrom, Format formatTo, NextFragmentCallback nextFragmentCallback, StaggeredLogger::Logger logger) : myFormatFrom(formatFrom), myFormatTo(formatTo), - myNextFragmentCallback(nextFragmentCallback) + myNextFragmentCallback(nextFragmentCallback), + myUnderrunLogger("audio buffer underrun", logger) {} virtual void fillFragment(float* fragment, uInt32 length) = 0; @@ -66,6 +68,8 @@ class Resampler { NextFragmentCallback myNextFragmentCallback; + StaggeredLogger myUnderrunLogger; + private: Resampler() = delete; diff --git a/src/common/audio/SimpleResampler.cxx b/src/common/audio/SimpleResampler.cxx index 5992e9577..1dc16bf25 100644 --- a/src/common/audio/SimpleResampler.cxx +++ b/src/common/audio/SimpleResampler.cxx @@ -21,8 +21,9 @@ SimpleResampler::SimpleResampler( Resampler::Format formatFrom, Resampler::Format formatTo, - Resampler::NextFragmentCallback nextFragmentCallback) - : Resampler(formatFrom, formatTo, nextFragmentCallback), + Resampler::NextFragmentCallback nextFragmentCallback, + StaggeredLogger::Logger logger) + : Resampler(formatFrom, formatTo, nextFragmentCallback, logger), myCurrentFragment(nullptr), myTimeIndex(0), myFragmentIndex(0), @@ -88,7 +89,7 @@ void SimpleResampler::fillFragment(float* fragment, uInt32 length) if (nextFragment) myCurrentFragment = nextFragment; else { - (cerr << "audio buffer underrun\n").flush(); + myUnderrunLogger.log(); myIsUnderrun = true; } } diff --git a/src/common/audio/SimpleResampler.hxx b/src/common/audio/SimpleResampler.hxx index 8db798aab..e25b495f9 100644 --- a/src/common/audio/SimpleResampler.hxx +++ b/src/common/audio/SimpleResampler.hxx @@ -27,7 +27,8 @@ class SimpleResampler : public Resampler SimpleResampler( Resampler::Format formatFrom, Resampler::Format formatTo, - Resampler::NextFragmentCallback NextFragmentCallback + Resampler::NextFragmentCallback NextFragmentCallback, + StaggeredLogger::Logger logger ); void fillFragment(float* fragment, uInt32 length) override; diff --git a/src/common/module.mk b/src/common/module.mk index d770551b3..530dda57a 100644 --- a/src/common/module.mk +++ b/src/common/module.mk @@ -20,7 +20,8 @@ MODULE_OBJS := \ src/common/AudioQueue.o \ src/common/AudioSettings.o \ src/common/FpsMeter.o \ - src/common/ThreadDebugging.o + src/common/ThreadDebugging.o \ + src/common/StaggeredLogger.o MODULE_DIRS += \ src/common diff --git a/src/emucore/Console.cxx b/src/emucore/Console.cxx index a75387803..a4e771bcb 100644 --- a/src/emucore/Console.cxx +++ b/src/emucore/Console.cxx @@ -818,7 +818,8 @@ void Console::createAudioQueue() myAudioQueue = make_shared( myEmulationTiming.audioFragmentSize(), myEmulationTiming.audioQueueCapacity(), - useStereo + useStereo, + [this](string msg){ myOSystem.logMessage(msg, 0); } ); }