From e5fb1759b16d2c99487acc4fb0a2711afa3aa1dc Mon Sep 17 00:00:00 2001 From: jacqueline Date: Tue, 24 Jan 2023 16:39:52 +1100 Subject: [PATCH] Add a bunch of logging from playback stream investigatons --- src/audio/audio_element_handle.cpp | 6 ++--- src/audio/audio_playback.cpp | 2 +- src/audio/audio_task.cpp | 28 +++++++++++++++------- src/audio/chunk.cpp | 8 ++++++- src/audio/fatfs_audio_input.cpp | 6 +++++ src/audio/include/audio_element.hpp | 4 +++- src/audio/include/audio_element_handle.hpp | 2 +- src/audio/stream_buffer.cpp | 8 ++++++- 8 files changed, 48 insertions(+), 16 deletions(-) diff --git a/src/audio/audio_element_handle.cpp b/src/audio/audio_element_handle.cpp index 1250bbcf..c5f0c374 100644 --- a/src/audio/audio_element_handle.cpp +++ b/src/audio/audio_element_handle.cpp @@ -39,15 +39,15 @@ auto AudioElementHandle::Quit() -> void { auto AudioElementHandle::PauseSync() -> void { PlayPause(PAUSE); - MonitorUtilState(eSuspended); + MonitorUntilState(eSuspended); } auto AudioElementHandle::QuitSync() -> void { Quit(); - MonitorUtilState(eDeleted); + MonitorUntilState(eDeleted); } -auto AudioElementHandle::MonitorUtilState(eTaskState desired) -> void { +auto AudioElementHandle::MonitorUntilState(eTaskState desired) -> void { while (eTaskGetState(*task_) != desired) { WakeUpTask(); vTaskDelay(pdMS_TO_TICKS(1)); diff --git a/src/audio/audio_playback.cpp b/src/audio/audio_playback.cpp index 34ede950..7462b4f6 100644 --- a/src/audio/audio_playback.cpp +++ b/src/audio/audio_playback.cpp @@ -54,7 +54,7 @@ auto AudioPlayback::create(drivers::GpioExpander* expander, // TODO(jacqueline): think about sizes AudioPlayback::AudioPlayback() - : stream_start_(128, 128), stream_end_(128, 128) {} + : stream_start_(128, 256), stream_end_(128, 256) {} AudioPlayback::~AudioPlayback() { for (auto& element : element_handles_) { diff --git a/src/audio/audio_task.cpp b/src/audio/audio_task.cpp index 079ae852..e3641973 100644 --- a/src/audio/audio_task.cpp +++ b/src/audio/audio_task.cpp @@ -22,6 +22,8 @@ namespace audio { + static const char *kTag = "task"; + auto StartAudioTask(const std::string& name, std::shared_ptr element) -> std::unique_ptr { @@ -30,6 +32,7 @@ auto StartAudioTask(const std::string& name, // Newly created task will free this. AudioTaskArgs* args = new AudioTaskArgs{.element = element}; + ESP_LOGI(kTag, "starting audio task %s", name.c_str()); xTaskCreate(&AudioTaskMain, name.c_str(), element->StackSizeBytes(), args, kTaskPriorityAudio, task_handle.get()); @@ -37,18 +40,19 @@ auto StartAudioTask(const std::string& name, } void AudioTaskMain(void* args) { + // Nest the body within an additional scope to ensure that destructors are + // called before the task quits. { AudioTaskArgs* real_args = reinterpret_cast(args); std::shared_ptr element = std::move(real_args->element); delete real_args; - char tag[] = "task"; ChunkReader chunk_reader = ChunkReader(element->InputBuffer()); while (element->ElementState() != STATE_QUIT) { if (element->ElementState() == STATE_PAUSE) { // TODO: park with a condition variable or something? - vTaskDelay(100); + vTaskDelay(1000); continue; } @@ -67,11 +71,11 @@ void AudioTaskMain(void* args) { return {}; } }, - element->IdleTimeout()); + 0); if (chunk_res == CHUNK_PROCESSING_ERROR || chunk_res == CHUNK_DECODING_ERROR) { - ESP_LOGE(tag, "failed to process chunk"); + ESP_LOGE(kTag, "failed to process chunk"); break; // TODO. } else if (chunk_res == CHUNK_STREAM_ENDED) { has_received_message = true; @@ -83,12 +87,12 @@ void AudioTaskMain(void* args) { if (type == TYPE_STREAM_INFO) { auto parse_res = ReadMessage(&StreamInfo::Parse, message); if (parse_res.has_error()) { - ESP_LOGE(tag, "failed to parse stream info"); + ESP_LOGE(kTag, "failed to parse stream info"); break; // TODO. } auto info_res = element->ProcessStreamInfo(parse_res.value()); if (info_res.has_error()) { - ESP_LOGE(tag, "failed to process stream info"); + ESP_LOGE(kTag, "failed to process stream info"); break; // TODO. } } @@ -112,8 +116,16 @@ void AudioTaskMain(void* args) { // Signal the element to do any of its idle tasks. auto process_error = element->ProcessIdle(); if (process_error.has_error()) { - ESP_LOGE(tag, "failed to process idle"); - break; // TODO. + auto err = process_error.error(); + if (err == OUT_OF_DATA) { + // If we ran out of data, then place ourselves into the pause state. + // We will be woken up when there's something to do. + element->ElementState(STATE_PAUSE); + continue; + } else { + ESP_LOGE(kTag, "failed to process idle"); + break; // TODO. + } } } } diff --git a/src/audio/chunk.cpp b/src/audio/chunk.cpp index 5f8f3148..b37fdfed 100644 --- a/src/audio/chunk.cpp +++ b/src/audio/chunk.cpp @@ -7,12 +7,15 @@ #include #include "cbor.h" +#include "esp_log.h" #include "stream_buffer.hpp" #include "stream_message.hpp" namespace audio { +static const char* kTag = "chunk"; + ChunkWriter::ChunkWriter(StreamBuffer* buffer) : stream_(buffer), leftover_bytes_(0) {} @@ -53,9 +56,11 @@ auto ChunkWriter::WriteChunkToStream( // Try to write to the buffer. Note the return type here will be either 0 or // header_size + chunk_size, as MessageBuffer doesn't allow partial writes. + size_t intended_write_size = header_size.value() + chunk_size; + ESP_LOGI(kTag, "writing chunk of size %d", intended_write_size); size_t actual_write_size = xMessageBufferSend(stream_->Handle(), write_buffer.data(), - header_size.value() + chunk_size, max_wait); + intended_write_size, max_wait); if (actual_write_size == 0) { leftover_bytes_ = chunk_size; @@ -86,6 +91,7 @@ auto ChunkReader::ReadChunkFromStream( // First, wait for a message to arrive over the buffer. cpp::span new_data_dest = stream_->ReadBuffer().last( stream_->ReadBuffer().size() - leftover_bytes_); + ESP_LOGI(kTag, "reading chunk of size %d", new_data_dest.size()); last_message_size_ = xMessageBufferReceive( stream_->Handle(), new_data_dest.data(), new_data_dest.size(), max_wait); diff --git a/src/audio/fatfs_audio_input.cpp b/src/audio/fatfs_audio_input.cpp index fc623d86..7f11805e 100644 --- a/src/audio/fatfs_audio_input.cpp +++ b/src/audio/fatfs_audio_input.cpp @@ -131,6 +131,10 @@ auto FatfsAudioInput::ProcessIdle() -> cpp::result { file_buffer_write_pos_ = file_buffer_.begin(); } } + } else if (GetRingBufferDistance() == 0) { + // We have no file open, and no data waiting to be written. We're out of + // stuff to do, so signal a pause. + return cpp::fail(OUT_OF_DATA); } // Now stream data into the output buffer until it's full. @@ -152,6 +156,8 @@ auto FatfsAudioInput::ProcessIdle() -> cpp::result { } } + // We've finished writing out chunks, but there may be more of the file to + // read. Return, and begin again in the next idle call. return {}; } diff --git a/src/audio/include/audio_element.hpp b/src/audio/include/audio_element.hpp index ec6d6e80..eb700180 100644 --- a/src/audio/include/audio_element.hpp +++ b/src/audio/include/audio_element.hpp @@ -32,6 +32,8 @@ enum AudioProcessingError { UNSUPPORTED_STREAM, // Indicates an error with reading or writing stream data. IO_ERROR, + // Indicates that the element has run out of data to process. + OUT_OF_DATA, }; /* @@ -65,7 +67,7 @@ class IAudioElement { * to ProcessIdle(). If this is portMAX_DELAY (the default), then ProcessIdle * will never be called. */ - virtual auto IdleTimeout() const -> TickType_t { return portMAX_DELAY; } + virtual auto IdleTimeout() const -> TickType_t { return 10; } virtual auto InputMinChunkSize() const -> std::size_t { return 0; } diff --git a/src/audio/include/audio_element_handle.hpp b/src/audio/include/audio_element_handle.hpp index adb26baa..e4d66491 100644 --- a/src/audio/include/audio_element_handle.hpp +++ b/src/audio/include/audio_element_handle.hpp @@ -33,7 +33,7 @@ class AudioElementHandle { std::unique_ptr task_; std::shared_ptr element_; - auto MonitorUtilState(eTaskState desired) -> void; + auto MonitorUntilState(eTaskState desired) -> void; auto SetStateAndWakeUp(ElementState state) -> void; auto WakeUpTask() -> void; }; diff --git a/src/audio/stream_buffer.cpp b/src/audio/stream_buffer.cpp index 740bea7f..9bdeaa72 100644 --- a/src/audio/stream_buffer.cpp +++ b/src/audio/stream_buffer.cpp @@ -1,4 +1,6 @@ #include "stream_buffer.hpp" +#include "assert.h" +#include "esp_log.h" namespace audio { @@ -14,7 +16,11 @@ StreamBuffer::StreamBuffer(std::size_t chunk_size, std::size_t buffer_size) input_chunk_(raw_input_chunk_, chunk_size * 1.5), raw_output_chunk_(static_cast( heap_caps_malloc(chunk_size, MALLOC_CAP_SPIRAM))), - output_chunk_(raw_output_chunk_, chunk_size) {} + output_chunk_(raw_output_chunk_, chunk_size) { + assert(input_chunk_.size() <= buffer_size); + assert(output_chunk_.size() <= buffer_size); + ESP_LOGI("streambuf", "created buffer of chunk size %d, total size %d", chunk_size, buffer_size); + } StreamBuffer::~StreamBuffer() { vMessageBufferDelete(handle_);