diff --git a/vlib/v/builder/compile.v b/vlib/v/builder/compile.v index c65798bd79..0948e82dd8 100644 --- a/vlib/v/builder/compile.v +++ b/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') } diff --git a/vlib/v/compiler_errors_test.v b/vlib/v/compiler_errors_test.v index 383660255f..d177acc316 100644 --- a/vlib/v/compiler_errors_test.v +++ b/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' { diff --git a/vlib/v/gen/c/cgen.v b/vlib/v/gen/c/cgen.v index 8efb220f1f..b6e728fa65 100644 --- a/vlib/v/gen/c/cgen.v +++ b/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() diff --git a/vlib/v/gen/c/cmain.v b/vlib/v/gen/c/cmain.v index 1b7f8c7dc1..992bcd4059 100644 --- a/vlib/v/gen/c/cmain.v +++ b/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();') +} diff --git a/vlib/v/pref/pref.v b/vlib/v/pref/pref.v index fb4ca7c796..5daa42c552 100644 --- a/vlib/v/pref/pref.v +++ b/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 { diff --git a/vlib/v/preludes/trace_calls.v b/vlib/v/preludes/trace_calls.v new file mode 100644 index 0000000000..30555f204a --- /dev/null +++ b/vlib/v/preludes/trace_calls.v @@ -0,0 +1,5 @@ +module main + +import v.trace_calls + +const trace_calls_used = trace_calls.is_used diff --git a/vlib/v/tests/trace_calls/simple.vv b/vlib/v/tests/testdata/trace_calls/simple.vv similarity index 100% rename from vlib/v/tests/trace_calls/simple.vv rename to vlib/v/tests/testdata/trace_calls/simple.vv diff --git a/vlib/v/tests/testdata/trace_calls/simple.vv.must_match b/vlib/v/tests/testdata/trace_calls/simple.vv.must_match new file mode 100644 index 0000000000..fad0cc54bc --- /dev/null +++ b/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* diff --git a/vlib/v/tests/trace_calls/with_modules.vv b/vlib/v/tests/testdata/trace_calls/with_modules.vv similarity index 100% rename from vlib/v/tests/trace_calls/with_modules.vv rename to vlib/v/tests/testdata/trace_calls/with_modules.vv diff --git a/vlib/v/tests/testdata/trace_calls/with_modules.vv.must_match b/vlib/v/tests/testdata/trace_calls/with_modules.vv.must_match new file mode 100644 index 0000000000..8a6d81f25d --- /dev/null +++ b/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* diff --git a/vlib/v/tests/trace_calls/simple.run.out b/vlib/v/tests/trace_calls/simple.run.out deleted file mode 100644 index d0bec344ca..0000000000 --- a/vlib/v/tests/trace_calls/simple.run.out +++ /dev/null @@ -1,6 +0,0 @@ -> trace fn main() -> trace fn foo() -> trace fn bar() -> trace fn baz() -> trace fn (b Boo) call_1() -end diff --git a/vlib/v/tests/trace_calls/with_modules.run.out b/vlib/v/tests/trace_calls/with_modules.run.out deleted file mode 100644 index 1c88b09c9c..0000000000 --- a/vlib/v/tests/trace_calls/with_modules.run.out +++ /dev/null @@ -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 diff --git a/vlib/v/tests/trace_calls_test.v b/vlib/v/tests/trace_calls_test.v new file mode 100644 index 0000000000..975c68ef09 --- /dev/null +++ b/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' + } + } + } +} diff --git a/vlib/v/trace_calls/tracing_calls.v b/vlib/v/trace_calls/tracing_calls.v new file mode 100644 index 0000000000..498e16a678 --- /dev/null +++ b/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 +} diff --git a/vlib/v/trace_calls/tracing_calls_d_musl.v b/vlib/v/trace_calls/tracing_calls_d_musl.v new file mode 100644 index 0000000000..853904218c --- /dev/null +++ b/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 +} diff --git a/vlib/v/transformer/transformer.v b/vlib/v/transformer/transformer.v index 9a465473cc..af7bd4a4a1 100644 --- a/vlib/v/transformer/transformer.v +++ b/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 -}