From 926cb33fc265a13946f2ddeb65089d532e5e85d3 Mon Sep 17 00:00:00 2001 From: Michael Herstine Date: Wed, 24 Apr 2024 17:45:37 -0700 Subject: [PATCH] Reduce logging. This patch will: - address the change to `OnSocketInput()` in which the argument was changed to a span - reduce logging considerably (which had been irritating me, and which prompted complaints on the PR) --- src/lib/fmt/ThreadIdFormatter.hxx | 2 +- src/output/plugins/visualization/Protocol.cxx | 1 + .../plugins/visualization/SoundInfoCache.cxx | 26 ++---- .../visualization/VisualizationClient.cxx | 88 ++----------------- .../visualization/VisualizationClient.hxx | 2 +- 5 files changed, 13 insertions(+), 106 deletions(-) diff --git a/src/lib/fmt/ThreadIdFormatter.hxx b/src/lib/fmt/ThreadIdFormatter.hxx index a687ee86e3..c5233cd21a 100644 --- a/src/lib/fmt/ThreadIdFormatter.hxx +++ b/src/lib/fmt/ThreadIdFormatter.hxx @@ -12,7 +12,7 @@ template<> struct fmt::formatter : formatter { template - auto format(std::thread::id id, FormatContext &ctx) { + auto format(std::thread::id id, FormatContext &ctx) const { std::stringstream stm; stm << id; return formatter::format(stm.str(), ctx); diff --git a/src/output/plugins/visualization/Protocol.cxx b/src/output/plugins/visualization/Protocol.cxx index 94a76219d3..4bbe7f14f7 100644 --- a/src/output/plugins/visualization/Protocol.cxx +++ b/src/output/plugins/visualization/Protocol.cxx @@ -11,6 +11,7 @@ Visualization::ParseResult Visualization::ParseClihlo(void *data, size_t length, ClientHello &clihlo) noexcept { + // CLIHLO payload is 6 bytes, header & footer are five more. if (length < sizeof(ClientHello) + 5) { return ParseResult::NEED_MORE_DATA; diff --git a/src/output/plugins/visualization/SoundInfoCache.cxx b/src/output/plugins/visualization/SoundInfoCache.cxx index e7625bcae3..9355c7f0c0 100644 --- a/src/output/plugins/visualization/SoundInfoCache.cxx +++ b/src/output/plugins/visualization/SoundInfoCache.cxx @@ -15,13 +15,6 @@ using namespace std::chrono; const Domain d_sound_info_cache("vis_sound_info_cache"); -inline -typename std::chrono::microseconds::rep -NowTicks() { - return duration_cast( - std::chrono::system_clock::now().time_since_epoch()).count(); -} - Visualization::SoundInfoCache::SoundInfoCache(const AudioFormat &audio_format, const Duration &buf_span): fmt(audio_format), @@ -57,9 +50,6 @@ Visualization::SoundInfoCache::SoundInfoCache(const AudioFormat &audio_format, void Visualization::SoundInfoCache::Add(const void *data, size_t size) { - FmtDebug(d_sound_info_cache, "[{}] SoundInfoCache::add(tid:{}," - "bytes:{})", NowTicks(), std::this_thread::get_id(), size); - std::lock_guard guard(mutex); if (t0.time_since_epoch().count() == 0) { @@ -159,11 +149,6 @@ Visualization::SoundInfoCache::GetByTime(size_t nsamp, Time t, { using std::min; - FmtDebug(d_sound_info_cache, "[{}] SoundInfoCache::get_by_time" - "(tid:{},t:{}us, delta:{}us)", NowTicks(), std::this_thread::get_id(), - duration_cast(t.time_since_epoch()).count(), - duration_cast(t1 - t).count()); - std::lock_guard guard(mutex); size_t cbsamp = nsamp * frame_size; @@ -171,16 +156,15 @@ Visualization::SoundInfoCache::GetByTime(size_t nsamp, Time t, /* Can't fit the requested number of frames/samples into `buf`-- fail. */ FmtWarning(d_sound_info_cache, - "[{}] SoundInfoCache::get_by_time: can't fit {} " - "samples into {} bytes", NowTicks(), nsamp, cbbuf); + "SoundInfoCache::get_by_time: can't fit {} " + "samples into {} bytes", nsamp, cbbuf); return false; } if (t > t1) { FmtWarning(d_sound_info_cache, - "[{}] SoundInfoCache::get_by_time: time t {}us is " + "SoundInfoCache::get_by_time: time t {}us is " "greater than time t1 {}us-- failing.", - NowTicks(), duration_cast(t.time_since_epoch()).count(), duration_cast(t1.time_since_epoch()).count()); return false; @@ -199,10 +183,10 @@ Visualization::SoundInfoCache::GetByTime(size_t nsamp, Time t, size_t cb_in_buf = size_t(ceil(delta_t / secs_per_frame)) * frame_size; if (cbsamp > cb_in_buf) { FmtWarning(d_sound_info_cache, - "[{}] SoundInfoCache::get_by_time: the requested " + "SoundInfoCache::get_by_time: the requested " "number of samples take up {} bytes, but we only " "have {} bytes in the buffer.", - NowTicks(), cbsamp, cb_in_buf); + cbsamp, cb_in_buf); return false; } diff --git a/src/output/plugins/visualization/VisualizationClient.cxx b/src/output/plugins/visualization/VisualizationClient.cxx index 7fbcd13d66..975aba723b 100644 --- a/src/output/plugins/visualization/VisualizationClient.cxx +++ b/src/output/plugins/visualization/VisualizationClient.cxx @@ -14,14 +14,6 @@ const Domain d_vis_client("vis_client"); -inline -typename std::chrono::microseconds::rep -NowTicks() { - return duration_cast( - std::chrono::system_clock::now().time_since_epoch()).count(); -} - - // Invoked when the client connects and the plugin is in the "closed" state. Visualization::VisualizationClient::VisualizationClient( UniqueSocketDescriptor fd, @@ -53,10 +45,6 @@ void Visualization::VisualizationClient::OnPluginOpened( const std::shared_ptr &pcache) { - FmtDebug(d_vis_client, "[{}] VisualizationClient::OnPluginOpened(" - "this:{},tid:{},state:{})", NowTicks(), (size_t)this, - std::this_thread::get_id(), (int)protocol_state); - pcm_state = HavePcmData { pcache, Visualization::SoundAnalysis(sound_params, pcache) }; @@ -67,10 +55,6 @@ Visualization::VisualizationClient::OnPluginOpened( void Visualization::VisualizationClient::OnPluginClosed() { - FmtDebug(d_vis_client, "[{}] VisualizationClient::OnPluginClosed(" - "this:{},tid:{},state:{})", NowTicks(), (size_t)this, - std::this_thread::get_id(), (int)protocol_state); - if (IsClosed()) { Shutdown(); return; @@ -84,23 +68,14 @@ Visualization::VisualizationClient::OnPluginClosed() } Visualization::VisualizationClient::~VisualizationClient() { - FmtDebug(d_vis_client, "[{}] VisualizationClient::~VisualizationClient()" - "this:{},tid:{},state:{})", NowTicks(), (size_t)this, - std::this_thread::get_id(), (int)protocol_state); // This will be invoked on the main thread; the socket & underlying // `SocketEvent` will be torn-down on the I/O thread. timer.Cancel(); } BufferedSocket::InputResult -Visualization::VisualizationClient::OnSocketInput(void *data, - size_t length) noexcept +Visualization::VisualizationClient::OnSocketInput(std::span src) noexcept { - FmtDebug(d_vis_client, "[{}] VisualizationClient::OnSocketInput(" - "this:{},tid:{},state:{},length:{})", NowTicks(), - (size_t)this, std::this_thread::get_id(), - (int)protocol_state, length); - // We have data available to be read, and it's present in `data`... if (ProtocolState::Init != protocol_state) { Shutdown(); @@ -109,7 +84,9 @@ Visualization::VisualizationClient::OnSocketInput(void *data, // attempt to parse it as a CLIHLO message... ClientHello clihlo; - ParseResult parse_result = ParseClihlo(data, length, clihlo); + // TODO(sp1ff): IN-PROGRESS + // ParseResult parse_result = ParseClihlo(data, length, clihlo); + ParseResult parse_result = ParseClihlo(src.data(), src.size(), clihlo); if (ParseResult::NEED_MORE_DATA == parse_result) { return InputResult::MORE; } else if (ParseResult::ERROR == parse_result) { @@ -119,9 +96,6 @@ Visualization::VisualizationClient::OnSocketInput(void *data, return InputResult::CLOSED; } - FmtDebug(d_vis_client, "[{}] Got CLIHLO: {}fps, tau={}ms", NowTicks(), - clihlo.requested_fps, clihlo.tau); - if (0 != clihlo.major_version || 1 != clihlo.minor_version) { FmtWarning(d_vis_client, "Unexpected protocol version {}.{} " "requested-- proceeding to serve 0.1.", @@ -142,15 +116,11 @@ Visualization::VisualizationClient::OnSocketInput(void *data, }; // Seems legit-- compose our response... - ConsumeInput(length); + ConsumeInput(src.size()); next_frame.clear(); SerializeSrvhlo((std::byte)0, (std::byte)1, back_inserter(next_frame)); - FmtDebug(d_vis_client, "[{}] Composed a SRVHLO frame, cancelled read, " - "scheduled a write, and shifted to state {}.", NowTicks(), - (int)ProtocolState::SrvHlo); - // shift state... protocol_state = ProtocolState::SrvHlo; // and schedule a write. @@ -168,18 +138,12 @@ Visualization::VisualizationClient::OnSocketError( void Visualization::VisualizationClient::OnSocketClosed() noexcept { - FmtInfo(d_vis_client, "[{}] VisualizationClient::OnSocketClosed(" - "this:{},tid:{})", NowTicks(), (size_t)this, std::this_thread::get_id()); Shutdown(); } void Visualization::VisualizationClient::OnSocketReady(unsigned flags) noexcept { - FmtDebug(d_vis_client, "[{}] VisualizationClient::OnSocketReady(" - "this:{},tid:{},state:{},flags:{})", NowTicks(), (size_t)this, - std::this_thread::get_id(), (int)protocol_state, flags); - switch (protocol_state) { case ProtocolState::Init: { @@ -246,10 +210,6 @@ Visualization::VisualizationClient::ComposeSoundAnalysisFrame() { using namespace std::chrono; - FmtDebug(d_vis_client, "[{}] VisualizationClient::" - "ComposeSoundAnalysisFrame(this:{},tid:{},state:{})", - NowTicks(), (size_t)this, std::this_thread::get_id(), (int)protocol_state); - if (!PluginIsOpen()) { protocol_state = ProtocolState::ProtocolClosed; return false; @@ -299,32 +259,15 @@ Visualization::VisualizationClient::HandleFirstFrame() auto tau = timings->tau; auto freq = timings->freq; if (tau < std::chrono::milliseconds::zero()) { - FmtDebug(d_vis_client, "[{}] VisualizationClient::" - "HandleFirstFrame([this:{}]) scheduling a write for " - "{} ms from now & transitioning to state {}.", - NowTicks(), (size_t)this, -tau.count(), - (int)ProtocolState::Waiting); timer.Schedule(std::chrono::milliseconds(-tau)); protocol_state = ProtocolState::Waiting; } else { if (ComposeSoundAnalysisFrame()) { - FmtDebug(d_vis_client, "[{}] VisualizationClient::" - "HandleFirstFrame(this:{}) carried out sound " - "analysis, scheduled a write & is shifting to " - "state {}.", NowTicks(), (size_t)this, - (int)ProtocolState::FrameReady); event.ScheduleWrite(); timer.Schedule(std::chrono::milliseconds(freq)); protocol_state = ProtocolState::FrameReady; } else { - FmtDebug(d_vis_client, "[{}] VisualizationClient::" - "OnPluginOpened(this:{}) failed to perform " - "sound analysis; cancelling any outstanding " - "writes, scheduling another attempt for {}ms " - "from now & shifting to state {}.", - NowTicks(), (size_t)this, freq.count(), - (int)ProtocolState::Waiting); event.CancelWrite(); timer.Schedule(std::chrono::milliseconds(freq)); protocol_state = ProtocolState::Waiting; @@ -418,10 +361,6 @@ Visualization::VisualizationClient::HandleSrvHlo(unsigned flags) if (PluginIsOpen()) { HandleFirstFrame(); } else { - FmtDebug(d_vis_client, "[{}] VisualizationClient::" - "HandleSrvHlo(): The visualization plugin is " - "closed; shifting to state {}.", - NowTicks(), (int)ProtocolState::ProtocolClosed); protocol_state = ProtocolState::ProtocolClosed; event.CancelWrite(); } @@ -448,23 +387,11 @@ Visualization::VisualizationClient::LogSocketWriteError( void Visualization::VisualizationClient::OnTimer() noexcept { - FmtDebug(d_vis_client, "[{}] VisualizationClient::OnTimer(this:{}," - "tid:{},state:{})", NowTicks(), (size_t)this, std::this_thread::get_id(), - (int)protocol_state); - if (ComposeSoundAnalysisFrame()) { - FmtDebug(d_vis_client, "VisualizationClient::OnTimer() " - "carried-out sound analysis, scheduled a write, " - "and shifted to state {}.", - (int)ProtocolState::FrameReady); event.ScheduleWrite(); protocol_state = ProtocolState::FrameReady; } else { // Give up for now-- wait for the next timer event - FmtDebug(d_vis_client, "VisualizationClient::OnTimer() " - "failed to carry-out sound analysis; cancelling " - "outstanding writes, shifting to state {}.", - (int)ProtocolState::Waiting); event.CancelWrite(); protocol_state = ProtocolState::Waiting; } @@ -521,11 +448,6 @@ Visualization::VisualizationClient::WriteFrame() cb_written, cb_expected); } - FmtDebug(d_vis_client, "[{}] VisualizationClient::WriteFrame(tid:{}," - "state:{}) wrote {} bytes (of {}); cancelling any outstanding " - "writes & clearing the frame buffer.", NowTicks(), std::this_thread::get_id(), - (int)protocol_state, cb_written, cb_expected); - event.CancelWrite(); next_frame.clear(); diff --git a/src/output/plugins/visualization/VisualizationClient.hxx b/src/output/plugins/visualization/VisualizationClient.hxx index b99d391774..4b21d64b48 100644 --- a/src/output/plugins/visualization/VisualizationClient.hxx +++ b/src/output/plugins/visualization/VisualizationClient.hxx @@ -225,7 +225,7 @@ protected: ///////////////////////////////////////////////////////////////////////// virtual BufferedSocket::InputResult - OnSocketInput(void *data, size_t length) noexcept override; + OnSocketInput(std::span src) noexcept override; virtual void OnSocketError(std::exception_ptr ep) noexcept override; virtual void OnSocketClosed() noexcept override;