From e2a3cc199deb51ffa09469b1570624fa9a6b25c8 Mon Sep 17 00:00:00 2001 From: Helge Norberg Date: Wed, 16 Dec 2015 14:31:15 +0100 Subject: [PATCH] Add call tracing at selected placed in the code to help debug deadlocks in OpenGL. --- accelerator/ogl/util/buffer.cpp | 2 ++ accelerator/ogl/util/device.cpp | 24 ++++++++++++++++++--- accelerator/ogl/util/device.h | 17 +++++++++++++-- accelerator/ogl/util/texture.cpp | 5 +++++ core/diagnostics/osd_graph.cpp | 1 + core/mixer/mixer.cpp | 2 ++ modules/html/html.cpp | 4 ++-- modules/screen/consumer/screen_consumer.cpp | 1 + protocol/amcp/AMCPProtocolStrategy.cpp | 2 +- protocol/util/strategy_adapters.cpp | 8 ++----- 10 files changed, 52 insertions(+), 14 deletions(-) diff --git a/accelerator/ogl/util/buffer.cpp b/accelerator/ogl/util/buffer.cpp index a5a7ab1a5..b6b4abc12 100644 --- a/accelerator/ogl/util/buffer.cpp +++ b/accelerator/ogl/util/buffer.cpp @@ -57,6 +57,7 @@ public: , target_(usage == buffer::usage::write_only ? GL_PIXEL_UNPACK_BUFFER : GL_PIXEL_PACK_BUFFER) , usage_(usage == buffer::usage::write_only ? GL_STREAM_DRAW : GL_STREAM_READ) { + CASPAR_LOG_CALL(trace) << "buffer::buffer() <- " << get_context(); caspar::timer timer; data_ = nullptr; @@ -84,6 +85,7 @@ public: ~impl() { + CASPAR_LOG_CALL(trace) << "buffer::~buffer() <- " << get_context(); glDeleteBuffers(1, &pbo_); (usage_ == GL_STREAM_DRAW ? g_w_total_size : g_r_total_size) -= size_; (usage_ == GL_STREAM_DRAW ? g_w_total_count : g_r_total_count) --; diff --git a/accelerator/ogl/util/device.cpp b/accelerator/ogl/util/device.cpp index e71ca3404..7afefa616 100644 --- a/accelerator/ogl/util/device.cpp +++ b/accelerator/ogl/util/device.cpp @@ -98,8 +98,11 @@ struct device::impl : public std::enable_shared_from_this ~impl() { + auto context = executor_.is_current() ? std::string() : get_context(); + executor_.invoke([=] { + CASPAR_SCOPED_CONTEXT_MSG(context); texture_cache_.clear(); for (auto& pool : host_pools_) @@ -250,8 +253,11 @@ struct device::impl : public std::enable_shared_from_this { caspar::timer timer; + auto context = executor_.is_current() ? std::string() : get_context(); + buf = executor_.invoke([&] { + CASPAR_SCOPED_CONTEXT_MSG(context); return std::make_shared(size, usage); }, task_priority::high_priority); @@ -266,8 +272,11 @@ struct device::impl : public std::enable_shared_from_this if (strong) { + auto context = executor_.is_current() ? std::string() : get_context(); + strong->executor_.invoke([&] { + CASPAR_SCOPED_CONTEXT_MSG(context); strong->texture_cache_.erase(buf.get()); }, task_priority::high_priority); @@ -310,9 +319,11 @@ struct device::impl : public std::enable_shared_from_this std::future> copy_async(const array& source, int width, int height, int stride, bool mipmapped) { std::shared_ptr buf = copy_to_buf(source); - + auto context = executor_.is_current() ? std::string() : get_context(); + return executor_.begin_invoke([=]() -> std::shared_ptr { + CASPAR_SCOPED_CONTEXT_MSG(context); tbb::concurrent_hash_map>::const_accessor a; if(texture_cache_.find(a, buf.get())) return spl::make_shared_ptr(a->second); @@ -329,9 +340,11 @@ struct device::impl : public std::enable_shared_from_this std::future> copy_async(const array& source, int width, int height, int stride, bool mipmapped) { std::shared_ptr buf = copy_to_buf(source); + auto context = executor_.is_current() ? std::string() : get_context(); return executor_.begin_invoke([=]() -> std::shared_ptr { + CASPAR_SCOPED_CONTEXT_MSG(context); auto texture = create_texture(width, height, stride, mipmapped, false); texture->copy_from(*buf); @@ -348,9 +361,14 @@ struct device::impl : public std::enable_shared_from_this source->copy_to(*buffer); auto self = shared_from_this(); - auto cmd = [self, buffer]() mutable -> array + auto context = get_context(); + auto cmd = [self, buffer, context]() mutable -> array { - self->executor_.invoke(std::bind(&buffer::map, std::ref(buffer))); // Defer blocking "map" call until data is needed. + self->executor_.invoke([&buffer, &context] // Defer blocking "map" call until data is needed. + { + CASPAR_LOG_CALL(trace) << "Readback <- " << context; + buffer->map(); + }); return array(buffer->data(), buffer->size(), true, buffer); }; return std::async(std::launch::deferred, std::move(cmd)); diff --git a/accelerator/ogl/util/device.h b/accelerator/ogl/util/device.h index bda7af819..faef96cc8 100644 --- a/accelerator/ogl/util/device.h +++ b/accelerator/ogl/util/device.h @@ -25,6 +25,7 @@ #include #include +#include #include @@ -61,13 +62,25 @@ public: template auto begin_invoke(Func&& func, task_priority priority = task_priority::normal_priority) -> std::future // noexcept { - return executor_.begin_invoke(std::forward(func), priority); + auto context = executor_.is_current() ? std::string() : get_context(); + + return executor_.begin_invoke([func, context]() mutable + { + CASPAR_SCOPED_CONTEXT_MSG(context); + return func(); + }, priority); } template auto invoke(Func&& func, task_priority priority = task_priority::normal_priority) -> decltype(func()) { - return executor_.invoke(std::forward(func), priority); + auto context = executor_.is_current() ? std::string() : get_context(); + + return executor_.invoke([func, context]() mutable + { + CASPAR_SCOPED_CONTEXT_MSG(context); + return func(); + }, priority); } std::future gc(); diff --git a/accelerator/ogl/util/texture.cpp b/accelerator/ogl/util/texture.cpp index 322ffeb13..73ff92796 100644 --- a/accelerator/ogl/util/texture.cpp +++ b/accelerator/ogl/util/texture.cpp @@ -59,6 +59,8 @@ public: , stride_(stride) , mipmapped_(mipmapped) { + CASPAR_LOG_CALL(trace) << "texture::texture() <- " << get_context(); + GL(glGenTextures(1, &id_)); GL(glBindTexture(GL_TEXTURE_2D, id_)); GL(glTexParameteri(GL_TEXTURE_2D, GL_TEXTURE_MIN_FILTER, (mipmapped ? GL_LINEAR_MIPMAP_LINEAR : GL_LINEAR))); @@ -98,6 +100,7 @@ public: ~impl() { + CASPAR_LOG_CALL(trace) << "texture::~texture() <- " << get_context(); glDeleteTextures(1, &id_); g_total_size -= static_cast(width_ * height_ * stride_ * (mipmapped_ ? 1.33 : 1.0)); g_total_count--; @@ -132,6 +135,7 @@ public: void copy_from(buffer& source) { + CASPAR_LOG_CALL(trace) << "texture::copy_from(buffer&) <- " << get_context(); source.unmap(); source.bind(); GL(glBindTexture(GL_TEXTURE_2D, id_)); @@ -147,6 +151,7 @@ public: void copy_to(buffer& dest) { + CASPAR_LOG_CALL(trace) << "texture::copy_to(buffer&) <- " << get_context(); dest.unmap(); dest.bind(); GL(glBindTexture(GL_TEXTURE_2D, id_)); diff --git a/core/diagnostics/osd_graph.cpp b/core/diagnostics/osd_graph.cpp index f0606f7e6..fefc74403 100644 --- a/core/diagnostics/osd_graph.cpp +++ b/core/diagnostics/osd_graph.cpp @@ -222,6 +222,7 @@ private: calculate_view_ = false; } + CASPAR_LOG_CALL(trace) << "osd_graph::tick()"; window_->draw(*this); static const auto THRESHOLD = 1; diff --git a/core/mixer/mixer.cpp b/core/mixer/mixer.cpp index 52efcbe45..c5b5e1fb3 100644 --- a/core/mixer/mixer.cpp +++ b/core/mixer/mixer.cpp @@ -86,6 +86,8 @@ public: { try { + CASPAR_SCOPED_CONTEXT_MSG(L" '" + executor_.name() + L"' "); + detail::set_current_aspect_ratio( static_cast(format_desc.square_width) / static_cast(format_desc.square_height)); diff --git a/modules/html/html.cpp b/modules/html/html.cpp index 867edb047..fdfe31e93 100644 --- a/modules/html/html.cpp +++ b/modules/html/html.cpp @@ -303,13 +303,13 @@ public: void Execute() override { - CASPAR_LOG(trace) << "[cef_task] executing task"; + CASPAR_LOG_CALL(trace) << "[cef_task] executing task"; try { function_(); promise_.set_value(); - CASPAR_LOG(trace) << "[cef_task] task succeeded"; + CASPAR_LOG_CALL(trace) << "[cef_task] task succeeded"; } catch (...) { diff --git a/modules/screen/consumer/screen_consumer.cpp b/modules/screen/consumer/screen_consumer.cpp index 3f0e4deda..84b3c5a07 100644 --- a/modules/screen/consumer/screen_consumer.cpp +++ b/modules/screen/consumer/screen_consumer.cpp @@ -473,6 +473,7 @@ public: void render(spl::shared_ptr av_frame) { + CASPAR_LOG_CALL(trace) << "screen_consumer::render() <- " << print(); GL(glBindTexture(GL_TEXTURE_2D, texture_)); GL(glBindBuffer(GL_PIXEL_UNPACK_BUFFER, pbos_[0])); diff --git a/protocol/amcp/AMCPProtocolStrategy.cpp b/protocol/amcp/AMCPProtocolStrategy.cpp index c35971977..871f25c91 100644 --- a/protocol/amcp/AMCPProtocolStrategy.cpp +++ b/protocol/amcp/AMCPProtocolStrategy.cpp @@ -105,7 +105,7 @@ public: //Thesefore the AMCPProtocolStrategy should be decorated with a delimiter_based_chunking_strategy void Parse(const std::wstring& message, ClientInfoPtr client) { - CASPAR_LOG(info) << L"Received message from " << client->address() << ": " << message << L"\\r\\n"; + CASPAR_LOG_COMMUNICATION(info) << L"Received message from " << client->address() << ": " << message << L"\\r\\n"; command_interpreter_result result; if(interpret_command_string(message, result, client)) diff --git a/protocol/util/strategy_adapters.cpp b/protocol/util/strategy_adapters.cpp index ce4b4e2cb..c229d3de1 100644 --- a/protocol/util/strategy_adapters.cpp +++ b/protocol/util/strategy_adapters.cpp @@ -59,11 +59,9 @@ public: : client_(client) , codepage_(codepage) { - CASPAR_LOG(trace) << "from_unicode_client_connection created."; } ~from_unicode_client_connection() { - CASPAR_LOG(trace) << "from_unicode_client_connection destroyed."; } void send(std::basic_string&& data) override @@ -76,10 +74,10 @@ public: { boost::replace_all(data, L"\n", L"\\n"); boost::replace_all(data, L"\r", L"\\r"); - CASPAR_LOG(info) << L"Sent message to " << client_->address() << L":" << data; + CASPAR_LOG_COMMUNICATION(info) << L"Sent message to " << client_->address() << L":" << data; } else - CASPAR_LOG(info) << L"Sent more than 512 bytes to " << client_->address(); + CASPAR_LOG_COMMUNICATION(info) << L"Sent more than 512 bytes to " << client_->address(); } void disconnect() override @@ -129,11 +127,9 @@ public: : strategy_(strategy) , client_info_(client_connection) { - CASPAR_LOG(trace) << "legacy_strategy_adapter created."; } ~legacy_strategy_adapter() { - CASPAR_LOG(trace) << "legacy_strategy_adapter destroyed."; } void parse(const std::basic_string& data) override -- 2.39.2