Improve logging of the matching process

src/common/transformations/docs/README.md

@@ -0,0 +1,15 @@
+# Transformations documentation
+
+## Debug capabilities
+
+ * [Matcher logging README](./debug_capabilities/LOGGING_README.md)
+
+## Key Contacts
+
+For assistance regarding snippets, contact a member of [openvino-ie-transformations-maintainers](https://github.com/orgs/openvinotoolkit/teams/openvino-ie-transformations-maintainers) group.
+
+## See also
+
+ * [OpenVINO™ README](../../../README.md)
+ * [OpenVINO Core Components](../../README.md)
+ * [Developer documentation](../../../docs/dev/index.md)

src/common/transformations/docs/debug_capabilities/matcher_logging.md

@@ -0,0 +1,22 @@
+# Logging of the pattern matching
+
+The logging functionality allows to observe/debug the pattern matching process.
+
+## Usage
+In order to utilzie the logging, first, you need to set the CMake flag ```-DENABLE_OPENVINO_DEBUG=ON```
+
+_NOTE: the logging would also work if your build is configured as Release_
+
+In order to start logging, set the environmental variable ```OV_MATCHER_LOGGING``` to ``true/ON`` before running your executable or script as following:
+```OV_MATCHER_LOGGING=true ./your_amazing_program```            
+
+If you want to log only specific matchers, use the ```OV_MATCHERS_TO_LOG``` environmental variable and provide their names separated as commas:
+```OV_MATCHER_LOGGING=true OV_MATCHERS_TO_LOG=EliminateSplitConcat,MarkDequantization ./your_amazing_program```
+
+You can also set the environmental variable ```OV_VERBOSE_LOGGING``` to ```true```, to turn on more verbose logging that would print more information about the nodes taking part in the matching process:
+```OV_MATCHER_LOGGING=true OV_VERBOSE_LOGGING=true ./your_amazing_program```
+
+## Useful feature:
+If you redirect the logging output into a .json file (extension is important for the correct processing of the file in Visual Studio Code). This allows collapsing blocks in Visual Studio Code as you would do with a normal .json file.
+
+If you have any suggestions for improvement or you observe a bug in logging, feel free to submit changes or contact Andrii Staikov <[email protected]>

src/common/transformations/include/transformations/utils/gen_pattern.hpp

@@ -22,6 +22,7 @@
 #include <string>
 #include <utility>
 
+#include "openvino/core/log_util.hpp"
 #include "openvino/opsets/opset1.hpp"
 #include "openvino/opsets/opset2.hpp"
 #include "openvino/opsets/opset3.hpp"
@@ -34,6 +35,7 @@
 #include "openvino/pass/pattern/op/label.hpp"
 #include "openvino/pass/pattern/op/or.hpp"
 #include "openvino/pass/pattern/op/wrap_type.hpp"
+#include "openvino/util/log.hpp"
 
 namespace ov {
 namespace gen_pattern {
@@ -811,17 +813,20 @@ class GenericPattern : public ov::pass::pattern::op::Pattern {
                          pattern_value.get_index(),
                          "!=",
                          graph_value.get_index());
+            OPENVINO_LOG_GENPATTERN1(matcher, pattern_value, graph_value);
             return false;
         }
 
         auto value_node = graph_value.get_node_shared_ptr();
         if (!value_node->get_type_info().is_castable(m_type_info)) {
             _VERBOSE_LOG(level, "X OP type mismatch: ", m_signature, " vs ", graph_value);
+            OPENVINO_LOG_GENPATTERN2(matcher, pattern_value, graph_value);
             return false;
         }
 
         if (!m_vt.predicate(graph_value)) {
             _VERBOSE_LOG(level, "X value info mismatch: ", m_signature, " vs ", graph_value);
+            OPENVINO_LOG_GENPATTERN3(matcher);
             return false;
         }
 
@@ -830,6 +835,7 @@ class GenericPattern : public ov::pass::pattern::op::Pattern {
             value_node->visit_attributes(visitor);
             if (!visitor.matched()) {
                 _VERBOSE_LOG(level, "X OP attrs mismatch: ", m_signature, " vs ", graph_value);
+                OPENVINO_LOG_GENPATTERN4(matcher);
                 return false;
             }
         }
@@ -843,14 +849,20 @@ class GenericPattern : public ov::pass::pattern::op::Pattern {
 
         if (matcher_verbose_enabled())
             level.push_back('\t');
+        OPENVINO_LOG_GENPATTERN5(matcher);
         bool ret = matcher->match_arguments(pattern_value.get_node(), graph_value.get_node_shared_ptr());
+        OPENVINO_LOG_GENPATTERN6(matcher, ret);
         if (matcher_verbose_enabled()) {
             level.pop_back();
             _VERBOSE_LOG(level, ret ? "O" : "X", m_signature, " vs ", graph_value);
         }
         return ret;
     }
 
+    const DiscreteTypeInfo& get_wrapped_type() const {
+        return m_type_info;
+    }
+
 private:
     const DiscreteTypeInfo& m_type_info;
     detail::AttrMap m_attrs;

src/common/util/include/openvino/util/env_util.hpp

@@ -6,7 +6,7 @@
 
 #include <cstdint>
 #include <string>
-
+#include <unordered_set>
 namespace ov {
 namespace util {
 /// \brief Get the names environment variable as a string.
@@ -31,5 +31,12 @@ int32_t getenv_int(const char* env_var, int32_t default_value = -1);
 /// \param default_value The value to return if the environment variable is not set.
 /// \return Returns the boolean value of the environment variable.
 bool getenv_bool(const char* env_var, bool default_value = false);
+
+/// \brief Splits a string using by a single character delimiter
+///        without modifying the original string
+/// \param str String to split
+/// \param delimiter Delimiter to use for splitting
+/// \return Returns an unordered set of split strings
+std::unordered_set<std::string> split_by_delimiter(const std::string& str, char delimiter);
 }  // namespace util
 }  // namespace ov

src/common/util/include/openvino/util/log.hpp

@@ -6,9 +6,17 @@
 
 #include <deque>
 #include <functional>
+#include <iostream>
 #include <sstream>
+#include <unordered_set>
 #include <vector>
 
+#if defined(__linux__) || (defined(__APPLE__) && defined(__MACH__))
+#    include <unistd.h>
+#endif
+
+#include "openvino/util/env_util.hpp"
+
 namespace ov {
 namespace util {
 
@@ -17,6 +25,7 @@ enum class LOG_TYPE {
     _LOG_TYPE_WARNING,
     _LOG_TYPE_INFO,
     _LOG_TYPE_DEBUG,
+    _LOG_TYPE_DEBUG_EMPTY,
 };
 
 class LogHelper {
@@ -50,6 +59,7 @@ class Logger {
 };
 
 void default_logger_handler_func(const std::string& s);
+void default_logger_handler_func_length(const std::string& s);
 
 #ifdef ENABLE_OPENVINO_DEBUG
 /* Template function _write_all_to_stream has duplicates
@@ -93,6 +103,41 @@ static inline std::ostream& _write_all_to_stream(std::ostream& os, const T& arg,
         do {                                                                                   \
             ov::util::_write_all_to_stream(OPENVINO_LOG_STREAM(_LOG_TYPE_DEBUG), __VA_ARGS__); \
         } while (0)
+
+static const bool logging_enabled = ov::util::getenv_bool("OV_MATCHER_LOGGING");
+static const std::unordered_set<std::string> matchers_to_log =
+    ov::util::split_by_delimiter(ov::util::getenv_string("OV_MATCHERS_TO_LOG"), ',');
+
+static inline bool is_terminal_output() {
+#    ifdef _WIN32
+    // No Windows support for colored logs for now.
+    return false;
+#    else
+    static const bool stdout_to_terminal = isatty(fileno(stdout));
+    return stdout_to_terminal;
+#    endif
+}
+
+#    define OPENVINO_RESET            (ov::util::is_terminal_output() ? "\033[0m" : "")
+#    define OPENVINO_RED              (ov::util::is_terminal_output() ? "\033[31m" : "")
+#    define OPENVINO_GREEN            (ov::util::is_terminal_output() ? "\033[1;32m" : "")
+#    define OPENVINO_YELLOW           (ov::util::is_terminal_output() ? "\033[33m" : "")
+#    define OPENVINO_BLOCK_BEG        "{"
+#    define OPENVINO_BLOCK_END        "}"
+#    define OPENVINO_BLOCK_BODY       "│"
+#    define OPENVINO_BLOCK_BODY_RIGHT "├─"
+
+#    define OPENVINO_LOG_MATCHING(matcher_ptr, ...)                                                               \
+        do {                                                                                                      \
+            if (ov::util::logging_enabled) {                                                                      \
+                if (ov::util::matchers_to_log.empty() ||                                                          \
+                    ov::util::matchers_to_log.find(matcher_ptr->get_name()) != ov::util::matchers_to_log.end()) { \
+                    ov::util::_write_all_to_stream(OPENVINO_LOG_STREAM(_LOG_TYPE_DEBUG_EMPTY),                    \
+                                                   __VA_ARGS__,                                                   \
+                                                   OPENVINO_RESET);                                               \
+                }                                                                                                 \
+            }                                                                                                     \
+        } while (0)
 #else
 #    define OPENVINO_ERR(...) \
         do {                  \
@@ -106,6 +151,9 @@ static inline std::ostream& _write_all_to_stream(std::ostream& os, const T& arg,
 #    define OPENVINO_DEBUG(...) \
         do {                    \
         } while (0)
+#    define OPENVINO_LOG_MATCHING(matcher_ptr, ...) \
+        do {                                        \
+        } while (0)
 #endif
 
 }  // namespace util

src/common/util/src/env_util.cpp

@@ -69,3 +69,17 @@ bool ov::util::getenv_bool(const char* env_var, bool default_value) {
     }
     return rc;
 }
+
+std::unordered_set<std::string> ov::util::split_by_delimiter(const std::string& str, char delimiter) {
+    std::unordered_set<std::string> res;
+    size_t start_search_from = 0;
+    size_t pos;
+    while ((pos = str.find(delimiter, start_search_from)) != std::string::npos) {
+        res.insert(str.substr(start_search_from, pos - start_search_from));
+        start_search_from = pos + 1;
+    }
+    if (start_search_from < str.size()) {
+        res.insert(str.substr(start_search_from));
+    }
+    return res;
+}

src/common/util/src/log.cpp

@@ -34,23 +34,27 @@ ov::util::LogHelper::LogHelper(LOG_TYPE type,
     case LOG_TYPE::_LOG_TYPE_DEBUG:
         m_stream << "[DEBUG] ";
         break;
+    case LOG_TYPE::_LOG_TYPE_DEBUG_EMPTY:
+        break;
     }
 
-    {
-        static std::mutex m;
-        time_t tt = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
-        std::lock_guard<std::mutex> lock(m);
-        auto tm = gmtime(&tt);
-        if (tm) {
-            char buffer[256];
-            strftime(buffer, sizeof(buffer), "%Y-%m-%dT%H:%M:%Sz", tm);
-            m_stream << buffer << " ";
+    if (type != LOG_TYPE::_LOG_TYPE_DEBUG_EMPTY) {
+        {
+            static std::mutex m;
+            time_t tt = std::chrono::system_clock::to_time_t(std::chrono::system_clock::now());
+            std::lock_guard<std::mutex> lock(m);
+            auto tm = gmtime(&tt);
+            if (tm) {
+                char buffer[256];
+                strftime(buffer, sizeof(buffer), "%Y-%m-%dT%H:%M:%Sz", tm);
+                m_stream << buffer << " ";
+            }
         }
-    }
 
-    m_stream << util::trim_file_name(file);
-    m_stream << " " << line;
-    m_stream << "\t";
+        m_stream << util::trim_file_name(file);
+        m_stream << " " << line;
+        m_stream << "\t";
+    }
 }
 
 ov::util::LogHelper::~LogHelper() {