mirror of
https://github.com/badaix/snapcast.git
synced 2025-05-09 23:26:47 +02:00
logging
This commit is contained in:
badaix
parent
84cdd5b8ff
commit
e57971c6cb
7 changed files with 671 additions and 52 deletions
|
|
@ -5,7 +5,8 @@
|
|||
#include "timeProvider.h"
|
||||
|
||||
using namespace std;
|
||||
using namespace chronos;
|
||||
//using namespace chronos;
|
||||
namespace cs = chronos;
|
||||
|
||||
|
||||
Stream::Stream(const msg::SampleFormat& sampleFormat) : format_(sampleFormat), sleep_(0), median_(0), shortMedian_(0), lastUpdate_(0), playedFrames_(0)
|
||||
|
|
@ -14,7 +15,7 @@ Stream::Stream(const msg::SampleFormat& sampleFormat) : format_(sampleFormat), s
|
|||
shortBuffer_.setSize(100);
|
||||
miniBuffer_.setSize(20);
|
||||
// cardBuffer_.setSize(50);
|
||||
bufferMs_ = msec(500);
|
||||
bufferMs_ = cs::msec(500);
|
||||
|
||||
/*
|
||||
48000 x
|
||||
|
|
@ -39,7 +40,7 @@ void Stream::setRealSampleRate(double sampleRate)
|
|||
|
||||
void Stream::setBufferLen(size_t bufferLenMs)
|
||||
{
|
||||
bufferMs_ = msec(bufferLenMs);
|
||||
bufferMs_ = cs::msec(bufferLenMs);
|
||||
}
|
||||
|
||||
|
||||
|
|
@ -53,7 +54,7 @@ void Stream::clearChunks()
|
|||
|
||||
void Stream::addChunk(msg::PcmChunk* chunk)
|
||||
{
|
||||
while (chunks_.size() * chunk->duration<chronos::msec>().count() > 10000)
|
||||
while (chunks_.size() * chunk->duration<cs::msec>().count() > 10000)
|
||||
chunks_.pop();
|
||||
chunks_.push(shared_ptr<msg::PcmChunk>(chunk));
|
||||
// logD << "new chunk: " << chunk_->getDuration() << ", Chunks: " << chunks_.size() << "\n";
|
||||
|
|
@ -61,11 +62,11 @@ void Stream::addChunk(msg::PcmChunk* chunk)
|
|||
|
||||
|
||||
|
||||
time_point_hrc Stream::getSilentPlayerChunk(void* outputBuffer, unsigned long framesPerBuffer)
|
||||
cs::time_point_hrc Stream::getSilentPlayerChunk(void* outputBuffer, unsigned long framesPerBuffer)
|
||||
{
|
||||
if (!chunk_)
|
||||
chunk_ = chunks_.pop();
|
||||
time_point_hrc tp = chunk_->start();
|
||||
cs::time_point_hrc tp = chunk_->start();
|
||||
memset(outputBuffer, 0, framesPerBuffer * format_.frameSize);
|
||||
return tp;
|
||||
}
|
||||
|
|
@ -98,10 +99,10 @@ time_point_hrc Stream::seek(long ms)
|
|||
return chunk_->start();
|
||||
|
||||
// time_point_ms tp = chunk_->timePoint();
|
||||
while (ms > chunk_->duration<chronos::msec>().count())
|
||||
while (ms > chunk_->duration<cs::msec>().count())
|
||||
{
|
||||
chunk_ = chunks_.pop();
|
||||
ms -= min(ms, (long)chunk_->durationLeft<chronos::msec>().count());
|
||||
ms -= min(ms, (long)chunk_->durationLeft<cs::msec>().count());
|
||||
}
|
||||
chunk_->seek(ms * format_.msRate());
|
||||
return chunk_->start();
|
||||
|
|
@ -109,12 +110,12 @@ time_point_hrc Stream::seek(long ms)
|
|||
*/
|
||||
|
||||
|
||||
time_point_hrc Stream::getNextPlayerChunk(void* outputBuffer, const chronos::usec& timeout, unsigned long framesPerBuffer)
|
||||
cs::time_point_hrc Stream::getNextPlayerChunk(void* outputBuffer, const cs::usec& timeout, unsigned long framesPerBuffer)
|
||||
{
|
||||
if (!chunk_ && !chunks_.try_pop(chunk_, timeout))
|
||||
throw 0;
|
||||
|
||||
time_point_hrc tp = chunk_->start();
|
||||
cs::time_point_hrc tp = chunk_->start();
|
||||
char* buffer = (char*)outputBuffer;
|
||||
unsigned long read = 0;
|
||||
while (read < framesPerBuffer)
|
||||
|
|
@ -127,14 +128,14 @@ time_point_hrc Stream::getNextPlayerChunk(void* outputBuffer, const chronos::use
|
|||
}
|
||||
|
||||
|
||||
time_point_hrc Stream::getNextPlayerChunk(void* outputBuffer, const chronos::usec& timeout, unsigned long framesPerBuffer, long framesCorrection)
|
||||
cs::time_point_hrc Stream::getNextPlayerChunk(void* outputBuffer, const cs::usec& timeout, unsigned long framesPerBuffer, long framesCorrection)
|
||||
{
|
||||
if (framesCorrection == 0)
|
||||
return getNextPlayerChunk(outputBuffer, timeout, framesPerBuffer);
|
||||
|
||||
long toRead = framesPerBuffer + framesCorrection;
|
||||
char* buffer = (char*)malloc(toRead * format_.frameSize);
|
||||
time_point_hrc tp = getNextPlayerChunk(buffer, timeout, toRead);
|
||||
cs::time_point_hrc tp = getNextPlayerChunk(buffer, timeout, toRead);
|
||||
|
||||
float factor = (float)toRead / framesPerBuffer;//(float)(framesPerBuffer*channels_);
|
||||
if (abs(framesCorrection) > 1)
|
||||
|
|
@ -170,28 +171,33 @@ void Stream::resetBuffers()
|
|||
|
||||
|
||||
|
||||
bool Stream::getPlayerChunk(void* outputBuffer, const chronos::usec& outputBufferDacTime, unsigned long framesPerBuffer)
|
||||
bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacTime, unsigned long framesPerBuffer)
|
||||
{
|
||||
if (outputBufferDacTime > bufferMs_)
|
||||
{
|
||||
logO << "outputBufferDacTime > bufferMs: " << outputBufferDacTime.count() << " > " << std::chrono::duration_cast<usec>(bufferMs_).count() << "\n";
|
||||
sleep_ = chronos::usec(0);
|
||||
logO << "outputBufferDacTime > bufferMs: " << cs::duration<cs::msec>(outputBufferDacTime) << " > " << cs::duration<cs::msec>(bufferMs_) << "\n";
|
||||
sleep_ = cs::usec(0);
|
||||
return false;
|
||||
}
|
||||
|
||||
if (!chunk_ && !chunks_.try_pop(chunk_, outputBufferDacTime))
|
||||
{
|
||||
logO << "!chunk_ && !chunks_.try_pop(chunk_, outputBufferDacTime)\n";
|
||||
sleep_ = chronos::usec(0);
|
||||
logO << "no chunks available\n";
|
||||
sleep_ = cs::usec(0);
|
||||
return false;
|
||||
}
|
||||
|
||||
playedFrames_ += framesPerBuffer;
|
||||
|
||||
chronos::usec age = std::chrono::duration_cast<usec>(TimeProvider::serverNow() - chunk_->start() - bufferMs_ + outputBufferDacTime);
|
||||
if ((sleep_.count() == 0) && (chronos::abs(age) > chronos::msec(200)))
|
||||
/// we have a chunk
|
||||
/// age = chunk age (server now - rec time: some positive value) - buffer (e.g. 1000ms) + time to DAC
|
||||
/// age = 0 => play now
|
||||
/// age < 0 => play in -age
|
||||
/// age > 0 => too old
|
||||
cs::usec age = std::chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - chunk_->start() - bufferMs_ + outputBufferDacTime);
|
||||
if ((sleep_.count() == 0) && (cs::abs(age) > cs::msec(200)))
|
||||
{
|
||||
logO << "age > 200: " << age.count() << "\n";
|
||||
logO << "age > 200: " << cs::duration<cs::msec>(age) << "\n";
|
||||
sleep_ = age;
|
||||
}
|
||||
|
||||
|
|
@ -199,54 +205,56 @@ bool Stream::getPlayerChunk(void* outputBuffer, const chronos::usec& outputBuffe
|
|||
{
|
||||
|
||||
//logD << "framesPerBuffer: " << framesPerBuffer << "\tms: " << framesPerBuffer*2 / PLAYER_CHUNK_MS_SIZE << "\t" << PLAYER_CHUNK_SIZE << "\n";
|
||||
chronos::nsec bufferDuration = chronos::nsec(chronos::usec::rep(framesPerBuffer / format_.nsRate()));
|
||||
cs::nsec bufferDuration = cs::nsec(cs::nsec::rep(framesPerBuffer / format_.nsRate()));
|
||||
// logD << "buffer duration: " << bufferDuration.count() << "\n";
|
||||
|
||||
chronos::usec correction = chronos::usec(0);
|
||||
cs::usec correction = cs::usec(0);
|
||||
if (sleep_.count() != 0)
|
||||
{
|
||||
resetBuffers();
|
||||
if (sleep_ < -bufferDuration/2)
|
||||
{
|
||||
logO << "sleep < -bufferDuration/2: " << cs::duration<cs::msec>(sleep_) << " < " << -cs::duration<cs::msec>(bufferDuration)/2 << ", ";
|
||||
// We're early: not enough chunks_. play silence. Reference chunk_ is the oldest (front) one
|
||||
sleep_ = chrono::duration_cast<usec>(TimeProvider::serverNow() - getSilentPlayerChunk(outputBuffer, framesPerBuffer) - bufferMs_ + outputBufferDacTime);
|
||||
//logD << "-sleep: " << sleep_.count() << " " << -bufferDuration.count() / 2000 << "\n";
|
||||
sleep_ = chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - getSilentPlayerChunk(outputBuffer, framesPerBuffer) - bufferMs_ + outputBufferDacTime);
|
||||
logO << "sleep: " << cs::duration<cs::msec>(sleep_) << "\n";
|
||||
if (sleep_ < -bufferDuration/2)
|
||||
return true;
|
||||
}
|
||||
else if (sleep_ > bufferDuration/2)
|
||||
{
|
||||
logO << "sleep > bufferDuration/2: " << cs::duration<cs::msec>(sleep_) << " > " << cs::duration<cs::msec>(bufferDuration)/2 << "\n";
|
||||
// We're late: discard oldest chunks
|
||||
while (sleep_ > chunk_->duration<chronos::usec>())
|
||||
while (sleep_ > chunk_->duration<cs::usec>())
|
||||
{
|
||||
logO << "sleep > chunk_->getDuration(): " << sleep_.count() << " > " << chunk_->duration<chronos::msec>().count() << ", chunks: " << chunks_.size() << ", out: " << outputBufferDacTime.count() << ", needed: " << bufferDuration.count() << "\n";
|
||||
sleep_ = std::chrono::duration_cast<usec>(TimeProvider::serverNow() - chunk_->start() - bufferMs_ + outputBufferDacTime);
|
||||
logO << "sleep > chunkDuration: " << cs::duration<cs::msec>(sleep_) << " > " << chunk_->duration<cs::msec>().count() << ", chunks: " << chunks_.size() << ", out: " << cs::duration<cs::msec>(outputBufferDacTime) << ", needed: " << cs::duration<cs::msec>(bufferDuration) << "\n";
|
||||
sleep_ = std::chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - chunk_->start() - bufferMs_ + outputBufferDacTime);
|
||||
if (!chunks_.try_pop(chunk_, outputBufferDacTime))
|
||||
{
|
||||
logO << "no chunks available\n";
|
||||
chunk_ = NULL;
|
||||
sleep_ = chronos::usec(0);
|
||||
sleep_ = cs::usec(0);
|
||||
return false;
|
||||
}
|
||||
}
|
||||
}
|
||||
|
||||
// out of sync, can be corrected by playing faster/slower
|
||||
if (sleep_ < -chronos::usec(100))
|
||||
if (sleep_ < -cs::usec(100))
|
||||
{
|
||||
sleep_ += chronos::usec(100);
|
||||
correction = -chronos::usec(100);
|
||||
sleep_ += cs::usec(100);
|
||||
correction = -cs::usec(100);
|
||||
}
|
||||
else if (sleep_ > chronos::usec(100))
|
||||
else if (sleep_ > cs::usec(100))
|
||||
{
|
||||
sleep_ -= chronos::usec(100);
|
||||
correction = chronos::usec(100);
|
||||
sleep_ -= cs::usec(100);
|
||||
correction = cs::usec(100);
|
||||
}
|
||||
else
|
||||
{
|
||||
logO << "Sleep " << sleep_.count() << "\n";
|
||||
logO << "Sleep " << cs::duration<cs::msec>(sleep_) << "\n";
|
||||
correction = sleep_;
|
||||
sleep_ = chronos::usec(0);
|
||||
sleep_ = cs::usec(0);
|
||||
}
|
||||
}
|
||||
|
||||
|
|
@ -257,55 +265,55 @@ bool Stream::getPlayerChunk(void* outputBuffer, const chronos::usec& outputBuffe
|
|||
playedFrames_ -= abs(correctAfterXFrames_);
|
||||
}
|
||||
|
||||
age = std::chrono::duration_cast<usec>(TimeProvider::serverNow() - getNextPlayerChunk(outputBuffer, outputBufferDacTime, framesPerBuffer, framesCorrection) - bufferMs_ + outputBufferDacTime);
|
||||
age = std::chrono::duration_cast<cs::usec>(TimeProvider::serverNow() - getNextPlayerChunk(outputBuffer, outputBufferDacTime, framesPerBuffer, framesCorrection) - bufferMs_ + outputBufferDacTime);
|
||||
|
||||
setRealSampleRate(format_.rate);
|
||||
if (sleep_.count() == 0)
|
||||
{
|
||||
if (buffer_.full())
|
||||
{
|
||||
if (chronos::usec(abs(median_)) > chronos::msec(1))
|
||||
if (cs::usec(abs(median_)) > cs::msec(1))
|
||||
{
|
||||
logO << "pBuffer->full() && (abs(median_) > 1): " << median_ << "\n";
|
||||
sleep_ = chronos::usec(shortMedian_);
|
||||
sleep_ = cs::usec(shortMedian_);
|
||||
}
|
||||
/* else if (chronos::usec(median_) > chronos::usec(300))
|
||||
/* else if (cs::usec(median_) > cs::usec(300))
|
||||
{
|
||||
setRealSampleRate(format_.rate - format_.rate / 1000);
|
||||
}
|
||||
else if (chronos::usec(median_) < -chronos::usec(300))
|
||||
else if (cs::usec(median_) < -cs::usec(300))
|
||||
{
|
||||
setRealSampleRate(format_.rate + format_.rate / 1000);
|
||||
}
|
||||
*/ }
|
||||
else if (shortBuffer_.full())
|
||||
{
|
||||
if (chronos::usec(abs(shortMedian_)) > chronos::msec(5))
|
||||
if (cs::usec(abs(shortMedian_)) > cs::msec(5))
|
||||
{
|
||||
logO << "pShortBuffer->full() && (abs(shortMedian_) > 5): " << shortMedian_ << "\n";
|
||||
sleep_ = chronos::usec(shortMedian_);
|
||||
sleep_ = cs::usec(shortMedian_);
|
||||
}
|
||||
/* else
|
||||
{
|
||||
setRealSampleRate(format_.rate + -shortMedian_ / 100);
|
||||
}
|
||||
*/ }
|
||||
else if (miniBuffer_.full() && (chronos::usec(abs(miniBuffer_.median())) > chronos::msec(50)))
|
||||
else if (miniBuffer_.full() && (cs::usec(abs(miniBuffer_.median())) > cs::msec(50)))
|
||||
{
|
||||
logO << "pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): " << miniBuffer_.median() << "\n";
|
||||
sleep_ = chronos::usec((chronos::msec::rep)miniBuffer_.mean());
|
||||
sleep_ = cs::usec((cs::msec::rep)miniBuffer_.mean());
|
||||
}
|
||||
}
|
||||
|
||||
if (sleep_.count() != 0)
|
||||
{
|
||||
logO << "Sleep " << sleep_.count() << ", age: " << age.count() << ", bufferDuration: " << std::chrono::duration_cast<usec>(bufferDuration).count() << "\n";
|
||||
logO << "Sleep " << cs::duration<cs::msec>(sleep_) << ", age: " << cs::duration<cs::msec>(age) << ", bufferDuration: " << cs::duration<cs::msec>(bufferDuration) << "\n";
|
||||
}
|
||||
else if (shortBuffer_.full())
|
||||
{
|
||||
if (chronos::usec(shortMedian_) > chronos::usec(100))
|
||||
if (cs::usec(shortMedian_) > cs::usec(100))
|
||||
setRealSampleRate(format_.rate * 0.9999);
|
||||
else if (chronos::usec(shortMedian_) < -chronos::usec(100))
|
||||
else if (cs::usec(shortMedian_) < -cs::usec(100))
|
||||
setRealSampleRate(format_.rate * 1.0001);
|
||||
}
|
||||
|
||||
|
|
@ -318,13 +326,13 @@ bool Stream::getPlayerChunk(void* outputBuffer, const chronos::usec& outputBuffe
|
|||
lastUpdate_ = now;
|
||||
median_ = buffer_.median();
|
||||
shortMedian_ = shortBuffer_.median();
|
||||
logO << "Chunk: " << age.count()/100 << "\t" << miniBuffer_.median()/100 << "\t" << shortMedian_/100 << "\t" << median_/100 << "\t" << buffer_.size() << "\t" << outputBufferDacTime.count() << "\n";
|
||||
logO << "Chunk: " << age.count()/100 << "\t" << miniBuffer_.median()/100 << "\t" << shortMedian_/100 << "\t" << median_/100 << "\t" << buffer_.size() << "\t" << cs::duration<cs::msec>(outputBufferDacTime) << "\n";
|
||||
}
|
||||
return true;
|
||||
}
|
||||
catch(int e)
|
||||
{
|
||||
sleep_ = chronos::usec(0);
|
||||
sleep_ = cs::usec(0);
|
||||
return false;
|
||||
}
|
||||
}
|
||||
|
|
|
|||
Loading…
Add table
Add a link
Reference in a new issue