[CPU] Enable OV_CPU_VERBOSE=info to print plugin relevant info

Author: EgorDuplensky

src/core/include/openvino/core/parallel.hpp

@@ -22,6 +22,18 @@
 #define OV_THREAD_SEQ      2
 #define OV_THREAD_TBB_AUTO 3
 
+#if (OV_THREAD == OV_THREAD_TBB)
+#    define OV_THREAD_NAME "TBB"
+#elif (OV_THREAD == OV_THREAD_OMP)
+#    define OV_THREAD_NAME "OMP"
+#elif (OV_THREAD == OV_THREAD_SEQ)
+#    define OV_THREAD_NAME "SEQ"
+#elif (OV_THREAD == OV_THREAD_TBB_AUTO)
+#    define OV_THREAD_NAME "TBB_AUTO"
+#else
+#    define OV_THREAD_NAME "UNKNOWN"
+#endif
+
 #if (OV_THREAD == OV_THREAD_TBB || OV_THREAD == OV_THREAD_TBB_AUTO)
 #    ifndef NOMINMAX
 #        define NOMINMAX

src/plugins/intel_cpu/src/config.cpp

@@ -6,6 +6,7 @@
 
 #include <algorithm>
 #include <cstdint>
+#include <cstdlib>
 #include <map>
 #include <memory>
 #include <set>
@@ -21,6 +22,7 @@
 #include "openvino/runtime/intel_cpu/properties.hpp"
 #include "openvino/runtime/internal_properties.hpp"
 #include "openvino/runtime/properties.hpp"
+#include "openvino/util/env_util.hpp"
 #include "utils/debug_capabilities.h"
 #include "utils/general_utils.h"
 #include "utils/precision_support.h"
@@ -48,12 +50,16 @@ Config::Config() {
  */
 void Config::applyDebugCapsProperties() {
     // always enable perf counters for verbose, performance summary and average counters
-    if (!debugCaps.verbose.empty() || debugCaps.summaryPerf || !debugCaps.averageCountersPath.empty()) {
+    if (!verbose.empty() || debugCaps.summaryPerf || !debugCaps.averageCountersPath.empty()) {
         collectPerfCounters = true;
     }
 }
 #endif
 
+void Config::readEnvProperties() {
+    verbose = ov::util::getenv_string("OV_CPU_VERBOSE");
+}
+
 void Config::readProperties(const ov::AnyMap& prop, const ModelType modelType) {
     const auto streamExecutorConfigKeys =
         streamExecutorConfig.get_property(ov::supported_properties.name()).as<std::vector<std::string>>();
@@ -537,6 +543,9 @@ void Config::readProperties(const ov::AnyMap& prop, const ModelType modelType) {
     this->modelType = modelType;
 
     CPU_DEBUG_CAP_ENABLE(applyDebugCapsProperties());
+
+    readEnvProperties();
+
     updateProperties();
 }
 

src/plugins/intel_cpu/src/config.h

@@ -54,6 +54,7 @@ struct Config {
     SnippetsMode snippetsMode = SnippetsMode::Enable;
     std::string dumpToDot;
     std::string device_id;
+    std::string verbose;
     float fcSparseWeiDecompressionRate = 1.0F;
     uint64_t fcDynamicQuantizationGroupSize = 32;
     bool fcDynamicQuantizationGroupSizeSetExplicitly = false;
@@ -125,6 +126,7 @@ struct Config {
     // is reserved.
     bool DAZOn = false;
 
+    void readEnvProperties();
     void readProperties(const ov::AnyMap& prop, ModelType modelType = ModelType::Unknown);
 
     void updateProperties();

src/plugins/intel_cpu/src/graph.cpp

@@ -1591,7 +1591,7 @@ class UpdateNodes : public UpdateNodesBase {
 /* group all the profiling macros into a single one
  * to avoid cluttering a core logic */
 #define VERBOSE_PERF_DUMP_ITT_DEBUG_LOG(ittScope, node, config) \
-    VERBOSE(node, (config).debugCaps.verbose);                  \
+    VERBOSE(node, (config).verbose);                            \
     PERF(node, (config).collectPerfCounters);                   \
     DUMP(node, (config).debugCaps, infer_count);                \
     OV_ITT_SCOPED_TASK(ittScope, (node)->profiling.execute);    \

src/plugins/intel_cpu/src/plugin.cpp

@@ -9,12 +9,17 @@
 #include <fstream>
 #include <istream>
 #include <memory>
+#include <ostream>
 #include <set>
 #include <string>
 #include <tuple>
 #include <unordered_map>
 #include <utility>
 #include <vector>
+
+#include "common/z_magic.hpp"
+#include "oneapi/dnnl/dnnl.hpp"
+#include "openvino/util/env_util.hpp"
 #if defined(__APPLE__)
 #    include <sys/sysctl.h>
 #    include <sys/types.h>
@@ -227,8 +232,41 @@ static std::string getDeviceFullName() {
     return brand_string;
 }
 
+// Print basic CPU information once when OV_CPU_VERBOSE=info is set
+static void print_plugin_info_once() {
+    static std::atomic_flag info_printed = ATOMIC_FLAG_INIT;
+    // @todo To avoid dealing with environment variables in multiple places
+    //       read them all here and pass to CPU config as a parameter
+    const auto& ov_cpu_verbose = ov::util::getenv_string("OV_CPU_VERBOSE");
+#if defined(CPU_DEBUG_CAPS)
+    // in case of debug caps enabled print info if OV_CPU_VERBOSE is set to any value
+    if (ov_cpu_verbose.empty()) {
+        return;
+    }
+#else
+    if (ov_cpu_verbose != "info") {
+        return;
+    }
+#endif
+
+    // Print info only once
+    if (info_printed.test_and_set()) {
+        return;
+    }
+
+    const auto& ov_version = ov::get_openvino_version();
+    const auto& dnnl_version = dnnl::version();
+    std::cout << "ov_cpu_verbose,info,intel_cpu_plugin,version: " << ov_version.buildNumber << '\n';
+    std::cout << "ov_cpu_verbose,info,onednn,version: " << dnnl_version->major << "." << dnnl_version->minor << "."
+              << dnnl_version->patch << " (commit " << dnnl_version->hash << ")" << '\n';
+    // @todo add more info regarding other backends if available
+    std::cout << "ov_cpu_verbose,info,isa: " << dnnl::impl::cpu::x64::get_isa_info() << '\n';
+    std::cout << "ov_cpu_verbose,info,intel_cpu_plugin,runtime: " << OV_THREAD_NAME << std::endl;
+}
+
 Plugin::Plugin() : deviceFullName(getDeviceFullName()), specialSetup(new CPUSpecialSetup) {
     set_device_name("CPU");
+    print_plugin_info_once();
     // Initialize Xbyak::util::Cpu object on Pcore for hybrid cores machine
     get_executor_manager()->execute_task_by_streams_executor(ov::hint::SchedulingCoreType::PCORE_ONLY, [] {
         dnnl::impl::cpu::x64::cpu();

src/plugins/intel_cpu/src/utils/debug_caps_config.cpp

@@ -37,10 +37,6 @@ void DebugCapsConfig::readProperties() {
         execGraphPath = envVarValue;
     }
 
-    if (const auto* envVarValue = readEnv("OV_CPU_VERBOSE")) {
-        verbose = envVarValue;
-    }
-
     if (const auto* envVarValue = readEnv("OV_CPU_BLOB_DUMP_DIR")) {
         blobDumpDir = envVarValue;
     }

src/plugins/intel_cpu/src/utils/debug_caps_config.h

@@ -44,7 +44,6 @@ class DebugCapsConfig {
 
     std::string execGraphPath;
     std::string averageCountersPath;
-    std::string verbose;
     std::string blobDumpDir = "cpu_dump";
     FORMAT blobDumpFormat = FORMAT::TEXT;
     std::unordered_map<FILTER, std::string> blobDumpFilters;

src/plugins/intel_cpu/src/utils/verbose.cpp

@@ -1,44 +1,43 @@
 // Copyright (C) 2018-2025 Intel Corporation
 // SPDX-License-Identifier: Apache-2.0
 //
-#include <algorithm>
-#include <cstdint>
-#include <cstdio>
-#include <cstring>
-#include <utility>
-
-#include "dnnl_extension_utils.h"
-#include "memory_desc/cpu_memory_desc.h"
-#include "onednn/iml_type_mapper.h"
-#include "utils/general_utils.h"
 #ifdef CPU_DEBUG_CAPS
+#    include "common/verbose.hpp"
 
 #    include <node.h>
 
+#    include <algorithm>
+#    include <cstdint>
+#    include <cstdio>
 #    include <cstdlib>
+#    include <cstring>
 #    include <iostream>
 #    include <sstream>
 #    include <string>
+#    include <utility>
 
 #    include "common/c_types_map.hpp"
-#    include "common/verbose.hpp"
 #    include "cpu_types.h"
+#    include "dnnl_extension_utils.h"
+#    include "memory_desc/cpu_memory_desc.h"
 #    include "memory_desc/cpu_memory_desc_utils.h"
+#    include "onednn/iml_type_mapper.h"
+#    include "utils/general_utils.h"
 #    include "verbose.h"
 
 namespace ov::intel_cpu {
 
 bool Verbose::shouldBePrinted() const {
-    if (lvl < 1) {
+    if (m_lvl < 1) {
         return false;
     }
 
-    if (lvl < 2 && any_of(node->getType(), Type::Input, Type::Output)) {
+    if (m_lvl < 2 && any_of(m_node->getType(), Type::Input, Type::Output)) {
         return false;
     }
 
-    const bool low_level = lvl < 3;
-    const bool is_constant = node->isConstant();
+    const bool low_level = m_lvl < 3;
+    const bool is_constant = m_node->isConstant();
     const bool skip_node = low_level && is_constant;
     return !skip_node;
 }
@@ -53,7 +52,7 @@ void Verbose::printInfo() {
     enum Color : uint8_t { RED, GREEN, YELLOW, BLUE, PURPLE, CYAN };
 
     auto colorize = [&](const Color color, const std::string& str) {
-        if (!colorUp) {
+        if (!m_colorUp) {
             return str;
         }
 
@@ -146,22 +145,22 @@ void Verbose::printInfo() {
         shift(written);
     };
 
-    for (size_t i = 0; i < node->getParentEdges().size(); i++) {
+    for (size_t i = 0; i < m_node->getParentEdges().size(); i++) {
         std::string prefix("src:" + std::to_string(i) + ':');
-        const auto& desc = node->getParentEdgeAt(i)->getMemory().getDescPtr();
+        const auto& desc = m_node->getParentEdgeAt(i)->getMemory().getDescPtr();
         formatMemDesc(desc, prefix);
     }
 
-    for (size_t i = 0; i < node->getChildEdges().size(); i++) {
+    for (size_t i = 0; i < m_node->getChildEdges().size(); i++) {
         std::string prefix("dst:" + std::to_string(i) + ':');
-        const auto& desc = node->getChildEdgeAt(i)->getMemory().getDescPtr();
+        const auto& desc = m_node->getChildEdgeAt(i)->getMemory().getDescPtr();
         formatMemDesc(desc, prefix);
     }
 
     std::string post_ops;
-    if (!node->getFusedWith().empty()) {
+    if (!m_node->getFusedWith().empty()) {
         post_ops += "post_ops:'";
-        for (const auto& fusedNode : node->getFusedWith()) {
+        for (const auto& fusedNode : m_node->getFusedWith()) {
             post_ops.append(colorize(GREEN, fusedNode->getName()))
                 .append(":")
                 .append(colorize(CYAN, NameFromType(fusedNode->getType())))
@@ -173,27 +172,27 @@ void Verbose::printInfo() {
     }
 
     std::string nodeImplementer = "cpu";
-    if (node->getType() == Type::Reference) {
+    if (m_node->getType() == Type::Reference) {
         nodeImplementer = "ngraph_ref";  // ngraph reference
     }
 
-    const std::string& nodeName = colorize(GREEN, node->getName());
-    const std::string& nodeType = colorize(CYAN, NameFromType(node->getType()));
-    const std::string& nodeAlg = algToString(node->getAlgorithm());
+    const std::string& nodeName = colorize(GREEN, m_node->getName());
+    const std::string& nodeType = colorize(CYAN, NameFromType(m_node->getType()));
+    const std::string& nodeAlg = algToString(m_node->getAlgorithm());
     const std::string& nodePrimImplType =
-        impl_type_to_string(node->getSelectedPrimitiveDescriptor()->getImplementationType());
+        impl_type_to_string(m_node->getSelectedPrimitiveDescriptor()->getImplementationType());
 
-    stream << "ov_cpu_verbose" << ',' << "exec" << ',' << nodeImplementer << ',' << nodeName << ":" << nodeType << ":"
-           << nodeAlg << ',' << nodePrimImplType << ',' << portsInfo << ',' << post_ops << ',';
+    m_stream << "ov_cpu_verbose" << ',' << "exec" << ',' << nodeImplementer << ',' << nodeName << ":" << nodeType << ":"
+             << nodeAlg << ',' << nodePrimImplType << ',' << portsInfo << ',' << post_ops << ',';
 }
 
 void Verbose::printDuration() {
-    const auto& duration = node->PerfCounter().duration().count();
-    stream << duration << "ms";
+    const auto& duration = m_node->PerfCounter().duration().count();
+    m_stream << duration << "ms";
 }
 
 void Verbose::flush() const {
-    std::cout << stream.rdbuf() << "\n";
+    std::cout << m_stream.rdbuf() << "\n";
 }
 
 }  // namespace ov::intel_cpu

src/plugins/intel_cpu/src/utils/verbose.h

@@ -4,28 +4,38 @@
 #pragma once
 
 #ifdef CPU_DEBUG_CAPS
-
 #    include <node.h>
 
+#    include <charconv>
 #    include <cstdlib>
 #    include <sstream>
 #    include <string>
 
 namespace ov::intel_cpu {
 
+static int getLevel(const std::string& str) {
+    int value = 0;
+
+    std::from_chars(str.data(), str.data() + str.size(), value);
+
+    return value;
+}
+
 class Verbose {
 public:
-    Verbose(const NodePtr& _node, const std::string& _lvl)
-        : node(_node),
-          lvl(atoi(_lvl.c_str()) % 10),
+    Verbose(const NodePtr& _node, int _lvl)
+        : m_node(_node),
+          m_lvl(_lvl % 10),
           /* 1,  2,  3,  etc -> no color. 11, 22, 33, etc -> colorize */
-          colorUp((atoi(_lvl.c_str()) / 10) != 0) {
+          m_colorUp(_lvl != 0) {
         if (!shouldBePrinted()) {
             return;
         }
         printInfo();
     }
 
+    Verbose(const NodePtr& _node, const std::string& _lvl) : Verbose(_node, getLevel(_lvl)) {}
+
     ~Verbose() {
         if (!shouldBePrinted()) {
             return;
@@ -36,10 +46,10 @@ class Verbose {
     }
 
 private:
-    const NodePtr& node;
-    const int lvl;
-    const bool colorUp;
-    std::stringstream stream;
+    const NodePtr& m_node;
+    const int m_lvl;
+    const bool m_colorUp;
+    std::stringstream m_stream;
 
     bool shouldBePrinted() const;
     void printInfo();