transformer: improve -trace-calls output, enable tracing of builtin fns, show elapsed ns and used stack size (#16205)

Make it easier to change later, by splitting the tracing call into its own `v.trace_calls` module, so that it can be iterated upon without changing the compiler itself.

vlib/v/builder/compile.v

@@ -236,6 +236,9 @@ pub fn (v &Builder) get_user_files() []string {
 	if v.pref.backend == .js_node {
 		preludes_path = os.join_path(vroot, 'vlib', 'v', 'preludes_js')
 	}
+	if v.pref.trace_calls {
+		user_files << os.join_path(preludes_path, 'trace_calls.v')
+	}
 	if v.pref.is_livemain || v.pref.is_liveshared {
 		user_files << os.join_path(preludes_path, 'live.v')
 	}

vlib/v/compiler_errors_test.v

@@ -85,7 +85,6 @@ fn test_all() {
 	global_run_dir := '$checker_dir/globals_run'
 	run_dir := '$checker_dir/run'
 	skip_unused_dir := 'vlib/v/tests/skip_unused'
-	trace_calls_dir := 'vlib/v/tests/trace_calls'
 	//
 	checker_tests := get_tests_in_dir(checker_dir, false).filter(!it.contains('with_check_option'))
 	parser_tests := get_tests_in_dir(parser_dir, false)
@@ -95,7 +94,6 @@ fn test_all() {
 	module_tests := get_tests_in_dir(module_dir, true)
 	run_tests := get_tests_in_dir(run_dir, false)
 	skip_unused_dir_tests := get_tests_in_dir(skip_unused_dir, false)
-	trace_calls_dir_tests := get_tests_in_dir(trace_calls_dir, false)
 	checker_with_check_option_tests := get_tests_in_dir(checker_with_check_option_dir,
 		false)
 	mut tasks := Tasks{
@@ -127,15 +125,6 @@ fn test_all() {
 		skip_unused_tasks.add('', skip_unused_dir, '-d no_backtrace -skip-unused run',
 			'.skip_unused.run.out', skip_unused_dir_tests, false)
 		skip_unused_tasks.run()
-		//
-		mut trace_calls_tasks := Tasks{
-			vexe: vexe
-			parallel_jobs: 1
-			label: '-trace-calls tests'
-		}
-		trace_calls_tasks.add('', trace_calls_dir, '-trace-calls run', '.run.out', trace_calls_dir_tests,
-			false)
-		trace_calls_tasks.run()
 	}
 	//
 	if github_job == 'ubuntu-tcc' {

vlib/v/gen/c/cgen.v

@@ -5040,6 +5040,9 @@ fn (mut g Gen) write_init_function() {
 
 	// ___argv is declared as voidptr here, because that unifies the windows/unix logic
 	g.writeln('void _vinit(int ___argc, voidptr ___argv) {')
+	if g.pref.trace_calls {
+		g.writeln('\tv__trace_calls__on_call(_SLIT("_vinit"));')
+	}
 
 	if g.use_segfault_handler {
 		// 11 is SIGSEGV. It is hardcoded here, to avoid FreeBSD compilation errors for trivial examples.
@@ -5095,6 +5098,9 @@ fn (mut g Gen) write_init_function() {
 	//
 	fn_vcleanup_start_pos := g.out.len
 	g.writeln('void _vcleanup(void) {')
+	if g.pref.trace_calls {
+		g.writeln('\tv__trace_calls__on_call(_SLIT("_vcleanup"));')
+	}
 	if g.is_autofree {
 		// g.writeln('puts("cleaning up...");')
 		reversed_table_modules := g.table.modules.reverse()

vlib/v/gen/c/cmain.v

@@ -94,6 +94,7 @@ fn (mut g Gen) gen_c_main_function_only_header() {
 
 fn (mut g Gen) gen_c_main_function_header() {
 	g.gen_c_main_function_only_header()
+	g.gen_c_main_trace_calls_hook()
 	g.writeln('\tg_main_argc = ___argc;')
 	g.writeln('\tg_main_argv = ___argv;')
 	if g.nr_closures > 0 {
@@ -153,6 +154,7 @@ void (_vsokol_cleanup_userdata_cb)(void* user_data) {
 	g.writeln('// The sokol_main entry point on Android
 sapp_desc sokol_main(int argc, char* argv[]) {
 	(void)argc; (void)argv;')
+	g.gen_c_main_trace_calls_hook()
 
 	if g.pref.gc_mode in [.boehm_full, .boehm_incr, .boehm_full_opt, .boehm_incr_opt, .boehm_leak] {
 		g.writeln('#if defined(_VGCBOEHM)')
@@ -334,3 +336,10 @@ pub fn (mut g Gen) filter_only_matching_fn_names(fnames []string) []string {
 	}
 	return res
 }
+
+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();')
+}

vlib/v/pref/pref.v

@@ -654,10 +654,6 @@ pub fn parse_args_and_show_errors(known_external_commands []string, args []strin
 			'-cc' {
 				res.ccompiler = cmdline.option(current_args, '-cc', 'cc')
 				res.build_options << '$arg "$res.ccompiler"'
-				if res.ccompiler == 'musl-gcc' {
-					res.is_musl = true
-					res.is_glibc = false
-				}
 				i++
 			}
 			'-checker-match-exhaustive-cutoff-limit' {
@@ -860,6 +856,15 @@ pub fn parse_args_and_show_errors(known_external_commands []string, args []strin
 		}
 		res.path = args[command_pos + 1]
 	}
+	if res.ccompiler == 'musl-gcc' {
+		res.is_musl = true
+		res.is_glibc = false
+	}
+	if res.is_musl {
+		// make `$if musl? {` work:
+		res.compile_defines << 'musl'
+		res.compile_defines_all << 'musl'
+	}
 	// keep only the unique res.build_options:
 	mut m := map[string]string{}
 	for x in res.build_options {

vlib/v/preludes/trace_calls.v

@@ -0,0 +1,5 @@
+module main
+
+import v.trace_calls
+
+const trace_calls_used = trace_calls.is_used

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

@@ -0,0 +1,9 @@
+*> trace * C.main*
+*> trace * _vinit*
+*> trace * main main.main/0*
+*> trace * main main.foo/0*
+*> trace * main main.bar/0*
+*> trace * main main.baz/0*
+*> trace * main main.Boo.call_1/1*
+*> trace * builtin eprintln/1*
+*> trace * _vcleanup*

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

@@ -0,0 +1,9 @@
+*> trace * C.main*
+*> trace * _vinit*
+*> trace * os os.init_os_args*
+*> trace * main main.main/0*
+*> trace * main main.f1/0*
+*> trace * main main.f2/0*
+*> trace * main main.f3/0*
+*> trace * os os.join_path/2*
+*> trace *_vcleanup*

vlib/v/tests/trace_calls/simple.run.out

@@ -1,6 +0,0 @@
-> trace fn main()
-> trace fn foo()
-> trace fn bar()
-> trace fn baz()
-> trace fn (b Boo) call_1()
-end

vlib/v/tests/trace_calls/with_modules.run.out

@@ -1,8 +0,0 @@
-> trace fn init_os_args(argc int, argv &&u8) []string
-> trace pub fn getwd() string
-> trace fn main()
-> trace fn f1()
-> trace fn f2()
-> trace fn f3()
-> trace pub fn join_path(base string, dirs ...string) string
-end

vlib/v/tests/trace_calls_test.v

@@ -0,0 +1,39 @@
+import os
+
+const vexe = @VEXE
+
+fn test_tracing() {
+	os.chdir(@VROOT)!
+	folder := os.join_path('vlib', 'v', 'tests', 'testdata', 'trace_calls')
+	files := os.walk_ext(folder, '.vv')
+	for fpath in files {
+		should_match_fpath := '${fpath}.must_match'
+		if !os.exists(should_match_fpath) {
+			eprintln('> skipping $fpath, because $should_match_fpath does not exist.')
+			continue
+		}
+		res := os.execute('${os.quoted_path(vexe)} -trace-calls run ${os.quoted_path(fpath)}')
+		if res.exit_code != 0 {
+			eprintln('> compilation output:\n$res.output')
+			assert res.exit_code == 0, 'compilation of $fpath failed'
+		}
+		lines := os.read_lines(should_match_fpath) or {
+			assert false, '$fpath should be readable'
+			return
+		}
+		if lines.len == 0 {
+			assert false, '$should_match_fpath should contain at least one line/glob match pattern'
+		}
+		mut matched := false
+		for line in lines {
+			if res.output.match_glob(line) {
+				matched = true
+				println('> 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'
+			}
+		}
+	}
+}

vlib/v/trace_calls/tracing_calls.v

@@ -0,0 +1,69 @@
+[has_globals]
+module trace_calls
+
+[markused]
+__global g_stack_base = &u8(0)
+__global g_start_time = u64(0)
+
+pub const is_used = 1
+
+// unix:
+pub struct C.timespec {
+mut:
+	tv_sec  i64
+	tv_nsec i64
+}
+
+fn C.gettid() u32
+fn C.clock_gettime(int, &C.timespec)
+fn C.pthread_self() u64
+
+// windows:
+fn C.GetCurrentThreadId() u32
+fn C.QueryPerformanceCounter(&u64) C.BOOL
+
+[markused]
+pub fn on_call(fname string) {
+	mut volatile pfbase := unsafe { &u8(0) }
+	volatile fbase := u8(0)
+	ns := current_time() - g_start_time
+	mut ssize := u64(0)
+	mut tid := u32(0)
+	unsafe {
+		$if windows {
+			tid = C.GetCurrentThreadId()
+		} $else $if linux {
+			tid = C.gettid()
+		} $else {
+			tid = u32(C.pthread_self())
+		}
+		pfbase = &fbase
+		ssize = u64(g_stack_base) - u64(pfbase)
+	}
+	C.fprintf(C.stderr, c'> trace %8d %8ld %8d %s\n', tid, ns, ssize, fname.str)
+	C.fflush(C.stderr)
+}
+
+[inline]
+fn current_time() u64 {
+	unsafe {
+		$if windows {
+			tm := u64(0)
+			C.QueryPerformanceCounter(&tm)
+			return tm
+		} $else {
+			ts := C.timespec{}
+			C.clock_gettime(C.CLOCK_MONOTONIC, &ts)
+			return u64(ts.tv_sec) * 1000000000 + u64(ts.tv_nsec)
+		}
+	}
+}
+
+[markused]
+pub fn on_c_main() {
+	g_start_time = current_time()
+	C.fprintf(C.stderr, c'#          tid       ns      ssize name\n')
+	C.fflush(C.stderr)
+	on_call('C.main')
+	//                    > trace  2128896   714640    28148 fn
+}

vlib/v/trace_calls/tracing_calls_d_musl.v

@@ -0,0 +1,8 @@
+module trace_calls
+
+// gettid is missing on musl/alpine, but present on most everything else
+[export: 'gettid']
+[weak]
+fn vgettid() &u32 {
+	return 0
+}

vlib/v/transformer/transformer.v

@@ -1041,45 +1041,38 @@ pub fn (mut t Transformer) sql_expr(mut node ast.SqlExpr) ast.Expr {
 // 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 {
-		// Skip `C.fn()` and all of builtin
-		// builtin could probably be traced also but would need
-		// special cases for, at least, println/eprintln
-		if node.no_body || node.is_builtin {
+		if node.no_body {
+			// Skip `C.fn()` calls
 			return
 		}
-		call_expr := t.gen_trace_print_call_expr(node)
+		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: call_expr
+			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)
 	}
 }
-
-// gen_trace_print_expr_stmt generates an ast.CallExpr representation of a
-// `eprint(...)` V code statement.
-fn (t Transformer) gen_trace_print_call_expr(node ast.FnDecl) ast.CallExpr {
-	print_str := '> trace ' + node.stringify(t.table, node.mod, map[string]string{})
-
-	call_arg := ast.CallArg{
-		expr: ast.StringLiteral{
-			val: print_str
-		}
-		typ: ast.string_type_idx
-	}
-	args := [call_arg]
-
-	fn_name := 'eprintln'
-	call_expr := ast.CallExpr{
-		name: fn_name
-		args: args
-		mod: node.mod
-		pos: node.pos
-		language: node.language
-		scope: node.scope
-		comments: [ast.Comment{
-			text: 'fn $node.short_name trace call'
-		}]
-	}
-
-	return call_expr
-}