add profiling tools in debug mode

This commit is contained in:
ValKmjolnir 2023-08-06 20:02:12 +08:00
parent 70a8be8e4c
commit 044ccb4bc6
8 changed files with 250 additions and 113 deletions

View File

@ -16,14 +16,16 @@
#include <thread>
#include <cstdlib>
const u32 VM_RAW_AST = 1;
const u32 VM_AST = 1<<1;
const u32 VM_CODE = 1<<2;
const u32 VM_TIME = 1<<3;
const u32 VM_EXEC = 1<<4;
const u32 VM_DETAIL = 1<<5;
const u32 VM_DEBUG = 1<<6;
const u32 VM_SYMINFO = 1<<7;
const u32 VM_RAW_AST = 1;
const u32 VM_AST = 1<<1;
const u32 VM_CODE = 1<<2;
const u32 VM_TIME = 1<<3;
const u32 VM_EXEC = 1<<4;
const u32 VM_DETAIL = 1<<5;
const u32 VM_DEBUG = 1<<6;
const u32 VM_SYMINFO = 1<<7;
const u32 VM_PROFILE = 1<<8;
const u32 VM_PROF_ALL = 1<<9;
std::ostream& help(std::ostream& out) {
out
@ -36,22 +38,25 @@ std::ostream& help(std::ostream& out) {
#endif
<< "\nnasal <option>\n"
<< "option:\n"
<< " -h, --help | get help.\n"
<< " -v, --version | get version.\n"
<< " -h, --help | get help.\n"
<< " -v, --version | get version.\n"
<< "\nnasal [option] <file> [argv]\n"
<< "option:\n"
<< " -a, --ast | view ast after link/optimize process.\n"
<< " --raw-ast | view ast without after-processing.\n"
<< " -c, --code | view generated bytecode.\n"
<< " -s, --symbol | show analysed symbol info.\n"
<< " -e, --exec | execute directly.\n"
<< " -t, --time | show execute time.\n"
<< " -d, --detail | get detail info.\n"
<< " -dbg, --debug | debug mode.\n"
<< " -a, --ast | view ast after link/optimize process.\n"
<< " --raw-ast | view ast without after-processing.\n"
<< " -c, --code | view generated bytecode.\n"
<< " -s, --symbol | show analysed symbol info.\n"
<< " -e, --exec | execute directly.\n"
<< " -t, --time | show execute time.\n"
<< " -d, --detail | get detail info.\n"
<< " -dbg, --debug | debug mode.\n"
<< " --prof | show profiling result, available under debug mode.\n"
<< " --prof-all | show profiling result of all files,"
<< "available under debug mode.\n"
<< "file:\n"
<< " <filename> | execute file.\n"
<< " <filename> | execute file.\n"
<< "argv:\n"
<< " <args> | cmd arguments used in program.\n"
<< " <args> | cmd arguments used in program.\n"
<< "\n";
return out;
}
@ -145,7 +150,7 @@ void execute(
// run
auto start = clk::now();
if (cmd&VM_DEBUG) {
dbg().run(gen, ld, argv);
dbg().run(gen, ld, argv, cmd&VM_PROFILE, cmd&VM_PROF_ALL);
} else if (cmd&VM_TIME || cmd&VM_EXEC) {
ctx.run(gen, ld, argv, cmd&VM_DETAIL);
}
@ -195,7 +200,9 @@ i32 main(i32 argc, const char* argv[]) {
{"--detail", VM_DETAIL|VM_EXEC},
{"-d", VM_DETAIL|VM_EXEC},
{"--debug", VM_DEBUG},
{"-dbg", VM_DEBUG}
{"-dbg", VM_DEBUG},
{"--prof", VM_PROFILE},
{"--prof-all", VM_PROF_ALL}
};
u32 cmd = 0;
std::string filename = "";

View File

@ -1,5 +1,12 @@
#include "nasal_codegen.h"
void codegen::init_file_map(const std::vector<std::string>& file_list) {
file_map = {};
for(usize i = 0; i<file_list.size(); ++i) {
file_map.insert({file_list[i], i});
}
}
void codegen::load_native_function_table(nasal_builtin_table* table) {
for(usize i = 0; table[i].func; ++i) {
if (native_function_mapper.count(table[i].name)) {
@ -1133,11 +1140,7 @@ void codegen::ret_gen(return_expr* node) {
const error& codegen::compile(parse& parse, linker& import, bool repl) {
init_native_function();
const auto& file = import.filelist();
file_map = {};
for(usize i = 0; i<file.size(); ++i) {
file_map[file[i]] = i;
}
init_file_map(import.get_file_list());
in_loop_level.push_back(0);

View File

@ -31,6 +31,7 @@ private:
// file mapper for file -> index
std::unordered_map<std::string, usize> file_map;
void init_file_map(const std::vector<std::string>&);
// used for generate pop in return expression
std::vector<u32> in_loop_level;

View File

@ -1,5 +1,94 @@
#include "nasal_dbg.h"
void debug_prof_data::init_counter() {
for(usize i = 0; i<debug_prof_data::operand_size; ++i) {
operand_counter[i] = 0;
}
}
void debug_prof_data::load_file_line_counter(
const std::vector<std::string>& file_list) {
file_name_list = file_list;
file_line_counter = {};
file_contents = {};
flstream fs;
for(usize i =0; i<file_list.size(); ++i) {
fs.load(file_list[i]);
file_contents.push_back(fs.file_content());
file_line_counter.push_back({});
file_line_counter.back().resize(fs.size(), 0);
}
}
void debug_prof_data::init(const std::vector<std::string>& file_list) {
init_counter();
load_file_line_counter(file_list);
}
void debug_prof_data::dump_counter() const {
typedef std::pair<u32, u64> op_count;
std::vector<op_count> opcall;
u64 total = 0;
for(usize i = 0; i<debug_prof_data::operand_size; ++i) {
total += operand_counter[i];
opcall.push_back({i, operand_counter[i]});
}
std::sort(opcall.begin(), opcall.end(),
[](const op_count& a, const op_count& b) {
return a.second>b.second;
}
);
std::clog << "\noperands call info (<1% ignored)\n";
for(const auto& i : opcall) {
u64 rate = i.second*100/total;
if (!rate) {
break;
}
std::clog << " " << opname[i.first] << " : ";
std::clog << i.second << " (" << rate << "%)\n";
}
std::clog << " total : " << total << '\n';
}
void debug_prof_data::dump_code_line_counter(std::ostream& os) const {
u64 max_call_time = 0;
for(const auto& context : file_line_counter) {
for(const auto& count : context) {
max_call_time = count>max_call_time? count:max_call_time;
}
}
auto pad_length = std::to_string(max_call_time).length();
for(usize i = 0; i<file_name_list.size(); ++i) {
os << "\ncode profiling data of " << file_name_list[i] << ":\n";
const auto& context = file_contents[i];
const auto& counter = file_line_counter[i];
for(usize j = 0; j<context.size(); ++j) {
os << " " << std::right << std::setw(pad_length);
os << std::setfill(' ');
os << (counter[j]==0? "":std::to_string(counter[j]));
os << " " << context[j] << "\n";
}
}
}
void debug_prof_data::dump_this_file_line_counter(std::ostream& os) const {
u64 max_call_time = 0;
for(const auto& count : file_line_counter[0]) {
max_call_time = count>max_call_time? count:max_call_time;
}
auto pad_length = std::to_string(max_call_time).length();
os << "\ncode profiling data of " << file_name_list[0] << ":\n";
const auto& context = file_contents[0];
const auto& counter = file_line_counter[0];
for(usize i = 0; i<context.size(); ++i) {
os << " " << std::right << std::setw(pad_length);
os << std::setfill(' ');
os << (counter[i]==0? "":std::to_string(counter[i]));
os << " " << context[i] << "\n";
}
}
std::vector<std::string> dbg::parse(const std::string& cmd) {
std::vector<std::string> res;
usize last = 0, pos = cmd.find(" ", 0);
@ -55,29 +144,6 @@ void dbg::list_file() const {
}
}
void dbg::call_sort(const u64* arr) const {
typedef std::pair<u32,u64> op;
std::vector<op> opcall;
u64 total = 0;
for(u32 i = 0; i<op_ret+1; ++i) {
total += arr[i];
opcall.push_back({i, arr[i]});
}
std::sort(opcall.begin(), opcall.end(),
[](const op& a, const op& b) {return a.second>b.second;}
);
std::clog << "\noperands call info (<1% ignored)\n";
for(auto& i : opcall) {
u64 rate = i.second*100/total;
if (!rate) {
break;
}
std::clog << " " << opname[i.first] << " : ";
std::clog << i.second << " (" << rate << "%)\n";
}
std::clog << " total : " << total << '\n';
}
void dbg::step_info() {
u32 line = bytecode[ctx.pc].line==0? 0:bytecode[ctx.pc].line-1;
u32 begin = (line>>3)==0? 0:((line>>3)<<3);
@ -108,6 +174,11 @@ void dbg::interact() {
if (bytecode[ctx.pc].op==op_exit) {
return;
}
// do not need interact while doing profiling
if (do_profiling) {
return;
}
if ((bytecode[ctx.pc].fidx!=bk_fidx ||
bytecode[ctx.pc].line!=bk_line) && // break point
@ -161,75 +232,45 @@ void dbg::interact() {
void dbg::run(
const codegen& gen,
const linker& linker,
const std::vector<std::string>& argv) {
const std::vector<std::string>& argv,
bool profile,
bool show_all_prof_result) {
verbose = true;
fsize = linker.filelist().size();
do_profiling = profile || show_all_prof_result;
const auto& file_list = linker.get_file_list();
fsize = file_list.size();
init(gen.strs(), gen.nums(), gen.natives(),
gen.codes(), gen.globals(), linker.filelist(), argv);
u64 count[op_ret+1] = {0};
typedef void (dbg::*nafunc)();
const nafunc oprs[] = {
nullptr, &dbg::o_intg,
&dbg::o_intl, &dbg::o_loadg,
&dbg::o_loadl, &dbg::o_loadu,
&dbg::o_pnum, &dbg::o_pnil,
&dbg::o_pstr, &dbg::o_newv,
&dbg::o_newh, &dbg::o_newf,
&dbg::o_happ, &dbg::o_para,
&dbg::o_deft, &dbg::o_dyn,
&dbg::o_lnot, &dbg::o_usub,
&dbg::o_bnot, &dbg::o_btor,
&dbg::o_btxor, &dbg::o_btand,
&dbg::o_add, &dbg::o_sub,
&dbg::o_mul, &dbg::o_div,
&dbg::o_lnk, &dbg::o_addc,
&dbg::o_subc, &dbg::o_mulc,
&dbg::o_divc, &dbg::o_lnkc,
&dbg::o_addeq, &dbg::o_subeq,
&dbg::o_muleq, &dbg::o_diveq,
&dbg::o_lnkeq, &dbg::o_bandeq,
&dbg::o_boreq, &dbg::o_bxoreq,
&dbg::o_addeqc, &dbg::o_subeqc,
&dbg::o_muleqc, &dbg::o_diveqc,
&dbg::o_lnkeqc, &dbg::o_addecp,
&dbg::o_subecp, &dbg::o_mulecp,
&dbg::o_divecp, &dbg::o_lnkecp,
&dbg::o_meq, &dbg::o_eq,
&dbg::o_neq, &dbg::o_less,
&dbg::o_leq, &dbg::o_grt,
&dbg::o_geq, &dbg::o_lessc,
&dbg::o_leqc, &dbg::o_grtc,
&dbg::o_geqc, &dbg::o_pop,
&dbg::o_jmp, &dbg::o_jt,
&dbg::o_jf, &dbg::o_cnt,
&dbg::o_findex, &dbg::o_feach,
&dbg::o_callg, &dbg::o_calll,
&dbg::o_upval, &dbg::o_callv,
&dbg::o_callvi, &dbg::o_callh,
&dbg::o_callfv, &dbg::o_callfh,
&dbg::o_callb, &dbg::o_slcbeg,
&dbg::o_slcend, &dbg::o_slc,
&dbg::o_slc2, &dbg::o_mcallg,
&dbg::o_mcalll, &dbg::o_mupval,
&dbg::o_mcallv, &dbg::o_mcallh,
&dbg::o_ret
};
gen.codes(), gen.globals(),
file_list, argv);
data.init(file_list);
std::vector<u32> code;
std::vector<u16> code_file_index;
std::vector<u32> code_line;
for(auto& i : gen.codes()) {
code.push_back(i.op);
code_file_index.push_back(i.fidx);
code_line.push_back(i.line);
imm.push_back(i.num);
}
while(oprs[code[ctx.pc]]) {
while(operand_function[code[ctx.pc]]) {
interact();
++count[code[ctx.pc]];
(this->*oprs[code[ctx.pc]])();
data.add_operand_counter(code[ctx.pc]);
data.add_code_line_counter(code_file_index[ctx.pc], code_line[ctx.pc]);
(this->*operand_function[code[ctx.pc]])();
if (ctx.top>=ctx.canary) {
die("stack overflow");
}
++ctx.pc;
}
call_sort(count);
data.dump_counter();
if (do_profiling) {
show_all_prof_result?
data.dump_code_line_counter(std::clog):
data.dump_this_file_line_counter(std::clog);
}
ngc.info();
ngc.clear();
imm.clear();

View File

@ -9,7 +9,82 @@
#include <algorithm>
#include <unordered_map>
class debug_prof_data {
private:
static const usize operand_size = op_code_type::op_ret + 1;
u64 operand_counter[operand_size];
std::vector<std::string> file_name_list;
std::vector<std::vector<u64>> file_line_counter;
std::vector<std::vector<std::string>> file_contents;
private:
void init_counter();
void load_file_line_counter(const std::vector<std::string>&);
public:
void init(const std::vector<std::string>&);
void dump_counter() const;
void dump_code_line_counter(std::ostream&) const;
void dump_this_file_line_counter(std::ostream&) const;
void add_operand_counter(usize index) {
operand_counter[index] += index<operand_size? 1:0;
}
void add_code_line_counter(usize fidx, usize line) {
auto& vec = file_line_counter[fidx];
vec[line==0? line: line-1]++;
}
};
class dbg:public vm {
private:
typedef void (dbg::*nasal_vm_func)();
const nasal_vm_func operand_function[op_ret + 1] = {
nullptr, &dbg::o_intg,
&dbg::o_intl, &dbg::o_loadg,
&dbg::o_loadl, &dbg::o_loadu,
&dbg::o_pnum, &dbg::o_pnil,
&dbg::o_pstr, &dbg::o_newv,
&dbg::o_newh, &dbg::o_newf,
&dbg::o_happ, &dbg::o_para,
&dbg::o_deft, &dbg::o_dyn,
&dbg::o_lnot, &dbg::o_usub,
&dbg::o_bnot, &dbg::o_btor,
&dbg::o_btxor, &dbg::o_btand,
&dbg::o_add, &dbg::o_sub,
&dbg::o_mul, &dbg::o_div,
&dbg::o_lnk, &dbg::o_addc,
&dbg::o_subc, &dbg::o_mulc,
&dbg::o_divc, &dbg::o_lnkc,
&dbg::o_addeq, &dbg::o_subeq,
&dbg::o_muleq, &dbg::o_diveq,
&dbg::o_lnkeq, &dbg::o_bandeq,
&dbg::o_boreq, &dbg::o_bxoreq,
&dbg::o_addeqc, &dbg::o_subeqc,
&dbg::o_muleqc, &dbg::o_diveqc,
&dbg::o_lnkeqc, &dbg::o_addecp,
&dbg::o_subecp, &dbg::o_mulecp,
&dbg::o_divecp, &dbg::o_lnkecp,
&dbg::o_meq, &dbg::o_eq,
&dbg::o_neq, &dbg::o_less,
&dbg::o_leq, &dbg::o_grt,
&dbg::o_geq, &dbg::o_lessc,
&dbg::o_leqc, &dbg::o_grtc,
&dbg::o_geqc, &dbg::o_pop,
&dbg::o_jmp, &dbg::o_jt,
&dbg::o_jf, &dbg::o_cnt,
&dbg::o_findex, &dbg::o_feach,
&dbg::o_callg, &dbg::o_calll,
&dbg::o_upval, &dbg::o_callv,
&dbg::o_callvi, &dbg::o_callh,
&dbg::o_callfv, &dbg::o_callfh,
&dbg::o_callb, &dbg::o_slcbeg,
&dbg::o_slcend, &dbg::o_slc,
&dbg::o_slc2, &dbg::o_mcallg,
&dbg::o_mcalll, &dbg::o_mupval,
&dbg::o_mcallv, &dbg::o_mcallh,
&dbg::o_ret
};
private:
enum class dbg_cmd {
cmd_error,
@ -66,20 +141,27 @@ private:
u32 bk_line;
error src;
debug_prof_data data;
bool do_profiling;
std::vector<std::string> parse(const std::string&);
u16 file_index(const std::string&) const;
void err();
void help();
void list_file() const;
void call_sort(const u64*) const;
void step_info();
void interact();
public:
dbg(): next(false), fsize(0), bk_fidx(0), bk_line(0) {}
dbg():
next(false), fsize(0),
bk_fidx(0), bk_line(0),
do_profiling(false) {}
void run(
const codegen&,
const linker&,
const std::vector<std::string>&
const std::vector<std::string>&,
bool,
bool
);
};

View File

@ -27,11 +27,13 @@ class flstream {
protected:
std::string file;
std::vector<std::string> res;
public:
flstream():file("") {}
void load(const std::string&);
const std::string& operator[](usize n) const {return res[n];}
const std::string& name() const {return file;}
const auto& name() const {return file;}
const auto& file_content() const {return res;}
usize size() const {return res.size();}
};
@ -49,6 +51,7 @@ private:
}
return tmp;
}
public:
error():cnt(0) {}
void fatal(const std::string&, const std::string&);

View File

@ -49,7 +49,7 @@ private:
public:
linker();
const error& link(parse&, const std::string&, bool);
const std::vector<std::string>& filelist() const {return files;}
const std::string& get_this_file() const {return this_file;}
const std::string& get_lib_path() const {return lib_path;}
const auto& get_file_list() const {return files;}
const auto& get_this_file() const {return this_file;}
const auto& get_lib_path() const {return lib_path;}
};

View File

@ -235,7 +235,7 @@ void vm::run(
const bool detail) {
verbose = detail;
init(gen.strs(), gen.nums(), gen.natives(),
gen.codes(), gen.globals(), linker.filelist(), argv);
gen.codes(), gen.globals(), linker.get_file_list(), argv);
#ifndef _MSC_VER
// using labels as values/computed goto
const void* oprs[] = {