Add call tracing at selected placed in the code to help debug deadlocks in OpenGL.

diff --git a/accelerator/ogl/util/buffer.cpp b/accelerator/ogl/util/buffer.cpp
index a5a7ab1a5995d6b2ebd5837f52cd7870d020e89e..b6b4abc125c5a0358959ee632f244c3173eea657 100644 (file)
--- 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 e71ca3404b2051ed80809c79f54d4c88539bc387..7afefa616c46bf49b5220501944c4a2c854a35eb 100644 (file)
--- 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>
 
        ~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<impl>
                {
                        caspar::timer timer;
 
+                       auto context = executor_.is_current() ? std::string() : get_context();
+
                        buf = executor_.invoke([&]
                        {
+                               CASPAR_SCOPED_CONTEXT_MSG(context);
                                return std::make_shared<buffer>(size, usage);
                        }, task_priority::high_priority);
                        
@@ -266,8 +272,11 @@ struct device::impl : public std::enable_shared_from_this<impl>
 
                        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<impl>
        std::future<std::shared_ptr<texture>> copy_async(const array<const std::uint8_t>& source, int width, int height, int stride, bool mipmapped)
        {
                std::shared_ptr<buffer> buf = copy_to_buf(source);
-                               
+               auto context = executor_.is_current() ? std::string() : get_context();
+
                return executor_.begin_invoke([=]() -> std::shared_ptr<texture>
                {
+                       CASPAR_SCOPED_CONTEXT_MSG(context);
                        tbb::concurrent_hash_map<buffer*, std::shared_ptr<texture>>::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<impl>
        std::future<std::shared_ptr<texture>> copy_async(const array<std::uint8_t>& source, int width, int height, int stride, bool mipmapped)
        {
                std::shared_ptr<buffer> buf = copy_to_buf(source);
+               auto context = executor_.is_current() ? std::string() : get_context();
 
                return executor_.begin_invoke([=]() -> std::shared_ptr<texture>
                {
+                       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<impl>
                source->copy_to(*buffer);       
 
                auto self = shared_from_this();
-               auto cmd = [self, buffer]() mutable -> array<const std::uint8_t>
+               auto context = get_context();
+               auto cmd = [self, buffer, context]() mutable -> array<const std::uint8_t>
                {
-                       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<const std::uint8_t>(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 bda7af81997104b8c36df06493870bb709275349..faef96cc8f8fe9cdd9fa4074be32d7f27d1fd422 100644 (file)
--- a/accelerator/ogl/util/device.h
+++ b/accelerator/ogl/util/device.h
@@ -25,6 +25,7 @@
 
 #include <common/memory.h>
 #include <common/executor.h>
+#include <common/except.h>
 
 #include <boost/property_tree/ptree_fwd.hpp>
 
@@ -61,13 +62,25 @@ public:
        template<typename Func>
        auto begin_invoke(Func&& func, task_priority priority = task_priority::normal_priority) -> std::future<decltype(func())> // noexcept
        {                       
-               return executor_.begin_invoke(std::forward<Func>(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<typename Func>
        auto invoke(Func&& func, task_priority priority = task_priority::normal_priority) -> decltype(func())
        {
-               return executor_.invoke(std::forward<Func>(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<void> gc();

diff --git a/accelerator/ogl/util/texture.cpp b/accelerator/ogl/util/texture.cpp
index 322ffeb13b74dab3ca8aac2def97515a5628501e..73ff927964f768ffc23992eea3253cdace9f3c0b 100644 (file)
--- 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<std::size_t>(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 f0606f7e69dc544277c4e2353b8278d282625a36..fefc74403b3a2c20e8d469e8080e99a10656dbab 100644 (file)
--- 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 52efcbe4527b705a135b60d2274161f9c52cf8cd..c5b5e1fb31f71fad85dc306bd3c24080d909dcab 100644 (file)
--- 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<double>(format_desc.square_width)
                                                / static_cast<double>(format_desc.square_height));

diff --git a/modules/html/html.cpp b/modules/html/html.cpp
index 867edb0470ea54eba5be538120c76a342f7dc682..fdfe31e9365cf16f46cb4f630b06f3333629556a 100644 (file)
--- 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 3f0e4dedaef22134bd09dca287eeaa2549991fde..84b3c5a0766addd9aec503978272ee8a7b77408f 100644 (file)
--- a/modules/screen/consumer/screen_consumer.cpp
+++ b/modules/screen/consumer/screen_consumer.cpp
@@ -473,6 +473,7 @@ public:
 
        void render(spl::shared_ptr<AVFrame> 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 c3597197705ef76365ac6955f32b966b6cfe8cc8..871f25c918d17d7d9133925f28d8e0d43c825028 100644 (file)
--- 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 ce4b4e2cbcd7920fc4b0e71b035e728efaa19537..c229d3de1589e50adddbebc22ff4aea1c27d5578 100644 (file)
--- a/protocol/util/strategy_adapters.cpp
+++ b/protocol/util/strategy_adapters.cpp
@@ -59,11 +59,9 @@ public:
                : client_(client)\r
                , codepage_(codepage)\r
        {\r
-               CASPAR_LOG(trace) << "from_unicode_client_connection created.";\r
        }\r
        ~from_unicode_client_connection()\r
        {\r
-               CASPAR_LOG(trace) << "from_unicode_client_connection destroyed.";\r
        }\r
 \r
        void send(std::basic_string<wchar_t>&& data) override\r
@@ -76,10 +74,10 @@ public:
                {\r
                        boost::replace_all(data, L"\n", L"\\n");\r
                        boost::replace_all(data, L"\r", L"\\r");\r
-                       CASPAR_LOG(info) << L"Sent message to " << client_->address() << L":" << data;\r
+                       CASPAR_LOG_COMMUNICATION(info) << L"Sent message to " << client_->address() << L":" << data;\r
                }\r
                else\r
-                       CASPAR_LOG(info) << L"Sent more than 512 bytes to " << client_->address();\r
+                       CASPAR_LOG_COMMUNICATION(info) << L"Sent more than 512 bytes to " << client_->address();\r
        }\r
 \r
        void disconnect() override\r
@@ -129,11 +127,9 @@ public:
                : strategy_(strategy)\r
                , client_info_(client_connection)\r
        {\r
-               CASPAR_LOG(trace) << "legacy_strategy_adapter created.";\r
        }\r
        ~legacy_strategy_adapter()\r
        {\r
-               CASPAR_LOG(trace) << "legacy_strategy_adapter destroyed.";\r
        }\r
 \r
        void parse(const std::basic_string<wchar_t>& data) override\r