tests: show compile time and runtime for each _test.v file in separat…

…e columns (#20520)

cmd/tools/modules/testing/common.v

@@ -56,6 +56,11 @@ fn get_all_processes() []string {
 	}
 }
 
+pub enum ActionMode {
+	compile
+	compile_and_run
+}
+
 pub struct TestSession {
 pub mut:
 	files         []string
@@ -77,6 +82,8 @@ pub mut:
 	failed_cmds   shared []string
 	reporter      Reporter = Reporter(NormalReporter{})
 	hash          string // used as part of the name of the temporary directory created for tests, to ease cleanup
+	//
+	exec_mode ActionMode = .compile // .compile_and_run only for `v test`
 }
 
 pub fn (mut ts TestSession) add_failed_cmd(cmd string) {
@@ -137,7 +144,7 @@ pub fn (mut ts TestSession) print_messages() {
 		// first sent *all events* to the output reporter, so it can then process them however it wants:
 		ts.reporter.report(ts.nmessage_idx, rmessage)
 
-		if rmessage.kind in [.cmd_begin, .cmd_end] {
+		if rmessage.kind in [.cmd_begin, .cmd_end, .compile_begin, .compile_end] {
 			// The following events, are sent before the test framework has determined,
 			// what the full completion status is. They can also be repeated multiple times,
 			// for tests that are flaky and need repeating.
@@ -432,13 +439,20 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 	is_vet := ts.vargs.contains('vet')
 	produces_file_output := !(is_fmt || is_vet)
 
-	if relative_file.ends_with('js.v') {
+	if relative_file.ends_with('.js.v') {
 		if produces_file_output {
 			cmd_options << ' -b js'
 			run_js = true
 		}
 	}
 
+	if relative_file.ends_with('.c.v') {
+		if produces_file_output {
+			cmd_options << ' -b c'
+			run_js = false
+		}
+	}
+
 	if relative_file.contains('global') && !is_fmt {
 		cmd_options << ' -enable-globals'
 	}
@@ -451,6 +465,7 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 		flow_id: thread_id.str()
 	}
 	normalised_relative_file := relative_file.replace('\\', '/')
+
 	// Ensure that the generated binaries will be stored in an *unique*, fresh, and per test folder,
 	// inside the common session temporary folder, used for all the tests.
 	// This is done to provide a clean working environment, for each test, that will not contain
@@ -467,10 +482,15 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 		os.mkdir_all(test_folder_path) or {}
 	}
 	fname := os.file_name(file)
+	// There are test files ending with `_test.v`, `_test.c.v` and `_test.js.v`.
+	mut fname_without_extension := fname.all_before_last('.v')
+	if fname_without_extension.ends_with('.c') {
+		fname_without_extension = fname_without_extension.all_before_last('.c')
+	}
 	generated_binary_fname := if os.user_os() == 'windows' && !run_js {
-		fname.all_before_last('.v') + '.exe'
+		fname_without_extension + '.exe'
 	} else {
-		fname.all_before_last('.v')
+		fname_without_extension
 	}
 	generated_binary_fpath := os.join_path_single(test_folder_path, generated_binary_fname)
 	if produces_file_output {
@@ -479,18 +499,29 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 		}
 		cmd_options << ' -o ${os.quoted_path(generated_binary_fpath)}'
 	}
-	cmd := '${os.quoted_path(ts.vexe)} ${cmd_options.join(' ')} ${os.quoted_path(file)}'
+	defer {
+		if produces_file_output && ts.rm_binaries {
+			os.rmdir_all(test_folder_path) or {}
+		}
+	}
+
+	cmd := '${os.quoted_path(ts.vexe)} -skip-running ${cmd_options.join(' ')} ${os.quoted_path(file)}'
+	run_cmd := if run_js { 'node ${generated_binary_fpath}' } else { generated_binary_fpath }
 	ts.benchmark.step()
 	tls_bench.step()
 	if relative_file.replace('\\', '/') in ts.skip_files {
 		ts.benchmark.skip()
 		tls_bench.skip()
 		if !testing.hide_skips {
-			ts.append_message(.skip, tls_bench.step_message_skip(normalised_relative_file),
-				mtc)
+			ts.append_message(.skip, tls_bench.step_message_with_label_and_duration(benchmark.b_skip,
+				normalised_relative_file, 0,
+				preparation: 1 * time.microsecond
+			), mtc)
 		}
 		return pool.no_result
 	}
+	mut compile_cmd_duration := time.Duration(0)
+	mut cmd_duration := time.Duration(0)
 	if ts.show_stats {
 		ts.reporter.divider()
 
@@ -505,7 +536,7 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 		}
 		mut status := res.exit_code
 
-		mut cmd_duration := d_cmd.elapsed()
+		cmd_duration = d_cmd.elapsed()
 		ts.append_message_with_duration(.cmd_end, '', cmd_duration, mtc)
 
 		if status != 0 {
@@ -536,40 +567,49 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 					goto test_passed_system
 				}
 			}
-
 			// most probably compiler error
 			if res.output.contains(': error: ') {
 				ts.append_message(.cannot_compile, 'Cannot compile file ${file}', mtc)
 			}
-
 			ts.benchmark.fail()
 			tls_bench.fail()
 			ts.add_failed_cmd(cmd)
 			return pool.no_result
-		} else {
-			test_passed_system:
-			ts.benchmark.ok()
-			tls_bench.ok()
 		}
 	} else {
 		if testing.show_start {
 			ts.append_message(.info, '                 starting ${relative_file} ...',
 				mtc)
 		}
-		ts.append_message(.cmd_begin, cmd, mtc)
-		d_cmd := time.new_stopwatch()
-		mut r := os.execute(cmd)
-		mut cmd_duration := d_cmd.elapsed()
-		ts.append_message_with_duration(.cmd_end, r.output, cmd_duration, mtc)
-
-		if r.exit_code < 0 {
+		ts.append_message(.compile_begin, cmd, mtc)
+		compile_d_cmd := time.new_stopwatch()
+		mut compile_r := os.execute(cmd)
+		compile_cmd_duration = compile_d_cmd.elapsed()
+		ts.append_message_with_duration(.compile_end, compile_r.output, compile_cmd_duration,
+			mtc)
+		if compile_r.exit_code != 0 {
 			ts.benchmark.fail()
 			tls_bench.fail()
-			ts.append_message_with_duration(.fail, tls_bench.step_message_fail(normalised_relative_file),
-				cmd_duration, mtc)
+			ts.append_message_with_duration(.fail, tls_bench.step_message_with_label_and_duration(benchmark.b_fail,
+				normalised_relative_file, cmd_duration,
+				preparation: compile_cmd_duration
+			), cmd_duration, mtc)
 			ts.add_failed_cmd(cmd)
 			return pool.no_result
 		}
+		tls_bench.step_restart()
+		ts.benchmark.step_restart()
+		if ts.exec_mode == .compile {
+			unsafe {
+				goto test_passed_execute
+			}
+		}
+		//
+		ts.append_message(.cmd_begin, run_cmd, mtc)
+		d_cmd := time.new_stopwatch()
+		mut r := os.execute(run_cmd)
+		cmd_duration = d_cmd.elapsed()
+		ts.append_message_with_duration(.cmd_end, r.output, cmd_duration, mtc)
 		if r.exit_code != 0 {
 			details := get_test_details(file)
 			os.setenv('VTEST_RETRY_MAX', '${details.retry}', true)
@@ -578,9 +618,9 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 					mtc)
 				os.setenv('VTEST_RETRY', '${retry}', true)
 
-				ts.append_message(.cmd_begin, cmd, mtc)
+				ts.append_message(.cmd_begin, run_cmd, mtc)
 				d_cmd_2 := time.new_stopwatch()
-				r = os.execute(cmd)
+				r = os.execute(run_cmd)
 				cmd_duration = d_cmd_2.elapsed()
 				ts.append_message_with_duration(.cmd_end, r.output, cmd_duration, mtc)
 
@@ -601,21 +641,24 @@ fn worker_trunner(mut p pool.PoolProcessor, idx int, thread_id int) voidptr {
 			ts.benchmark.fail()
 			tls_bench.fail()
 			ending_newline := if r.output.ends_with('\n') { '\n' } else { '' }
-			ts.append_message_with_duration(.fail, tls_bench.step_message_fail('${normalised_relative_file}\n${r.output.trim_space()}${ending_newline}'),
-				cmd_duration, mtc)
+			ts.append_message_with_duration(.fail, tls_bench.step_message_with_label_and_duration(benchmark.b_fail,
+				'${normalised_relative_file}\n${r.output.trim_space()}${ending_newline}',
+				cmd_duration,
+				preparation: compile_cmd_duration
+			), cmd_duration, mtc)
 			ts.add_failed_cmd(cmd)
-		} else {
-			test_passed_execute:
-			ts.benchmark.ok()
-			tls_bench.ok()
-			if !testing.hide_oks {
-				ts.append_message_with_duration(.ok, tls_bench.step_message_ok(normalised_relative_file),
-					cmd_duration, mtc)
-			}
+			return pool.no_result
 		}
 	}
-	if produces_file_output && ts.rm_binaries {
-		os.rmdir_all(test_folder_path) or {}
+	test_passed_system:
+	test_passed_execute:
+	ts.benchmark.ok()
+	tls_bench.ok()
+	if !testing.hide_oks {
+		ts.append_message_with_duration(.ok, tls_bench.step_message_with_label_and_duration(benchmark.b_ok,
+			normalised_relative_file, cmd_duration,
+			preparation: compile_cmd_duration
+		), cmd_duration, mtc)
 	}
 	return pool.no_result
 }

cmd/tools/modules/testing/output.v

@@ -3,6 +3,8 @@ module testing
 import time
 
 pub enum MessageKind {
+	compile_begin // sent right before *each* _test.v file compilation, the resulting status is not known yet, but the _test.v file itself is
+	compile_end // sent right after *each* _test.v file compilation, the message contains the output of that compilation
 	cmd_begin // sent right before *each* _test.v file execution, the resulting status is not known yet, but the _test.v file itself is
 	cmd_end // sent right after *each* _test.v file execution, the message contains the output of that execution
 	//
@@ -21,7 +23,7 @@ pub:
 	kind    MessageKind   // see the MessageKind declaration above
 	file    string        // the _test.v file that the message is about
 	when    time.Time     // when was the message sent (messages are sent by the execution threads at the *end* of each event)
-	flow_id string        // the messages of each thread, producing LogMessage, will have all the same unique flowid. Messages by other threads will have other flowid. If you use VJOBS=1 to serialise the execution, then all messages will have the same flowid.
+	flow_id string        // the messages of each thread, producing LogMessage, will have all the same unique flow_id. Messages by other threads will have other flow_id. If you use VJOBS=1 to serialise the execution, then all messages will have the same flow_id.
 	took    time.Duration // the duration of the event, that this message describes
 	message string        // the actual message text; the result of the event, that the message describes; most reporters could ignore this, since it could be reconstructed by the other fields
 }

cmd/tools/modules/testing/output_normal.v

@@ -1,5 +1,6 @@
 module testing
 
+import time
 import term
 
 pub const empty = term.header(' ', ' ')
@@ -8,20 +9,29 @@ pub const empty = term.header(' ', ' ')
 // It is used by default by `v test .`
 // It was extracted by the original non customiseable output implementation directly in cmd/tools/modules/testing/common.v
 pub struct NormalReporter {
+mut:
+	runtime  time.Duration
+	comptime time.Duration
 }
 
 pub fn (r NormalReporter) session_start(message string, mut ts TestSession) {
 	header(message)
 }
 
 pub fn (r NormalReporter) session_stop(message string, mut ts TestSession) {
-	println(ts.benchmark.total_message(message))
+	println('${ts.benchmark.total_message(message)} Comptime: ${r.comptime.microseconds() / 1000} ms. Runtime: ${r.runtime.microseconds() / 1000} ms.')
 }
 
 // the most general form; it may be useful for other reporters
 // in the normal one, it currently does nothing
-pub fn (r NormalReporter) report(index int, message LogMessage) {
+pub fn (mut r NormalReporter) report(index int, message LogMessage) {
 	// eprintln('> ${@METHOD} index: $index | message: $message')
+	if message.kind == .compile_end {
+		r.comptime += message.took
+	}
+	if message.kind == .cmd_end {
+		r.runtime += message.took
+	}
 }
 
 pub fn (r NormalReporter) report_stop() {

cmd/tools/vtest-self.v

@@ -352,6 +352,7 @@ fn main() {
 	}
 	testing.eheader(title)
 	mut tsession := testing.new_test_session(cmd_prefix, true)
+	tsession.exec_mode = .compile_and_run
 	tsession.files << all_test_files.filter(!it.contains('testdata' + os.path_separator))
 	tsession.skip_files << skip_test_files
 

cmd/tools/vtest.v

@@ -32,9 +32,10 @@ fn main() {
 		exit(1)
 	}
 	backend_pos := args_before.index('-b')
-	backend := if backend_pos == -1 { '.c' } else { args_before[backend_pos + 1] } // this giant mess because closures are not implemented
+	backend := if backend_pos == -1 { '.c' } else { args_before[backend_pos + 1] }
 
 	mut ts := testing.new_test_session(args_before.join(' '), true)
+	ts.exec_mode = .compile_and_run
 	ts.fail_fast = ctx.fail_fast
 	for targ in args_after {
 		if os.is_dir(targ) {
@@ -152,6 +153,9 @@ fn (mut ctx Context) should_test(path string, backend string) ShouldTestStatus {
 	if path.ends_with('_test.v') {
 		return ctx.should_test_when_it_contains_matching_fns(path, backend)
 	}
+	if path.ends_with('_test.c.v') {
+		return ctx.should_test_when_it_contains_matching_fns(path, backend)
+	}
 	if path.ends_with('_test.js.v') {
 		if testing.is_node_present {
 			return ctx.should_test_when_it_contains_matching_fns(path, backend)