#12524: Update fmt and unify logging API (#12464)

#0: Update fmt and unify logging API

Our logging macros accept variadic arguments and print them as-is,
requiring callers to use fmt::format to prepare the arguments. But the
low-level log_fatal, log_warning and so on functions accept a runtime
format string.

This PR unifies the logging API by requiring users to always specify a
valid format string, and avoids runtime formatting.

Force-merging by @tt-rkim  because @TT-BrianLiu is out of office. Post-commit should be passing.

ErrorMessageBestPractices.md

@@ -1,5 +1,5 @@
 # Guidelines for Writing Effective Error Messages ✍️
-Clear and informative error messages are crucial for debugging and maintenance. A well-crafted error message can save hours of troubleshooting and make our codebase more user-friendly, especially for those less familiar with the system. 
+Clear and informative error messages are crucial for debugging and maintenance. A well-crafted error message can save hours of troubleshooting and make our codebase more user-friendly, especially for those less familiar with the system.
 
 A well-written error message provides the following information to the user:
 * What happened and why?
@@ -17,7 +17,7 @@ TT_FATAL(input_shape.rank() == 3, "Invalid input tensor dimensions.");
 ```
 Write:
 ```cpp
-TT_FATAL(input_shape.rank() == 3, fmt::format("Invalid input tensor: expected 3 dimensions, but found {}.", input_shape.rank()));
+TT_FATAL(input_shape.rank() == 3, "Invalid input tensor: expected 3 dimensions, but found {}.", input_shape.rank());
 ```
 ### 2. Explain the Issue
 Provide a brief explanation of why the error occurred or why the condition is important. This helps users understand the context of the error.
@@ -53,15 +53,15 @@ TT_FATAL(head_size % TILE_WIDTH != 0, "Head size is invalid.");
 ```
 Write:
 ```cpp
-TT_FATAL(head_size % TILE_WIDTH != 0, fmt::format("Invalid head size: {}. The head size must be a multiple of tile width ({}). Please adjust the dimensions accordingly.", head_size, TILE_WIDTH));
+TT_FATAL(head_size % TILE_WIDTH != 0, "Invalid head size: {}. The head size must be a multiple of tile width ({}). Please adjust the dimensions accordingly.", head_size, TILE_WIDTH);
 ```
 
 ## Good Example
 This message clearly states the problem, includes the actual value of head_size, and offers guidance on how to fix it.
 ```cpp
 TT_FATAL(head_size % TILE_WIDTH == 0,
-         fmt::format("Invalid head size: {}. The head size must be a multiple of the tile width ({}). Please adjust the dimensions accordingly.", 
-                     head_size, TILE_WIDTH));
+         "Invalid head size: {}. The head size must be a multiple of the tile width ({}). Please adjust the dimensions accordingly.",
+         head_size, TILE_WIDTH);
 ```
 
 ## Style recommendations

tests/tt_eager/ops/test_eltwise_unary_op.cpp

@@ -121,7 +121,7 @@ void test_operation_infrastructure() {
         false};
     ttnn::operations::unary::tensor_args_t tensor_args {input_tensor};
     auto program_hash = ttnn::operations::unary::UnaryDeviceOperation::compute_program_hash(op_args, tensor_args);
-    TT_FATAL(program_hash == 3018574135764717736ULL, fmt::format("Actual value is {}", program_hash));
+    TT_FATAL(program_hash == 3018574135764717736ULL, "Actual value is {}", program_hash);
 
     TT_FATAL(tt::tt_metal::CloseDevice(device), "Error");
 }

tests/tt_eager/ops/test_sliding_window_ops.cpp

@@ -76,7 +76,7 @@ uint32_t validate_generate_halo_kernel_config(
             if (pad_metadata[idx] != val) {
                 invalids++;
                 log_info(
-                    tt::LogTest, "Error at index = {}, Expected = {}, Calculated = {}", idx, val, pad_metadata[idx]);
+                    tt::LogTest, "Error at index = {}, Expected = {}, Calculated = {}", idx, val, bool(pad_metadata[idx]));
             }
         }
         return invalids;
@@ -155,7 +155,7 @@ uint32_t validate_generate_functions(
     if (ref_pad_metadata != pad_metadata) {
         for (auto i = 0; i < ref_pad_metadata.size(); i++) {
             if (ref_pad_metadata[i] != pad_metadata[i])
-                log_info(tt::LogTest, "Error at i = {}, Calculated = {}", i, ref_pad_metadata[i]);
+                log_info(tt::LogTest, "Error at i = {}, Calculated = {}", i, bool(ref_pad_metadata[i]));
         }
         log_error(
             tt::LogTest,

tests/tt_eager/ops/test_tilize_zero_padding.cpp

@@ -62,7 +62,7 @@ int main(int argc, char **argv) {
         for(uint32_t i = 0; i < result_vec.size() ; i++) {
             if(result_vec[i] != golden_vec[i]) {
                 if(num_errors < 10)
-                    log_error(LogTest, "Error at i={} result={} golden={}", i, result_vec[i], golden_vec[i]);
+                    log_error(LogTest, "Error at i={} result={} golden={}", i, result_vec[i].to_float(), golden_vec[i].to_float());
                 num_errors++;
             }
         }

tests/tt_eager/ops/test_tilize_zero_padding_channels_last.cpp

@@ -63,7 +63,7 @@ int main(int argc, char **argv) {
         for(uint32_t i = 0; i < result_vec.size() ; i++) {
             if(result_vec[i] != golden_vec[i]) {
                 if(num_errors < 10)
-                    log_error(LogTest, "Error at i={} result={} golden={}", i, result_vec[i], golden_vec[i]);
+                    log_error(LogTest, "Error at i={} result={} golden={}", i, result_vec[i].to_float(), golden_vec[i].to_float());
                 num_errors++;
             }
         }

tests/tt_metal/test_utils/env_vars.hpp

@@ -14,7 +14,7 @@ inline std::string get_env_arch_name() {
     if (const char* arch_name_ptr = std::getenv(ARCH_NAME_ENV_VAR.data())) {
         arch_name = arch_name_ptr;
     } else {
-        TT_THROW("Env var " + std::string(ARCH_NAME_ENV_VAR) + " is not set.");
+        TT_THROW("Env var {} is not set.", ARCH_NAME_ENV_VAR);
     }
     return arch_name;
 }

tests/tt_metal/tt_metal/perf_microbenchmark/dispatch/test_dispatcher.cpp

@@ -539,7 +539,7 @@ int main(int argc, char **argv) {
             log_info(LogTest, "Running packed write unicast");
             break;
         case 5:
-            log_info(LogTest, "Running alternate packed write unicast");
+            log_info(LogTest, "Running packed write large unicast");
             break;
         }
 

tests/tt_metal/tt_metal/perf_microbenchmark/ethernet/test_ethernet_hop_latencies_no_edm.cpp

@@ -439,7 +439,7 @@ int main (int argc, char** argv) {
                 return std::vector<Device*>{all_devices[0], all_devices[4], all_devices[5], all_devices[1], all_devices[2], all_devices[3], all_devices[0], all_devices[1], all_devices[2], all_devices[6], all_devices[7], all_devices[3]};
 
             default:
-                TT_ASSERT("Unsupported hop_count");
+                TT_THROW("Unsupported hop_count");
                 return std::vector<Device*>{};
         };
     };

tests/tt_metal/tt_metal/test_bcast.cpp

@@ -40,7 +40,7 @@ const char* get_reader_name(bool multibank, BcastDim::Enum bcast_dim) {
             "tests/tt_metal/tt_metal/test_kernels/dataflow/reader_bcast_hw_8bank.cpp" :
             "tt_metal/kernels/dataflow/reader_binary_diff_lengths.cpp";
     }
-    TT_FATAL(false && "Unexpected bcast_dim!", "Error");
+    TT_THROW("Unexpected bcast_dim!");
     return "";
 }
 
@@ -49,7 +49,7 @@ const char* get_compute_name(BcastDim::Enum bcast_dim) {
         case BcastDim::H:  return "tests/tt_metal/tt_metal/test_kernels/compute/bcast_h.cpp";
         case BcastDim::W:  return "tests/tt_metal/tt_metal/test_kernels/compute/bcast_w.cpp";
         case BcastDim::HW: return "tests/tt_metal/tt_metal/test_kernels/compute/bcast_hw.cpp";
-        default:           TT_FATAL(false && "Unexpected bcast_dim!", "Error");
+        default:           TT_THROW("Unexpected bcast_dim!");
     }
     return "";
 }

tests/tt_metal/tt_metal/test_clean_init.cpp

@@ -142,7 +142,7 @@ int main(int argc, char **argv) {
 
     // Skip teardown by throwing.
     if (skip_teardown) {
-        TT_FATAL(false, "Skip teardown by throwing");
+        TT_THROW("Skip teardown by throwing");
     } else {
         for (auto device : devices) {
             pass &= CloseDevice(device);

tests/tt_metal/tt_metal/test_compile_args.cpp

@@ -91,7 +91,7 @@ int main(int argc, char **argv) {
                     } else if (line.find("ARG_0=1,ARG_1=5,ARG_2=0,ARG_3=124") != std::string::npos) {
                         num_found++;
                     } else {
-                        TT_FATAL(false, "Expected kernel_args.csv to contain the compile args for test_compile_args");
+                        TT_THROW("Expected kernel_args.csv to contain the compile args for test_compile_args");
                     }
                 }
             }

tests/tt_metal/tt_metal/test_compile_program.cpp

@@ -151,7 +151,7 @@ void assert_kernel_binary_path_exists(const Program &program, int build_key, con
         auto kernel = detail::GetKernel(program, kernel_id);
         auto hash = kernel_name_to_hash.at(kernel->name());
         auto kernel_binary_path = jit_build_get_kernel_compile_outpath(build_key) + kernel->name() + "/" + hash;
-        TT_FATAL(std::filesystem::exists(kernel_binary_path), "Expected " + kernel_binary_path + " folder to exist!");
+        TT_FATAL(std::filesystem::exists(kernel_binary_path), "Expected {} folder to exist!", kernel_binary_path);
     }
 }
 
@@ -160,14 +160,14 @@ void assert_program_cache_hit_status(const Program &program, bool hit_expected,
     for (size_t kernel_id = 0; kernel_id < program.num_kernels(); kernel_id++) {
         auto kernel = detail::GetKernel(program, kernel_id);
         auto hit_status = kernel_name_to_cache_hit_status.at(kernel->name());
-        TT_FATAL(hit_status == hit_expected, "Did not get expected cache status " + std::to_string(hit_expected) + " for kernel " + kernel->name());
+        TT_FATAL(hit_status == hit_expected, "Did not get expected cache status {} for kernel {}", hit_expected, kernel->name());
     }
 }
 
 void assert_kernel_hash_matches(const std::unordered_map<std::string, std::string> &golden_kernel_name_to_hash, const KernelCacheStatus &kernel_cache_status) {
     for (const auto &[kernel_name, hash] : kernel_cache_status.kernel_name_to_hash_str) {
         auto expected_hash = golden_kernel_name_to_hash.at(kernel_name);
-        TT_FATAL(hash == expected_hash, "Expected hash for " + kernel_name + " " + expected_hash + " but got " + hash);
+        TT_FATAL(hash == expected_hash, "Expected hash for {} {} but got {}", kernel_name, expected_hash, hash);
     }
 }
 
@@ -231,9 +231,9 @@ void assert_hash_comparison_for_kernel_type(
         auto curr_hash = curr_kernel_name_to_hash.at(kernel->name());
         bool same_hash_expected = type_to_same_hash_expected.at(kernel->processor());
         if (same_hash_expected) {
-            TT_FATAL(prev_hash == curr_hash, "Expected same hashes for " + kernel->name());
+            TT_FATAL(prev_hash == curr_hash, "Expected same hashes for {}", kernel->name());
         } else {
-            TT_FATAL(prev_hash != curr_hash, "Expected different hashes for " + kernel->name());
+            TT_FATAL(prev_hash != curr_hash, "Expected different hashes for {}", kernel->name());
         }
     }
 }
@@ -244,7 +244,7 @@ void assert_cache_hit_status_for_kernel_type(const Program &program, const std::
         auto kernel = detail::GetKernel(program, kernel_id);
         bool hit_expected = type_to_cache_hit_status.at(kernel->processor());
         auto hit_status = kernel_name_to_cache_hit_status.at(kernel->name());
-        TT_FATAL(hit_status == hit_expected, "Did not get expected cache status " + std::to_string(hit_expected) + " for kernel " + kernel->name());
+        TT_FATAL(hit_status == hit_expected, "Did not get expected cache status {} for kernel {}", hit_expected, kernel->name());
     }
 }
 

tests/tt_metal/tt_metal/test_compile_sets_kernel_binaries.cpp

@@ -212,8 +212,7 @@ int main(int argc, char **argv) {
                             ll_api::memory trisc_binary = llrt::get_risc_binary(trisc_hex_path);
                             TT_FATAL(
                                 trisc_binary == compute_binaries.at(mask).at(trisc_id),
-                                "Expected saved TRISC binary for " + trisc_id_str +
-                                    " to be the same as binary in persistent cache");
+                                "Expected saved TRISC binary for {} to be the same as binary in persistent cache", trisc_id_str);
                         }
                     }
                 });

tests/tt_metal/tt_metal/test_gold_impls.hpp

@@ -97,7 +97,7 @@ inline std::vector<uint16_t> gold_bcast_op(
             case BcastDim::W:  b_index = h + c*H + n*C*H; break; // bcast tensor is nch
             case BcastDim::HW: b_index = c + n*C; break; // bcast tensor is nc
             default:
-            TT_FATAL(false && "Unexpected broadcast mode in gold_bcast_op", "Error");
+            TT_THROW("Unexpected broadcast mode in gold_bcast_op");
         }
         float bval = bfloat16(bcast_vals[b_index]).to_float();
         float result1 = 0.0f;
@@ -106,7 +106,7 @@ inline std::vector<uint16_t> gold_bcast_op(
             case BcastOp::SUB: result1 = bfloat16(src_vec[offs]).to_float() - bval; break;
             case BcastOp::MUL: result1 = bfloat16(src_vec[offs]).to_float() * bval; break;
             default:
-                TT_FATAL(false && "Unexpected bcast_op", "Error");
+                TT_THROW("Unexpected bcast_op");
         }
         result[offs] = bfloat16(result1).to_uint16();
     }

tests/tt_metal/tt_metal/test_multiple_programs.cpp

@@ -27,7 +27,7 @@ std::map<string, string> get_defines(BinaryOpType::Enum op_type){
         case BinaryOpType::ADD: op_name = "add_tiles"; op_binary_type = "EltwiseBinaryType::ELWADD"; break;
         case BinaryOpType::SUB: op_name = "sub_tiles"; op_binary_type = "EltwiseBinaryType::ELWSUB"; break;
         case BinaryOpType::MUL: op_name = "mul_tiles"; op_binary_type = "EltwiseBinaryType::ELWMUL"; break;
-        default: TT_FATAL(false && "Undefined op type", "Error");
+        default: TT_THROW("Undefined op type");
     }
     defines["ELTWISE_OP"] = op_name.c_str();
     defines["ELTWISE_OP_TYPE"] = op_binary_type.c_str();

tests/tt_metal/tt_metal/test_untilize_eltwise_binary.cpp

@@ -41,15 +41,15 @@ inline std::vector<uint32_t> gold_standard_untilize(std::vector<uint32_t> src_ve
                     // Left face row copy
                     for (int k = 0; k < 8; k++) {
                         int idx = physical_start_for_tile_row + i * 8 + k + j * tile_size;
-                        TT_FATAL(ind.find(idx) == ind.end(), t);
+                        TT_FATAL(ind.find(idx) == ind.end(), "{}", t);
                         ind.insert(idx);
                         dst_vec.push_back(src_vec.at(idx));
                     }
 
                     // Right face row copy
                     for (int k = 0; k < 8; k++) {
                         int idx = physical_start_for_tile_row + i * 8 + k + face_size + j * tile_size;
-                        TT_FATAL(ind.find(idx) == ind.end(), t);
+                        TT_FATAL(ind.find(idx) == ind.end(), "{}", t);
                         ind.insert(idx);
                         dst_vec.push_back(src_vec.at(idx));
                     }

tests/tt_metal/tt_metal/unit_tests/compute/test_golden_impls.cpp

@@ -49,7 +49,7 @@ std::vector<uint32_t> gold_standard_untilize(const std::vector<uint32_t> &src_ve
                     // Left face row copy
                     for (int k = 0; k < num_c_dim; k++) {
                         int idx = physical_start_for_tile_row + i * num_c_dim + k + j * tile_size;
-                        TT_FATAL(ind.find(idx) == ind.end(), t);
+                        TT_FATAL(ind.find(idx) == ind.end(), "{}", t);
                         ind.insert(idx);
                         dst_vec.push_back(src_vec.at(idx));
                     }
@@ -58,7 +58,7 @@ std::vector<uint32_t> gold_standard_untilize(const std::vector<uint32_t> &src_ve
                         // Right face row copy
                         for (int k = 0; k < num_c_dim; k++) {
                             int idx = physical_start_for_tile_row + i * num_c_dim + k + face_size + j * tile_size;
-                            TT_FATAL(ind.find(idx) == ind.end(), t);
+                            TT_FATAL(ind.find(idx) == ind.end(), "{}", t);
                             ind.insert(idx);
                             dst_vec.push_back(src_vec.at(idx));
                         }

tests/tt_metal/tt_metal/unit_tests/compute/test_reduce.cpp

@@ -143,7 +143,7 @@ void add_reader_writer_kernels(tt_metal::Program &program, const CoreCoord &logi
             break;
         }
         default:
-            TT_FATAL(false, "Unsupported reduce dim!");
+            TT_THROW("Unsupported reduce dim!");
     }
 }
 
@@ -154,7 +154,7 @@ std::string get_reduce_dim_define_string(const ReduceDim &reduce_dim) {
         case ReduceDim::W: reduce_dim_define_str = "ReduceDim::REDUCE_ROW"; break;
         case ReduceDim::HW: reduce_dim_define_str = "ReduceDim::REDUCE_SCALAR"; break;
         default:
-            TT_FATAL(false, "Unsupported reduce dim!");
+            TT_THROW("Unsupported reduce dim!");
     }
     return reduce_dim_define_str;
 }
@@ -166,7 +166,7 @@ std::string get_compute_kernel_name(const ReduceDim &reduce_dim) {
         case ReduceDim::W: compute_kernel_name = "tests/tt_metal/tt_metal/test_kernels/compute/reduce_w.cpp"; break;
         case ReduceDim::HW: compute_kernel_name = "tests/tt_metal/tt_metal/test_kernels/compute/reduce_hw.cpp"; break;
         default:
-            TT_FATAL(false, "Unsupported reduce dim!");
+            TT_THROW("Unsupported reduce dim!");
     }
     return compute_kernel_name;
 }
@@ -190,7 +190,7 @@ void run_single_core_reduce_program(tt_metal::Device* device, const ReduceConfig
         case ReduceDim::W: num_golden_elements = NC*H*TILE_WIDTH/2; break; // expecting one tile in H, and half the elements since the vector packs 2 uint16_ts
         case ReduceDim::HW: num_golden_elements = NC*32*32/2; break; // expecting one tile in H, and half the elements since the vector packs 2 uint16_ts
         default:
-            TT_FATAL(false, "Unsupported reduce dim!");
+            TT_THROW("Unsupported reduce dim!");
     }
 
     float scaler = (test_config.do_max or test_config.reduce_dim == ReduceDim::HW) ? 1.0f : (test_config.reduce_dim == ReduceDim::H ? 1.0f/H : 1.0f/W);
@@ -218,7 +218,7 @@ void run_single_core_reduce_program(tt_metal::Device* device, const ReduceConfig
         case ReduceDim::W: output_size_bytes = dram_buffer_size / Wt; break;
         case ReduceDim::HW: output_size_bytes = dram_buffer_size / (Ht * Wt); break;
         default:
-            TT_FATAL(false, "Unsupported reduce dim!");
+            TT_THROW("Unsupported reduce dim!");
     }
 
     tt_metal::InterleavedBufferConfig dst_config{

tests/tt_metal/tt_metal/unit_tests_common/compute/matmul/test_matmul_multi_core_X_dram.cpp

@@ -197,9 +197,21 @@ bool matmul_multi_core_single_dram(tt_metal::Device *device){
             uint32_t dram_buffer_size_weights = single_tile_size * K * per_core_N; // num_tiles of FP16_B, hard-coded in the reader/writer kernels
             uint32_t dram_buffer_size_out = single_tile_size * per_core_M * per_core_N; // num_tiles of FP16_B, hard-coded in the reader/writer kernels
 
-            TT_FATAL(dram_buffer_src0_addr + dram_buffer_size_act < 1024 * 1024 * 1024, "addr {} + size {} too large", dram_buffer_src0_addr, dram_buffer_size_act);
-            TT_FATAL(dram_buffer_src1_addr + dram_buffer_size_weights < 1024 * 1024 * 1024, dram_buffer_src1_addr, dram_buffer_size_weights);
-            TT_FATAL(dram_buffer_dst_addr + dram_buffer_size_out < 1024 * 1024 * 1024, dram_buffer_dst_addr, dram_buffer_size_out);
+            TT_FATAL(
+                dram_buffer_src0_addr + dram_buffer_size_act < 1024 * 1024 * 1024,
+                "addr {} + size {} too large",
+                dram_buffer_src0_addr,
+                dram_buffer_size_act);
+            TT_FATAL(
+                dram_buffer_src1_addr + dram_buffer_size_weights < 1024 * 1024 * 1024,
+                "addr {} + size {} too large",
+                dram_buffer_src1_addr,
+                dram_buffer_size_weights);
+            TT_FATAL(
+                dram_buffer_dst_addr + dram_buffer_size_out < 1024 * 1024 * 1024,
+                "addr {} + size {} too large",
+                dram_buffer_dst_addr,
+                dram_buffer_size_out);
 
             auto dram_src0_noc_xy = device->dram_core_from_dram_channel(dram_src0_channel_id);
             auto dram_src1_noc_xy = device->dram_core_from_dram_channel(dram_src1_channel_id);

tests/tt_metal/tt_metal/unit_tests_fast_dispatch/command_queue/test_EnqueueProgram.cpp

@@ -1382,7 +1382,7 @@ TEST_F(CommandQueueFixture, TestRandomizedProgram) {
                 SetRuntimeArgs(program, dummy_trisc_kernel, cr_set, trisc_unique_rtargs);
                 SetCommonRuntimeArgs(program, dummy_trisc_kernel, trisc_common_rtargs);
             } else {
-                TT_ASSERT("Invalid");
+                TT_THROW("Invalid");
             }
         }