Summarize audio buffer errors and log them to the main log.

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;

src/common/AudioQueue.hxx

@@ -21,6 +21,7 @@
 #include <mutex>
 
 #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;

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<SimpleResampler>(formatFrom, formatTo, nextFragmentCallback);
+      myResampler = make_unique<SimpleResampler>(formatFrom, formatTo, nextFragmentCallback, logger);
       break;
 
     case AudioSettings::ResamplingQuality::lanczos_2:
-      myResampler = make_unique<LanczosResampler>(formatFrom, formatTo, nextFragmentCallback, 2);
+      myResampler = make_unique<LanczosResampler>(formatFrom, formatTo, nextFragmentCallback, 2, logger);
       break;
 
     case AudioSettings::ResamplingQuality::lanczos_3:
-      myResampler = make_unique<LanczosResampler>(formatFrom, formatTo, nextFragmentCallback, 3);
+      myResampler = make_unique<LanczosResampler>(formatFrom, formatTo, nextFragmentCallback, 3, logger);
       break;
 
     default:

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 <ctime>
+
+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<std::mutex> lock(myMutex);
+
+  _log();
+}
+
+// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -
+void StaggeredLogger::advance()
+{
+  std::lock_guard<std::mutex> 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<duration<Int64, std::milli>>(now - myCurrentIntervalStartTimestamp).count();
+
+    if (msecSinceIntervalStart > myCurrentIntervalSize) logLine();
+  }
+
+  Int64 msec =
+    duration_cast<duration<Int64, std::milli>>(now - myLastLogEventTimestamp).count();
+
+  while (msec > myCooldownTime && myCurrentIntervalFactor > 1) {
+    msec -= myCooldownTime;
+    decreaseInterval();
+  }
+}

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 <functional>
+#include <chrono>
+#include <thread>
+
+#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<void(const string&)> 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

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;
       }
     }

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;

src/common/audio/Resampler.hxx

@@ -21,6 +21,7 @@
 #include <functional>
 
 #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;

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;
       }
     }

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;

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

src/emucore/Console.cxx

@@ -818,7 +818,8 @@ void Console::createAudioQueue()
   myAudioQueue = make_shared<AudioQueue>(
     myEmulationTiming.audioFragmentSize(),
     myEmulationTiming.audioQueueCapacity(),
-    useStereo
+    useStereo,
+    [this](string msg){ myOSystem.logMessage(msg, 0); }
   );
 }