From 9b22c6afa7946dd94aaaa036e4b9e476b90854bf Mon Sep 17 00:00:00 2001 From: Christian Speckner Date: Sat, 15 Dec 2018 23:58:52 +0100 Subject: [PATCH] Rewrite StaggeredLogger with a timer. --- src/common/SoundSDL2.cxx | 2 +- src/common/StaggeredLogger.cxx | 95 ++++++++++++++++++++-------------- src/common/StaggeredLogger.hxx | 22 +++++--- src/emucore/Console.cxx | 2 +- 4 files changed, 75 insertions(+), 46 deletions(-) diff --git a/src/common/SoundSDL2.cxx b/src/common/SoundSDL2.cxx index 194090ecf..e55f59e19 100644 --- a/src/common/SoundSDL2.cxx +++ b/src/common/SoundSDL2.cxx @@ -305,7 +305,7 @@ void SoundSDL2::initResampler() return nextFragment; }; - StaggeredLogger::Logger logger = [this](string msg) { myOSystem.logMessage(msg, 0); }; + StaggeredLogger::Logger logger = [this](string msg) { myOSystem.logMessage(msg, 1); }; Resampler::Format formatFrom = Resampler::Format(myEmulationTiming->audioSampleRate(), myAudioQueue->fragmentSize(), myAudioQueue->isStereo()); diff --git a/src/common/StaggeredLogger.cxx b/src/common/StaggeredLogger.cxx index de89ae951..71b341007 100644 --- a/src/common/StaggeredLogger.cxx +++ b/src/common/StaggeredLogger.cxx @@ -42,13 +42,34 @@ StaggeredLogger::StaggeredLogger(const string& message, Logger logger) myCurrentIntervalSize(100), myMaxIntervalFactor(9), myCurrentIntervalFactor(1), - myCooldownTime(1000) + myCooldownTime(1000), + myTimer(new TimerManager()) { if (logger) myLogger = logger; } +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +StaggeredLogger::~StaggeredLogger() +{ + myTimer->clear(myTimerId); + + // make sure that the worker thread joins before continuing with the destruction + delete myTimer; + + // the worker thread has joined and there will be no more reentrant calls -> + // continue with destruction +} + // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - void StaggeredLogger::setLogger(Logger logger) +{ + std::lock_guard lock(myMutex); + + _setLogger(logger); +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::_setLogger(Logger logger) { myLogger = logger; } @@ -61,49 +82,32 @@ void StaggeredLogger::log() _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(); - } + if (!myIsCurrentlyCollecting) startInterval(); myCurrentEventCount++; - myLastLogEventTimestamp = high_resolution_clock::now(); } // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - void StaggeredLogger::logLine() { + if (!myLogger) return; + high_resolution_clock::time_point now = high_resolution_clock::now(); - Int64 millisecondsSinceLastLogEvent = - duration_cast>(now - myCurrentIntervalStartTimestamp).count(); + Int64 millisecondsSinceIntervalStart = + duration_cast>(now - myLastIntervalStartTimestamp).count(); stringstream ss; ss << currentTimestamp() << ": " << myMessage << " (" << myCurrentEventCount << " times in " - << millisecondsSinceLastLogEvent << " milliseconds" + << millisecondsSinceIntervalStart << " milliseconds" << ")"; - myLogger(ss.str()); - - myIsCurrentlyCollecting = false; - - increaseInterval(); + myLogger(ss.str()); } // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - @@ -125,22 +129,37 @@ void StaggeredLogger::decreaseInterval() } // - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - -void StaggeredLogger::_advance() +void StaggeredLogger::startInterval() { + if (myIsCurrentlyCollecting) return; + + myIsCurrentlyCollecting = true; + high_resolution_clock::time_point now = high_resolution_clock::now(); + Int64 msecSinceLastIntervalEnd = + duration_cast>(now - myLastIntervalEndTimestamp).count(); - 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; + while (msecSinceLastIntervalEnd > myCooldownTime && myCurrentIntervalFactor > 1) { + msecSinceLastIntervalEnd -= myCooldownTime; decreaseInterval(); } + + myCurrentEventCount = 0; + myLastIntervalStartTimestamp = now; + + myTimer->clear(myTimerId); + myTimerId = myTimer->setTimeout(std::bind(&StaggeredLogger::onTimerExpired, this), myCurrentIntervalSize); +} + +// - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - - +void StaggeredLogger::onTimerExpired() +{ + std::lock_guard lock(myMutex); + + logLine(); + + myIsCurrentlyCollecting = false; + increaseInterval(); + + myLastIntervalEndTimestamp = high_resolution_clock::now(); } diff --git a/src/common/StaggeredLogger.hxx b/src/common/StaggeredLogger.hxx index 7f93e60e0..6e6e93c06 100644 --- a/src/common/StaggeredLogger.hxx +++ b/src/common/StaggeredLogger.hxx @@ -24,7 +24,7 @@ #include #include "bspf.hxx" - +#include "TimerManager.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. @@ -40,9 +40,9 @@ class StaggeredLogger { StaggeredLogger(const string& message, Logger logger = Logger()); - void log(); + ~StaggeredLogger(); - void advance(); + void log(); void setLogger(Logger logger); @@ -50,7 +50,11 @@ class StaggeredLogger { void _log(); - void _advance(); + void _setLogger(Logger logger); + + void onTimerExpired(); + + void startInterval(); void increaseInterval(); @@ -64,8 +68,8 @@ class StaggeredLogger { uInt32 myCurrentEventCount; bool myIsCurrentlyCollecting; - std::chrono::high_resolution_clock::time_point myCurrentIntervalStartTimestamp; - std::chrono::high_resolution_clock::time_point myLastLogEventTimestamp; + std::chrono::high_resolution_clock::time_point myLastIntervalStartTimestamp; + std::chrono::high_resolution_clock::time_point myLastIntervalEndTimestamp; uInt32 myCurrentIntervalSize; uInt32 myMaxIntervalFactor; @@ -73,6 +77,12 @@ class StaggeredLogger { uInt32 myCooldownTime; std::mutex myMutex; + + // We need control over the destruction porcess and over the exact point where + // the worker thread joins -> allocate on the heap end delete explicitly in + // our destructor. + TimerManager *myTimer; + TimerManager::TimerId myTimerId; }; #endif // STAGGERED_LOGGER diff --git a/src/emucore/Console.cxx b/src/emucore/Console.cxx index a4e771bcb..e770715cf 100644 --- a/src/emucore/Console.cxx +++ b/src/emucore/Console.cxx @@ -819,7 +819,7 @@ void Console::createAudioQueue() myEmulationTiming.audioFragmentSize(), myEmulationTiming.audioQueueCapacity(), useStereo, - [this](string msg){ myOSystem.logMessage(msg, 0); } + [this](string msg){ myOSystem.logMessage(msg, 1); } ); }