tools: improve v test by updating VTEST_REPORT_RUNNING_PERIOD_MS to 5 minutes by default, and adding stats for the currently compiling tests too

spytheman · spytheman · commit 9649af30e2c5 · 2025-02-17T11:43:29.000+02:00
diff --git a/cmd/tools/modules/testing/output_normal.v b/cmd/tools/modules/testing/output_normal.v
@@ -1,8 +1,10 @@
 module testing
 
+import os
 import time
 import term
-import os
+import strings
+import runtime
 
 pub const empty = term.header(' ', ' ')
 
@@ -12,7 +14,7 @@ pub const empty = term.header(' ', ' ')
 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
+	return os.getenv_opt('VTEST_REPORT_RUNNING_PERIOD_MS') or { '300_000' }.int() * time.millisecond // 5 minutes by default
 }
 
 // NormalReporter implements the interface testing.Reporter.
@@ -22,35 +24,53 @@ pub struct NormalReporter {
 mut:
 	runtime  time.Duration
 	comptime time.Duration
-	running  shared map[string]LogMessage
 	nfiles   int
+	njobs    int
+	//
+	running   shared map[string]LogMessage
+	compiling shared map[string]LogMessage
 }
 
 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()
+	r.njobs = runtime.nr_jobs()
+	spawn r.report_current_running_and_compiling_status_periodically()
 }
 
-fn (r &NormalReporter) report_current_running_status_periodically() {
+fn (r &NormalReporter) report_current_running_and_compiling_status_periodically() {
 	if report_running_period_ms == 0 {
 		return
 	}
 	mut start_t := time.now()
 	mut pi := 0
+	mut ccompiling := map[string]LogMessage{}
 	mut crunning := map[string]LogMessage{}
+	mut sb := strings.new_builder(1024)
 	for {
 		pi++
 		time.sleep(report_running_period_ms)
 		t := time.now()
+		rlock r.compiling {
+			ccompiling = r.compiling.clone()
+		}
 		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}`')
+		ckeys := ccompiling.keys()
+		rkeys := crunning.keys()
+		sb.writeln('')
+		sb.writeln('       >>>>> ${t.format_ss_micro()} | period ${pi:2} | started: ${t - start_t:10} ago | vjobs: ${r.njobs} | _test.v files: ${r.nfiles:5} | C: ${ckeys.len:3} | R: ${rkeys.len:3}')
+		for ik, k in ckeys {
+			cval := ccompiling[k]
+			sb.writeln('       >>>>> compiling ${ik + 1:2}/${ckeys.len:-2}, T: ${cval.flow_id:2}, started: ${t - cval.when:10} ago, `${k}`')
+		}
+		for ik, k in rkeys {
+			cval := crunning[k]
+			sb.writeln('       >>>>>   running ${ik + 1:2}/${rkeys.len:-2}, T: ${cval.flow_id:2}, started: ${t - cval.when:10} ago, `${k}`')
 		}
+		sb.writeln('')
+		eprint(sb.str()) // write everything at once, to minimise the chance of interference with the normal output of `v test`
 	}
 }
 
@@ -62,8 +82,16 @@ pub fn (r &NormalReporter) session_stop(message string, mut ts TestSession) {
 // in the normal one, it currently does nothing
 pub fn (mut r NormalReporter) report(index int, message LogMessage) {
 	// eprintln('> ${@METHOD} index: $index | message: $message')
+	if message.kind == .compile_begin {
+		lock r.compiling {
+			r.compiling[message.file] = message
+		}
+	}
 	if message.kind == .compile_end {
 		r.comptime += message.took
+		lock r.compiling {
+			r.compiling.delete(message.file)
+		}
 	}
 	if message.kind == .cmd_end {
 		r.runtime += message.took
