From df3676be2121f7745695d17924a71e3269615b11 Mon Sep 17 00:00:00 2001 From: AShivangi <124935354+AShivangi@users.noreply.github.com> Date: Tue, 4 Jun 2024 23:18:40 +0530 Subject: [PATCH] hide extra validate details in verbose (#8210) Signed-off-by: AShivangi --- .../core/tools/common/tests/TestDF_bandwidth.cpp | 12 ++++++++---- .../core/tools/common/tests/TestGemm.cpp | 12 +++++++----- .../core/tools/common/tests/TestNPULatency.cpp | 9 ++++++--- .../core/tools/common/tests/TestNPUThroughput.cpp | 11 +++++++---- .../core/tools/common/tests/TestTCTAllColumn.cpp | 12 ++++++++---- .../core/tools/common/tests/TestTCTOneColumn.cpp | 13 ++++++++----- 6 files changed, 44 insertions(+), 25 deletions(-) diff --git a/src/runtime_src/core/tools/common/tests/TestDF_bandwidth.cpp b/src/runtime_src/core/tools/common/tests/TestDF_bandwidth.cpp index 4542cd2cd15..596a8a47344 100644 --- a/src/runtime_src/core/tools/common/tests/TestDF_bandwidth.cpp +++ b/src/runtime_src/core/tools/common/tests/TestDF_bandwidth.cpp @@ -111,7 +111,8 @@ TestDF_bandwidth::run(std::shared_ptr dev) return ptree; } auto kernelName = xkernel.get_name(); - logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); auto working_dev = xrt::device(dev); working_dev.register_xclbin(xclbin); @@ -152,8 +153,10 @@ TestDF_bandwidth::run(std::shared_ptr dev) bo_ifm.sync(XCL_BO_SYNC_BO_TO_DEVICE); //Log - logger(ptree, "Details", boost::str(boost::format("Buffer size: '%f'GB") % buffer_size_gb)); - logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); + if(XBU::getVerbose()) { + logger(ptree, "Details", boost::str(boost::format("Buffer size: '%f'GB") % buffer_size_gb)); + logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); + } auto start = std::chrono::high_resolution_clock::now(); for (int i = 0; i < itr_count; i++) { @@ -185,7 +188,8 @@ TestDF_bandwidth::run(std::shared_ptr dev) float elapsedSecs = std::chrono::duration_cast>(end-start).count(); //Data is read and written in parallel hence x2 float bandwidth = (buffer_size_gb*itr_count*2) / elapsedSecs; - logger(ptree, "Details", boost::str(boost::format("Total duration: '%.1f's") % elapsedSecs)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Total duration: '%.1f's") % elapsedSecs)); logger(ptree, "Details", boost::str(boost::format("Average bandwidth per shim DMA: '%.1f' GB/s") % bandwidth)); ptree.put("status", test_token_passed); diff --git a/src/runtime_src/core/tools/common/tests/TestGemm.cpp b/src/runtime_src/core/tools/common/tests/TestGemm.cpp index 124b672e063..a3a138aca37 100644 --- a/src/runtime_src/core/tools/common/tests/TestGemm.cpp +++ b/src/runtime_src/core/tools/common/tests/TestGemm.cpp @@ -134,7 +134,8 @@ TestGemm::run(std::shared_ptr dev) if (!std::filesystem::exists(dpu_instr)) return ptree; - logger(ptree, "DPU-Sequence", dpu_instr); + if(XBU::getVerbose()) + logger(ptree, "DPU-Sequence", dpu_instr); size_t instr_size = 0; try { @@ -219,10 +220,11 @@ TestGemm::run(std::shared_ptr dev) //reset the performance mode xrt_core::device_update(dev.get(), static_cast(perf_mode)); - - logger(ptree, "Details", boost::str(boost::format("Total Duration: '%.1f' ns") % (ipu_hclck_period * (total_cycle_count/num_of_cores)))); - logger(ptree, "Details", boost::str(boost::format("Average cycle count: '%.1f'") % (total_cycle_count/num_of_cores))); - logger(ptree, "Details", boost::str(boost::format("IPU H-Clock: '%f' MHz") % ipu_hclock)); + if(XBU::getVerbose()) { + logger(ptree, "Details", boost::str(boost::format("Total Duration: '%.1f' ns") % (ipu_hclck_period * (total_cycle_count/num_of_cores)))); + logger(ptree, "Details", boost::str(boost::format("Average cycle count: '%.1f'") % (total_cycle_count/num_of_cores))); + logger(ptree, "Details", boost::str(boost::format("NPU H-Clock: '%f' MHz") % ipu_hclock)); + } logger(ptree, "Details", boost::str(boost::format("TOPS: '%.1f'") % TOPS)); ptree.put("status", test_token_passed); diff --git a/src/runtime_src/core/tools/common/tests/TestNPULatency.cpp b/src/runtime_src/core/tools/common/tests/TestNPULatency.cpp index 23181467e01..19cc0ae6ee6 100644 --- a/src/runtime_src/core/tools/common/tests/TestNPULatency.cpp +++ b/src/runtime_src/core/tools/common/tests/TestNPULatency.cpp @@ -61,7 +61,8 @@ TestNPULatency::run(std::shared_ptr dev) return ptree; } auto kernelName = xkernel.get_name(); - logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); auto working_dev = xrt::device(dev); working_dev.register_xclbin(xclbin); @@ -87,8 +88,10 @@ TestNPULatency::run(std::shared_ptr dev) bo_mc.sync(XCL_BO_SYNC_BO_TO_DEVICE); //Log - logger(ptree, "Details", boost::str(boost::format("Instruction size: '%f' bytes") % buffer_size)); - logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); + if(XBU::getVerbose()) { + logger(ptree, "Details", boost::str(boost::format("Instruction size: '%f' bytes") % buffer_size)); + logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); + } // Run the test to compute latency where we submit one job at a time and wait for its completion before // we submit the next one diff --git a/src/runtime_src/core/tools/common/tests/TestNPUThroughput.cpp b/src/runtime_src/core/tools/common/tests/TestNPUThroughput.cpp index 88e26150a13..c983f74a515 100644 --- a/src/runtime_src/core/tools/common/tests/TestNPUThroughput.cpp +++ b/src/runtime_src/core/tools/common/tests/TestNPUThroughput.cpp @@ -60,7 +60,8 @@ TestNPUThroughput::run(std::shared_ptr dev) return ptree; } auto kernelName = xkernel.get_name(); - logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); auto working_dev = xrt::device(dev); working_dev.register_xclbin(xclbin); @@ -86,8 +87,10 @@ TestNPUThroughput::run(std::shared_ptr dev) bo_mc.sync(XCL_BO_SYNC_BO_TO_DEVICE); //Log - logger(ptree, "Details", boost::str(boost::format("Instruction size: '%f' bytes") % buffer_size)); - logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count_throughput)); + if(XBU::getVerbose()) { + logger(ptree, "Details", boost::str(boost::format("Instruction size: '%f' bytes") % buffer_size)); + logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count_throughput)); + } // Run the test to compute throughput where we saturate NPU with jobs and then wait for all // completions at the end @@ -111,7 +114,7 @@ TestNPUThroughput::run(std::shared_ptr dev) // Compute the throughput const double throughput = (elapsedSecs != 0.0) ? runhandles.size() / elapsedSecs : 0.0; - logger(ptree, "Details", boost::str(boost::format("Average throughput: '%.1f' ops/s") % throughput)); + logger(ptree, "Details", boost::str(boost::format("Average throughput: '%.1f' ops") % throughput)); ptree.put("status", test_token_passed); return ptree; } diff --git a/src/runtime_src/core/tools/common/tests/TestTCTAllColumn.cpp b/src/runtime_src/core/tools/common/tests/TestTCTAllColumn.cpp index 2a92fbf16dc..fe2e1fd6985 100644 --- a/src/runtime_src/core/tools/common/tests/TestTCTAllColumn.cpp +++ b/src/runtime_src/core/tools/common/tests/TestTCTAllColumn.cpp @@ -107,7 +107,8 @@ TestTCTAllColumn::run(std::shared_ptr dev) return ptree; } auto kernelName = xkernel.get_name(); - logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); auto working_dev = xrt::device(dev); working_dev.register_xclbin(xclbin); @@ -148,8 +149,10 @@ TestTCTAllColumn::run(std::shared_ptr dev) bo_ifm.sync(XCL_BO_SYNC_BO_TO_DEVICE); //Log - logger(ptree, "Details", boost::str(boost::format("Buffer size: '%f' bytes") % buffer_size)); - logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); + if(XBU::getVerbose()) { + logger(ptree, "Details", boost::str(boost::format("Buffer size: '%f' bytes") % buffer_size)); + logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); + } auto start = std::chrono::high_resolution_clock::now(); try { @@ -179,7 +182,8 @@ TestTCTAllColumn::run(std::shared_ptr dev) float elapsedSecs = std::chrono::duration_cast>(end-start).count(); float throughput = itr_count / elapsedSecs; float latency = (elapsedSecs / itr_count) * 1000000; //convert s to us - logger(ptree, "Details", boost::str(boost::format("Average time for TCT: '%.1f' us") % latency)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Average time for TCT: '%.1f' us") % latency)); logger(ptree, "Details", boost::str(boost::format("Average TCT throughput: '%.1f' TCT/s") % throughput)); ptree.put("status", test_token_passed); diff --git a/src/runtime_src/core/tools/common/tests/TestTCTOneColumn.cpp b/src/runtime_src/core/tools/common/tests/TestTCTOneColumn.cpp index 78add9e722d..2e863f77f06 100644 --- a/src/runtime_src/core/tools/common/tests/TestTCTOneColumn.cpp +++ b/src/runtime_src/core/tools/common/tests/TestTCTOneColumn.cpp @@ -107,7 +107,8 @@ TestTCTOneColumn::run(std::shared_ptr dev) return ptree; } auto kernelName = xkernel.get_name(); - logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Kernel name is '%s'") % kernelName)); auto working_dev = xrt::device(dev); working_dev.register_xclbin(xclbin); @@ -148,9 +149,10 @@ TestTCTOneColumn::run(std::shared_ptr dev) bo_ifm.sync(XCL_BO_SYNC_BO_TO_DEVICE); //Log - logger(ptree, "Details", boost::str(boost::format("Buffer size: '%f'bytes") % buffer_size)); - logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); - + if(XBU::getVerbose()) { + logger(ptree, "Details", boost::str(boost::format("Buffer size: '%f'bytes") % buffer_size)); + logger(ptree, "Details", boost::str(boost::format("No. of iterations: '%f'") % itr_count)); + } auto start = std::chrono::high_resolution_clock::now(); try { auto run = kernel(host_app, bo_ifm, NULL, bo_ofm, NULL, bo_instr, instr_size, NULL); @@ -179,7 +181,8 @@ TestTCTOneColumn::run(std::shared_ptr dev) float elapsedSecs = std::chrono::duration_cast>(end-start).count(); float throughput = itr_count / elapsedSecs; float latency = (elapsedSecs / itr_count) * 1000000; //convert s to us - logger(ptree, "Details", boost::str(boost::format("Average time for TCT: '%.1f' us") % latency)); + if(XBU::getVerbose()) + logger(ptree, "Details", boost::str(boost::format("Average time for TCT: '%.1f' us") % latency)); logger(ptree, "Details", boost::str(boost::format("Average TCT throughput: '%.1f' TCT/s") % throughput)); ptree.put("status", test_token_passed);