v2 / cmd / tools / modules / testing / output_normal.v
235 lines · 211 sloc · 6.37 KB · 8e35f4d9848f7ad35d857a187dddbfd2eca5e19d
Raw
1module testing
2
3import os
4import time
5import term
6import strings
7import runtime
8
9pub 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
14pub const report_running_period_ms = get_report_running_period_ms()
15
16fn 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
23pub struct NormalReporter {
24mut:
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
37pub 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
45fn (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
81fn (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
128pub 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
137pub 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
171pub 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:
178pub 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.
184pub fn (r NormalReporter) update_last_line(index int, message string) {
185 print('\r${empty}\r${message}')
186 flush_stdout()
187}
188
189pub 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
195pub fn (r NormalReporter) message(index int, message string) {
196 eprintln(message)
197}
198
199pub fn (r NormalReporter) divider() {
200 h_divider()
201}
202
203//
204
205pub fn (r NormalReporter) worker_threads_start(files []string, mut ts TestSession) {
206 // eprintln('> ${@METHOD}')
207}
208
209pub fn (r NormalReporter) worker_threads_finish(mut ts TestSession) {
210 // eprintln('> ${@METHOD}')
211}
212
213pub 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
225enum TaskKind {
226 comptime
227 runtime
228 totaltime
229}
230
231struct TaskDuration {
232mut:
233 path string
234 duration time.Duration
235}
236