Skip to content

Commit

Permalink
Reduce logging.
Browse files Browse the repository at this point in the history 
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)
  • Loading branch information
@sp1ff
sp1ff committed Sep 30, 2024
1 parent b69438d commit 926cb33
Show file tree
Hide file tree
Showing 5 changed files with 13 additions and 106 deletions.
2 changes: 1 addition & 1 deletion src/lib/fmt/ThreadIdFormatter.hxx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -12,7 +12,7 @@ template<>
struct fmt::formatter<std::thread::id> : formatter<string_view>
{
template<typename FormatContext>
auto format(std::thread::id id, FormatContext &ctx) {
auto format(std::thread::id id, FormatContext &ctx) const {
std::stringstream stm;
stm << id;
return formatter<string_view>::format(stm.str(), ctx);
Expand Down
1 change: 1 addition & 0 deletions src/output/plugins/visualization/Protocol.cxx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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;
Expand Down
26 changes: 5 additions & 21 deletions src/output/plugins/visualization/SoundInfoCache.cxx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -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::microseconds>(
std::chrono::system_clock::now().time_since_epoch()).count();
}

Visualization::SoundInfoCache::SoundInfoCache(const AudioFormat &audio_format,
const Duration &buf_span):
fmt(audio_format),
Expand Down Expand Up @@ -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<Mutex> guard(mutex);

if (t0.time_since_epoch().count() == 0) {
Expand Down Expand Up @@ -159,28 +149,22 @@ 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<std::chrono::microseconds>(t.time_since_epoch()).count(),
duration_cast<std::chrono::microseconds>(t1 - t).count());

std::lock_guard<Mutex> guard(mutex);

size_t cbsamp = nsamp * frame_size;
if (cbsamp > cbbuf) {
/* 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<std::chrono::microseconds>(t.time_since_epoch()).count(),
duration_cast<std::chrono::microseconds>(t1.time_since_epoch()).count());
return false;
Expand All @@ -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;
}

Expand Down
88 changes: 5 additions & 83 deletions src/output/plugins/visualization/VisualizationClient.cxx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -14,14 +14,6 @@

const Domain d_vis_client("vis_client");

inline
typename std::chrono::microseconds::rep
NowTicks() {
return duration_cast<std::chrono::microseconds>(
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,
Expand Down Expand Up @@ -53,10 +45,6 @@ void
Visualization::VisualizationClient::OnPluginOpened(
const std::shared_ptr<SoundInfoCache> &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)
};
Expand All @@ -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;
Expand All @@ -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<std::byte> 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();
Expand All @@ -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) {
Expand All @@ -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.",
Expand All @@ -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.
Expand All @@ -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: {

Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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;
Expand Down Expand Up @@ -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();
}
Expand All @@ -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;
}
Expand Down Expand Up @@ -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();

Expand Down
2 changes: 1 addition & 1 deletion src/output/plugins/visualization/VisualizationClient.hxx
View file
Original file line number Diff line number Diff line change
Expand Up @@ -225,7 +225,7 @@ protected:
/////////////////////////////////////////////////////////////////////////

virtual BufferedSocket::InputResult
OnSocketInput(void *data, size_t length) noexcept override;
OnSocketInput(std::span<std::byte> src) noexcept override;
virtual void OnSocketError(std::exception_ptr ep) noexcept override;
virtual void OnSocketClosed() noexcept override;

Expand Down

0 comments on commit 926cb33

Please sign in to comment.