From 3fa9128716cdc8a794b2ec0be4fb2be454ea25ee Mon Sep 17 00:00:00 2001 From: Delyan Angelov Date: Wed, 26 Jan 2022 19:52:08 +0200 Subject: [PATCH] cgen,pref: support `-profile-fns strings__new_builder,i64_str -profile -` --- cmd/v/help/build.txt | 19 +++++- vlib/v/gen/c/cmain.v | 11 +++- vlib/v/gen/c/fn.v | 79 +++++++++++----------- vlib/v/gen/c/profile.v | 17 ++++- vlib/v/pref/pref.v | 36 ++++++---- vlib/v/tests/profile/profile_test.v | 94 ++++++++++++++++++--------- vlib/v/tests/profile/profile_test_3.v | 14 ++++ 7 files changed, 184 insertions(+), 86 deletions(-) create mode 100644 vlib/v/tests/profile/profile_test_3.v diff --git a/cmd/v/help/build.txt b/cmd/v/help/build.txt index 13e037a42e..aba89a75f2 100644 --- a/cmd/v/help/build.txt +++ b/cmd/v/help/build.txt @@ -77,7 +77,7 @@ NB: the build flags are shared with the run command too: to fix them first. -prof, -profile - Compile the executable with all functions profiled. + Compile the executable with all functions profiled. The profile results will be stored in `file.txt`. The format is 4 fields, separated by a space, for each v function: a) how many times it was called @@ -85,6 +85,9 @@ NB: the build flags are shared with the run command too: c) an average for each function (i.e. (b) / (a) ) d) the function name + NB: the profiler is *NOT* currently thread safe, so look at the profile results of + multithreaded programs very sceptically ! + NB: if you want to output the profile info to stdout, use `-profile -`. NB: you can use `import v.profile`, and then calls to `profile.on(false)` @@ -94,6 +97,20 @@ NB: the build flags are shared with the run command too: program's `fn main()` starts, pass `-d no_profile_startup` too. (V constants, and module init() functions are evaluated before `main()` is called) + NB: You can also select specific functions for profiling. For example: + v -profile-fns println,i64_str -profile - run examples/hanoi.v + In this case, the profile counters will be updated only for them, *and* for the functions that they call. + The profile result (after the program finishes), will look similar to this: + 127 0.721ms 5680ns println + 127 0.693ms 5456ns _writeln_to_fd + 127 0.565ms 4449ns _write_buf_to_fd + 127 0.045ms 353ns _v_malloc + 127 0.017ms 131ns malloc_noscan + 127 0.017ms 133ns _v_free + 127 0.014ms 113ns vmemmove + 127 0.110ms 866ns i64_str + 127 0.016ms 127ns tos + -message-limit The maximum amount of warnings / errors / notices, that will be accumulated (defaults to 100). The checker will abort prematurely once this limit has been reached. diff --git a/vlib/v/gen/c/cmain.v b/vlib/v/gen/c/cmain.v index e80ff8a19c..25ece3b36b 100644 --- a/vlib/v/gen/c/cmain.v +++ b/vlib/v/gen/c/cmain.v @@ -96,8 +96,15 @@ fn (mut g Gen) gen_c_main_header() { if g.pref.is_livemain { g.generate_hotcode_reloading_main_caller() } - if 'no_profile_startup' in g.pref.compile_defines { - g.writeln('vreset_profile_stats();') + if g.pref.profile_file != '' { + if 'no_profile_startup' in g.pref.compile_defines { + g.writeln('vreset_profile_stats();') + } + if g.pref.profile_fns.len > 0 { + g.writeln('vreset_profile_stats();') + // v__profile_enabled will be set true *inside* the fns in g.pref.profile_fns: + g.writeln('v__profile_enabled = false;') + } } } diff --git a/vlib/v/gen/c/fn.v b/vlib/v/gen/c/fn.v index 296eec5ff5..f0c7680435 100644 --- a/vlib/v/gen/c/fn.v +++ b/vlib/v/gen/c/fn.v @@ -210,45 +210,9 @@ fn (mut g Gen) gen_fn_decl(node &ast.FnDecl, skip bool) { eprintln('INFO: compile with `v -live $g.pref.path `, if you want to use the [live] function $node.name .') } // - mut name := node.name - if name in ['+', '-', '*', '/', '%', '<', '=='] { - name = util.replace_op(name) - } - if node.is_method { - unwrapped_rec_sym := g.table.sym(g.unwrap_generic(node.receiver.typ)) - if unwrapped_rec_sym.kind == .placeholder { - return - } - name = g.cc_type(node.receiver.typ, false) + '_' + name - // name = g.table.sym(node.receiver.typ).name + '_' + name - } - if node.language == .c { - name = util.no_dots(name) - } else { - name = c_name(name) - } + mut name := g.c_fn_name(node) or { return } mut type_name := g.typ(node.return_type) - if node.generic_names.len > 0 { - name = g.generic_fn_name(g.cur_concrete_types, name, true) - } - - if g.pref.translated && node.attrs.contains('c') { - // This fixes unknown symbols errors when building separate .c => .v files - // into .o files - // - // example: - // [c: 'P_TryMove'] - // fn p_trymove(thing &Mobj_t, x int, y int) bool - // - // => - // - // bool P_TryMove(main__Mobj_t* thing, int x, int y); - // - // In fn_call every time `p_trymove` is called, `P_TryMove` will be generated instead. - name = node.attrs[0].arg - } - if g.pref.obfuscate && g.cur_mod.name == 'main' && name.starts_with('main__') && !node.is_main && node.name != 'str' { mut key := node.name @@ -449,6 +413,47 @@ fn (mut g Gen) gen_fn_decl(node &ast.FnDecl, skip bool) { } } +fn (mut g Gen) c_fn_name(node &ast.FnDecl) ?string { + mut name := node.name + if name in ['+', '-', '*', '/', '%', '<', '=='] { + name = util.replace_op(name) + } + if node.is_method { + unwrapped_rec_sym := g.table.sym(g.unwrap_generic(node.receiver.typ)) + if unwrapped_rec_sym.kind == .placeholder { + return none + } + name = g.cc_type(node.receiver.typ, false) + '_' + name + // name = g.table.sym(node.receiver.typ).name + '_' + name + } + if node.language == .c { + name = util.no_dots(name) + } else { + name = c_name(name) + } + + if node.generic_names.len > 0 { + name = g.generic_fn_name(g.cur_concrete_types, name, true) + } + + if g.pref.translated && node.attrs.contains('c') { + // This fixes unknown symbols errors when building separate .c => .v files + // into .o files + // + // example: + // [c: 'P_TryMove'] + // fn p_trymove(thing &Mobj_t, x int, y int) bool + // + // => + // + // bool P_TryMove(main__Mobj_t* thing, int x, int y); + // + // In fn_call every time `p_trymove` is called, `P_TryMove` will be generated instead. + name = node.attrs[0].arg + } + return name +} + const closure_ctx = '_V_closure_ctx' fn closure_ctx_struct(node ast.FnDecl) string { diff --git a/vlib/v/gen/c/profile.v b/vlib/v/gen/c/profile.v index 5aa81c807a..b7d89bb54f 100644 --- a/vlib/v/gen/c/profile.v +++ b/vlib/v/gen/c/profile.v @@ -14,20 +14,33 @@ fn (mut g Gen) profile_fn(fn_decl ast.FnDecl) { return } fn_name := fn_decl.name + cfn_name := g.last_fn_c_name if fn_name.starts_with('time.vpc_now') || fn_name.starts_with('v.profile.') { g.defer_profile_code = '' } else { measure_fn_name := if g.pref.os == .macos { 'time__vpc_now_darwin' } else { 'time__vpc_now' } - fn_profile_counter_name := 'vpc_$g.last_fn_c_name' + fn_profile_counter_name := 'vpc_$cfn_name' fn_profile_counter_name_calls := '${fn_profile_counter_name}_calls' g.writeln('') + should_restore_v__profile_enabled := g.pref.profile_fns.len > 0 + && cfn_name in g.pref.profile_fns + if should_restore_v__profile_enabled { + $if trace_profile_fns ? { + eprintln('> profile_fn | $g.pref.profile_fns | $cfn_name') + } + g.writeln('\tbool _prev_v__profile_enabled = v__profile_enabled;') + g.writeln('\tv__profile_enabled = true;') + } g.writeln('\tdouble _PROF_FN_START = ${measure_fn_name}();') g.writeln('\tif(v__profile_enabled) { $fn_profile_counter_name_calls++; } // $fn_name') g.writeln('') g.defer_profile_code = '\tif(v__profile_enabled) { $fn_profile_counter_name += ${measure_fn_name}() - _PROF_FN_START; }' + if should_restore_v__profile_enabled { + g.defer_profile_code += '\n\t\tv__profile_enabled = _prev_v__profile_enabled;' + } g.pcs_declarations.writeln('double $fn_profile_counter_name = 0.0; u64 $fn_profile_counter_name_calls = 0;') g.pcs << ProfileCounterMeta{ - fn_name: g.last_fn_c_name + fn_name: cfn_name vpc_name: fn_profile_counter_name vpc_calls: fn_profile_counter_name_calls } diff --git a/vlib/v/pref/pref.v b/vlib/v/pref/pref.v index d0d57cbd68..4e16102fa1 100644 --- a/vlib/v/pref/pref.v +++ b/vlib/v/pref/pref.v @@ -99,20 +99,21 @@ pub mut: // verbosity VerboseLevel is_verbose bool // nofmt bool // disable vfmt - is_test bool // `v test string_test.v` - is_script bool // single file mode (`v program.v`), main function can be skipped - is_vsh bool // v script (`file.vsh`) file, the `os` module should be made global - is_livemain bool // main program that contains live/hot code - is_liveshared bool // a shared library, that will be used in a -live main program - is_shared bool // an ordinary shared library, -shared, no matter if it is live or not - is_o bool // building an .o file - is_prof bool // benchmark every function - test_runner string // can be 'simple' (fastest, but much less detailed), 'tap', 'normal' - profile_file string // the profile results will be stored inside profile_file - profile_no_inline bool // when true, [inline] functions would not be profiled - translated bool // `v translate doom.v` are we running V code translated from C? allow globals, ++ expressions, etc - is_prod bool // use "-O2" - obfuscate bool // `v -obf program.v`, renames functions to "f_XXX" + is_test bool // `v test string_test.v` + is_script bool // single file mode (`v program.v`), main function can be skipped + is_vsh bool // v script (`file.vsh`) file, the `os` module should be made global + is_livemain bool // main program that contains live/hot code + is_liveshared bool // a shared library, that will be used in a -live main program + is_shared bool // an ordinary shared library, -shared, no matter if it is live or not + is_o bool // building an .o file + is_prof bool // benchmark every function + test_runner string // can be 'simple' (fastest, but much less detailed), 'tap', 'normal' + profile_file string // the profile results will be stored inside profile_file + profile_no_inline bool // when true, [inline] functions would not be profiled + profile_fns []string // when set, profiling will be off by default, but inside these functions (and what they call) it will be on. + translated bool // `v translate doom.v` are we running V code translated from C? allow globals, ++ expressions, etc + is_prod bool // use "-O2" + obfuscate bool // `v -obf program.v`, renames functions to "f_XXX" is_repl bool is_run bool is_debug bool // turned on by -g or -cg, it tells v to pass -g to the C backend compiler. @@ -424,6 +425,13 @@ pub fn parse_args_and_show_errors(known_external_commands []string, args []strin res.build_options << '$arg $res.profile_file' i++ } + '-profile-fns' { + profile_fns := cmdline.option(current_args, arg, '').split(',') + if profile_fns.len > 0 { + res.profile_fns << profile_fns + } + i++ + } '-profile-no-inline' { res.profile_no_inline = true } diff --git a/vlib/v/tests/profile/profile_test.v b/vlib/v/tests/profile/profile_test.v index c38bf2e1ba..5c4275bbe5 100644 --- a/vlib/v/tests/profile/profile_test.v +++ b/vlib/v/tests/profile/profile_test.v @@ -10,40 +10,74 @@ fn test_vexe_exists() { } fn test_v_profile_works() { - os.chdir(vroot) or {} - program_source := os.join_path(vroot, 'vlib/v/tests/profile/profile_test_1.v') - res := os.execute('${os.quoted_path(vexe)} -profile - run ${os.quoted_path(program_source)}') - // eprintln('res: $res') - assert res.exit_code == 0 - assert res.output.len > 0 - assert res.output.contains(' os__init_os_args') - assert res.output.contains(' main__main') - assert res.output.contains(' println') - assert res.output.contains(' strconv__atoi') + sfile := 'vlib/v/tests/profile/profile_test_1.v' + validate_output(@FN, '', sfile, { + 'os__init_os_args': 1 + 'main__main': 1 + 'println': 1 + 'strconv__atoi': 1 + }) } fn test_v_profile_on_off_api_works() { - os.chdir(vroot) or {} - program_source := os.join_path(vroot, 'vlib/v/tests/profile/profile_test_2.v') - res := os.execute('${os.quoted_path(vexe)} -profile - run ${os.quoted_path(program_source)}') - // eprintln('res: $res') - assert res.exit_code == 0 - assert res.output.len > 0 - assert res.output.contains(' builtin_init') - assert res.output.contains(' main__main') - assert res.output.contains(' main__abc') - res_lines := res.output.split_into_lines() - abc_count := res_lines.filter(it.contains('main__abc'))[0].trim_space().all_before(' ').int() - assert abc_count == 1 - + sfile := 'vlib/v/tests/profile/profile_test_2.v' + res_lines := validate_output(@FN, '', sfile, { + 'builtin_init': 1 + 'main__main': 1 + 'main__abc': 1 + }) // test that `-d no_profile_startup` *also* works: - res2 := os.execute('${os.quoted_path(vexe)} -d no_profile_startup -profile - run ${os.quoted_path(program_source)}') - assert res2.exit_code == 0 - assert res2.output.len > 0 - assert !res2.output.contains(' builtin_init') - assert res2.output.contains(' main__main') - assert res2.output.contains(' main__abc') - res2_lines := res2.output.split_into_lines() + res2_lines := validate_output(@FN, '-d no_profile_startup', sfile, { + 'builtin_init': -1 + 'main__main': 1 + 'main__abc': 1 + }) assert res_lines.len > res2_lines.len // dump(res2_lines) } + +fn test_v_profile_fns_option_works() { + sfile := 'vlib/v/tests/profile/profile_test_3.v' + validate_output(@FN, '-profile-fns println', sfile, { + 'main__main': -1 + 'main__abc': -1 + 'main__xyz': -1 + 'println': 10 + }) + validate_output(@FN, '-profile-fns main__abc', sfile, { + 'main__main': -1 + 'main__abc': 1 + 'main__xyz': 2 + 'println': 10 + }) + validate_output(@FN, '-profile-fns main__xyz', sfile, { + 'main__main': -1 + 'main__abc': -1 + 'main__xyz': 2 + 'println': 10 + }) +} + +fn counter_value(lines []string, what string) int { + res := lines.filter(it.contains(what)) + if res.len == 0 { + return -1 + } + return res[0].trim_space().all_before(' ').int() +} + +fn validate_output(fn_name string, vopts string, fsource string, expected map[string]int) []string { + println('> validating $fn_name with: `v $vopts -profile - run $fsource`') + os.chdir(vroot) or {} + program_source := os.join_path(vroot, fsource) + res := os.execute('${os.quoted_path(vexe)} $vopts -profile - run ${os.quoted_path(program_source)}') + assert res.exit_code == 0 + assert res.output.len > 0 + res_lines := res.output.split_into_lines() + for expected_counter_name, expected_counter_value in expected { + produced_value := counter_value(res_lines, expected_counter_name) + println(' counter_name: $expected_counter_name') + assert produced_value == expected_counter_value + } + return res_lines +} diff --git a/vlib/v/tests/profile/profile_test_3.v b/vlib/v/tests/profile/profile_test_3.v new file mode 100644 index 0000000000..87fd07056d --- /dev/null +++ b/vlib/v/tests/profile/profile_test_3.v @@ -0,0 +1,14 @@ +fn xyz() { + for i in 0 .. 5 { + println('${@FN} - i: $i') + } +} + +fn abc() { + xyz() + xyz() +} + +fn main() { + abc() +}