diff --git a/src/common/transformations/docs/README.md b/src/common/transformations/docs/README.md new file mode 100644 index 00000000000000..2622dd7a68e523 --- /dev/null +++ b/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) \ No newline at end of file diff --git a/src/common/transformations/docs/debug_capabilities/matcher_logging.md b/src/common/transformations/docs/debug_capabilities/matcher_logging.md new file mode 100644 index 00000000000000..74665ef5062012 --- /dev/null +++ b/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 \ No newline at end of file diff --git a/src/common/transformations/include/transformations/utils/gen_pattern.hpp b/src/common/transformations/include/transformations/utils/gen_pattern.hpp index dafad4d09de7b1..132046e15e59e9 100644 --- a/src/common/transformations/include/transformations/utils/gen_pattern.hpp +++ b/src/common/transformations/include/transformations/utils/gen_pattern.hpp @@ -22,6 +22,7 @@ #include #include +#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,7 +849,9 @@ 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); @@ -851,6 +859,10 @@ class GenericPattern : public ov::pass::pattern::op::Pattern { return ret; } + const DiscreteTypeInfo& get_wrapped_type() const { + return m_type_info; + } + private: const DiscreteTypeInfo& m_type_info; detail::AttrMap m_attrs; diff --git a/src/common/util/include/openvino/util/env_util.hpp b/src/common/util/include/openvino/util/env_util.hpp index e608c4ae05a942..36c558d68793f2 100644 --- a/src/common/util/include/openvino/util/env_util.hpp +++ b/src/common/util/include/openvino/util/env_util.hpp @@ -6,7 +6,7 @@ #include #include - +#include 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 split_by_delimiter(const std::string& str, char delimiter); } // namespace util } // namespace ov diff --git a/src/common/util/include/openvino/util/log.hpp b/src/common/util/include/openvino/util/log.hpp index f4ca2d94cb7173..4f4606ee61d3c7 100644 --- a/src/common/util/include/openvino/util/log.hpp +++ b/src/common/util/include/openvino/util/log.hpp @@ -6,9 +6,17 @@ #include #include +#include #include +#include #include +#if defined(__linux__) || (defined(__APPLE__) && defined(__MACH__)) +# include +#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 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 diff --git a/src/common/util/src/env_util.cpp b/src/common/util/src/env_util.cpp index 1eb9e3f21147cc..82471371777b3a 100644 --- a/src/common/util/src/env_util.cpp +++ b/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 ov::util::split_by_delimiter(const std::string& str, char delimiter) { + std::unordered_set 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; +} diff --git a/src/common/util/src/log.cpp b/src/common/util/src/log.cpp index 1dcff038ae7eb0..8cf2cdf9e2991b 100644 --- a/src/common/util/src/log.cpp +++ b/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 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 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() { diff --git a/src/core/dev_api/openvino/core/log_util.hpp b/src/core/dev_api/openvino/core/log_util.hpp new file mode 100644 index 00000000000000..8982bfb1ab7cf7 --- /dev/null +++ b/src/core/dev_api/openvino/core/log_util.hpp @@ -0,0 +1,702 @@ +// Copyright (C) 2018-2025 Intel Corporation +// SPDX-License-Identifier: Apache-2.0 +// + +#pragma once + +#include +#include + +#include "openvino/core/core_visibility.hpp" +#include "openvino/core/node.hpp" + +#ifdef ENABLE_OPENVINO_DEBUG + +namespace ov { +namespace util { + +class OPENVINO_API LevelString { +private: + LevelString(const std::string& level_identifier_) : level_identifier(level_identifier_) {} + +public: + static LevelString& get() { + static LevelString instance("│ "); + return instance; + } + + LevelString& operator++() { + level += 1; + return *this; + } + + LevelString operator++(int) { + LevelString res = *this; + level += 1; + return res; + } + + LevelString& operator--() { + if (level > 1) { + level -= 1; + } + return *this; + } + + LevelString operator--(int) { + LevelString res = *this; + if (level > 1) { + level -= 1; + } + return res; + } + + friend std::ostream& operator<<(std::ostream& stream, const LevelString& level_string) { + for (int i = 0; i < level_string.level; ++i) { + stream << level_string.level_identifier; + } + return stream; + } + +private: + const std::string level_identifier; + int level = 1; +}; + +OPENVINO_API std::string node_version_type_str(const ov::Node& node); +OPENVINO_API std::string node_version_type_name_str(const ov::Node& node); +OPENVINO_API std::string node_with_arguments(const ov::Node& node); + +// For each file, that has the matcher logging functionality present, +// there's a set of macro for avoiding the additional clutter +// of the matching code. + +// transformations/utils/gen_pattern.hpp +# define OPENVINO_LOG_GENPATTERN1(matcher, pattern_value, graph_value) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " OUTPUT INDICES DIDN'T MATCH. EXPECTED: ", \ + pattern_value.get_index(), \ + ". OBSERVED: ", \ + graph_value.get_index()); \ + } while (0) + +# define OPENVINO_LOG_GENPATTERN2(matcher, pattern_value, graph_value) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " NODES' TYPE DIDN'T MATCH. EXPECTED: ", \ + ov::util::node_version_type_str(*pattern_value.get_node_shared_ptr()), \ + ". OBSERVED: ", \ + ov::util::node_version_type_str(*graph_value.get_node_shared_ptr())); \ + } while (0) + +# define OPENVINO_LOG_GENPATTERN3(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " PREDICATE DIDN'T MATCH."); \ + } while (0) + +# define OPENVINO_LOG_GENPATTERN4(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " ATTRIBUTES DIDN'T MATCH."); \ + } while (0) + +# define OPENVINO_LOG_GENPATTERN5(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY_RIGHT, \ + " TYPE MATCHED. CHECKING PATTERN ARGUMENTS"); \ + } while (0) + +# define OPENVINO_LOG_GENPATTERN6(matcher, status) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY, \ + '\n', \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + (status ? OPENVINO_GREEN : OPENVINO_RED), \ + (status ? " ALL ARGUMENTS MATCHED" : " ARGUMENTS DIDN'T MATCH")); \ + } while (0) + +// core/src/node.cpp +# define OPENVINO_LOG_NODE1(matcher, pattern_value, graph_value) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + " INDEX, ELEMENT TYPE or PARTIAL SHAPE MISMATCH. EXPECTED IN PATTERN: ", \ + pattern_value.get_index(), \ + ", ", \ + pattern_value.get_element_type(), \ + ", ", \ + pattern_value.get_partial_shape(), \ + ". OBSERVED IN GRAPH: ", \ + graph_value.get_index(), \ + ", ", \ + graph_value.get_element_type(), \ + ", ", \ + graph_value.get_partial_shape()); \ + } while (0) + +# define OPENVINO_LOG_NODE2(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY_RIGHT, \ + " TYPE MATCHED. CHECKING PATTERN ARGUMENTS"); \ + } while (0) + +# define OPENVINO_LOG_NODE3(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY, \ + '\n', \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " ALL ARGUMENTS MATCHED"); \ + } while (0) + +# define OPENVINO_LOG_NODE4(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY, \ + '\n', \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " ARGUMENTS DIDN'T MATCH"); \ + } while (0) + +# define OPENVINO_LOG_NODE5(matcher, pattern_value, graph_value) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " NODES' TYPE DIDN'T MATCH. EXPECTED: ", \ + ov::util::node_version_type_str(*pattern_value), \ + ". OBSERVED: ", \ + ov::util::node_version_type_str(*graph_value.get_node_shared_ptr())); \ + } while (0) + +// src/pass/graph_rewrite.cpp +# define OPENVINO_LOG_GRAPH_REWRITE1(matcher, node_ptr) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + OPENVINO_BLOCK_BEG, \ + OPENVINO_YELLOW, \ + " [", \ + matcher->get_name(), \ + "] START: trying to start pattern matching with ", \ + ov::util::node_version_type_name_str(*node_ptr)); \ + } while (0) + +# define OPENVINO_LOG_GRAPH_REWRITE2(matcher, status) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + OPENVINO_BLOCK_BODY, \ + '\n', \ + OPENVINO_BLOCK_END, \ + (status ? OPENVINO_GREEN : OPENVINO_RED), \ + " [", \ + matcher->get_name(), \ + "] END: PATTERN MATCHED, CALLBACK ", \ + (status ? "SUCCEDED" : "FAILED"), \ + "\n"); \ + } while (0) + +# define OPENVINO_LOG_GRAPH_REWRITE3(matcher, exception) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + OPENVINO_BLOCK_BODY, \ + '\n', \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " [", \ + matcher->get_name(), \ + "] END: PATTERN MATCHED, CALLBACK HAS THROWN: ", \ + exception.what()); \ + } while (0) + +# define OPENVINO_LOG_GRAPH_REWRITE4(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + OPENVINO_BLOCK_BODY, \ + '\n', \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " [", \ + matcher->get_name(), \ + "] END: PATTERN DIDN'T MATCH\n"); \ + } while (0) + +// src/pattern/matcher.cpp +# define OPENVINO_LOG_MATCHER1(matcher, pattern_value, graph_value) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + '\n', \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BEG, \ + " MATCHING PATTERN NODE: ", \ + ov::util::node_with_arguments(*pattern_value.get_node_shared_ptr()), \ + '\n', \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY_RIGHT, \ + " AGAINST GRAPH NODE: ", \ + ov::util::node_with_arguments(*graph_value.get_node_shared_ptr())); \ + } while (0) + +# define OPENVINO_LOG_MATCHER2(matcher, idx) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ++ov::util::LevelString::get()); \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get()++, OPENVINO_BLOCK_BEG, " ARGUMENT ", idx); \ + } while (0) + +# define OPENVINO_LOG_MATCHER3(matcher, idx) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, --ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()--, \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " ARGUMENT ", \ + idx, \ + " DIDN'T MATCH "); \ + } while (0) + +# define OPENVINO_LOG_MATCHER4(matcher, idx) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, --ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()--, \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " ARGUMENT ", \ + idx, \ + " MATCHED"); \ + } while (0) + +# define OPENVINO_LOG_MATCHER5(matcher, pattern_arg_size, graph_arg_size) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY_RIGHT, \ + OPENVINO_RED, \ + " NUMBER OF ARGUMENTS DOESN'T MATCH. EXPECTED IN PATTERN NODE: ", \ + pattern_arg_size, \ + ". OBSERVED IN GRAPH NODE: ", \ + graph_arg_size); \ + } while (0) + +# define OPENVINO_LOG_MATCHER6(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ++ov::util::LevelString::get()); \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BEG, " NEW PERMUTATION"); \ + } while (0) + +# define OPENVINO_LOG_MATCHER7(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()--, \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " PERMUTATION MATCHED"); \ + } while (0) + +# define OPENVINO_LOG_MATCHER8(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()--, \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " PERMUTATION DIDN'T MATCH"); \ + } while (0) + +# define OPENVINO_LOG_MATCHER9(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ++ov::util::LevelString::get()); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BEG, \ + " GRAPH NODE IS NOT COMMUTATIVE, A SINGLE PERMUTATION IS PRESENT ONLY"); \ + } while (0) + +# define OPENVINO_LOG_MATCHER10(matcher, status) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()--, \ + OPENVINO_BLOCK_END, \ + (status ? OPENVINO_GREEN : OPENVINO_RED), \ + " PERMUTATION ", \ + (status ? "MATCHED" : "DIDN'T MATCH")); \ + } while (0) + +# define OPENVINO_LOG_MATCHER11(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY_RIGHT, \ + OPENVINO_RED, \ + " NONE OF PERMUTATIONS MATCHED"); \ + } while (0) + +// pattern/op/label.cpp +# define OPENVINO_LOG_LABEL1(matcher, label_name) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " LABEL MATCHED: ", \ + label_name); \ + } while (0); + +# define OPENVINO_LOG_LABEL2(matcher, label_name) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()++, \ + OPENVINO_BLOCK_BODY_RIGHT, \ + " CHECKING INSIDE LABEL: ", \ + label_name); \ + } while (0); + +# define OPENVINO_LOG_LABEL3(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, --ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " LABEL MATCHED"); \ + } while (0); + +# define OPENVINO_LOG_LABEL4(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " LABEL DIDN'T MATCH"); \ + } while (0); + +// pattern/op/optional.cpp +# define OPENVINO_LOG_OPTIONAL1(matcher, or_node, wrap_node, opt_name) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()++, \ + OPENVINO_BLOCK_BODY_RIGHT, \ + (or_node == wrap_node ? " LEAVING OPTIONAL AS WRAP TYPE AND TRYING TO MATCH: " \ + : " UNFOLDING OPTIONAL INTO OR AND TRYING TO MATCH: "), \ + opt_name); \ + } while (0); + +# define OPENVINO_LOG_OPTIONAL2(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, --ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " OPTIONAL MATCHED"); \ + } while (0); + +# define OPENVINO_LOG_OPTIONAL3(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, --ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " OPTIONAL DIDN'T MATCH"); \ + } while (0); + +// pattern/op/or.cpp +# define OPENVINO_LOG_OR1(matcher, input_size, or_name) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY_RIGHT, \ + " CHECKING ", \ + input_size, \ + " OR BRANCHES: ", \ + or_name); \ + } while (0); + +# define OPENVINO_LOG_OR2(matcher, idx, input_value) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ++ov::util::LevelString::get()); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()++, \ + OPENVINO_BLOCK_BEG, \ + " BRANCH ", \ + idx, \ + ": ", \ + ov::util::node_version_type_str(*input_value.get_node_shared_ptr())); \ + } while (0); + +# define OPENVINO_LOG_OR3(matcher, idx) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, --ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()--, \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " BRANCH ", \ + idx, \ + " MATCHED"); \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " BRANCH ", \ + idx, \ + " HAS MATCHED"); \ + } while (0); + +# define OPENVINO_LOG_OR4(matcher, idx) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, --ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get()--, \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " BRANCH ", \ + idx, \ + " DIDN'T MATCH"); \ + } while (0); + +# define OPENVINO_LOG_OR5(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, ov::util::LevelString::get(), OPENVINO_BLOCK_BODY); \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " NONE OF OR BRANCHES MATCHED"); \ + } while (0); + +// pattern/op/true.cpp +# define OPENVINO_LOG_TRUE1(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_GREEN, \ + " TRUE ALWAYS MATCHES"); \ + } while (0); + +// pattern/op/wrap_type.cpp +# define OPENVINO_LOG_WRAPTYPE1(matcher, pattern_value, graph_value) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " NODES' TYPE DIDN'T MATCH. EXPECTED: ", \ + ov::util::node_version_type_str(*pattern_value.get_node_shared_ptr()), \ + ". OBSERVED: ", \ + ov::util::node_version_type_str(*graph_value.get_node_shared_ptr())); \ + } while (0); + +# define OPENVINO_LOG_WRAPTYPE2(matcher) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + OPENVINO_RED, \ + " NODES' TYPE MATCHED, but PREDICATE FAILED"); \ + } while (0); + +# define OPENVINO_LOG_WRAPTYPE3(matcher, num_arguments) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY_RIGHT, \ + OPENVINO_GREEN, \ + " NODES' TYPE and PREDICATE MATCHED. CHECKING ", \ + num_arguments, \ + " PATTERN ARGUMENTS: "); \ + } while (0); + +# define OPENVINO_LOG_WRAPTYPE4(matcher, status) \ + do { \ + OPENVINO_LOG_MATCHING(matcher, \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_BODY, \ + '\n', \ + ov::util::LevelString::get(), \ + OPENVINO_BLOCK_END, \ + (status ? OPENVINO_GREEN : OPENVINO_RED), \ + (status ? " ALL ARGUMENTS MATCHED" : " ARGUMENTS DIDN'T MATCH")); \ + } while (0); + +} // namespace util +} // namespace ov + +#else + +# define OPENVINO_LOG_GENPATTERN1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GENPATTERN2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GENPATTERN3(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GENPATTERN4(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GENPATTERN5(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GENPATTERN6(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_NODE1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_NODE2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_NODE3(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_NODE4(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_NODE5(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_MATCHER1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER3(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER4(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER5(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER6(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER7(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER8(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER9(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER10(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_MATCHER11(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_LABEL1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_LABEL2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_LABEL3(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_LABEL4(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_GRAPH_REWRITE1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GRAPH_REWRITE2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GRAPH_REWRITE3(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_GRAPH_REWRITE4(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_OR1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_OR2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_OR3(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_OR4(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_OR5(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_TRUE1(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_OPTIONAL1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_OPTIONAL2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_OPTIONAL3(...) \ + do { \ + } while (0) + +# define OPENVINO_LOG_WRAPTYPE1(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_WRAPTYPE2(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_WRAPTYPE3(...) \ + do { \ + } while (0) +# define OPENVINO_LOG_WRAPTYPE4(...) \ + do { \ + } while (0) + +#endif \ No newline at end of file diff --git a/src/core/include/openvino/pass/pattern/op/wrap_type.hpp b/src/core/include/openvino/pass/pattern/op/wrap_type.hpp index b9fc694d8198e6..ffad9aa7ef7664 100644 --- a/src/core/include/openvino/pass/pattern/op/wrap_type.hpp +++ b/src/core/include/openvino/pass/pattern/op/wrap_type.hpp @@ -12,7 +12,7 @@ namespace ov::pass::pattern { namespace op { class OPENVINO_API WrapType : public Pattern { public: - OPENVINO_RTTI("patternAnyType"); + OPENVINO_RTTI("WrapType"); explicit WrapType(const std::vector& wrapped_types) : Pattern({}), m_wrapped_types(wrapped_types) { set_output_type(0, element::Type_t::dynamic, PartialShape::dynamic()); diff --git a/src/core/src/graph_util.cpp b/src/core/src/graph_util.cpp index e8bd73d96b537d..d2944f28982716 100644 --- a/src/core/src/graph_util.cpp +++ b/src/core/src/graph_util.cpp @@ -20,6 +20,7 @@ #include "openvino/pass/manager.hpp" #include "openvino/pass/pattern/op/wrap_type.hpp" #include "openvino/pass/visualize_tree.hpp" +#include "openvino/util/env_util.hpp" #include "openvino/util/file_util.hpp" #include "transformations/common_optimizations/compress_float_constants.hpp" #include "transformations/common_optimizations/fused_names_cleanup.hpp" diff --git a/src/core/src/log_util.cpp b/src/core/src/log_util.cpp new file mode 100644 index 00000000000000..f7bcbb366cb301 --- /dev/null +++ b/src/core/src/log_util.cpp @@ -0,0 +1,108 @@ +// Copyright (C) 2018-2025 Intel Corporation +// SPDX-License-Identifier: Apache-2.0 +// + +#include "openvino/core/log_util.hpp" + +#include "openvino/pass/pattern/op/wrap_type.hpp" +#include "openvino/util/env_util.hpp" +#include "transformations/utils/gen_pattern.hpp" + +namespace ov { +namespace util { + +#ifdef ENABLE_OPENVINO_DEBUG +// Switch on verbose matching logging using OV_VERBOSE_LOGGING=true +static const bool verbose = ov::util::getenv_bool("OV_VERBOSE_LOGGING"); + +// These functions are used for printing nodes in a pretty way for matching logging +static std::string wrapped_type_str(const ov::gen_pattern::detail::GenericPattern& gp, bool verbose) { + auto wrapped_type_info = gp.get_wrapped_type(); + auto version = wrapped_type_info.version_id; + std::string res = "<"; + if (verbose && version) + res += version + std::string("::"); + + res += wrapped_type_info.name + std::string(">"); + return res; +} + +static std::string wrapped_type_str(const ov::pass::pattern::op::WrapType& wt, bool verbose) { + bool first = true; + std::string res = "<"; + for (const auto& type : wt.get_wrapped_types()) { + auto version = type.version_id; + res += std::string(first ? "" : ", "); + if (verbose && version) + res += version + std::string("::"); + + res += type.name; + first = false; + } + res += ">"; + return res; +} + +static std::string arguments_str(const OutputVector& input_values, bool verbose) { + std::string sep = ""; + std::stringstream stream; + stream << "("; + + for (const auto& arg : input_values) { + if (verbose) + stream << sep << arg; + else + stream << sep << arg.get_node_shared_ptr()->get_type_name(); + sep = ", "; + } + stream << ")"; + + return stream.str(); +} + +std::string node_version_type_name_str(const ov::Node& node) { + return ov::util::node_version_type_str(node) + " " + node.get_name(); +} + +std::string node_version_type_str(const ov::Node& node) { + auto version = node.get_type_info().version_id; + std::string res; + if (verbose && version) + res = version + std::string("::"); + + res += node.get_type_info().name; + + if (auto wrap_type = ov::as_type(&node)) { + res += wrapped_type_str(*wrap_type, verbose); + } else if (auto generic_pattern = ov::as_type(&node)) { + res += wrapped_type_str(*generic_pattern, verbose); + } + + return res; +} + +std::string node_with_arguments(const ov::Node& node) { + std::string res; + auto version = node.get_type_info().version_id; + if (verbose && version) + res += version + std::string("::"); + + res += node.get_type_info().name; + + if (auto wrap_type = ov::as_type(&node)) { + res += wrapped_type_str(*wrap_type, verbose); + } else if (auto generic_pattern = ov::as_type(&node)) { + res += wrapped_type_str(*generic_pattern, verbose); + } + + if (verbose) + res += " " + node.get_friendly_name(); + + res += arguments_str(node.input_values(), verbose); + + return res; +} + +#endif +} // namespace util +} // namespace ov \ No newline at end of file diff --git a/src/core/src/node.cpp b/src/core/src/node.cpp index a1da08c73106c2..ad82378f1723e1 100644 --- a/src/core/src/node.cpp +++ b/src/core/src/node.cpp @@ -14,11 +14,13 @@ #include "itt.hpp" #include "openvino/core/descriptor/input.hpp" #include "openvino/core/descriptor_tensor.hpp" +#include "openvino/core/log_util.hpp" #include "openvino/core/rt_info.hpp" #include "openvino/core/shape_util.hpp" #include "openvino/op/util/op_types.hpp" #include "openvino/pass/constant_folding.hpp" #include "openvino/pass/pattern/matcher.hpp" +#include "openvino/util/log.hpp" #include "shape_validation.hpp" #include "shared_node_info.hpp" @@ -533,6 +535,7 @@ bool ov::Node::match_value(ov::pass::pattern::Matcher* matcher, (matcher->is_strict_mode() && (!pattern_value.get_element_type().compatible(graph_value.get_element_type()) || !pattern_value.get_partial_shape().compatible(graph_value.get_partial_shape())))) { + OPENVINO_LOG_NODE1(matcher, pattern_value, graph_value); return false; } return match_node(matcher, graph_value); @@ -547,11 +550,17 @@ bool ov::Node::match_node(ov::pass::pattern::Matcher* matcher, const Outputget_type_info().is_castable(get_type_info()) && - matcher->match_arguments(this, graph_value.get_node_shared_ptr())) { - auto& pattern_map = matcher->get_pattern_value_map(); - pattern_map[shared_from_this()] = graph_value; - return true; + if (graph_value.get_node_shared_ptr()->get_type_info().is_castable(get_type_info())) { + OPENVINO_LOG_NODE2(matcher); + if (matcher->match_arguments(this, graph_value.get_node_shared_ptr())) { + auto& pattern_map = matcher->get_pattern_value_map(); + pattern_map[shared_from_this()] = graph_value; + OPENVINO_LOG_NODE3(matcher); + return true; + } + OPENVINO_LOG_NODE4(matcher); + } else { + OPENVINO_LOG_NODE5(matcher, shared_from_this(), graph_value); } return false; } diff --git a/src/core/src/pass/graph_rewrite.cpp b/src/core/src/pass/graph_rewrite.cpp index b7e839838c54fa..41348d8b62f691 100644 --- a/src/core/src/pass/graph_rewrite.cpp +++ b/src/core/src/pass/graph_rewrite.cpp @@ -13,6 +13,7 @@ #include #include "openvino/cc/pass/itt.hpp" +#include "openvino/core/log_util.hpp" #include "openvino/op/util/multi_subgraph_base.hpp" #include "openvino/pass/backward_graph_rewrite.hpp" #include "openvino/pass/pattern/op/wrap_type.hpp" @@ -282,21 +283,22 @@ void ov::pass::MatcherPass::register_matcher(const std::shared_ptr& node) -> bool { - OPENVINO_DEBUG("[MATCHER] ", m->get_name(), " trying to match ", node); + OPENVINO_LOG_GRAPH_REWRITE1(m, node); if (m->match(node->output(0))) { - OPENVINO_DEBUG("[MATCHER] ", m->get_name(), " matched ", node); OV_PASS_CALLBACK(m); try { const bool status = callback(*m.get()); - OPENVINO_DEBUG("[MATCHER] ", m->get_name(), " callback ", (status ? "succeded" : "failed")); // explicitly clear Matcher state because it holds pointers to matched nodes m->clear_state(); + OPENVINO_LOG_GRAPH_REWRITE2(m, status); return status; } catch (const std::exception& exp) { - OPENVINO_THROW("[MATCHER] ", m->get_name(), "node: ", node, " callback has thrown: ", exp.what()); + OPENVINO_LOG_GRAPH_REWRITE3(m, exp); + OPENVINO_THROW("[", m->get_name(), "] END: node: ", node, " CALLBACK HAS THROWN: ", exp.what(), "\n"); } } + OPENVINO_LOG_GRAPH_REWRITE4(m); m->clear_state(); return false; }; diff --git a/src/core/src/pass/manager.cpp b/src/core/src/pass/manager.cpp index c3a41c44f1e3d5..78b871db3fd766 100644 --- a/src/core/src/pass/manager.cpp +++ b/src/core/src/pass/manager.cpp @@ -255,7 +255,7 @@ class Profiler { if (m_visualize.is_bool()) { _visualize(); } else { - const auto& filter_tokens = split_by_delimiter(m_visualize.get_str(), ','); + const auto& filter_tokens = ov::util::split_by_delimiter(m_visualize.get_str(), ','); for (const auto& token : filter_tokens) { if (pass_name.find(token) != std::string::npos) { _visualize(); @@ -278,7 +278,7 @@ class Profiler { if (m_serialize.is_bool()) { _serialize(); } else { - const auto& filter_tokens = split_by_delimiter(m_serialize.get_str(), ','); + const auto& filter_tokens = ov::util::split_by_delimiter(m_serialize.get_str(), ','); for (const auto& token : filter_tokens) { if (pass_name.find(token) != std::string::npos) { _serialize(); @@ -301,19 +301,6 @@ class Profiler { return name.str(); } - static std::vector split_by_delimiter(std::string str, char delimiter) { - std::vector res; - size_t pos = 0; - while ((pos = str.find(delimiter)) != std::string::npos) { - res.push_back(str.substr(0, pos)); - str.erase(0, pos + 1); - } - if (pos != str.size() - 1) { - res.push_back(str); - } - return res; - } - std::unordered_map stopwatches; EnvVar m_visualize; diff --git a/src/core/src/pattern/matcher.cpp b/src/core/src/pattern/matcher.cpp index 034dfba5ee0687..948e4f7dde0262 100644 --- a/src/core/src/pattern/matcher.cpp +++ b/src/core/src/pattern/matcher.cpp @@ -7,6 +7,7 @@ #include #include +#include "openvino/core/log_util.hpp" #include "openvino/op/util/op_types.hpp" #include "openvino/util/env_util.hpp" #include "openvino/util/log.hpp" @@ -129,39 +130,29 @@ bool Matcher::is_contained_match(const NodeVector& exclusions, bool ignore_unuse bool Matcher::match_value(const ov::Output& pattern_value, const ov::Output& graph_value) { std::shared_ptr pattern_node = pattern_value.get_node_shared_ptr(); std::shared_ptr graph_node = graph_value.get_node_shared_ptr(); + OPENVINO_LOG_MATCHER1(this, pattern_value, graph_value); return pattern_node->match_value(this, pattern_value, graph_value); } bool Matcher::match_permutation(const OutputVector& pattern_args, const OutputVector& args) { for (size_t i = 0; i < args.size(); i++) { + OPENVINO_LOG_MATCHER2(this, i); if (!match_value(pattern_args.at(i), args.at(i))) { - OPENVINO_DEBUG("[MATCHER] Aborting. Argument ", - i, - " (", - args.at(i).get_node()->get_friendly_name(), - ") mismatch for pattern: ", - pattern_args.at(i)); + OPENVINO_LOG_MATCHER3(this, i); return false; } + OPENVINO_LOG_MATCHER4(this, i); } return true; } bool Matcher::match_arguments(Node* pattern_node, const std::shared_ptr& graph_node) { - OPENVINO_DEBUG("[MATCHER] Match arguments at"); - OPENVINO_DEBUG("\t", *graph_node); - OPENVINO_DEBUG("for pattern"); - OPENVINO_DEBUG("\t", *pattern_node); - auto args = graph_node->input_values(); auto pattern_args = pattern_node->input_values(); if (args.size() != pattern_args.size()) { - OPENVINO_DEBUG("[MATCHER] Aborting. Args count mismatch: candidate: ", - args.size(), - "; pattern: ", - pattern_args.size()); + OPENVINO_LOG_MATCHER5(this, pattern_args.size(), args.size()); return false; } @@ -174,20 +165,27 @@ bool Matcher::match_arguments(Node* pattern_node, const std::shared_ptr& g return n1 < n2; }); do { + OPENVINO_LOG_MATCHER6(this); auto saved = start_match(); if (match_permutation(pattern_args, args)) { - return saved.finish(true); + auto res = saved.finish(true); + OPENVINO_LOG_MATCHER7(this); + return res; } + OPENVINO_LOG_MATCHER8(this); } while (std::next_permutation(begin(pattern_args), end(pattern_args), [](const ov::Output& n1, const ov::Output& n2) { return n1 < n2; })); } else { - return match_permutation(pattern_args, args); + OPENVINO_LOG_MATCHER9(this); + auto res = match_permutation(pattern_args, args); + OPENVINO_LOG_MATCHER10(this, res); + return res; } - OPENVINO_DEBUG("[MATCHER] Aborting"); + OPENVINO_LOG_MATCHER11(this); return false; } diff --git a/src/core/src/pattern/op/label.cpp b/src/core/src/pattern/op/label.cpp index 44bb0ec076985f..d87aad4b3237e1 100644 --- a/src/core/src/pattern/op/label.cpp +++ b/src/core/src/pattern/op/label.cpp @@ -4,9 +4,11 @@ #include "openvino/pass/pattern/op/label.hpp" +#include "openvino/core/log_util.hpp" #include "openvino/pass/pattern/matcher.hpp" #include "openvino/pass/pattern/op/or.hpp" #include "openvino/pass/pattern/op/true.hpp" +#include "openvino/util/log.hpp" ov::Output ov::pass::pattern::op::Label::wrap_values(const ov::OutputVector& wrapped_values) { switch (wrapped_values.size()) { @@ -27,12 +29,17 @@ bool ov::pass::pattern::op::Label::match_value(ov::pass::pattern::Matcher* match auto saved = matcher->start_match(); matcher->add_node(graph_value); if (pattern_map.count(shared_from_this())) { + OPENVINO_LOG_LABEL1(matcher, get_name()); return saved.finish(pattern_map[shared_from_this()] == graph_value); } else { pattern_map[shared_from_this()] = graph_value; - return saved.finish(matcher->match_value(input_value(0), graph_value)); + OPENVINO_LOG_LABEL2(matcher, get_name()); + auto res = saved.finish(matcher->match_value(input_value(0), graph_value)); + OPENVINO_LOG_LABEL3(matcher); + return res; } } + OPENVINO_LOG_LABEL4(matcher); return false; } diff --git a/src/core/src/pattern/op/optional.cpp b/src/core/src/pattern/op/optional.cpp index dfd6e3b8f2460c..cc5ee24db4caba 100644 --- a/src/core/src/pattern/op/optional.cpp +++ b/src/core/src/pattern/op/optional.cpp @@ -4,9 +4,11 @@ #include "openvino/pass/pattern/op/optional.hpp" +#include "openvino/core/log_util.hpp" #include "openvino/pass/pattern/matcher.hpp" #include "openvino/pass/pattern/op/or.hpp" #include "openvino/pass/pattern/op/wrap_type.hpp" +#include "openvino/util/log.hpp" using namespace ov::pass::pattern::op; @@ -27,12 +29,15 @@ bool Optional::match_value(Matcher* matcher, const Output& pattern_value, auto or_node = is_empty_in_values ? std::static_pointer_cast(wrap_node) : std::static_pointer_cast(std::make_shared( ov::OutputVector{wrap_node, input_values_to_optional[0]})); + OPENVINO_LOG_OPTIONAL1(matcher, or_node, wrap_node, get_name()); if (matcher->match_value(or_node, graph_value)) { auto& pattern_map = matcher->get_pattern_value_map(); if (pattern_map.count(wrap_node)) { pattern_map[shared_from_this()] = graph_value; } + OPENVINO_LOG_OPTIONAL2(matcher); return true; } + OPENVINO_LOG_OPTIONAL3(matcher); return false; } diff --git a/src/core/src/pattern/op/or.cpp b/src/core/src/pattern/op/or.cpp index d77a0e394dbb5f..81686c1ca5896a 100644 --- a/src/core/src/pattern/op/or.cpp +++ b/src/core/src/pattern/op/or.cpp @@ -4,18 +4,26 @@ #include "openvino/pass/pattern/op/or.hpp" +#include "openvino/core/log_util.hpp" #include "openvino/pass/pattern/matcher.hpp" +#include "openvino/util/log.hpp" bool ov::pass::pattern::op::Or::match_value(Matcher* matcher, const Output& pattern_value, const Output& graph_value) { - for (const auto& input_value : input_values()) { + OPENVINO_LOG_OR1(matcher, this->get_input_size(), this->get_name()); + for (size_t i = 0; i < get_input_size(); ++i) { + OPENVINO_LOG_OR2(matcher, i, input_value(i)); auto saved = matcher->start_match(); - if (matcher->match_value(input_value, graph_value)) { + if (matcher->match_value(input_value(i), graph_value)) { auto& pattern_map = matcher->get_pattern_value_map(); pattern_map[shared_from_this()] = graph_value; - return saved.finish(true); + auto res = saved.finish(true); + OPENVINO_LOG_OR3(matcher, i); + return res; } + OPENVINO_LOG_OR4(matcher, i); } + OPENVINO_LOG_OR5(matcher); return false; } diff --git a/src/core/src/pattern/op/true.cpp b/src/core/src/pattern/op/true.cpp index 23f463cfd05700..014cb242fd29e9 100644 --- a/src/core/src/pattern/op/true.cpp +++ b/src/core/src/pattern/op/true.cpp @@ -4,10 +4,13 @@ #include "openvino/pass/pattern/op/true.hpp" +#include "openvino/core/log_util.hpp" #include "openvino/pass/pattern/matcher.hpp" +#include "openvino/util/log.hpp" bool ov::pass::pattern::op::True::match_value(Matcher* matcher, const Output& pattern_value, const Output& graph_value) { + OPENVINO_LOG_TRUE1(matcher); return true; } diff --git a/src/core/src/pattern/op/wrap_type.cpp b/src/core/src/pattern/op/wrap_type.cpp index 91dc63aa2da51b..5f48922f363d61 100644 --- a/src/core/src/pattern/op/wrap_type.cpp +++ b/src/core/src/pattern/op/wrap_type.cpp @@ -5,25 +5,34 @@ #include "openvino/pass/pattern/op/wrap_type.hpp" #include "openvino/core/except.hpp" +#include "openvino/core/log_util.hpp" #include "openvino/pass/pattern/matcher.hpp" +#include "openvino/util/log.hpp" bool ov::pass::pattern::op::WrapType::match_value(Matcher* matcher, const Output& pattern_value, const Output& graph_value) { - if (std::any_of(m_wrapped_types.begin(), - m_wrapped_types.end(), - [&](const NodeTypeInfo& type_info) { - return graph_value.get_node_shared_ptr()->get_type_info().is_castable(type_info); - }) && - m_predicate(matcher->get_symbols(), graph_value)) { - auto& pattern_map = matcher->get_pattern_value_map(); - pattern_map[shared_from_this()] = graph_value; - matcher->add_node(graph_value); - return (get_input_size() == 0 - ? true - : matcher->match_arguments(pattern_value.get_node(), graph_value.get_node_shared_ptr())); + if (std::none_of(m_wrapped_types.begin(), m_wrapped_types.end(), [&](const NodeTypeInfo& type_info) { + return graph_value.get_node_shared_ptr()->get_type_info().is_castable(type_info); + })) { + OPENVINO_LOG_WRAPTYPE1(matcher, pattern_value, graph_value); + return false; } - return false; + + if (!m_predicate(matcher->get_symbols(), graph_value)) { + OPENVINO_LOG_WRAPTYPE2(matcher); + return false; + } + + auto& pattern_map = matcher->get_pattern_value_map(); + pattern_map[shared_from_this()] = graph_value; + matcher->add_node(graph_value); + OPENVINO_LOG_WRAPTYPE3(matcher, get_input_size()); + auto res = + (get_input_size() == 0 ? true + : matcher->match_arguments(pattern_value.get_node(), graph_value.get_node_shared_ptr())); + OPENVINO_LOG_WRAPTYPE4(matcher, res); + return res; } ov::NodeTypeInfo ov::pass::pattern::op::WrapType::get_wrapped_type() const { @@ -50,4 +59,4 @@ std::ostream& ov::pass::pattern::op::WrapType::write_type_description(std::ostre } out << (m_wrapped_types.size() > 1 ? ">" : ""); return out; -} +} \ No newline at end of file diff --git a/src/tests/test_utils/common_test_utils/tests/utils_tests.cpp b/src/tests/test_utils/common_test_utils/tests/utils_tests.cpp index 5360b03b3c1485..e333988442cffd 100644 --- a/src/tests/test_utils/common_test_utils/tests/utils_tests.cpp +++ b/src/tests/test_utils/common_test_utils/tests/utils_tests.cpp @@ -6,6 +6,7 @@ #include "openvino/util/common_util.hpp" #include "openvino/util/file_util.hpp" +#include "openvino/util/env_util.hpp" using namespace testing; using namespace ov::util; @@ -51,3 +52,53 @@ TEST(UtilsTests, filter_lines_by_prefix) { res = filter_lines_by_prefix(lines, "ab"); ASSERT_EQ(res, ""); } + +TEST(UtilsTests, split_by_delimiter) { + const auto line = "EliminateSplitConcat,MarkDequantization,StatefulSDPAFusion"; + + const auto split_set = ov::util::split_by_delimiter(line, ','); + + const std::unordered_set expected_set = {"EliminateSplitConcat", "MarkDequantization", "StatefulSDPAFusion"}; + + ASSERT_EQ(split_set, expected_set); +} + +TEST(UtilsTests, split_by_delimiter_single) { + const auto line = "EliminateSplitConcat"; + + const auto split_set = ov::util::split_by_delimiter(line, ','); + + const std::unordered_set expected_set = {"EliminateSplitConcat"}; + + ASSERT_EQ(split_set, expected_set); +} + +TEST(UtilsTests, split_by_delimiter_single_with_comma) { + const auto line = "EliminateSplitConcat,"; + + const auto split_set = ov::util::split_by_delimiter(line, ','); + + const std::unordered_set expected_set = {"EliminateSplitConcat"}; + + ASSERT_EQ(split_set, expected_set); +} + +TEST(UtilsTests, split_by_delimiter_empty) { + const auto line = ""; + + const auto split_set = ov::util::split_by_delimiter(line, ','); + + const std::unordered_set expected_set = {}; + + ASSERT_EQ(split_set, expected_set); +} + +TEST(UtilsTests, split_by_delimiter_empty_and_comma) { + const auto line = ","; + + const auto split_set = ov::util::split_by_delimiter(line, ','); + + const std::unordered_set expected_set = {"", ""}; + + ASSERT_EQ(split_set, expected_set); +} \ No newline at end of file