From 99a587af9513b581dca19a12389b35e40818d4f6 Mon Sep 17 00:00:00 2001 From: Delyan Angelov Date: Tue, 4 Feb 2025 10:33:51 +0200 Subject: [PATCH] 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) --- cmd/tools/modules/testing/output_normal.v | 50 ++++++++++++++++++++++- cmd/tools/vtest-self.v | 6 +-- vlib/v/builder/cc.v | 4 +- vlib/v/builder/msvc_windows.v | 1 + 4 files changed, 55 insertions(+), 6 deletions(-) diff --git a/cmd/tools/modules/testing/output_normal.v b/cmd/tools/modules/testing/output_normal.v index f789b27b60dbe2..d8de7e9539093f 100644 --- a/cmd/tools/modules/testing/output_normal.v +++ b/cmd/tools/modules/testing/output_normal.v @@ -2,9 +2,19 @@ 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 @@ -12,13 +22,39 @@ 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() { diff --git a/cmd/tools/vtest-self.v b/cmd/tools/vtest-self.v index 08fc5656ecdc2f..cf9f16e3d8277b 100644 --- a/cmd/tools/vtest-self.v +++ b/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) } } diff --git a/vlib/v/builder/cc.v b/vlib/v/builder/cc.v index e833045f537fcf..e9267841d69f0f 100644 --- a/vlib/v/builder/cc.v +++ b/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}') diff --git a/vlib/v/builder/msvc_windows.v b/vlib/v/builder/msvc_windows.v index d2d563048b7982..3473c178786bc4 100644 --- a/vlib/v/builder/msvc_windows.v +++ b/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') }