Makre resync more tolerant

This commit is contained in:
badaix 2020-03-01 18:54:00 +01:00
parent 5ab89e1a54
commit 2b14641704
5 changed files with 103 additions and 86 deletions

View file

@ -136,7 +136,7 @@ void StreamServer::onChunkRead(const PcmStream* pcmStream, std::shared_ptr<msg::
void StreamServer::onResync(const PcmStream* pcmStream, double ms) void StreamServer::onResync(const PcmStream* pcmStream, double ms)
{ {
LOG(INFO) << "onResync (" << pcmStream->getName() << "): " << ms << "ms\n"; LOG(INFO) << "onResync (" << pcmStream->getName() << "): " << ms << " ms\n";
} }

View file

@ -154,7 +154,7 @@ template <typename ReadStream>
void AsioStream<ReadStream>::on_connect() void AsioStream<ReadStream>::on_connect()
{ {
first_ = true; first_ = true;
chronos::systemtimeofday(&tvEncodedChunk_); tvEncodedChunk_ = std::chrono::steady_clock::now();
do_read(); do_read();
} }
@ -163,68 +163,69 @@ template <typename ReadStream>
void AsioStream<ReadStream>::do_read() void AsioStream<ReadStream>::do_read()
{ {
// LOG(DEBUG, "AsioStream") << "do_read\n"; // LOG(DEBUG, "AsioStream") << "do_read\n";
boost::asio::async_read( boost::asio::async_read(*stream_, boost::asio::buffer(chunk_->payload, chunk_->payloadSize),
*stream_, boost::asio::buffer(chunk_->payload, chunk_->payloadSize), [this](boost::system::error_code ec, std::size_t length) mutable { [this](boost::system::error_code ec, std::size_t length) mutable {
if (ec) if (ec)
{ {
LOG(ERROR, "AsioStream") << "Error reading message: " << ec.message() << ", length: " << length << "\n"; LOG(ERROR, "AsioStream") << "Error reading message: " << ec.message() << ", length: " << length << "\n";
connect(); connect();
return; return;
} }
bytes_read_ += length; bytes_read_ += length;
// LOG(DEBUG, "AsioStream") << "Read: " << length << " bytes\n"; // LOG(DEBUG, "AsioStream") << "Read: " << length << " bytes\n";
// First read after connect. Set the initial read timestamp // First read after connect. Set the initial read timestamp
// the timestamp will be incremented after encoding, // the timestamp will be incremented after encoding,
// since we do not know how much the encoder actually encoded // since we do not know how much the encoder actually encoded
if (!first_) if (!first_)
{ {
timeval now; auto now = std::chrono::steady_clock::now();
chronos::systemtimeofday(&now); auto stream2systime_diff = now - tvEncodedChunk_;
auto stream2systime_diff = chronos::diff<std::chrono::milliseconds>(now, tvEncodedChunk_); if (stream2systime_diff > chronos::sec(5) + chronos::msec(chunk_ms_))
if (stream2systime_diff > chronos::sec(5) + chronos::msec(chunk_ms_)) {
{ LOG(WARNING, "AsioStream") << "Stream and system time out of sync: "
LOG(WARNING, "AsioStream") << "Stream and system time out of sync: " << stream2systime_diff.count() << "ms, resetting stream time.\n"; << std::chrono::duration_cast<std::chrono::microseconds>(stream2systime_diff).count() / 1000.
first_ = true; << " ms, resetting stream time.\n";
} first_ = true;
} }
if (first_) }
{ if (first_)
first_ = false; {
chronos::systemtimeofday(&tvEncodedChunk_); first_ = false;
nextTick_ = std::chrono::steady_clock::now() + std::chrono::milliseconds(buffer_ms_); tvEncodedChunk_ = std::chrono::steady_clock::now() - chunk_->duration<std::chrono::nanoseconds>();
} nextTick_ = std::chrono::steady_clock::now();
}
encoder_->encode(chunk_.get()); encoder_->encode(chunk_.get());
nextTick_ += chunk_->duration<std::chrono::nanoseconds>(); nextTick_ += chunk_->duration<std::chrono::nanoseconds>();
auto currentTick = std::chrono::steady_clock::now(); auto currentTick = std::chrono::steady_clock::now();
// Synchronize read to chunk_ms_ // Synchronize read to chunk_ms_
if (nextTick_ >= currentTick) if (nextTick_ >= currentTick)
{ {
read_timer_.expires_after(nextTick_ - currentTick); read_timer_.expires_after(nextTick_ - currentTick);
read_timer_.async_wait([this](const boost::system::error_code& ec) { read_timer_.async_wait([this](const boost::system::error_code& ec) {
if (ec) if (ec)
{ {
LOG(ERROR, "AsioStream") << "Error during async wait: " << ec.message() << "\n"; LOG(ERROR, "AsioStream") << "Error during async wait: " << ec.message() << "\n";
} }
else else
{ {
do_read(); do_read();
} }
}); });
return; return;
} }
// Read took longer, wait for the buffer to fill up // Read took longer, wait for the buffer to fill up
else else
{ {
pcmListener_->onResync(this, std::chrono::duration_cast<std::chrono::milliseconds>(currentTick - nextTick_).count()); pcmListener_->onResync(this, std::chrono::duration_cast<std::chrono::milliseconds>(currentTick - nextTick_).count());
nextTick_ = currentTick + std::chrono::milliseconds(buffer_ms_); nextTick_ = currentTick + std::chrono::milliseconds(buffer_ms_);
first_ = true; first_ = true;
do_read(); do_read();
} }
}); });
} }
} // namespace streamreader } // namespace streamreader

View file

@ -133,9 +133,11 @@ void PcmStream::onChunkEncoded(const encoder::Encoder* /*encoder*/, std::shared_
if (duration <= 0) if (duration <= 0)
return; return;
chunk->timestamp.sec = tvEncodedChunk_.tv_sec; auto microsecs = std::chrono::duration_cast<std::chrono::microseconds>(tvEncodedChunk_.time_since_epoch()).count();
chunk->timestamp.usec = tvEncodedChunk_.tv_usec; chunk->timestamp.sec = microsecs / 1000000;
chronos::addUs(tvEncodedChunk_, duration * 1000); chunk->timestamp.usec = microsecs % 1000000;
tvEncodedChunk_ += std::chrono::nanoseconds(static_cast<std::chrono::nanoseconds::rep>(duration * 1000000));
if (pcmListener_) if (pcmListener_)
pcmListener_->onChunkRead(this, chunk, duration); pcmListener_->onChunkRead(this, chunk, duration);
} }

View file

@ -103,7 +103,7 @@ protected:
void setState(const ReaderState& newState); void setState(const ReaderState& newState);
timeval tvEncodedChunk_; std::chrono::time_point<std::chrono::steady_clock> tvEncodedChunk_;
PcmListener* pcmListener_; PcmListener* pcmListener_;
StreamUri uri_; StreamUri uri_;
SampleFormat sampleFormat_; SampleFormat sampleFormat_;

View file

@ -35,7 +35,7 @@ namespace streamreader
{ {
static constexpr auto LOG_TAG = "PosixStream"; static constexpr auto LOG_TAG = "PosixStream";
static constexpr auto kResyncTolerance = 50ms;
PosixStream::PosixStream(PcmListener* pcmListener, boost::asio::io_context& ioc, const StreamUri& uri) : AsioStream<stream_descriptor>(pcmListener, ioc, uri) PosixStream::PosixStream(PcmListener* pcmListener, boost::asio::io_context& ioc, const StreamUri& uri) : AsioStream<stream_descriptor>(pcmListener, ioc, uri)
{ {
@ -80,28 +80,25 @@ void PosixStream::do_read()
if (!stream_->is_open()) if (!stream_->is_open())
throw SnapException("failed to open stream: \"" + uri_.path + "\""); throw SnapException("failed to open stream: \"" + uri_.path + "\"");
if (first_)
{
LOG(DEBUG, LOG_TAG) << "First read, initializing nextTick to now\n";
nextTick_ = std::chrono::steady_clock::now();
}
int toRead = chunk_->payloadSize; int toRead = chunk_->payloadSize;
auto duration = chunk_->duration<std::chrono::nanoseconds>();
int len = 0; int len = 0;
do do
{ {
int count = read(stream_->native_handle(), chunk_->payload + len, toRead - len); int count = read(stream_->native_handle(), chunk_->payload + len, toRead - len);
if (count < 0 && idle_bytes_ < max_idle_bytes_) if (count < 0)
{ {
// nothing to read for a longer time now, set the chunk to silent // no data available, fill with silence
LOG(DEBUG, LOG_TAG) << "count < 0: " << errno
<< " && idleBytes < maxIdleBytes, ms: " << 1000 * chunk_->payloadSize / (sampleFormat_.rate() * sampleFormat_.frameSize())
<< "\n";
memset(chunk_->payload + len, 0, toRead - len); memset(chunk_->payload + len, 0, toRead - len);
idle_bytes_ += toRead - len; idle_bytes_ += toRead - len;
len += toRead - len;
break; break;
} }
else if (count < 0)
{
// nothing to read, try again (chunk_ms_ / 2) later
wait(read_timer_, std::chrono::milliseconds(chunk_ms_ / 2), [this] { do_read(); });
return;
}
else if (count == 0) else if (count == 0)
{ {
throw SnapException("end of file"); throw SnapException("end of file");
@ -115,29 +112,46 @@ void PosixStream::do_read()
} }
} while (len < toRead); } while (len < toRead);
// LOG(DEBUG, LOG_TAG) << "Received " << len << "/" << toRead << " bytes\n";
if (first_) if (first_)
{ {
first_ = false; first_ = false;
chronos::systemtimeofday(&tvEncodedChunk_); // initialize the stream's base timestamp to now minus the chunk's duration
nextTick_ = std::chrono::steady_clock::now() + std::chrono::milliseconds(buffer_ms_); tvEncodedChunk_ = std::chrono::steady_clock::now() - duration;
} }
encoder_->encode(chunk_.get());
nextTick_ += chunk_->duration<std::chrono::nanoseconds>();
auto currentTick = std::chrono::steady_clock::now();
if (nextTick_ >= currentTick) if ((idle_bytes_ == 0) || (idle_bytes_ <= max_idle_bytes_))
{
// the encoder will update the tvEncodedChunk when a chunk is encoded
encoder_->encode(chunk_.get());
}
else
{
// no data available
// set first_ = true will cause the timestamps to be updated without encoding
first_ = true;
}
nextTick_ += duration;
auto currentTick = std::chrono::steady_clock::now();
auto next_read = nextTick_ - currentTick;
if (next_read >= 0ms)
{ {
// synchronize reads to an interval of chunk_ms_ // synchronize reads to an interval of chunk_ms_
wait(read_timer_, nextTick_ - currentTick, [this] { do_read(); }); wait(read_timer_, nextTick_ - currentTick, [this] { do_read(); });
return; return;
} }
else if (next_read >= -kResyncTolerance)
{
LOG(INFO) << "next read < 0 (" << getName() << "): " << std::chrono::duration_cast<std::chrono::microseconds>(next_read).count() / 1000. << " ms\n";
do_read();
}
else else
{ {
// reading chunk_ms_ took longer than chunk_ms_ // reading chunk_ms_ took longer than chunk_ms_
pcmListener_->onResync(this, std::chrono::duration_cast<std::chrono::milliseconds>(currentTick - nextTick_).count()); pcmListener_->onResync(this, std::chrono::duration_cast<std::chrono::milliseconds>(-next_read).count());
nextTick_ = currentTick + std::chrono::milliseconds(buffer_ms_);
first_ = true; first_ = true;
do_read(); wait(read_timer_, duration + kResyncTolerance, [this] { do_read(); });
} }
lastException_ = ""; lastException_ = "";