cgen,pref: support `-profile-fns strings__new_builder,i64_str -profile -`

cmd/v/help/build.txt

@@ -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 <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.

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 {
+	if g.pref.profile_file != '' {
-		g.writeln('vreset_profile_stats();')
+		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;')
+		}
 	}
 }
 

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
+	mut name := g.c_fn_name(node) or { return }
-	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 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 {

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
 		}

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_test           bool     // `v test string_test.v`
-	is_script         bool   // single file mode (`v program.v`), main function can be skipped
+	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_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_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_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_shared         bool     // an ordinary shared library, -shared, no matter if it is live or not
-	is_o              bool   // building an .o file
+	is_o              bool     // building an .o file
-	is_prof           bool   // benchmark every function
+	is_prof           bool     // benchmark every function
-	test_runner       string // can be 'simple' (fastest, but much less detailed), 'tap', 'normal'
+	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_file      string   // the profile results will be stored inside profile_file
-	profile_no_inline bool   // when true, [inline] functions would not be profiled
+	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
+	profile_fns       []string // when set, profiling will be off by default, but inside these functions (and what they call) it will be on.	
-	is_prod           bool   // use "-O2"
+	translated        bool     // `v translate doom.v` are we running V code translated from C? allow globals, ++ expressions, etc
-	obfuscate         bool   // `v -obf program.v`, renames functions to "f_XXX"
+	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
 			}

vlib/v/tests/profile/profile_test.v

@@ -10,40 +10,74 @@ fn test_vexe_exists() {
 }
 
 fn test_v_profile_works() {
-	os.chdir(vroot) or {}
+	sfile := 'vlib/v/tests/profile/profile_test_1.v'
-	program_source := os.join_path(vroot, 'vlib/v/tests/profile/profile_test_1.v')
+	validate_output(@FN, '', sfile, {
-	res := os.execute('${os.quoted_path(vexe)} -profile - run ${os.quoted_path(program_source)}')
+		'os__init_os_args': 1
-	// eprintln('res: $res')
+		'main__main':       1
-	assert res.exit_code == 0
+		'println':          1
-	assert res.output.len > 0
+		'strconv__atoi':    1
-	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')
 }
 
 fn test_v_profile_on_off_api_works() {
-	os.chdir(vroot) or {}
+	sfile := 'vlib/v/tests/profile/profile_test_2.v'
-	program_source := os.join_path(vroot, 'vlib/v/tests/profile/profile_test_2.v')
+	res_lines := validate_output(@FN, '', sfile, {
-	res := os.execute('${os.quoted_path(vexe)} -profile - run ${os.quoted_path(program_source)}')
+		'builtin_init': 1
-	// eprintln('res: $res')
+		'main__main':   1
-	assert res.exit_code == 0
+		'main__abc':    1
-	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
-
 	// 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)}')
+	res2_lines := validate_output(@FN, '-d no_profile_startup', sfile, {
-	assert res2.exit_code == 0
+		'builtin_init': -1
-	assert res2.output.len > 0
+		'main__main':   1
-	assert !res2.output.contains(' builtin_init')
+		'main__abc':    1
-	assert res2.output.contains(' main__main')
+	})
-	assert res2.output.contains(' main__abc')
-	res2_lines := res2.output.split_into_lines()
 	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
+}

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()
+}