Rewrite StaggeredLogger with a timer.

This commit is contained in:
Christian Speckner 2018-12-15 23:58:52 +01:00
parent 06c20103af
commit 9b22c6afa7
4 changed files with 75 additions and 46 deletions

View File

@ -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());

View File

@ -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<std::mutex> 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<std::mutex> 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<duration<Int64, std::milli>>(now - myCurrentIntervalStartTimestamp).count();
Int64 millisecondsSinceIntervalStart =
duration_cast<duration<Int64, std::milli>>(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<duration<Int64, std::milli>>(now - myLastIntervalEndTimestamp).count();
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;
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<std::mutex> lock(myMutex);
logLine();
myIsCurrentlyCollecting = false;
increaseInterval();
myLastIntervalEndTimestamp = high_resolution_clock::now();
}

View File

@ -24,7 +24,7 @@
#include <mutex>
#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

View File

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