From b6bf2fa29dc0fd26a540684fc383788ec0e10ec3 Mon Sep 17 00:00:00 2001 From: Yi Li Date: Tue, 30 Nov 2021 00:05:45 -0500 Subject: [PATCH 1/5] add time recording feature for ilator debugging --- src/target-sc/ilator.cc | 17 ++++++++++++----- 1 file changed, 12 insertions(+), 5 deletions(-) diff --git a/src/target-sc/ilator.cc b/src/target-sc/ilator.cc index 4f76ffc93..42651e89d 100644 --- a/src/target-sc/ilator.cc +++ b/src/target-sc/ilator.cc @@ -483,7 +483,8 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { fmt::format_to( // headers buff, "#include \n" - "#include <{project}.h>\n", + "#include <{project}.h>\n" + "#include \n", // add chrono to record time for debugging fmt::arg("project", GetProjectName())); fmt::format_to( // logging @@ -495,9 +496,10 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { "void {project}::IncrementInstrCntr() {{\n" " instr_cntr++;\n" "}}\n" - "void {project}::LogInstrSequence(const std::string& instr_name) {{\n" + "void {project}::LogInstrSequence(const std::string& instr_name, const long int& exec_time) {{\n" " instr_log << \"Instr No.\" << std::setw(5) << GetInstrCntr() << '\\t';\n" - " instr_log << instr_name << \" is activated\\n\";\n" + " instr_log << instr_name << \" is activated\\t\";\n" + " instr_log << \"exec_time: \" << exec_time * 1e-3 << \" ms\\n\";\n" " IncrementInstrCntr();\n" "}}\n", fmt::arg("project", GetProjectName())); @@ -524,10 +526,15 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { fmt::format_to( buff, "if ({valid_func_name}() && {decode_func_name}()) {{\n" + "#ifdef ILATOR_VERBOSE\n" + " auto start = std::chrono::high_resolution_clock::now();\n" + "#endif\n" " {update_func_name}();\n" " {child_counter}" "#ifdef ILATOR_VERBOSE\n" - " LogInstrSequence(\"{instr_name}\");\n" + " auto stop = std::chrono::high_resolution_clock::now();\n" + " auto exec_time = std::chrono::duration_cast(stop-start).count();\n" + " LogInstrSequence(\"{instr_name}\", exec_time);\n" "#endif\n" "}}\n", fmt::arg("valid_func_name", GetValidFuncName(instr->host())), @@ -583,7 +590,7 @@ bool Ilator::GenerateGlobalHeader(const std::string& dir) { " std::ofstream instr_update_log;\n" // add instruction state update logging " int GetInstrCntr();\n" " void IncrementInstrCntr();\n" - " void LogInstrSequence(const std::string& instr_name);\n", + " void LogInstrSequence(const std::string& instr_name, const long int&);\n", fmt::arg("project", GetProjectName())); // input From 4e7a5f5edec3055817be8cf56d7f5d84175b4ace Mon Sep 17 00:00:00 2001 From: Yi Li Date: Tue, 30 Nov 2021 12:13:03 -0500 Subject: [PATCH 2/5] fixed instr log format for profiling --- src/target-sc/ilator.cc | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/target-sc/ilator.cc b/src/target-sc/ilator.cc index 42651e89d..644968865 100644 --- a/src/target-sc/ilator.cc +++ b/src/target-sc/ilator.cc @@ -497,7 +497,7 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { " instr_cntr++;\n" "}}\n" "void {project}::LogInstrSequence(const std::string& instr_name, const long int& exec_time) {{\n" - " instr_log << \"Instr No.\" << std::setw(5) << GetInstrCntr() << '\\t';\n" + " instr_log << \"Instr No. \" << std::setw(8) << GetInstrCntr() << '\\t';\n" " instr_log << instr_name << \" is activated\\t\";\n" " instr_log << \"exec_time: \" << exec_time * 1e-3 << \" ms\\n\";\n" " IncrementInstrCntr();\n" From 865d7c95e6592a87f50793a9cad4eaf4acb3e244 Mon Sep 17 00:00:00 2001 From: Yi Li Date: Fri, 14 Jan 2022 11:47:11 -0500 Subject: [PATCH 3/5] changed the time unit to nanosecond for finer-grain profiling --- src/target-sc/ilator.cc | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/target-sc/ilator.cc b/src/target-sc/ilator.cc index 644968865..7202ccf80 100644 --- a/src/target-sc/ilator.cc +++ b/src/target-sc/ilator.cc @@ -499,7 +499,7 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { "void {project}::LogInstrSequence(const std::string& instr_name, const long int& exec_time) {{\n" " instr_log << \"Instr No. \" << std::setw(8) << GetInstrCntr() << '\\t';\n" " instr_log << instr_name << \" is activated\\t\";\n" - " instr_log << \"exec_time: \" << exec_time * 1e-3 << \" ms\\n\";\n" + " instr_log << \"exec_time: \" << exec_time * 1e-6 << \" ms\\n\";\n" " IncrementInstrCntr();\n" "}}\n", fmt::arg("project", GetProjectName())); @@ -530,10 +530,10 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { " auto start = std::chrono::high_resolution_clock::now();\n" "#endif\n" " {update_func_name}();\n" - " {child_counter}" + " {child_counter}\n" "#ifdef ILATOR_VERBOSE\n" " auto stop = std::chrono::high_resolution_clock::now();\n" - " auto exec_time = std::chrono::duration_cast(stop-start).count();\n" + " auto exec_time = std::chrono::duration_cast(stop-start).count();\n" " LogInstrSequence(\"{instr_name}\", exec_time);\n" "#endif\n" "}}\n", From f544a48ec0b7a9b09d69253f0df0c4264eb3ae2e Mon Sep 17 00:00:00 2001 From: Yi Li Date: Fri, 14 Jan 2022 14:34:09 -0500 Subject: [PATCH 4/5] separate ilator instr time profiling and instr update logging --- src/target-sc/ilator.cc | 15 +++++++++------ 1 file changed, 9 insertions(+), 6 deletions(-) diff --git a/src/target-sc/ilator.cc b/src/target-sc/ilator.cc index 7202ccf80..6a28a8269 100644 --- a/src/target-sc/ilator.cc +++ b/src/target-sc/ilator.cc @@ -499,7 +499,7 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { "void {project}::LogInstrSequence(const std::string& instr_name, const long int& exec_time) {{\n" " instr_log << \"Instr No. \" << std::setw(8) << GetInstrCntr() << '\\t';\n" " instr_log << instr_name << \" is activated\\t\";\n" - " instr_log << \"exec_time: \" << exec_time * 1e-6 << \" ms\\n\";\n" + " instr_log << \"exec_time: \" << exec_time * 1e-3 << \" us\\n\";\n" " IncrementInstrCntr();\n" "}}\n", fmt::arg("project", GetProjectName())); @@ -526,12 +526,12 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) { fmt::format_to( buff, "if ({valid_func_name}() && {decode_func_name}()) {{\n" - "#ifdef ILATOR_VERBOSE\n" + "#ifdef ILATOR_PROFILING\n" " auto start = std::chrono::high_resolution_clock::now();\n" "#endif\n" " {update_func_name}();\n" " {child_counter}\n" - "#ifdef ILATOR_VERBOSE\n" + "#ifdef ILATOR_PROFILING\n" " auto stop = std::chrono::high_resolution_clock::now();\n" " auto exec_time = std::chrono::duration_cast(stop-start).count();\n" " LogInstrSequence(\"{instr_name}\", exec_time);\n" @@ -662,8 +662,8 @@ bool Ilator::GenerateBuildSupport(const std::string& dir) { "cmake_minimum_required(VERSION 3.14.0)\n" "project({project} LANGUAGES CXX)\n" "\n" - "option(ILATOR_VERBOSE \"Enable instruction sequence logging\" OFF)\n" - // "option(ILATOR_INSN_VERBOSE \"Enable instruction state updates logging\" OFF)\n" + "option(ILATOR_PROFILING \"Enable instruction sequence logging and profiling\" OFF)\n" + "option(ILATOR_VERBOSE \"Enable instruction state updates logging\" OFF)\n" "option(JSON_SUPPORT \"Build JSON parser support\" OFF)\n" "\n" "find_package(SystemCLanguage CONFIG REQUIRED)\n" @@ -678,8 +678,11 @@ bool Ilator::GenerateBuildSupport(const std::string& dir) { "\n" "target_include_directories({project} PRIVATE {dir_include})\n" "target_link_libraries({project} SystemC::systemc)\n" + "if(${{ILATOR_PROFILING}})\n" + " target_compile_definitions({project} PRIVATE ILATOR_PROFILING)\n" + "endif()\n" "if(${{ILATOR_VERBOSE}})\n" - " target_compile_definitions({project} PRIVATE ILATOR_VERBOSE)\n" + " target_compile_definitions({project} PRIVATE ILATOR_PROFILING ILATOR_VERBOSE)\n" "endif()\n" // "if(${{ILATOR_INSN_VERBOSE}})\n" // " target_compile_definitions({project} PRIVATE ILATOR_INSN_VERBOSE)\n" From e829bcb79122186870d6191e1096d392c5d98458 Mon Sep 17 00:00:00 2001 From: Yi Li Date: Fri, 14 Jan 2022 16:10:02 -0500 Subject: [PATCH 5/5] add a python script to summary ilator profiling results --- scripts/ilator/profile_ila_instr_log.py | 48 +++++++++++++++++++++++++ 1 file changed, 48 insertions(+) create mode 100644 scripts/ilator/profile_ila_instr_log.py diff --git a/scripts/ilator/profile_ila_instr_log.py b/scripts/ilator/profile_ila_instr_log.py new file mode 100644 index 000000000..2f6fd1c7a --- /dev/null +++ b/scripts/ilator/profile_ila_instr_log.py @@ -0,0 +1,48 @@ +import sys + +from numpy.core.numeric import extend_all + +def profile_ila_log(fname, sortby="avg"): + logs = open(fname, "r").readlines() + unit = logs[0].split()[8] + total_time = dict() + num_cnt = dict() + avg_time = dict() + max_opname_len = 0 + for line in logs: + split_line = line.split() + instr_name = split_line[3] + exec_time = split_line[7] + if instr_name in total_time: + num_cnt[instr_name] += 1 + total_time[instr_name] += float(exec_time) + else: + num_cnt[instr_name] = 1 + total_time[instr_name] = float(exec_time) + for key in total_time: + avg_time[key] = total_time[key] / num_cnt[key] + max_opname_len = max(len(key), max_opname_len) + if sortby == "avg": + print("sorted by avg exec_time") + sorted_instr = sorted(avg_time.items(), key=lambda x: x[1], reverse=True) + else: + print("sorted by total exec_time") + sorted_instr = sorted(total_time.items(), key=lambda x: x[1], reverse=True) + + for i in sorted_instr: + print( + f"{i[0]: <{max_opname_len}}:\t" + + f"total exec_time: {total_time[i[0]]:.2f} {unit};\t" + + f"num count: {num_cnt[i[0]]};\t" + + f"avg. exec_time: {avg_time[i[0]]:.2f} {unit}" + ) + +if __name__ == "__main__": + if len(sys.argv) < 2: + print("Usage: python3 profile_ila_instr_log.py [file_path] [sortby]") + exit(0) + if len(sys.argv) == 3: + sortby = sys.argv[2] + else: + sortby = "avg" + profile_ila_log(sys.argv[1], sortby)