From ce7d4df26ca9ee3bda33969597dee934867f1c74 Mon Sep 17 00:00:00 2001 From: Helge Norberg Date: Wed, 28 Oct 2015 15:01:06 +0100 Subject: [PATCH] * Added logging of severe diagnostics events to log at warning level. graph::set_tag now takes a severity parameter allowing expected tags such as param and seek to not be logged as a warning --- common/CMakeLists.txt | 2 + common/diagnostics/graph.cpp | 6 +- common/diagnostics/graph.h | 10 ++- common/diagnostics/graph_to_log_sink.cpp | 78 +++++++++++++++++++ common/diagnostics/graph_to_log_sink.h | 31 ++++++++ core/diagnostics/osd_graph.cpp | 2 +- core/diagnostics/subject_diagnostics.cpp | 16 +++- .../decklink/consumer/decklink_consumer.cpp | 6 +- .../decklink/producer/decklink_producer.cpp | 4 +- modules/ffmpeg/consumer/ffmpeg_consumer.cpp | 2 +- modules/ffmpeg/producer/ffmpeg_producer.cpp | 4 +- modules/ffmpeg/producer/input/input.cpp | 2 +- modules/flash/producer/flash_producer.cpp | 4 +- modules/html/producer/html_producer.cpp | 4 +- .../newtek/consumer/newtek_ivga_consumer.cpp | 2 +- modules/oal/consumer/oal_consumer.cpp | 4 +- modules/screen/consumer/screen_consumer.cpp | 2 +- shell/server.cpp | 4 +- 18 files changed, 157 insertions(+), 26 deletions(-) create mode 100644 common/diagnostics/graph_to_log_sink.cpp create mode 100644 common/diagnostics/graph_to_log_sink.h diff --git a/common/CMakeLists.txt b/common/CMakeLists.txt index b441b27b5..cd1bfb9fa 100644 --- a/common/CMakeLists.txt +++ b/common/CMakeLists.txt @@ -3,6 +3,7 @@ project (common) set(SOURCES diagnostics/graph.cpp + diagnostics/graph_to_log_sink.cpp gl/gl_check.cpp @@ -44,6 +45,7 @@ elseif (CMAKE_COMPILER_IS_GNUCXX) endif () set(HEADERS diagnostics/graph.h + diagnostics/graph_to_log_sink.h gl/gl_check.h diff --git a/common/diagnostics/graph.cpp b/common/diagnostics/graph.cpp index 4cd3fc582..539a92be6 100644 --- a/common/diagnostics/graph.cpp +++ b/common/diagnostics/graph.cpp @@ -91,10 +91,10 @@ public: sink->set_value(name, value); } - void set_tag(const std::string& name) + void set_tag(tag_severity severity, const std::string& name) { for (auto& sink : sinks_) - sink->set_tag(name); + sink->set_tag(severity, name); } void set_color(const std::string& name, int color) @@ -121,7 +121,7 @@ graph::graph() : impl_(new impl) void graph::set_text(const std::wstring& value) { impl_->set_text(value); } void graph::set_value(const std::string& name, double value) { impl_->set_value(name, value); } void graph::set_color(const std::string& name, int color) { impl_->set_color(name, color); } -void graph::set_tag(const std::string& name) { impl_->set_tag(name); } +void graph::set_tag(tag_severity severity, const std::string& name) { impl_->set_tag(severity, name); } void graph::auto_reset() { impl_->auto_reset(); } void register_graph(const spl::shared_ptr& graph) diff --git a/common/diagnostics/graph.h b/common/diagnostics/graph.h index f925b78b6..0b8888013 100644 --- a/common/diagnostics/graph.h +++ b/common/diagnostics/graph.h @@ -34,6 +34,12 @@ namespace caspar { namespace diagnostics { int color(float r, float g, float b, float a = 1.0f); std::tuple color(int code); +enum class tag_severity +{ + WARNING, + INFO +}; + class graph : boost::noncopyable { friend void register_graph(const spl::shared_ptr& graph); @@ -42,7 +48,7 @@ public: void set_text(const std::wstring& value); void set_value(const std::string& name, double value); void set_color(const std::string& name, int color); - void set_tag(const std::string& name); + void set_tag(tag_severity severity, const std::string& name); void auto_reset(); private: struct impl; @@ -61,7 +67,7 @@ public: virtual void set_text(const std::wstring& value) = 0; virtual void set_value(const std::string& name, double value) = 0; virtual void set_color(const std::string& name, int color) = 0; - virtual void set_tag(const std::string& name) = 0; + virtual void set_tag(tag_severity severity, const std::string& name) = 0; virtual void auto_reset() = 0; }; diff --git a/common/diagnostics/graph_to_log_sink.cpp b/common/diagnostics/graph_to_log_sink.cpp new file mode 100644 index 000000000..214a5458a --- /dev/null +++ b/common/diagnostics/graph_to_log_sink.cpp @@ -0,0 +1,78 @@ +/* +* Copyright (c) 2011 Sveriges Television AB +* +* This file is part of CasparCG (www.casparcg.com). +* +* CasparCG 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. +* +* CasparCG 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 CasparCG. If not, see . +* +* Author: Helge Norberg, helge.norberg@svt.se +*/ + +#include "graph_to_log_sink.h" + +#include "../log.h" + +#include + +namespace caspar { namespace diagnostics { + +class graph_to_log_sink : public spi::graph_sink +{ + tbb::spin_mutex mutex_; + std::wstring text_; +public: + void activate() override + { + } + + void set_text(const std::wstring& value) override + { + tbb::spin_mutex::scoped_lock lock(mutex_); + text_ = value; + } + + void set_value(const std::string& name, double value) override + { + } + + void set_color(const std::string& name, int color) override + { + } + + void set_tag(tag_severity severity, const std::string& name) override + { + tbb::spin_mutex::scoped_lock lock(mutex_); + + switch (severity) + { + case tag_severity::INFO: + CASPAR_LOG(trace) << L"[diagnostics] [" << text_ << L"] " << name; + break; + case tag_severity::WARNING: + CASPAR_LOG(warning) << L"[diagnostics] [" << text_ << L"] " << name; + break; + } + } + + void auto_reset() override + { + } +}; + +void register_graph_to_log_sink() +{ + spi::register_sink_factory([] { return spl::make_shared(); }); +} + +}} diff --git a/common/diagnostics/graph_to_log_sink.h b/common/diagnostics/graph_to_log_sink.h new file mode 100644 index 000000000..1a1559932 --- /dev/null +++ b/common/diagnostics/graph_to_log_sink.h @@ -0,0 +1,31 @@ +/* +* Copyright (c) 2011 Sveriges Television AB +* +* This file is part of CasparCG (www.casparcg.com). +* +* CasparCG 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. +* +* CasparCG 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 CasparCG. If not, see . +* +* Author: Helge Norberg, helge.norberg@svt.se +*/ + +#pragma once + +#include "../memory.h" +#include "graph.h" + +namespace caspar { namespace diagnostics { + +void register_graph_to_log_sink(); + +}} diff --git a/core/diagnostics/osd_graph.cpp b/core/diagnostics/osd_graph.cpp index 1753284c4..c4a8c518a 100644 --- a/core/diagnostics/osd_graph.cpp +++ b/core/diagnostics/osd_graph.cpp @@ -422,7 +422,7 @@ struct graph : public drawable, public caspar::diagnostics::spi::graph_sink, pub lines_[name].set_value(value); } - void set_tag(const std::string& name) override + void set_tag(caspar::diagnostics::tag_severity /*severity*/, const std::string& name) override { lines_[name].set_tag(); } diff --git a/core/diagnostics/subject_diagnostics.cpp b/core/diagnostics/subject_diagnostics.cpp index c9b8acbf9..84f846169 100644 --- a/core/diagnostics/subject_diagnostics.cpp +++ b/core/diagnostics/subject_diagnostics.cpp @@ -92,9 +92,21 @@ public: *subject_ << monitor::message("/color/" + name) % color; } - void set_tag(const std::string& name) override + void set_tag(caspar::diagnostics::tag_severity severity, const std::string& name) override { - *subject_ << monitor::message("/tag/" + name); + std::string severity_path; + + switch (severity) + { + case caspar::diagnostics::tag_severity::INFO: + severity_path = "info/"; + break; + case caspar::diagnostics::tag_severity::WARNING: + severity_path = "warning/"; + break; + } + + *subject_ << monitor::message("/tag/" + severity_path + name); send_full_state_if_long_ago(); } diff --git a/modules/decklink/consumer/decklink_consumer.cpp b/modules/decklink/consumer/decklink_consumer.cpp index 418179586..c9fb588fb 100644 --- a/modules/decklink/consumer/decklink_consumer.cpp +++ b/modules/decklink/consumer/decklink_consumer.cpp @@ -505,7 +505,7 @@ public: if(result == bmdOutputFrameDisplayedLate) { - graph_->set_tag("late-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "late-frame"); video_scheduled_ += format_desc_.duration; audio_scheduled_ += dframe->audio_data().size() / out_channel_layout_.num_channels; //++video_scheduled_; @@ -513,9 +513,9 @@ public: //++audio_scheduled_; } else if(result == bmdOutputFrameDropped) - graph_->set_tag("dropped-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "dropped-frame"); else if(result == bmdOutputFrameFlushed) - graph_->set_tag("flushed-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "flushed-frame"); auto frame = core::const_frame::empty(); video_frame_buffer_.pop(frame); diff --git a/modules/decklink/producer/decklink_producer.cpp b/modules/decklink/producer/decklink_producer.cpp index 3f6cc8b7d..19521f1f1 100644 --- a/modules/decklink/producer/decklink_producer.cpp +++ b/modules/decklink/producer/decklink_producer.cpp @@ -269,7 +269,7 @@ public: frame_buffer_.try_pop(dummy); frame_buffer_.try_push(frame); - graph_->set_tag("dropped-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "dropped-frame"); } } @@ -295,7 +295,7 @@ public: core::draw_frame frame = core::draw_frame::late(); if(!frame_buffer_.try_pop(frame)) - graph_->set_tag("late-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "late-frame"); graph_->set_value("output-buffer", static_cast(frame_buffer_.size())/static_cast(frame_buffer_.capacity())); return frame; } diff --git a/modules/ffmpeg/consumer/ffmpeg_consumer.cpp b/modules/ffmpeg/consumer/ffmpeg_consumer.cpp index 44394b9a8..15eaf4a29 100644 --- a/modules/ffmpeg/consumer/ffmpeg_consumer.cpp +++ b/modules/ffmpeg/consumer/ffmpeg_consumer.cpp @@ -389,7 +389,7 @@ public: void mark_dropped() { - graph_->set_tag("dropped-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "dropped-frame"); } std::wstring print() const diff --git a/modules/ffmpeg/producer/ffmpeg_producer.cpp b/modules/ffmpeg/producer/ffmpeg_producer.cpp index 9e65e7562..7896dce56 100644 --- a/modules/ffmpeg/producer/ffmpeg_producer.cpp +++ b/modules/ffmpeg/producer/ffmpeg_producer.cpp @@ -205,8 +205,8 @@ public: muxer_->pop(); } else - graph_->set_tag("underflow"); - + graph_->set_tag(diagnostics::tag_severity::WARNING, "underflow"); + graph_->set_value("frame-time", frame_timer.elapsed()*format_desc_.fps*0.5); *monitor_subject_ << core::monitor::message("/profiler/time") % frame_timer.elapsed() % (1.0/format_desc_.fps); diff --git a/modules/ffmpeg/producer/input/input.cpp b/modules/ffmpeg/producer/input/input.cpp index 1f9490443..9a4befa0b 100644 --- a/modules/ffmpeg/producer/input/input.cpp +++ b/modules/ffmpeg/producer/input/input.cpp @@ -213,7 +213,7 @@ struct input::impl : boost::noncopyable private: void internal_seek(uint32_t target) { - graph_->set_tag("seek"); + graph_->set_tag(diagnostics::tag_severity::INFO, "seek"); CASPAR_LOG(debug) << print() << " Seeking: " << target; diff --git a/modules/flash/producer/flash_producer.cpp b/modules/flash/producer/flash_producer.cpp index 90b04c316..2f7aaea8d 100644 --- a/modules/flash/producer/flash_producer.cpp +++ b/modules/flash/producer/flash_producer.cpp @@ -270,7 +270,7 @@ public: if (boost::starts_with(result, L"")) CASPAR_LOG(warning) << print() << L" Flash call failed:" << result; - graph_->set_tag("param"); + graph_->set_tag(diagnostics::tag_severity::INFO, "param"); return result; } @@ -412,7 +412,7 @@ public: if (output_buffer_.try_pop(frame)) last_frame_ = frame; else - graph_->set_tag("late-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "late-frame"); fill_buffer(); diff --git a/modules/html/producer/html_producer.cpp b/modules/html/producer/html_producer.cpp index e890a93f3..3e6aba777 100644 --- a/modules/html/producer/html_producer.cpp +++ b/modules/html/producer/html_producer.cpp @@ -229,7 +229,7 @@ private: while (frames_.size() > max_in_queue) { frames_.pop(); - graph_->set_tag("dropped-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "dropped-frame"); } }); graph_->set_value("copy-time", copy_timer.elapsed() @@ -416,7 +416,7 @@ private: } else { - graph_->set_tag("late-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "late-frame"); if (format_desc_.field_mode != core::field_mode::progressive) { diff --git a/modules/newtek/consumer/newtek_ivga_consumer.cpp b/modules/newtek/consumer/newtek_ivga_consumer.cpp index 44d7e1010..139a4040d 100644 --- a/modules/newtek/consumer/newtek_ivga_consumer.cpp +++ b/modules/newtek/consumer/newtek_ivga_consumer.cpp @@ -138,7 +138,7 @@ public: if (executor_.size() > 0 || executor_.is_currently_in_task()) { - graph_->set_tag("dropped-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "dropped-frame"); return make_ready_future(true); } diff --git a/modules/oal/consumer/oal_consumer.cpp b/modules/oal/consumer/oal_consumer.cpp index 8099d5b0f..58e87e8b0 100644 --- a/modules/oal/consumer/oal_consumer.cpp +++ b/modules/oal/consumer/oal_consumer.cpp @@ -212,7 +212,7 @@ public: } } alSourcePlay(source_); - graph_->set_tag("late-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "late-frame"); } auto audio = core::audio_32_to_16(channel_remapper_->mix_and_rearrange(frame.audio_data())); @@ -225,7 +225,7 @@ public: alSourceQueueBuffers(source_, 1, &buffer); } else - graph_->set_tag("dropped-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "dropped-frame"); graph_->set_value("tick-time", perf_timer_.elapsed()*format_desc_.fps*0.5); perf_timer_.restart(); diff --git a/modules/screen/consumer/screen_consumer.cpp b/modules/screen/consumer/screen_consumer.cpp index a8938a027..303e82448 100644 --- a/modules/screen/consumer/screen_consumer.cpp +++ b/modules/screen/consumer/screen_consumer.cpp @@ -517,7 +517,7 @@ public: std::future send(core::const_frame frame) { if(!frame_buffer_.try_push(frame)) - graph_->set_tag("dropped-frame"); + graph_->set_tag(diagnostics::tag_severity::WARNING, "dropped-frame"); return make_ready_future(is_running_.load()); } diff --git a/shell/server.cpp b/shell/server.cpp index 76b0d3556..f80db3495 100644 --- a/shell/server.cpp +++ b/shell/server.cpp @@ -32,6 +32,7 @@ #include #include #include +#include #include #include @@ -149,7 +150,8 @@ struct server::impl : boost::noncopyable , shutdown_server_now_(shutdown_server_now) { running_ = false; - core::diagnostics::osd::register_sink(); + caspar::diagnostics::register_graph_to_log_sink(); + caspar::core::diagnostics::osd::register_sink(); diag_subject_->attach_parent(monitor_subject_); module_dependencies dependencies( -- 2.39.5