| 1 | module testing |
| 2 | |
| 3 | import os |
| 4 | import time |
| 5 | import term |
| 6 | import strings |
| 7 | import runtime |
| 8 | |
| 9 | pub const empty = term.header(' ', ' ') |
| 10 | |
| 11 | // TODO: AGAIN --- this !!!*reliably*!!! fails compilation of `v cmd/tools/vbuild-examples.v` with a cgen error, without `-no-parallel`: |
| 12 | // pub const report_running_period_ms = os.getenv_opt('VTEST_REPORT_RUNNING_PERIOD_MS') or { '60000' }.int() * time.millisecond |
| 13 | |
| 14 | pub const report_running_period_ms = get_report_running_period_ms() |
| 15 | |
| 16 | fn get_report_running_period_ms() time.Duration { |
| 17 | return os.getenv_opt('VTEST_REPORT_RUNNING_PERIOD_MS') or { '300_000' }.int() * time.millisecond // 5 minutes by default |
| 18 | } |
| 19 | |
| 20 | // NormalReporter implements the interface testing.Reporter. |
| 21 | // It is used by default by `v test .` |
| 22 | // It was extracted by the original non customiseable output implementation directly in cmd/tools/modules/testing/common.v |
| 23 | pub struct NormalReporter { |
| 24 | mut: |
| 25 | vroot string |
| 26 | runtime time.Duration |
| 27 | comptime time.Duration |
| 28 | nfiles int |
| 29 | njobs int |
| 30 | // |
| 31 | running shared map[string]LogMessage |
| 32 | compiling shared map[string]LogMessage |
| 33 | rtimes shared []TaskDuration |
| 34 | ctimes shared []TaskDuration |
| 35 | } |
| 36 | |
| 37 | pub fn (mut r NormalReporter) session_start(message string, mut ts TestSession) { |
| 38 | r.vroot = ts.vroot.replace('\\', '/') + '/' |
| 39 | header(message) |
| 40 | r.nfiles = ts.files.len |
| 41 | r.njobs = runtime.nr_jobs() |
| 42 | spawn r.report_current_running_and_compiling_status_periodically() |
| 43 | } |
| 44 | |
| 45 | fn (r &NormalReporter) report_current_running_and_compiling_status_periodically() { |
| 46 | if report_running_period_ms == 0 { |
| 47 | return |
| 48 | } |
| 49 | mut start_t := time.now() |
| 50 | mut pi := 0 |
| 51 | mut ccompiling := map[string]LogMessage{} |
| 52 | mut crunning := map[string]LogMessage{} |
| 53 | mut sb := strings.new_builder(1024) |
| 54 | for { |
| 55 | pi++ |
| 56 | time.sleep(report_running_period_ms) |
| 57 | t := time.now() |
| 58 | rlock r.compiling { |
| 59 | ccompiling = r.compiling.clone() |
| 60 | } |
| 61 | rlock r.running { |
| 62 | crunning = r.running.clone() |
| 63 | } |
| 64 | ckeys := ccompiling.keys() |
| 65 | rkeys := crunning.keys() |
| 66 | sb.writeln('') |
| 67 | 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}') |
| 68 | for ik, k in ckeys { |
| 69 | cval := ccompiling[k] |
| 70 | sb.writeln(' >>>>> compiling ${ik + 1:2}/${ckeys.len:-2}, T: ${cval.flow_id:2}, started: ${t - cval.when:10} ago, `${k}`') |
| 71 | } |
| 72 | for ik, k in rkeys { |
| 73 | cval := crunning[k] |
| 74 | sb.writeln(' >>>>> running ${ik + 1:2}/${rkeys.len:-2}, T: ${cval.flow_id:2}, started: ${t - cval.when:10} ago, `${k}`') |
| 75 | } |
| 76 | sb.writeln('') |
| 77 | eprint(sb.str()) // write everything at once, to minimise the chance of interference with the normal output of `v test` |
| 78 | } |
| 79 | } |
| 80 | |
| 81 | fn (r &NormalReporter) show_longest(label string, limit int, kind TaskKind) { |
| 82 | if limit <= 0 { |
| 83 | return |
| 84 | } |
| 85 | println('> Longest ${limit} by ${label}:') |
| 86 | mut tasks := []TaskDuration{cap: r.nfiles} |
| 87 | match kind { |
| 88 | .comptime { |
| 89 | rlock r.ctimes { |
| 90 | tasks << r.ctimes |
| 91 | } |
| 92 | } |
| 93 | .runtime { |
| 94 | rlock r.rtimes { |
| 95 | tasks << r.rtimes |
| 96 | } |
| 97 | } |
| 98 | .totaltime { |
| 99 | mut tall := []TaskDuration{} |
| 100 | rlock r.rtimes { |
| 101 | tall << r.rtimes |
| 102 | } |
| 103 | rlock r.ctimes { |
| 104 | tall << r.ctimes |
| 105 | } |
| 106 | mut mall := map[string]TaskDuration{} |
| 107 | for task in tall { |
| 108 | if current := mall[task.path] { |
| 109 | mall[task.path].duration = current.duration + task.duration |
| 110 | continue |
| 111 | } |
| 112 | mall[task.path] = task |
| 113 | } |
| 114 | tasks = mall.values() |
| 115 | } |
| 116 | } |
| 117 | |
| 118 | tasks.sort(a.duration > b.duration) |
| 119 | for tidx, task in tasks { |
| 120 | npath := task.path.replace('\\', '/').replace(r.vroot, '') |
| 121 | println(' ${tidx + 1:3} | ${task.duration:10s} | ${npath}') |
| 122 | if tidx + 1 >= limit { |
| 123 | break |
| 124 | } |
| 125 | } |
| 126 | } |
| 127 | |
| 128 | pub fn (r &NormalReporter) session_stop(message string, mut ts TestSession) { |
| 129 | r.show_longest('compilation time', show_longest_by_comptime, .comptime) |
| 130 | r.show_longest('run time', show_longest_by_runtime, .runtime) |
| 131 | r.show_longest('total time', show_longest_by_totaltime, .totaltime) |
| 132 | println('${ts.benchmark.total_message(message)} Comptime: ${r.comptime.microseconds() / 1000} ms. Runtime: ${r.runtime.microseconds() / 1000} ms.') |
| 133 | } |
| 134 | |
| 135 | // the most general form; it may be useful for other reporters |
| 136 | // in the normal one, it currently does nothing |
| 137 | pub fn (mut r NormalReporter) report(index int, message LogMessage) { |
| 138 | // eprintln('> ${@METHOD} index: ${index} | message: ${message}') |
| 139 | if message.kind == .compile_begin { |
| 140 | lock r.compiling { |
| 141 | r.compiling[message.file] = message |
| 142 | } |
| 143 | } |
| 144 | if message.kind == .compile_end { |
| 145 | r.comptime += message.took |
| 146 | lock r.ctimes { |
| 147 | r.ctimes << TaskDuration{message.file, message.took} |
| 148 | } |
| 149 | lock r.compiling { |
| 150 | r.compiling.delete(message.file) |
| 151 | } |
| 152 | } |
| 153 | if message.kind == .cmd_end { |
| 154 | lock r.rtimes { |
| 155 | r.rtimes << TaskDuration{message.file, message.took} |
| 156 | } |
| 157 | r.runtime += message.took |
| 158 | } |
| 159 | if message.kind == .cmd_begin { |
| 160 | lock r.running { |
| 161 | r.running[message.file] = message |
| 162 | } |
| 163 | } |
| 164 | if message.kind == .cmd_end { |
| 165 | lock r.running { |
| 166 | r.running.delete(message.file) |
| 167 | } |
| 168 | } |
| 169 | } |
| 170 | |
| 171 | pub fn (r NormalReporter) report_stop() { |
| 172 | // eprintln('> ${@METHOD}') |
| 173 | eprintln('') |
| 174 | } |
| 175 | |
| 176 | // progress will show the given message normally |
| 177 | // TODO: reconsider if these should be public: |
| 178 | pub fn (r NormalReporter) progress(index int, message string) { |
| 179 | eprintln(message) |
| 180 | } |
| 181 | |
| 182 | // in progress mode, the last line will be rewritten many times, and does not end with \n |
| 183 | // the \n will be printed just once when some progress has been made. |
| 184 | pub fn (r NormalReporter) update_last_line(index int, message string) { |
| 185 | print('\r${empty}\r${message}') |
| 186 | flush_stdout() |
| 187 | } |
| 188 | |
| 189 | pub fn (r NormalReporter) update_last_line_and_move_to_next(index int, message string) { |
| 190 | // the last \n is needed, so SKIP/FAIL messages |
| 191 | // will not get overwritten by the OK ones |
| 192 | eprint('\r${empty}\r${message}\n') |
| 193 | } |
| 194 | |
| 195 | pub fn (r NormalReporter) message(index int, message string) { |
| 196 | eprintln(message) |
| 197 | } |
| 198 | |
| 199 | pub fn (r NormalReporter) divider() { |
| 200 | h_divider() |
| 201 | } |
| 202 | |
| 203 | // |
| 204 | |
| 205 | pub fn (r NormalReporter) worker_threads_start(files []string, mut ts TestSession) { |
| 206 | // eprintln('> ${@METHOD}') |
| 207 | } |
| 208 | |
| 209 | pub fn (r NormalReporter) worker_threads_finish(mut ts TestSession) { |
| 210 | // eprintln('> ${@METHOD}') |
| 211 | } |
| 212 | |
| 213 | pub fn (r NormalReporter) list_of_failed_commands(failed_cmds []string) { |
| 214 | for i, cmd in failed_cmds { |
| 215 | eprintln(term.failed('To reproduce just failure ${i + 1} run:') + ' ${cmd}') |
| 216 | } |
| 217 | if failed_cmds.len > 0 { |
| 218 | vflags := os.getenv('VFLAGS') |
| 219 | if vflags != '' { |
| 220 | eprintln(term.failed('VFLAGS was: "${vflags}"')) |
| 221 | } |
| 222 | } |
| 223 | } |
| 224 | |
| 225 | enum TaskKind { |
| 226 | comptime |
| 227 | runtime |
| 228 | totaltime |
| 229 | } |
| 230 | |
| 231 | struct TaskDuration { |
| 232 | mut: |
| 233 | path string |
| 234 | duration time.Duration |
| 235 | } |
| 236 | |