Prepend DPrint messages with device id, core coords, and RISC

docs/source/tt-metalium/tools/kernel_print.rst

@@ -21,12 +21,13 @@ Note that the core coordinates are logical coordinates, so worker cores and ethe
 
 .. code-block::
 
-    export TT_METAL_DPRINT_CORES=0,0           # required, x,y OR (x1,y1),(x2,y2),(x3,y3) OR (x1,y1)-(x2,y2) OR all OR worker OR dispatch
-    export TT_METAL_DPRINT_ETH_CORES=0,0       # optional, x,y OR (x1,y1),(x2,y2),(x3,y3) OR (x1,y1)-(x2,y2) OR all OR worker OR dispatch
-    export TT_METAL_DPRINT_CHIPS=0             # optional, comma separated list of chips
-    export TT_METAL_DPRINT_RISCVS=BR           # optional, default is all RISCs.  Use a subset of BR,NC,TR0,TR1,TR2
-    export TT_METAL_DPRINT_FILE=log.txt        # optional, default is to print to the screen
-    export TT_METAL_DPRINT_ONE_FILE_PER_RISC=1 # optional, splits DPRINT data on a per-RISC basis into files under $TT_METAL_HOME/generated/dprint/. Overrides TT_METAL_DPRINT_FILE.
+    export TT_METAL_DPRINT_CORES=0,0                    # required, x,y OR (x1,y1),(x2,y2),(x3,y3) OR (x1,y1)-(x2,y2) OR all OR worker OR dispatch
+    export TT_METAL_DPRINT_ETH_CORES=0,0                # optional, x,y OR (x1,y1),(x2,y2),(x3,y3) OR (x1,y1)-(x2,y2) OR all OR worker OR dispatch
+    export TT_METAL_DPRINT_CHIPS=0                      # optional, comma separated list of chips
+    export TT_METAL_DPRINT_RISCVS=BR                    # optional, default is all RISCs. Use a subset of BR,NC,TR0,TR1,TR2
+    export TT_METAL_DPRINT_FILE=log.txt                 # optional, default is to print to the screen
+    export TT_METAL_DPRINT_PREPEND_DEVICE_CORE_RISC=0   # optional, enabled by default. Prepends prints with <device id>:(<core x>, <core y>):<RISC>:.
+    export TT_METAL_DPRINT_ONE_FILE_PER_RISC=1          # optional, splits DPRINT data on a per-RISC basis into files under $TT_METAL_HOME/generated/dprint/. Overrides TT_METAL_DPRINT_FILE and disables TT_METAL_DPRINT_PREPEND_DEVICE_CORE_RISC.
 
 To generate kernel debug prints on the device, include the ``debug/dprint.h`` header and use the APIs defined there.
 An example with the different features available is shown below:
@@ -122,4 +123,4 @@ formats for printing from CBs are ``DataFormat::Float32``, ``DataFormat::Float16
     }
 
 .. note::
-    Note that the DPRINT buffer for a RISC is flushed when ``ENDL()`` is called, a ``\n`` character is read, or the device that the RISC belongs to is closed.
+    The DPRINT buffer for a RISC is only flushed when ``ENDL()`` is called, a ``\n`` character is read, or the device that the RISC belongs to is closed.

tests/tt_metal/tt_metal/debug_tools/CMakeLists.txt

@@ -7,6 +7,7 @@ set(UNIT_TESTS_DEBUG_TOOLS_SRC
     ${CMAKE_CURRENT_SOURCE_DIR}/dprint/test_print_all_harts.cpp
     ${CMAKE_CURRENT_SOURCE_DIR}/dprint/test_print_before_finish.cpp
     ${CMAKE_CURRENT_SOURCE_DIR}/dprint/test_print_hanging.cpp
+    ${CMAKE_CURRENT_SOURCE_DIR}/dprint/test_print_prepend_device_core_risc.cpp
     ${CMAKE_CURRENT_SOURCE_DIR}/dprint/test_print_tensix_dest.cpp
     ${CMAKE_CURRENT_SOURCE_DIR}/dprint/test_print_tiles.cpp
     ${CMAKE_CURRENT_SOURCE_DIR}/dprint/test_raise_wait.cpp
@@ -22,7 +23,7 @@ set(UNIT_TESTS_DEBUG_TOOLS_SRC
 add_executable(unit_tests_debug_tools ${UNIT_TESTS_DEBUG_TOOLS_SRC})
 TT_ENABLE_UNITY_BUILD(unit_tests_debug_tools)
 
-target_link_libraries(unit_tests_debug_tools PUBLIC test_metal_common_libs)
+target_link_libraries(unit_tests_debug_tools PRIVATE test_metal_common_libs)
 target_include_directories(
     unit_tests_debug_tools
     PRIVATE

tests/tt_metal/tt_metal/debug_tools/debug_tools_fixture.hpp

@@ -46,6 +46,8 @@ class DPrintFixture : public DebugToolsFixture {
         // used by all tests using this fixture, so set dprint enabled for
         // all cores and all devices
         tt::llrt::RunTimeOptions::get_instance().set_feature_enabled(tt::llrt::RunTimeDebugFeatureDprint, true);
+        tt::llrt::RunTimeOptions::get_instance().set_feature_prepend_device_core_risc(
+            tt::llrt::RunTimeDebugFeatureDprint, false);
         tt::llrt::RunTimeOptions::get_instance().set_feature_all_cores(
             tt::llrt::RunTimeDebugFeatureDprint, CoreType::WORKER, tt::llrt::RunTimeDebugClassWorker);
         tt::llrt::RunTimeOptions::get_instance().set_feature_all_cores(
@@ -79,6 +81,8 @@ class DPrintFixture : public DebugToolsFixture {
             tt::llrt::RunTimeDebugFeatureDprint, CoreType::ETH, tt::llrt::RunTimeDebugClassNoneSpecified);
         tt::llrt::RunTimeOptions::get_instance().set_feature_all_chips(tt::llrt::RunTimeDebugFeatureDprint, false);
         tt::llrt::RunTimeOptions::get_instance().set_feature_file_name(tt::llrt::RunTimeDebugFeatureDprint, "");
+        tt::llrt::RunTimeOptions::get_instance().set_feature_prepend_device_core_risc(
+            tt::llrt::RunTimeDebugFeatureDprint, true);
         tt::llrt::RunTimeOptions::get_instance().set_test_mode_enabled(false);
     }
 

tests/tt_metal/tt_metal/debug_tools/dprint/test_print_prepend_device_core_risc.cpp

@@ -0,0 +1,113 @@
+// SPDX-FileCopyrightText: © 2024 Tenstorrent Inc.
+//
+// SPDX-License-Identifier: Apache-2.0
+
+#include <string>
+#include <vector>
+#include "core_coord.hpp"
+#include "debug_tools_fixture.hpp"
+#include "gtest/gtest.h"
+#include "debug_tools_test_utils.hpp"
+#include "kernels/kernel_types.hpp"
+#include "tt_metal/detail/tt_metal.hpp"
+#include "tt_metal/host_api.hpp"
+
+////////////////////////////////////////////////////////////////////////////////
+// A test for checking that prints are prepended with their corresponding device, core and RISC.
+////////////////////////////////////////////////////////////////////////////////
+using namespace tt;
+using namespace tt::tt_metal;
+
+namespace {
+namespace CMAKE_UNIQUE_NAMESPACE {
+static void UpdateGoldenOutput(std::vector<string>& golden_output, const Device* device, const string& risc) {
+    // Using wildcard characters in lieu of actual values for the physical coordinates as physical coordinates can vary
+    // by machine
+    const string& device_core_risc = std::to_string(device->id()) + ":(x=*,y=*):" + risc + ": ";
+
+    const string& output_line_all_riscs = device_core_risc + "Printing on a RISC.";
+    golden_output.push_back(output_line_all_riscs);
+
+    if (risc != "ER") {
+        const string& output_line_risc = device_core_risc + "Printing on " + risc + ".";
+        golden_output.push_back(output_line_risc);
+    }
+}
+
+static void RunTest(DPrintFixture* fixture, Device* device, const bool add_active_eth_kernel = false) {
+    std::vector<string> golden_output;
+
+    CoreRange cores({0, 0}, {0, 1});
+    Program program = Program();
+
+    KernelHandle brisc_kernel_id = CreateKernel(
+        program,
+        "tests/tt_metal/tt_metal/test_kernels/misc/print_simple.cpp",
+        cores,
+        DataMovementConfig{.processor = DataMovementProcessor::RISCV_0, .noc = NOC::RISCV_0_default});
+
+    KernelHandle ncrisc_kernel_id = CreateKernel(
+        program,
+        "tests/tt_metal/tt_metal/test_kernels/misc/print_simple.cpp",
+        cores,
+        DataMovementConfig{.processor = DataMovementProcessor::RISCV_1, .noc = NOC::RISCV_1_default});
+
+    KernelHandle trisc_kernel_id =
+        CreateKernel(program, "tests/tt_metal/tt_metal/test_kernels/misc/print_simple.cpp", cores, ComputeConfig{});
+
+    for (const CoreCoord& core : cores) {
+        UpdateGoldenOutput(golden_output, device, "BR");
+        UpdateGoldenOutput(golden_output, device, "NC");
+        UpdateGoldenOutput(golden_output, device, "TR0");
+        UpdateGoldenOutput(golden_output, device, "TR1");
+        UpdateGoldenOutput(golden_output, device, "TR2");
+    }
+
+    if (add_active_eth_kernel) {
+        const std::unordered_set<CoreCoord>& active_eth_cores = device->get_active_ethernet_cores(true);
+        CoreRangeSet crs(std::set<CoreRange>(active_eth_cores.begin(), active_eth_cores.end()));
+        KernelHandle erisc_kernel_id = CreateKernel(
+            program,
+            "tests/tt_metal/tt_metal/test_kernels/misc/print_simple.cpp",
+            crs,
+            EthernetConfig{.noc = NOC::NOC_0});
+
+        for (const CoreCoord& core : active_eth_cores) {
+            UpdateGoldenOutput(golden_output, device, "ER");
+        }
+    }
+
+    fixture->RunProgram(device, program);
+
+    // Check the print log against golden output.
+    EXPECT_TRUE(FileContainsAllStrings(DPrintFixture::dprint_file_name, golden_output));
+}
+}  // namespace CMAKE_UNIQUE_NAMESPACE
+}  // namespace
+
+TEST_F(DPrintFixture, TensixTestPrintPrependDeviceCoreRisc) {
+    tt::llrt::RunTimeOptions::get_instance().set_feature_prepend_device_core_risc(
+        tt::llrt::RunTimeDebugFeatureDprint, true);
+    for (Device* device : this->devices_) {
+        this->RunTestOnDevice(
+            [](DPrintFixture* fixture, Device* device) { CMAKE_UNIQUE_NAMESPACE::RunTest(fixture, device); }, device);
+    }
+    tt::llrt::RunTimeOptions::get_instance().set_feature_prepend_device_core_risc(
+        tt::llrt::RunTimeDebugFeatureDprint, false);
+}
+
+TEST_F(DPrintFixture, TensixActiveEthTestPrintPrependDeviceCoreRisc) {
+    tt::llrt::RunTimeOptions::get_instance().set_feature_prepend_device_core_risc(
+        tt::llrt::RunTimeDebugFeatureDprint, true);
+    for (Device* device : this->devices_) {
+        if (device->get_active_ethernet_cores(true).empty()) {
+            log_info(tt::LogTest, "Skipping device {} due to no active ethernet cores...", device->id());
+            continue;
+        }
+        this->RunTestOnDevice(
+            [](DPrintFixture* fixture, Device* device) { CMAKE_UNIQUE_NAMESPACE::RunTest(fixture, device, true); },
+            device);
+    }
+    tt::llrt::RunTimeOptions::get_instance().set_feature_prepend_device_core_risc(
+        tt::llrt::RunTimeDebugFeatureDprint, false);
+}

tests/tt_metal/tt_metal/test_kernels/misc/print_simple.cpp

@@ -0,0 +1,23 @@
+// SPDX-FileCopyrightText: © 2024 Tenstorrent Inc.
+//
+// SPDX-License-Identifier: Apache-2.0
+
+#include "debug/dprint.h"
+
+#if defined(COMPILE_FOR_TRISC)
+#include "compute_kernel_api/common.h"
+namespace NAMESPACE {
+void MAIN {
+#else
+void kernel_main() {
+#endif
+    DPRINT << "Printing on a RISC." << ENDL();
+    DPRINT_UNPACK(DPRINT << "Printing on TR0." << ENDL(););
+    DPRINT_MATH(DPRINT << "Printing on TR1." << ENDL(););
+    DPRINT_PACK(DPRINT << "Printing on TR2." << ENDL(););
+    DPRINT_DATA0(DPRINT << "Printing on BR." << ENDL(););
+    DPRINT_DATA1(DPRINT << "Printing on NC." << ENDL(););
+}
+#if defined(COMPILE_FOR_TRISC)
+}
+#endif

tt_metal/impl/debug/dprint_server.cpp

@@ -57,21 +57,21 @@ static inline float bfloat16_to_float(uint16_t bfloat_val) {
     return f;
 }
 
-static string GetRiscName(CoreType core_type, int hart_id) {
+static string GetRiscName(CoreType core_type, int hart_id, bool abbreviated = false) {
     if (core_type == CoreType::ETH) {
         switch (hart_id) {
             case DPRINT_RISCV_INDEX_ER:
-                return "ERISC";
+                return abbreviated ? "ER" : "ERISC";
                 // Default case falls through and handled at end.
         }
     } else {
         switch (hart_id) {
-            case DPRINT_RISCV_INDEX_NC: return "NCRISC";
-            case DPRINT_RISCV_INDEX_TR0: return "TRISC0";
-            case DPRINT_RISCV_INDEX_TR1: return "TRISC1";
-            case DPRINT_RISCV_INDEX_TR2: return "TRISC2";
+            case DPRINT_RISCV_INDEX_NC: return abbreviated ? "NC" : "NCRISC";
+            case DPRINT_RISCV_INDEX_TR0: return abbreviated ? "TR0" : "TRISC0";
+            case DPRINT_RISCV_INDEX_TR1: return abbreviated ? "TR1" : "TRISC1";
+            case DPRINT_RISCV_INDEX_TR2: return abbreviated ? "TR2" : "TRISC2";
             case DPRINT_RISCV_INDEX_BR:
-                return "BRISC";
+                return abbreviated ? "BR" : "BRISC";
                 // Default case falls through and handled at end.
         }
     }
@@ -226,6 +226,9 @@ struct DebugPrintServerContext {
     // data is visible to the user.
     void TransferToAndFlushOutputStream(const HartKey& hart_key, ostringstream* intermediate_stream);
 
+    // Returns the dprint data that should be outputted by the output stream.
+    string GetDataToOutput(const HartKey& hart_key, const ostringstream* stream);
+
     // Returns the stream that the dprint data should be output to. Can be auto-generated files, the user-selected file,
     // stdout, or nothing.
     ostream* GetOutputStream(const HartKey& hart_key);
@@ -466,6 +469,8 @@ DebugPrintServerContext::DebugPrintServerContext() {
         tt::llrt::RunTimeOptions::get_instance().get_feature_file_name(tt::llrt::RunTimeDebugFeatureDprint);
     bool one_file_per_risc =
         tt::llrt::RunTimeOptions::get_instance().get_feature_one_file_per_risc(tt::llrt::RunTimeDebugFeatureDprint);
+    bool prepend_device_core_risc =
+        tt::llrt::RunTimeOptions::get_instance().get_feature_prepend_device_core_risc(tt::llrt::RunTimeDebugFeatureDprint);
 
     // One file per risc auto-generates the output files and ignores the env var for it. Print a warning if both are
     // specified just in case.
@@ -475,6 +480,13 @@ DebugPrintServerContext::DebugPrintServerContext() {
             "TT_METAL_DPRINT_FILE_NAME will be ignored.");
     }
 
+    if (prepend_device_core_risc && one_file_per_risc) {
+        log_warning(
+            "Both TT_METAL_DPRINT_PREPEND_DEVICE_CORE_RISC and TT_METAL_DPRINT_ONE_FILE_PER_RISC are specified. "
+            "TT_METAL_DPRINT_PREPEND_DEVICE_CORE_RISC will be disabled.");
+        tt::llrt::RunTimeOptions::get_instance().set_feature_prepend_device_core_risc(tt::llrt::RunTimeDebugFeatureDprint, false);
+    }
+
     // Set the output stream according to RTOptions, either a file name or stdout if none specified.
     std::filesystem::path output_dir(tt::llrt::RunTimeOptions::get_instance().get_root_dir() + logfile_path);
     std::filesystem::create_directories(output_dir);
@@ -1190,12 +1202,36 @@ void DebugPrintServerContext::TransferIntermediateStreamsToOutputStreamAndFlush(
 
 void DebugPrintServerContext::TransferToAndFlushOutputStream(
     const HartKey& hart_key, ostringstream* intermediate_stream) {
-    const string& intermediate_stream_data = intermediate_stream->str();
+    const string& output_data = GetDataToOutput(hart_key, intermediate_stream);
     ostream* output_stream = GetOutputStream(hart_key);
-    *output_stream << intermediate_stream_data << flush;
+    *output_stream << output_data << flush;
     ResetStream(intermediate_stream);
 }  // TransferToAndFlushOutputStream
 
+string DebugPrintServerContext::GetDataToOutput(const HartKey& hart_key, const ostringstream* stream) {
+    string output;
+    const bool prepend_device_core_risc =
+        tt::llrt::RunTimeOptions::get_instance().get_feature_prepend_device_core_risc(tt::llrt::RunTimeDebugFeatureDprint);
+    if (prepend_device_core_risc) {
+        const chip_id_t device_id = get<0>(hart_key);
+        const CoreDescriptor& core_desc = get<1>(hart_key);
+        const uint32_t risc_id = get<2>(hart_key);
+
+        const string& device_id_str = to_string(device_id);
+        const string& core_coord_str = core_desc.coord.str();
+        const string& risc_name = GetRiscName(core_desc.type, risc_id, true);
+        output += fmt::format("{}:{}:{}: ", device_id_str, core_coord_str, risc_name);
+    }
+
+    if (stream->str().empty()) {
+        output = "";
+    } else {
+        output += stream->str();
+    }
+
+    return output;
+}
+
 ostream* DebugPrintServerContext::GetOutputStream(const HartKey& hart_key) {
     ostream* output_stream = stream_;
     if (tt::llrt::RunTimeOptions::get_instance().get_feature_one_file_per_risc(tt::llrt::RunTimeDebugFeatureDprint)) {

tt_metal/llrt/rtoptions.cpp

@@ -204,6 +204,7 @@ void RunTimeOptions::ParseFeatureEnv(RunTimeDebugFeatures feature) {
     ParseFeatureRiscvMask(feature, feature_env_prefix + "_RISCVS");
     ParseFeatureFileName(feature, feature_env_prefix + "_FILE");
     ParseFeatureOneFilePerRisc(feature, feature_env_prefix + "_ONE_FILE_PER_RISC");
+    ParseFeaturePrependDeviceCoreRisc(feature, feature_env_prefix + "_PREPEND_DEVICE_CORE_RISC");
 
     // Set feature enabled if the user asked for any feature cores
     feature_targets[feature].enabled = false;
@@ -356,6 +357,12 @@ void RunTimeOptions::ParseFeatureOneFilePerRisc(RunTimeDebugFeatures feature, co
     feature_targets[feature].one_file_per_risc = (env_var_str != nullptr);
 }
 
+void RunTimeOptions::ParseFeaturePrependDeviceCoreRisc(RunTimeDebugFeatures feature, const std::string &env_var) {
+    char *env_var_str = std::getenv(env_var.c_str());
+    feature_targets[feature].prepend_device_core_risc =
+        (env_var_str != nullptr) ? (strcmp(env_var_str, "1") == 0) : true;
+}
+
 }  // namespace llrt
 
 }  // namespace tt

tt_metal/llrt/rtoptions.hpp

@@ -81,6 +81,7 @@ struct TargetSelection {
     uint32_t riscv_mask = 0;
     std::string file_name;  // File name to write output to.
     bool one_file_per_risc = false;
+    bool prepend_device_core_risc;
 };
 
 class RunTimeOptions {
@@ -225,6 +226,12 @@ class RunTimeOptions {
     inline void set_feature_one_file_per_risc(RunTimeDebugFeatures feature, bool one_file_per_risc) {
         feature_targets[feature].one_file_per_risc = one_file_per_risc;
     }
+    inline bool get_feature_prepend_device_core_risc(RunTimeDebugFeatures feature) {
+        return feature_targets[feature].prepend_device_core_risc;
+    }
+    inline void set_feature_prepend_device_core_risc(RunTimeDebugFeatures feature, bool prepend_device_core_risc) {
+        feature_targets[feature].prepend_device_core_risc = prepend_device_core_risc;
+    }
     inline TargetSelection get_feature_targets(RunTimeDebugFeatures feature) { return feature_targets[feature]; }
     inline void set_feature_targets(RunTimeDebugFeatures feature, TargetSelection targets) {
         feature_targets[feature] = targets;
@@ -293,11 +300,12 @@ class RunTimeOptions {
 private:
     // Helper functions to parse feature-specific environment vaiables.
     void ParseFeatureEnv(RunTimeDebugFeatures feature);
-    void ParseFeatureCoreRange(RunTimeDebugFeatures feature, const std::string& env_var, CoreType core_type);
-    void ParseFeatureChipIds(RunTimeDebugFeatures feature, const std::string& env_var);
-    void ParseFeatureRiscvMask(RunTimeDebugFeatures feature, const std::string& env_var);
-    void ParseFeatureFileName(RunTimeDebugFeatures feature, const std::string& env_var);
-    void ParseFeatureOneFilePerRisc(RunTimeDebugFeatures feature, const std::string& env_var);
+    void ParseFeatureCoreRange(RunTimeDebugFeatures feature, const std::string &env_var, CoreType core_type);
+    void ParseFeatureChipIds(RunTimeDebugFeatures feature, const std::string &env_var);
+    void ParseFeatureRiscvMask(RunTimeDebugFeatures feature, const std::string &env_var);
+    void ParseFeatureFileName(RunTimeDebugFeatures feature, const std::string &env_var);
+    void ParseFeatureOneFilePerRisc(RunTimeDebugFeatures feature, const std::string &env_var);
+    void ParseFeaturePrependDeviceCoreRisc(RunTimeDebugFeatures feature, const std::string &env_var);
 
     // Helper function to parse watcher-specific environment variables.
     void ParseWatcherEnv();
@@ -315,9 +323,6 @@ class RunTimeOptions {
     bool watcher_feature_disabled(const std::string& name) {
         return watcher_disabled_features.find(name) != watcher_disabled_features.end();
     }
-
-    // Helper function to generate a message string when an environment variable has not been set
-    std::string generate_env_var_not_set_message(const std::string& env_var) const;
 };
 
 }  // namespace llrt