v.pref: support filtering while tracing, with v -trace-calls -trace-fns main,gg*draw* run examples/tetris/ (#21021)

vlib/v/gen/c/cgen.v

@@ -6172,7 +6172,7 @@ fn (mut g Gen) write_init_function() {
 
 	g.write_debug_calls_typeof_functions()
 
-	if g.pref.trace_calls {
+	if g.pref.trace_calls && g.pref.should_trace_fn_name('_vinit') {
 		g.writeln('\tv__trace_calls__on_call(_SLIT("_vinit"));')
 	}
 
@@ -6267,7 +6267,7 @@ fn (mut g Gen) write_init_function() {
 
 	fn_vcleanup_start_pos := g.out.len
 	g.writeln('void _vcleanup(void) {')
-	if g.pref.trace_calls {
+	if g.pref.trace_calls && g.pref.should_trace_fn_name('_vcleanup') {
 		g.writeln('\tv__trace_calls__on_call(_SLIT("_vcleanup"));')
 	}
 	if g.is_autofree {

vlib/v/gen/c/cmain.v

@@ -350,5 +350,6 @@ pub fn (mut g Gen) gen_c_main_trace_calls_hook() {
 	if !g.pref.trace_calls {
 		return
 	}
-	g.writeln('\tu8 bottom_of_stack = 0; g_stack_base = &bottom_of_stack; v__trace_calls__on_c_main();')
+	should_trace_c_main := g.pref.should_trace_fn_name('C.main')
+	g.writeln('\tu8 bottom_of_stack = 0; g_stack_base = &bottom_of_stack; v__trace_calls__on_c_main(${should_trace_c_main});')
 }

vlib/v/pref/pref.c.v

@@ -174,8 +174,9 @@ pub mut:
 	no_bounds_checking bool // `-no-bounds-checking` turns off *all* bounds checks for all functions at runtime, as if they all had been tagged with `[direct_array_access]`
 	autofree           bool // `v -manualfree` => false, `v -autofree` => true; false by default for now.
 	// Disabling `free()` insertion results in better performance in some applications (e.g. compilers)
-	trace_calls bool // -trace-calls true = the transformer stage will generate and inject print calls for tracing function calls
-	compress    bool // when set, use `upx` to compress the generated executable
+	trace_calls bool     // -trace-calls true = the transformer stage will generate and inject print calls for tracing function calls
+	trace_fns   []string // when set, tracing will be done only for functions, whose names match the listed patterns.
+	compress    bool     // when set, use `upx` to compress the generated executable
 	// generating_vh    bool
 	no_builtin       bool   // Skip adding the `builtin` module implicitly. The generated C code may not compile.
 	enable_globals   bool   // allow __global for low level code
@@ -551,8 +552,19 @@ pub fn parse_args_and_show_errors(known_external_commands []string, args []strin
 				res.build_options << arg
 			}
 			'-trace-calls' {
+				res.build_options << arg
 				res.trace_calls = true
 			}
+			'-trace-fns' {
+				value := cmdline.option(current_args, arg, '')
+				res.build_options << arg
+				res.build_options << value
+				trace_fns := value.split(',')
+				if trace_fns.len > 0 {
+					res.trace_fns << trace_fns
+				}
+				i++
+			}
 			'-manualfree' {
 				res.autofree = false
 				res.build_options << arg
@@ -951,6 +963,17 @@ pub fn parse_args_and_show_errors(known_external_commands []string, args []strin
 			}
 		}
 	}
+	if res.trace_calls {
+		if res.trace_fns.len == 0 {
+			res.trace_fns << '*'
+		}
+		for mut fpattern in res.trace_fns {
+			if fpattern.contains('*') {
+				continue
+			}
+			fpattern = '*${fpattern}*'
+		}
+	}
 	if command == 'crun' {
 		res.is_crun = true
 	}
@@ -1245,3 +1268,7 @@ fn (mut prefs Preferences) diagnose_deprecated_defines(define_parts []string) {
 pub fn supported_test_runners_list() string {
 	return pref.supported_test_runners.map('`${it}`').join(', ')
 }
+
+pub fn (pref &Preferences) should_trace_fn_name(fname string) bool {
+	return pref.trace_fns.any(fname.match_glob(it))
+}

vlib/v/tests/testdata/trace_calls/single_println.vv

@@ -0,0 +1 @@
+println('hi')

vlib/v/tests/testdata/trace_calls/single_println.vv.must_match

@@ -0,0 +1 @@
+*hi*

vlib/v/tests/trace_calls_test.v

@@ -4,6 +4,23 @@ const vexe = @VEXE
 const gcc_path = os.find_abs_path_of_executable('gcc') or { '' }
 const cdefs_h_32bit_exists = os.exists('/usr/include/i386-linux-gnu/sys/cdefs.h')
 
+fn separator() {
+	eprintln('-'.repeat(30))
+}
+
+fn test_trace_fns() {
+	os.chdir(@VROOT)!
+	folder := os.join_path('vlib', 'v', 'tests', 'testdata', 'trace_calls')
+	fpath := os.join_path(folder, 'single_println.vv')
+	should_match_fpath := os.join_path(folder, 'single_println.vv.must_match.simple')
+	assert run_trace_fns(fpath, 'println') == 1
+	assert run_trace_fns(fpath, '_vinit') == 1
+	assert run_trace_fns(fpath, 'println,main.main') == 2
+	assert run_trace_fns(fpath, 'builtin') > 3
+	eprintln('> `-trace-calls -trace-fns PATTERNS` works')
+	separator()
+}
+
 fn test_tracing() {
 	os.chdir(@VROOT)!
 	folder := os.join_path('vlib', 'v', 'tests', 'testdata', 'trace_calls')
@@ -21,18 +38,34 @@ fn test_tracing() {
 		} else {
 			eprintln('> skipping -m32 compilation since either 32bit headers are not installed, or you do not have gcc installed')
 		}
-		eprintln('-'.repeat(30))
+		separator()
 	}
 }
 
-fn run_single_program(fpath string, should_match_fpath string, compiler_opts string, label string) {
-	res := os.execute('${os.quoted_path(vexe)} ${compiler_opts} -trace-calls run ${os.quoted_path(fpath)}')
+struct CmdOutput {
+	cmd    string
+	output string
+}
+
+fn run(fpath string, compiler_opts string, label string) CmdOutput {
+	cmd := '${os.quoted_path(vexe)} ${compiler_opts} -trace-calls run ${os.quoted_path(fpath)}'
+	res := os.execute(cmd)
 	if res.exit_code != 0 {
 		eprintln('> ${label} compilation output:\n${res.output}')
 		assert res.exit_code == 0, 'compilation of ${fpath} failed'
 	}
+	return CmdOutput{cmd, res.output}
+}
+
+fn run_trace_fns(fpath string, patterns string) int {
+	// ignore the header line and the final output `hi` line:
+	return run(fpath, '-trace-fns ${patterns}', 'trace_fns_only_println').output.split_into_lines().len - 2
+}
+
+fn run_single_program(fpath string, should_match_fpath string, compiler_opts string, label string) {
+	c := run(fpath, compiler_opts, label)
 	lines := os.read_lines(should_match_fpath) or {
-		assert false, '${fpath} should be readable'
+		assert false, '${should_match_fpath} should be readable'
 		return
 	}
 	if lines.len == 0 {
@@ -40,13 +73,15 @@ fn run_single_program(fpath string, should_match_fpath string, compiler_opts str
 	}
 	mut matched := false
 	for line in lines {
-		if res.output.match_glob(line) {
+		if c.output.match_glob(line) {
 			matched = true
 			println('> ${label} trace output of ${fpath} matches line pattern: ${line}')
 			continue
 		} else {
-			eprintln(res.output)
-			assert false, '> trace output of ${fpath} DID NOT match the line pattern: ${line}'
+			eprintln('-----------------------------------')
+			eprintln(c.output)
+			eprintln('-----------------------------------')
+			assert false, '> trace output of ${fpath} DID NOT match the line pattern: `${line}`, run cmd:\n${c.cmd}'
 		}
 	}
 }

vlib/v/trace_calls/tracing_calls.c.v

@@ -49,10 +49,12 @@ fn current_time() u64 {
 }
 
 @[markused]
-pub fn on_c_main() {
+pub fn on_c_main(should_trace_c_main bool) {
 	g_start_time = current_time()
+	//                    > trace  2128896   714640    28148 fn
 	C.fprintf(C.stderr, c'#          tid       ns      ssize name\n')
 	C.fflush(C.stderr)
-	on_call('C.main')
-	//                    > trace  2128896   714640    28148 fn
+	if should_trace_c_main {
+		on_call('C.main')
+	}
 }

vlib/v/transformer/transformer.v

@@ -236,7 +236,9 @@ pub fn (mut t Transformer) stmt(mut node ast.Stmt) ast.Stmt {
 			}
 		}
 		ast.FnDecl {
-			t.fn_decl(mut node)
+			if t.pref.trace_calls {
+				t.fn_decl_trace_calls(mut node)
+			}
 			t.index.indent(true)
 			for mut stmt in node.stmts {
 				stmt = t.stmt(mut stmt)
@@ -1101,43 +1103,42 @@ pub fn (mut t Transformer) sql_expr(mut node ast.SqlExpr) ast.Expr {
 	return node
 }
 
-// fn_decl mutates `node`.
-// if `pref.trace_calls` is true ast Nodes for `eprintln(...)` is prepended to the `FnDecl`'s
-// stmts list to let the gen backend generate the target specific code for the print.
-pub fn (mut t Transformer) fn_decl(mut node ast.FnDecl) {
-	if t.pref.trace_calls {
-		if node.no_body {
-			// Skip `C.fn()` calls
-			return
-		}
-		if node.name.starts_with('v.trace_calls.') {
-			// do not instrument the tracing functions, to avoid infinite regress
-			return
-		}
-		fname := if node.is_method {
-			receiver_name := global_table.type_to_str(node.receiver.typ)
-			'${node.mod} ${receiver_name}.${node.name}/${node.params.len}'
-		} else {
-			'${node.mod} ${node.name}/${node.params.len}'
-		}
-
-		expr_stmt := ast.ExprStmt{
-			expr: ast.CallExpr{
-				mod: node.mod
-				pos: node.pos
-				language: .v
-				scope: node.scope
-				name: 'v.trace_calls.on_call'
-				args: [
-					ast.CallArg{
-						expr: ast.StringLiteral{
-							val: fname
-						}
-						typ: ast.string_type_idx
-					},
-				]
-			}
-		}
-		node.stmts.prepend(expr_stmt)
+pub fn (mut t Transformer) fn_decl_trace_calls(mut node ast.FnDecl) {
+	// Prepend ast Nodes for `eprintln(...)` to the `FnDecl`'s stmts list,
+	// to let the gen backend generate the target specific code for the print.
+	if node.no_body {
+		// Skip `C.fn()` calls
+		return
 	}
+	if node.name.starts_with('v.trace_calls.') {
+		// do not instrument the tracing functions, to avoid infinite regress
+		return
+	}
+	fname := if node.is_method {
+		receiver_name := global_table.type_to_str(node.receiver.typ)
+		'${node.mod} ${receiver_name}.${node.name}/${node.params.len}'
+	} else {
+		'${node.mod} ${node.name}/${node.params.len}'
+	}
+	if !t.pref.trace_fns.any(fname.match_glob(it)) {
+		return
+	}
+	expr_stmt := ast.ExprStmt{
+		expr: ast.CallExpr{
+			mod: node.mod
+			pos: node.pos
+			language: .v
+			scope: node.scope
+			name: 'v.trace_calls.on_call'
+			args: [
+				ast.CallArg{
+					expr: ast.StringLiteral{
+						val: fname
+					}
+					typ: ast.string_type_idx
+				},
+			]
+		}
+	}
+	node.stmts.prepend(expr_stmt)
 }