Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

Sign up for GitHub

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

Jump to bottom

add time recording feature for ilator debugging #220

Open
wants to merge 5 commits into
base: master
Choose a base branch
from
Open

add time recording feature for ilator debugging #220

Show file tree
Hide file tree
Changes from all commits
Commits
Show all changes
5 commits
Select commit Hold shift + click to select a range
b6bf2fa
add time recording feature for ilator debugging
Nov 30, 2021
4e7a5f5
fixed instr log format for profiling
Nov 30, 2021
865d7c9
changed the time unit to nanosecond for finer-grain profiling
Jan 14, 2022
f544a48
separate ilator instr time profiling and instr update logging
Jan 14, 2022
e829bcb
add a python script to summary ilator profiling results
Jan 14, 2022
File filter

Filter by extension

Filter by extension
Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
48 changes: 48 additions & 0 deletions scripts/ilator/profile_ila_instr_log.py
View file
Open in desktop
Original file line number Diff line number Diff line change
@@ -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)
32 changes: 21 additions & 11 deletions src/target-sc/ilator.cc
View file
Open in desktop
Original file line number Diff line number Diff line change
Expand Up @@ -483,7 +483,8 @@ bool Ilator::GenerateExecuteKernel(const std::string& dir) {
fmt::format_to( // headers
buff,
"#include <iomanip>\n"
"#include <{project}.h>\n",
"#include <{project}.h>\n"
"#include <chrono>\n", // add chrono to record time for debugging
fmt::arg("project", GetProjectName()));

fmt::format_to( // logging
Expand All @@ -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"
" instr_log << \"Instr No.\" << std::setw(5) << GetInstrCntr() << '\\t';\n"
" instr_log << instr_name << \" is activated\\n\";\n"
"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 << \" us\\n\";\n"
" IncrementInstrCntr();\n"
"}}\n",
fmt::arg("project", GetProjectName()));
Expand All @@ -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_PROFILING\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"
" {child_counter}\n"
"#ifdef ILATOR_PROFILING\n"
" auto stop = std::chrono::high_resolution_clock::now();\n"
" auto exec_time = std::chrono::duration_cast<std::chrono::nanoseconds>(stop-start).count();\n"
" LogInstrSequence(\"{instr_name}\", exec_time);\n"
"#endif\n"
"}}\n",
fmt::arg("valid_func_name", GetValidFuncName(instr->host())),
Expand Down Expand Up @@ -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
Expand Down Expand Up @@ -655,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"
Expand All @@ -671,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"
Expand Down