v / cmd / tools / vrepeat.v
516 lines · 487 sloc · 16.63 KB · e2e5cf8db56f3562c7baa735061690be936bdf3e
Raw
1module main
2
3import os
4import flag
5import time
6import math
7import term
8
9const tred = term.red
10const tbold = term.bold
11const tgray = term.gray
12const tcyan = term.cyan
13const tgreen = term.green
14const tbcyan = term.bright_cyan
15const tbblue = term.bright_blue
16const tdivider = term.h_divider
17
18fn c(cfn fn (string) string, s string) string {
19 return term.colorize(cfn, s)
20}
21
22const hline = '-'.repeat(80)
23
24fn show_failure_output(output string) {
25 eprintln(hline)
26 eprint(output)
27 eprintln(hline)
28}
29
30const max_fail_percent = 100 * 1000
31const max_time = 60 * 1000 // ms
32
33const performance_regression_label = 'Performance regression detected, failing since '
34
35struct Aints {
36 values []i64 // uS
37mut:
38 imin i64 // uS
39 imax i64 // uS
40 average f64
41 stddev f64
42 nmins int // number of discarded fastest results
43 nmaxs int // number of discarded slowest results
44}
45
46struct CmdResult {
47mut:
48 runs int
49 cmd string
50 icmd int
51 outputs []string
52 ous map[string][]i64 // uS
53 summary map[string]Aints
54 timings []i64
55 atiming Aints
56}
57
58struct Context {
59mut:
60 run_count int
61 repeats_count int
62 current_run int
63 series int
64 warmup int
65 show_help bool
66 show_output bool
67 is_silent bool // do not print progress lines
68 use_newline bool // use \n instead of \r, so the last line is not overwritten
69 fail_on_regress_percent int
70 fail_on_maxtime int // in ms
71 verbose bool
72 commands []string
73 results []CmdResult
74 cmd_template string // {T} will be substituted with the current command
75 cmd_params map[string][]string
76 cline string // a terminal clearing line
77 cgoback string
78 nmins int // number of minimums to discard
79 nmaxs int // number of maximums to discard
80 ignore_failed bool // ignore commands that exit with != 0 exit code
81 no_vexe_setenv bool // do not change the VEXE variable
82
83 fail_count map[string]int // how many times a command has failed so far. Only the first failure output is shown.
84 repeat_timer time.StopWatch = time.new_stopwatch()
85}
86
87fn new_aints(ovals []i64, extreme_mins int, extreme_maxs int) Aints {
88 mut res := Aints{
89 values: ovals // remember the original values
90 nmins: extreme_mins
91 nmaxs: extreme_maxs
92 }
93 // discard the extremes, if needed:
94 mut vals := []i64{}
95 for x in ovals {
96 vals << x
97 }
98 vals.sort()
99 if extreme_mins > 0 {
100 vals = vals#[extreme_mins..].clone()
101 }
102 if extreme_maxs > 0 {
103 vals = vals#[..-extreme_maxs].clone()
104 }
105 // statistical processing of the remaining values:
106 mut sum := i64(0)
107 mut imin := i64(max_i64)
108 mut imax := i64(-max_i64)
109 for i in vals {
110 sum += i
111 if i < imin {
112 imin = i
113 }
114 if i > imax {
115 imax = i
116 }
117 }
118 res.imin = imin
119 res.imax = imax
120 if vals.len > 0 {
121 res.average = sum / f64(vals.len)
122 }
123
124 mut devsum := f64(0.0)
125 for i in vals {
126 x := f64(i) - res.average
127 devsum += (x * x)
128 }
129 res.stddev = math.sqrt(devsum / f64(vals.len))
130 // eprintln('\novals: ${ovals}\n vals: ${vals}\n vals.len: ${vals.len} | res.imin: ${res.imin} | res.imax: ${res.imax} | res.average: ${res.average} | res.stddev: ${res.stddev}')
131 return res
132}
133
134fn bold(s string) string {
135 return c(tgreen, c(tbold, s))
136}
137
138fn (a Aints) str() string {
139 avg := bold('${a.average / 1000:6.1f}ms')
140 tdev := c(tred, '${a.stddev / 1000:6.1f}ms')
141 baseline := '${avg} ± σ: ${tdev},'
142 tmin := c(tbcyan, '${f64(a.imin) / 1000:6.1f}ms')
143 tmax := c(tbblue, '${f64(a.imax) / 1000:6.1f}ms')
144 return '${baseline:-46s} ${tmin}…${tmax}'
145}
146
147fn flushed_print(s string) {
148 print(s)
149 flush_stdout()
150}
151
152fn (mut context Context) clear_line() {
153 if context.is_silent {
154 return
155 }
156 flushed_print(context.cline)
157}
158
159fn (mut context Context) flushed_print(s string) {
160 if context.is_silent {
161 return
162 }
163 flushed_print(s)
164}
165
166fn (mut context Context) expand_all_commands(commands []string) []string {
167 mut all_commands := []string{}
168 for cmd in commands {
169 maincmd := context.cmd_template.replace('{T}', cmd)
170 mut substituted_commands := []string{}
171 substituted_commands << maincmd
172 for paramk, paramlist in context.cmd_params {
173 for paramv in paramlist {
174 mut new_substituted_commands := []string{}
175 for cscmd in substituted_commands {
176 scmd := cscmd.replace('{${paramk}}', paramv)
177 new_substituted_commands << scmd
178 }
179 substituted_commands << new_substituted_commands
180 }
181 }
182 all_commands << substituted_commands
183 }
184 mut unique := map[string]int{}
185 for x in all_commands {
186 if x.contains('{') && x.contains('}') {
187 continue
188 }
189 unique[x] = 1
190 }
191 return unique.keys()
192}
193
194fn (mut context Context) run() {
195 for si in 0 .. context.series {
196 for icmd, cmd in context.commands {
197 mut runs := 0
198 mut sum := i64(0)
199 mut avg := f64(0)
200 mut duration := i64(0)
201 mut oldres := ''
202 series_label := '${icmd + 1}/${context.commands.len}, ${si + 1}/${context.series}'
203 line_prefix := '${context.cgoback}Command: ${c(tgray, cmd)}, ${series_label:9}'
204 if context.series != 1 || context.commands.len != 1 {
205 context.flushed_print(line_prefix)
206 }
207 if context.warmup > 0 {
208 for i in 0 .. context.warmup {
209 context.flushed_print('${line_prefix}, warm up run: ${i + 1:4}/${context.warmup:-4}, took: ${f64(duration) / 1000:6.1f}ms ...')
210 mut sw := time.new_stopwatch()
211 res := os.execute(cmd)
212 duration = i64(sw.elapsed().microseconds())
213 mut should_show_fail_output := false
214 if res.exit_code != 0 && !context.ignore_failed {
215 if context.fail_count[cmd] == 0 {
216 should_show_fail_output = true
217 }
218 context.fail_count[cmd]++
219 }
220 if should_show_fail_output {
221 eprintln('\nCommand exited with exit code: ${res.exit_code} in ${f64(duration) / 1000:6.1f}ms .')
222 eprintln('Use -e or --ignore to ignore the failed commands.')
223 eprintln('The failed cmd was: `${c(tred, cmd)}` ; cmd output:')
224 show_failure_output(res.output)
225 }
226 }
227 }
228 for i in 0 .. context.run_count {
229 mut sw := time.new_stopwatch()
230 res := os.execute(cmd)
231 duration = i64(sw.elapsed().microseconds())
232 //
233 mut should_show_fail_output := false
234 if res.exit_code != 0 && !context.ignore_failed {
235 if context.fail_count[cmd] == 0 {
236 should_show_fail_output = true
237 }
238 context.fail_count[cmd]++
239 }
240 sum += duration
241 runs++
242 avg = (f64(sum) / f64(i + 1))
243 cavg := '${avg / 1000:9.3f}ms'
244 context.flushed_print('${line_prefix}, current average: ${c(tgreen, cavg)}, run ${
245 i + 1:4}/${context.run_count:-4}, took: ${f64(duration) / 1000:6} ms')
246 if context.show_output {
247 context.flushed_print(' | result: ${oldres:s}')
248 }
249 trimmed_output := res.output.trim_right('\r\n')
250 trimmed_normalized := trimmed_output.replace('\r\n', '\n')
251 lines := trimmed_normalized.split('\n')
252 context.results[icmd].outputs << lines
253 context.results[icmd].timings << duration
254 oldres = res.output.replace('\n', ' ')
255 if should_show_fail_output {
256 eprintln('\n${i + 1:10} non 0 exit code for cmd: ${cmd}; cmd output:')
257 show_failure_output(res.output)
258 }
259 }
260 context.results[icmd].cmd = cmd
261 context.results[icmd].icmd = icmd
262 context.results[icmd].runs += runs
263 context.results[icmd].atiming = new_aints(context.results[icmd].timings, context.nmins,
264 context.nmaxs)
265 context.clear_line()
266 context.flushed_print(context.cgoback)
267 context.show_timings_details(si, icmd, cmd)
268 }
269 }
270 // create full summaries, taking account of all runs
271 for icmd in 0 .. context.results.len {
272 mut new_full_summary := map[string]Aints{}
273 for k, v in context.results[icmd].ous {
274 new_full_summary[k] = new_aints(v, context.nmins, context.nmaxs)
275 }
276 context.results[icmd].summary = new_full_summary.clone()
277 }
278}
279
280fn (mut context Context) show_timings_details(si int, icmd int, cmd string) {
281 if !cmd.contains('-show-timings') {
282 return
283 }
284 // This is specific to V compilations, when they are run with `-show-timings`,
285 // which will show more details about each compilation stage.
286 mut m := map[string][]i64{}
287 ioutputs := context.results[icmd].outputs
288 for o in ioutputs {
289 x := o.split('ms ')
290 if x.len > 1 {
291 v := i64(x[0].trim_left(' ').f64() * 1000)
292 k := x[1].all_before(' ')
293 if k !in m {
294 m[k] = []i64{}
295 }
296 m[k] << v
297 }
298 }
299 if m.len == 0 {
300 return
301 }
302 println('> Timing details for series ${si + 1}, icmd: ${icmd + 1}, cmd: `${cmd}`:')
303 mut summary := map[string]Aints{}
304 for k, v in m {
305 // show a temporary summary for the current series/cmd cycle
306 s := new_aints(v, context.nmins, context.nmaxs)
307 println(' ${k:-40s}: ${s}')
308 summary[k] = s
309 }
310 // merge current raw results to the previous ones
311 old_ous := context.results[icmd].ous.clone()
312 mut new_ous := map[string][]i64{}
313 for k, v in m {
314 if old_ous[k].len == 0 {
315 new_ous[k] = v
316 } else {
317 new_ous[k] = old_ous[k].clone()
318 new_ous[k] << v
319 }
320 }
321 context.results[icmd].ous = new_ous.clone()
322}
323
324fn compare_by_average(a &CmdResult, b &CmdResult) int {
325 if a.atiming.average < b.atiming.average {
326 return -1
327 }
328 if a.atiming.average > b.atiming.average {
329 return 1
330 }
331 return 0
332}
333
334fn (mut context Context) show_diff_summary() {
335 if context.results.len == 0 {
336 eprintln('no results')
337 exit(5)
338 }
339 base := context.results[0].atiming.average
340 context.results.sort_with_compare(compare_by_average)
341 mut first_cmd_percentage := f64(100.0)
342 mut first_marker := ''
343 if context.results.len == 1 {
344 gcmd := c(tgreen, context.results[0].cmd)
345 context.show_summary_title('${context.results[0].atiming}, ${context.series} series, ${context.run_count} runs for ${gcmd}')
346 } else {
347 context.show_summary_title('Summary after ${context.series} series x ${context.run_count} runs (%s are relative to first command, or `base`)')
348 for i, r in context.results {
349 first_marker = ' '
350 cpercent := (r.atiming.average / base) * 100 - 100
351 if r.icmd == 0 {
352 first_marker = bold('>')
353 first_cmd_percentage = cpercent
354 }
355 mut comparison := ''
356 if r.atiming.average != base {
357 comparison = '${cpercent:+8.1f}%'
358 }
359 mut tcomparison := ' base '
360 if r.atiming.average != base {
361 tcomparison = readable_comparison(r.atiming.average, base, cpercent)
362 }
363 gcmd := c(tgreen, r.cmd)
364 println(' ${first_marker}${(i + 1):3} ${comparison:7} ${tcomparison:5} ${r.atiming} `${gcmd}`')
365 }
366 }
367 $if debugcontext ? {
368 println('context: ${context}')
369 }
370 if base > f64(context.fail_on_maxtime * 1000) {
371 flushed_print(performance_regression_label)
372 println('average time: ${base / 1000:6.1f} ms > ${context.fail_on_maxtime} ms threshold.')
373 exit(2)
374 }
375 if context.fail_on_regress_percent == max_fail_percent || context.results.len < 2 {
376 return
377 }
378 fail_threshold_max := f64(context.fail_on_regress_percent)
379 if first_cmd_percentage > fail_threshold_max {
380 flushed_print(performance_regression_label)
381 println('${first_cmd_percentage:5.1f}% > ${fail_threshold_max:5.1f}% threshold.')
382 exit(3)
383 }
384}
385
386fn readable_comparison(tcurrent f64, tbase f64, cpercent f64) string {
387 is_same := math.abs(cpercent) <= 0.15
388 mut label := '~same~'
389 if tcurrent < tbase {
390 if !is_same {
391 label = c(tgreen, 'faster')
392 }
393 return '${tbase / tcurrent:6.2f}x ${label}'
394 } else {
395 if !is_same {
396 label = c(tcyan, 'slower')
397 }
398 return '${tcurrent / tbase:6.2f}x ${label}'
399 }
400}
401
402fn (mut context Context) show_summary_title(line string) {
403 mut msg := [line]
404 if context.nmins > 0 {
405 msg << 'discard mins: ${context.nmins:2}'
406 }
407 if context.nmaxs > 0 {
408 msg << 'discard maxs: ${context.nmaxs:2}'
409 }
410 if context.repeats_count > 1 {
411 msg << 'repeat: ${context.current_run}/${context.repeats_count}, took: ${f64(context.repeat_timer.elapsed().microseconds()) / 1000:8.3f} ms'
412 context.repeat_timer.restart()
413 }
414 println(msg.join(', '))
415}
416
417fn (mut context Context) parse_options() ! {
418 mut fp := flag.new_flag_parser(os.args#[1..])
419 fp.application(os.file_name(os.executable()))
420 fp.version('0.0.3')
421 fp.description('Repeat command(s) and collect statistics.\nNote: quote each command (argument), when it contains spaces.')
422 fp.arguments_description('CMD1 CMD2 ...')
423 fp.skip_executable()
424 fp.limit_free_args_to_at_least(1)!
425 context.show_help = fp.bool('help', `h`, false, 'Show this help screen.')
426 context.run_count = fp.int('runs', `r`, 10, 'Run count. Default: 10')
427 context.repeats_count = fp.int('repeats', `R`, 1,
428 'Repeats count (it repeats everything, including reporting). Default: 1')
429 context.warmup = fp.int('warmup', `w`, 2,
430 'Warmup run count. These are done *at the start* of each series, and the timings are ignored. Default: 2')
431 context.series = fp.int('series', `s`, 1,
432 'Series count. `-s 2 -r 4 a b` => aaaabbbbaaaabbbb, while `-s 3 -r 2 a b` => aabbaabbaabb. Default: 1')
433 context.ignore_failed = fp.bool('ignore', `e`, false,
434 'Ignore failed commands (returning a non 0 exit code).')
435 context.no_vexe_setenv = fp.bool('no_vexe_reset', `N`, false,
436 'Do not reset the VEXE env variable at the start. \n By default, VEXE will be set to "", to allow for measuring different V executables. Use this option to override it')
437 context.use_newline = fp.bool('newline', `n`, false,
438 'Use \\n, do not overwrite the last line. Produces more output, but easier to diagnose.')
439 context.is_silent = fp.bool('silent', `S`, false,
440 'Do not show progress lines, print only the final summary. Suitable for CIs.')
441 if os.getenv('VREPEAT_SILENT') != '' {
442 context.is_silent = true
443 }
444 context.show_output = fp.bool('output', `O`, false,
445 'Show command stdout/stderr in the progress indicator for each command. Note: slower, for verbose commands.')
446 context.verbose = fp.bool('verbose', `v`, false, 'Be more verbose.')
447 context.fail_on_maxtime = fp.int('max_time', `m`, max_time,
448 'Fail with exit code 2, when first cmd takes above M milliseconds (regression). Default: ${max_time}')
449 context.fail_on_regress_percent = fp.int('fail_percent', `f`, max_fail_percent,
450 'Fail with exit code 3, when first cmd is X% slower than the rest (regression). Default: ${max_fail_percent}')
451 context.cmd_template = fp.string('template', `t`, '{T}',
452 'Command template. {T} will be substituted with the current command. Default: {T}. \n Here is an example, that will produce and run 24 permutations = (3 for opt) x (2 for source) x (4 = v names):\n v repeat -p opt=-check-syntax,-check,"-o x.c" -p source=examples/hello_world.v,examples/hanoi.v --template "./{T} {opt} {source}" vold vnew vold_prod vnew_prod')
453 cmd_params := fp.string_multi('parameter', `p`,
454 'A parameter substitution list. `pp=val1,val2,val2` means that {pp} in the template, will be substituted with *each* of val1, val2, val3.')
455 context.nmins = fp.int('nmins', `i`, 0,
456 'Ignore the BOTTOM X results (minimum execution time). Makes the results more robust to performance flukes. Default: 0')
457 context.nmaxs = fp.int('nmaxs', `a`, 0,
458 'Ignore the TOP X results (maximum execution time). Makes the results more robust to performance flukes. Default: 0')
459 for p in cmd_params {
460 parts := p.split('=')
461 if parts.len > 1 {
462 context.cmd_params[parts[0].trim('{}')] = parts[1].split(',')
463 }
464 }
465 if context.show_help {
466 println(fp.usage())
467 exit(0)
468 }
469 commands := fp.finalize() or {
470 eprintln('Error: ${err}')
471 exit(1)
472 }
473 context.commands = context.expand_all_commands(commands)
474 context.reset_results()
475 if context.nmins >= context.run_count {
476 context.error_no_run_counts_to_report('${context.run_count - 1} bottom results with `-i ${context.nmins}`')
477 } else if context.nmaxs >= context.run_count {
478 context.error_no_run_counts_to_report('${context.run_count - 1} top results with `-a ${context.nmaxs}`')
479 } else if context.nmaxs + context.nmins >= context.run_count {
480 context.error_no_run_counts_to_report('${context.nmaxs + context.nmins - 1} results with `-i ${context.nmins}` and `-a ${context.nmaxs}`')
481 }
482 if context.use_newline {
483 context.cline = '\n'
484 context.cgoback = '\n'
485 } else {
486 context.cline = '\r' + tdivider('') + '\r'
487 context.cgoback = '\r'
488 }
489}
490
491fn (mut context Context) error_no_run_counts_to_report(detail string) {
492 eprintln('${bold('Warning:')} discarding more than ${detail}, with only `-r ${context.run_count}` runs, will leave you with no results to report at all.')
493}
494
495fn (mut context Context) reset_results() {
496 context.results = []CmdResult{len: context.commands.len, cap: 20, init: CmdResult{
497 outputs: []string{cap: 500}
498 timings: []i64{cap: 500}
499 }}
500}
501
502fn main() {
503 mut context := Context{}
504 context.parse_options()!
505 if !context.no_vexe_setenv {
506 // Make sure that we can measure various V executables
507 // without influencing them, by presetting VEXE
508 os.setenv('VEXE', '', true)
509 }
510 for i := 1; i <= context.repeats_count; i++ {
511 context.current_run = i
512 context.reset_results()
513 context.run()
514 context.show_diff_summary()
515 }
516}
517