tools: let v test . show the running _test.v files each minute (set by VTEST_REPORT_RUNNING_PERIOD_MS); diagnose stuck windows gcc CI jobs (#23649)

Author: spytheman

cmd/tools/modules/testing/output_normal.v

@@ -2,23 +2,59 @@ module testing
 
 import time
 import term
+import os
 
 pub const empty = term.header(' ', ' ')
 
+// TODO: AGAIN --- this !!!*reliably*!!! fails compilation of `v cmd/tools/vbuild-examples.v` with a cgen error, without `-no-parallel`:
+// pub const report_running_period_ms = os.getenv_opt('VTEST_REPORT_RUNNING_PERIOD_MS') or { '60000' }.int() * time.millisecond
+
+pub const report_running_period_ms = get_report_running_period_ms()
+
+fn get_report_running_period_ms() time.Duration {
+	return os.getenv_opt('VTEST_REPORT_RUNNING_PERIOD_MS') or { '60000' }.int() * time.millisecond
+}
+
 // NormalReporter implements the interface testing.Reporter.
 // 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
+	running  shared map[string]LogMessage
+	nfiles   int
 }
 
-pub fn (r NormalReporter) session_start(message string, mut ts TestSession) {
+pub fn (mut r NormalReporter) session_start(message string, mut ts TestSession) {
 	header(message)
+	r.nfiles = ts.files.len
+	spawn r.report_current_running_status_periodically()
 }
 
-pub fn (r NormalReporter) session_stop(message string, mut ts TestSession) {
+fn (r &NormalReporter) report_current_running_status_periodically() {
+	if report_running_period_ms == 0 {
+		return
+	}
+	mut start_t := time.now()
+	mut pi := 0
+	mut crunning := map[string]LogMessage{}
+	for {
+		pi++
+		time.sleep(report_running_period_ms)
+		t := time.now()
+		rlock r.running {
+			crunning = r.running.clone()
+		}
+		keys := crunning.keys()
+		eprintln('       >>>>> ${t.format_ss_micro()} | period ${pi:2} | started: ${t - start_t:10} ago | total files: ${r.nfiles:5} | vjobs: ${' | running ${keys.len} _test.v files'}')
+		for ik, k in keys {
+			eprintln('       >>>>>     ${ik + 1:4}/${keys.len:-4}, T: ${crunning[k].flow_id:3}, started: ${t - crunning[k].when:10} ago, `${k}`')
+		}
+	}
+}
+
+pub fn (r &NormalReporter) session_stop(message string, mut ts TestSession) {
 	println('${ts.benchmark.total_message(message)} Comptime: ${r.comptime.microseconds() / 1000} ms. Runtime: ${r.runtime.microseconds() / 1000} ms.')
 }
 
@@ -32,6 +68,16 @@ pub fn (mut r NormalReporter) report(index int, message LogMessage) {
 	if message.kind == .cmd_end {
 		r.runtime += message.took
 	}
+	if message.kind == .cmd_begin {
+		lock r.running {
+			r.running[message.file] = message
+		}
+	}
+	if message.kind == .cmd_end {
+		lock r.running {
+			r.running.delete(message.file)
+		}
+	}
 }
 
 pub fn (r NormalReporter) report_stop() {

cmd/tools/vtest-self.v

@@ -429,7 +429,6 @@ fn main() {
 	}
 	// dump(cfg)
 	title := 'testing: ${cfg.test_dirs.join(', ')}'
-	testing.eheader(title)
 	mut tpaths := map[string]bool{}
 	mut tpaths_ref := &tpaths
 	for dir in cfg.test_dirs {
@@ -541,10 +540,11 @@ fn main() {
 		exit(1)
 	}
 	tsession.skip_files = tsession.skip_files.map(os.abs_path)
+	tsession.session_start(title)
 	tsession.test()
-	eprintln(tsession.benchmark.total_message(title))
+	tsession.session_stop(title)
 	if tsession.benchmark.nfail > 0 {
-		eprintln('\nWARNING: failed ${tsession.benchmark.nfail} times.\n')
+		eprintln('\nError: failed ${tsession.benchmark.nfail} times.\n')
 		exit(1)
 	}
 }

vlib/v/builder/cc.v

@@ -19,6 +19,8 @@ const c_verror_message_marker = 'VERROR_MESSAGE '
 
 const current_os = os.user_os()
 
+const c_compilation_error_title = 'C compilation error'
+
 fn (mut v Builder) show_c_compiler_output(ccompiler string, res os.Result) {
 	header := '======== Output of the C Compiler (${ccompiler}) ========'
 	println(header)
@@ -58,7 +60,7 @@ fn (mut v Builder) post_process_c_compiler_output(ccompiler string, res os.Resul
 			trimmed_output := res.output.trim_space()
 			original_elines := trimmed_output.split_into_lines()
 			elines := error_context_lines(trimmed_output, 'error:', 1, 12)
-			header := '================== C compilation error (from ${ccompiler}): =============='
+			header := '================== ${c_compilation_error_title} (from ${ccompiler}): =============='
 			println(header)
 			for eline in elines {
 				println('cc: ${eline}')

vlib/v/builder/msvc_windows.v

@@ -373,6 +373,7 @@ pub fn (mut v Builder) cc_msvc() {
 	util.timing_start('C msvc')
 	res := os.execute(cmd)
 	if res.exit_code != 0 {
+		eprintln('================== ${c_compilation_error_title} (from msvc): ==============')
 		eprintln(res.output)
 		verror('msvc error')
 	}