/*** This file is part of snapcast Copyright (C) 2014-2020 Johannes Pohl This program is free software: you can redistribute it and/or modify it under the terms of the GNU General Public License as published by the Free Software Foundation, either version 3 of the License, or (at your option) any later version. This program is distributed in the hope that it will be useful, but WITHOUT ANY WARRANTY; without even the implied warranty of MERCHANTABILITY or FITNESS FOR A PARTICULAR PURPOSE. See the GNU General Public License for more details. You should have received a copy of the GNU General Public License along with this program. If not, see . ***/ #include "stream.hpp" #include "common/aixlog.hpp" #include "time_provider.hpp" #include #include #include using namespace std; namespace cs = chronos; static constexpr auto LOG_TAG = "Stream"; static constexpr auto kCorrectionBegin = 100us; Stream::Stream(const SampleFormat& in_format, const SampleFormat& out_format) : in_format_(in_format), median_(0), shortMedian_(0), lastUpdate_(0), playedFrames_(0), bufferMs_(cs::msec(500)), soxr_(nullptr), frame_delta_(0), hard_sync_(true) { buffer_.setSize(500); shortBuffer_.setSize(100); miniBuffer_.setSize(20); if (out_format.rate != 0) format_ = out_format; else format_ = in_format_; /* 48000 x ------- = ----- 47999,2 x - 1 x = 1,000016667 / (1,000016667 - 1) */ // setRealSampleRate(format_.rate); if ((format_.rate != in_format_.rate) || (format_.bits != in_format_.bits)) { LOG(INFO, LOG_TAG) << "Resampling from " << in_format_.getFormat() << " to " << format_.getFormat() << "\n"; soxr_error_t error; soxr_datatype_t in_type = SOXR_INT16_I; soxr_datatype_t out_type = SOXR_INT16_I; if (in_format_.sampleSize > 2) in_type = SOXR_INT32_I; if (format_.sampleSize > 2) out_type = SOXR_INT32_I; soxr_io_spec_t iospec = soxr_io_spec(in_type, out_type); // HQ should be fine: http://sox.sourceforge.net/Docs/FAQ soxr_quality_spec_t q_spec = soxr_quality_spec(SOXR_HQ, 0); soxr_ = soxr_create(static_cast(in_format_.rate), static_cast(format_.rate), format_.channels, &error, &iospec, &q_spec, NULL); if (error) { LOG(ERROR, LOG_TAG) << "Error soxr_create: " << error << "\n"; } // initialize the buffer with 20ms (~latency of the reampler) resample_buffer_.resize(format_.frameSize * ceil(format_.msRate()) * 20); } } Stream::~Stream() { if (soxr_) soxr_delete(soxr_); } void Stream::setRealSampleRate(double sampleRate) { if (sampleRate == format_.rate) { correctAfterXFrames_ = 0; } else { correctAfterXFrames_ = round((format_.rate / sampleRate) / (format_.rate / sampleRate - 1.)); // LOG(DEBUG, LOG_TAG) << "Correct after X: " << correctAfterXFrames_ << " (Real rate: " << sampleRate << ", rate: " << format_.rate << ")\n"; } } void Stream::setBufferLen(size_t bufferLenMs) { bufferMs_ = cs::msec(bufferLenMs); } void Stream::clearChunks() { while (chunks_.size() > 0) chunks_.pop(); resetBuffers(); } void Stream::addChunk(unique_ptr chunk) { while (chunks_.size() * chunk->duration().count() > 10000) chunks_.pop(); // chunks_.push(move(chunk)); // LOG(DEBUG, LOG_TAG) << "new chunk: " << chunk->duration().count() << ", Chunks: " << chunks_.size() << "\n"; if (soxr_ == nullptr) { chunks_.push(move(chunk)); } else { if (in_format_.bits == 24) { // sox expects 32 bit input, shift 8 bits left int32_t* frames = (int32_t*)chunk->payload; for (size_t n = 0; n < chunk->getSampleCount(); ++n) frames[n] = frames[n] << 8; } size_t idone; size_t odone; auto resample_buffer_framesize = resample_buffer_.size() / format_.frameSize; auto error = soxr_process(soxr_, chunk->payload, chunk->getFrameCount(), &idone, resample_buffer_.data(), resample_buffer_framesize, &odone); if (error) { LOG(ERROR, LOG_TAG) << "Error soxr_process: " << error << "\n"; // delete out; } else { LOG(TRACE, LOG_TAG) << "Resample idone: " << idone << "/" << chunk->getFrameCount() << ", odone: " << odone << "/" << resample_buffer_.size() / format_.frameSize << ", delay: " << soxr_delay(soxr_) << "\n"; // some data has been resampled (odone frames) and some is still in the pipe (soxr_delay frames) if (odone > 0) { // get the resamples ts from the input ts auto input_end_ts = chunk->start() + chunk->duration(); double resampled_ms = (odone + soxr_delay(soxr_)) / format_.msRate(); auto resampled_start = input_end_ts - std::chrono::microseconds(static_cast(resampled_ms * 1000.)); auto resampled_chunk = new msg::PcmChunk(format_, 0); auto us = chrono::duration_cast(resampled_start.time_since_epoch()).count(); resampled_chunk->timestamp.sec = us / 1000000; resampled_chunk->timestamp.usec = us % 1000000; // copy from the resample_buffer to the resampled chunk resampled_chunk->payloadSize = odone * format_.frameSize; resampled_chunk->payload = (char*)realloc(resampled_chunk->payload, resampled_chunk->payloadSize); memcpy(resampled_chunk->payload, resample_buffer_.data(), resampled_chunk->payloadSize); if (format_.bits == 24) { // sox has quantized to 32 bit, shift 8 bits right int32_t* frames = (int32_t*)resampled_chunk->payload; for (size_t n = 0; n < resampled_chunk->getSampleCount(); ++n) { // +128 to round to the nearest so that quantisation steps are distributed evenly frames[n] = (frames[n] + 128) >> 8; if (frames[n] > 0x7fffffff) frames[n] = 0x7fffffff; } } chunks_.push(shared_ptr(resampled_chunk)); // check if the resample_buffer is large enough, or if soxr was using all available space if (odone == resample_buffer_framesize) { // buffer for resampled data too small, add space for 5ms resample_buffer_.resize(resample_buffer_.size() + format_.frameSize * ceil(format_.msRate()) * 5); LOG(INFO, LOG_TAG) << "Resample buffer completely filled, adding space for 5ms; new buffer size: " << resample_buffer_.size() << " bytes\n"; } // //LOG(TRACE, LOG_TAG) << "ts: " << out->timestamp.sec << "s, " << out->timestamp.usec/1000.f << " ms, duration: " << odone / format_.msRate() // << "\n"; // int64_t next_us = us + static_cast(odone / format_.msRate() * 1000); // LOG(TRACE, LOG_TAG) << "ts: " << us << ", next: " << next_us << ", diff: " << next_us_ - us << "\n"; // next_us_ = next_us; } } } } bool Stream::waitForChunk(size_t ms) const { return chunks_.wait_for(std::chrono::milliseconds(ms)); } cs::time_point_clk Stream::getSilentPlayerChunk(void* outputBuffer, unsigned long frames) { if (!chunk_) chunk_ = chunks_.pop(); cs::time_point_clk tp = chunk_->start(); memset(outputBuffer, 0, frames * format_.frameSize); return tp; } cs::time_point_clk Stream::getNextPlayerChunk(void* outputBuffer, const cs::usec& timeout, unsigned long frames) { if (!chunk_ && !chunks_.try_pop(chunk_, timeout)) throw 0; cs::time_point_clk tp = chunk_->start(); unsigned long read = 0; while (read < frames) { read += chunk_->readFrames(static_cast(outputBuffer) + read * format_.frameSize, frames - read); if (chunk_->isEndOfChunk() && !chunks_.try_pop(chunk_, timeout)) throw 0; } return tp; } cs::time_point_clk Stream::getNextPlayerChunk(void* outputBuffer, const cs::usec& timeout, unsigned long frames, long framesCorrection) { if (framesCorrection < 0 && frames + framesCorrection <= 0) { // Avoid underflow in new char[] constructor. framesCorrection = -frames + 1; } frame_delta_ -= framesCorrection; if (framesCorrection == 0) return getNextPlayerChunk(outputBuffer, timeout, frames); long toRead = frames + framesCorrection; char* buffer = new char[toRead * format_.frameSize]; cs::time_point_clk tp = getNextPlayerChunk(buffer, timeout, toRead); const auto max = framesCorrection < 0 ? frames : toRead; // Divide the buffer into one more slice than frames that need to be dropped. // We will drop/repeat 0 frames from the first slice, 1 frame from the second, ..., and framesCorrection frames from the last slice. size_t slices = abs(framesCorrection) + 1; if (slices > max) { // We cannot have more slices than frames, because that would cause // size = 0 -> pos = 0 -> pos - n < 0 in the loop below // Overwriting slices effectively corrects less frames than asked for in framesCorrection. slices = max; } // Size of each slice. The last slice may be bigger. int size = max / slices; // LOG(TRACE, LOG_TAG) << "getNextPlayerChunk, frames: " << frames << ", correction: " << framesCorrection << " (" << toRead << "), slices: " << slices // << "\n"; size_t pos = 0; for (size_t n = 0; n < slices; ++n) { // Adjust size in the last iteration, because the last slice may be bigger if (n + 1 == slices) size = max - pos; if (framesCorrection < 0) { // Read one frame less per slice from the input, but write a duplicated frame per slice to the output // LOG(TRACE, LOG_TAG) << "duplicate - requested: " << frames << ", read: " << toRead << ", slice: " << n << ", size: " << size << ", out pos: " << // pos << ", // source pos: " << pos - n << "\n"; memcpy(static_cast(outputBuffer) + pos * format_.frameSize, buffer + (pos - n) * format_.frameSize, size * format_.frameSize); } else { // Read all input frames, but skip a frame per slice when writing to the output. // LOG(TRACE, LOG_TAG) << "remove - requested: " << frames << ", read: " << toRead << ", slice: " << n << ", size: " << size << ", out pos: " << pos // - n << // ", source pos: " << pos << "\n"; memcpy(static_cast(outputBuffer) + (pos - n) * format_.frameSize, buffer + pos * format_.frameSize, size * format_.frameSize); } pos += size; } delete[] buffer; return tp; } /* 2020-01-12 20-25-26 [Info] Chunk: 7 7 11 15 179 120 2020-01-12 20-25-27 [Info] Chunk: 6 6 8 15 212 122 2020-01-12 20-25-28 [Info] Chunk: 6 6 7 12 245 123 2020-01-12 20-25-29 [Info] Chunk: 5 6 6 9 279 117 2020-01-12 20-25-30 [Info] Chunk: 4 5 6 8 312 117 2020-01-12 20-25-30 [Error] Controller::onException: read_some: End of file 2020-01-12 20-25-30 [Error] Exception in Controller::worker(): read_some: End of file 2020-01-12 20-25-31 [Error] Exception in Controller::worker(): connect: Connection refused 2020-01-12 20-25-31 [Error] Error in socket shutdown: Transport endpoint is not connected 2020-01-12 20-25-32 [Error] Exception in Controller::worker(): connect: Connection refused 2020-01-12 20-25-32 [Error] Error in socket shutdown: Transport endpoint is not connected ^C2020-01-12 20-25-32 [Info] Received signal 2: Interrupt 2020-01-12 20-25-32 [Info] Stopping controller 2020-01-12 20-25-32 [Error] Error in socket shutdown: Bad file descriptor 2020-01-12 20-25-32 [Error] Exception: Invalid argument 2020-01-12 20-25-32 [Notice] daemon terminated. ================================================================= ==22383==ERROR: LeakSanitizer: detected memory leaks Direct leak of 5756 byte(s) in 1 object(s) allocated from: #0 0x7f3d60635602 in malloc (/usr/lib/x86_64-linux-gnu/libasan.so.2+0x98602) #1 0x448fc2 in Stream::getNextPlayerChunk(void*, std::chrono::duration > const&, unsigned long, long) /home/johannes/Develop/snapcast/client/stream.cpp:163 SUMMARY: AddressSanitizer: 5756 byte(s) leaked in 1 allocation(s). */ void Stream::updateBuffers(int age) { buffer_.add(age); miniBuffer_.add(age); shortBuffer_.add(age); } void Stream::resetBuffers() { buffer_.clear(); miniBuffer_.clear(); shortBuffer_.clear(); } bool Stream::getPlayerChunk(void* outputBuffer, const cs::usec& outputBufferDacTime, unsigned long frames) { if (outputBufferDacTime > bufferMs_) { LOG(INFO, LOG_TAG) << "outputBufferDacTime > bufferMs: " << cs::duration(outputBufferDacTime) << " > " << cs::duration(bufferMs_) << "\n"; return false; } if (!chunk_ && !chunks_.try_pop(chunk_, outputBufferDacTime)) { LOG(INFO, LOG_TAG) << "no chunks available\n"; return false; } cs::nsec chunk_duration = cs::nsec(static_cast(frames / format_.nsRate())); /// 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 => wait for a while, play silence in the meantime /// age > 0 => too old => throw them away try { if (hard_sync_) { cs::usec age = std::chrono::duration_cast(TimeProvider::serverNow() - chunk_->start()) - bufferMs_ + outputBufferDacTime; // LOG(INFO, LOG_TAG) << "age: " << age.count() / 1000 << ", buffer: " << std::chrono::duration_cast(chunk_duration).count() // << "\n"; if (age < -chunk_duration) { // the oldest chunk (top of the stream) is too young for the buffer // e.g. age = -100ms (=> should be played in 100ms) // but the requested chunk duration is 50ms, so there is not data in this iteration available getSilentPlayerChunk(outputBuffer, frames); return true; } else { if (age.count() > 0) { // age > 0: the top of the stream is too old. We must fast foward. while (chunks_.try_pop(chunk_, 0ms)) { age = std::chrono::duration_cast(TimeProvider::serverNow() - chunk_->start()) - bufferMs_ + outputBufferDacTime; LOG(DEBUG, LOG_TAG) << "age: " << age.count() / 1000 << ", chunk_duration: " << -std::chrono::duration_cast(chunk_duration).count() << ", duration: " << chunk_->duration().count() << "\n"; if (age <= 0ms) break; } } if (age.count() < 0) { // the oldest chunk (top of the stream) can be played in this iteration // e.g. age = -20ms (=> should be played in 20ms) // and the current chunk duration is 50ms, so we need to play 20ms silence (as we don't have data) // and can play 30ms of the stream size_t silent_frames = static_cast(-chunk_->format.nsRate() * std::chrono::duration_cast(age).count()); LOG(DEBUG, LOG_TAG) << "Silent frames: " << silent_frames << ", frames: " << frames << ", age: " << std::chrono::duration_cast(age).count() / 1000. << "\n"; getSilentPlayerChunk(outputBuffer, silent_frames); getNextPlayerChunk((char*)outputBuffer + (chunk_->format.frameSize * silent_frames), 0ms, frames - silent_frames); hard_sync_ = false; resetBuffers(); return true; } return false; } } // sample rate correction // framesCorrection = number of frames to be read more or less to get in-sync long framesCorrection = 0; if (correctAfterXFrames_ != 0) { playedFrames_ += frames; if (playedFrames_ >= (unsigned long)abs(correctAfterXFrames_)) { framesCorrection = static_cast(playedFrames_) / correctAfterXFrames_; playedFrames_ %= abs(correctAfterXFrames_); } } cs::usec age = std::chrono::duration_cast(TimeProvider::serverNow() - getNextPlayerChunk(outputBuffer, 0ms, frames, framesCorrection) - bufferMs_ + outputBufferDacTime); setRealSampleRate(format_.rate); // check if we need a hard sync if (buffer_.full() && (cs::usec(abs(median_)) > cs::msec(2))) { LOG(INFO, LOG_TAG) << "pBuffer->full() && (abs(median_) > 2): " << median_ << "\n"; hard_sync_ = true; } else if (shortBuffer_.full() && (cs::usec(abs(shortMedian_)) > cs::msec(5))) { LOG(INFO, LOG_TAG) << "pShortBuffer->full() && (abs(shortMedian_) > 5): " << shortMedian_ << "\n"; hard_sync_ = true; } else if (miniBuffer_.full() && (cs::usec(abs(miniBuffer_.median())) > cs::msec(50))) { LOG(INFO, LOG_TAG) << "pMiniBuffer->full() && (abs(pMiniBuffer->mean()) > 50): " << miniBuffer_.median() << "\n"; hard_sync_ = true; } else if (cs::abs(age) > 500ms) { LOG(INFO, LOG_TAG) << "abs(age > 500): " << cs::abs(age).count() << "\n"; hard_sync_ = true; } else if (shortBuffer_.full()) { // No hard sync needed // Check if we need a samplerate correction (change playback speed (soft sync)) auto miniMedian = miniBuffer_.median(); if ((cs::usec(shortMedian_) > kCorrectionBegin) && (cs::usec(miniMedian) > cs::usec(50)) && (cs::usec(age) > cs::usec(50))) { double rate = (shortMedian_ / 100) * 0.00005; rate = 1.0 - std::min(rate, 0.0005); // LOG(INFO, LOG_TAG) << "Rate: " << rate << "\n"; // we are late (age > 0), this means we are not playing fast enough // => the real sample rate seems to be lower, we have to drop some frames setRealSampleRate(format_.rate * rate); // 0.9999); } else if ((cs::usec(shortMedian_) < -kCorrectionBegin) && (cs::usec(miniMedian) < -cs::usec(50)) && (cs::usec(age) < -cs::usec(50))) { double rate = (-shortMedian_ / 100) * 0.00005; rate = 1.0 + std::min(rate, 0.0005); // LOG(INFO, LOG_TAG) << "Rate: " << rate << "\n"; // we are early (age > 0), this means we are playing too fast // => the real sample rate seems to be higher, we have to insert some frames setRealSampleRate(format_.rate * rate); // 1.0001); } } updateBuffers(age.count()); // print sync stats time_t now = time(nullptr); if (now != lastUpdate_) { lastUpdate_ = now; median_ = buffer_.median(); shortMedian_ = shortBuffer_.median(); LOG(INFO, LOG_TAG) << "Chunk: " << age.count() / 100 << "\t" << miniBuffer_.median() / 100 << "\t" << shortMedian_ / 100 << "\t" << median_ / 100 << "\t" << buffer_.size() << "\t" << cs::duration(outputBufferDacTime) << "\t" << frame_delta_ << "\n"; frame_delta_ = 0; } return (abs(cs::duration(age)) < 500); } catch (int e) { LOG(INFO) << "Exception\n"; return false; } }