| 1 | module benchmark |
| 2 | |
| 3 | import time |
| 4 | import term |
| 5 | import arrays |
| 6 | |
| 7 | const step_label_width = 5 |
| 8 | |
| 9 | pub const b_ok = term.ok_message('OK ') |
| 10 | pub const b_fail = term.fail_message('FAIL') |
| 11 | pub const b_skip = term.warn_message('SKIP') |
| 12 | pub const b_spent = term.ok_message('SPENT') |
| 13 | |
| 14 | pub struct Benchmark { |
| 15 | pub mut: |
| 16 | bench_timer time.StopWatch |
| 17 | verbose bool |
| 18 | no_cstep bool |
| 19 | step_timer time.StopWatch |
| 20 | ntotal int |
| 21 | nok int |
| 22 | nfail int |
| 23 | nskip int |
| 24 | nexpected_steps int |
| 25 | njobs int |
| 26 | cstep int |
| 27 | bok string |
| 28 | bfail string |
| 29 | measured_steps []string |
| 30 | step_data map[string][]f64 |
| 31 | } |
| 32 | |
| 33 | // new_benchmark returns a `Benchmark` instance on the stack. |
| 34 | pub fn new_benchmark() Benchmark { |
| 35 | return Benchmark{ |
| 36 | bench_timer: time.new_stopwatch() |
| 37 | verbose: true |
| 38 | } |
| 39 | } |
| 40 | |
| 41 | // new_benchmark_no_cstep returns a new `Benchmark` instance with step counting disabled. |
| 42 | pub fn new_benchmark_no_cstep() Benchmark { |
| 43 | return Benchmark{ |
| 44 | bench_timer: time.new_stopwatch() |
| 45 | verbose: true |
| 46 | no_cstep: true |
| 47 | } |
| 48 | } |
| 49 | |
| 50 | // new_benchmark_pointer returns a new `Benchmark` instance allocated on the heap. |
| 51 | // This is useful for long-lived use of `Benchmark` instances. |
| 52 | pub fn new_benchmark_pointer() &Benchmark { |
| 53 | return &Benchmark{ |
| 54 | bench_timer: time.new_stopwatch() |
| 55 | verbose: true |
| 56 | } |
| 57 | } |
| 58 | |
| 59 | // set_total_expected_steps sets the total amount of steps the benchmark is expected to take. |
| 60 | pub fn (mut b Benchmark) set_total_expected_steps(n int) { |
| 61 | b.nexpected_steps = n |
| 62 | } |
| 63 | |
| 64 | // stop stops the internal benchmark timer. |
| 65 | pub fn (mut b Benchmark) stop() { |
| 66 | b.bench_timer.stop() |
| 67 | } |
| 68 | |
| 69 | // step increases the step count by 1 and restarts the internal timer. |
| 70 | pub fn (mut b Benchmark) step() { |
| 71 | b.step_timer.restart() |
| 72 | if !b.no_cstep { |
| 73 | b.cstep++ |
| 74 | } |
| 75 | } |
| 76 | |
| 77 | // step_restart will restart the internal step timer. |
| 78 | // Note that the step count will *stay the same*. |
| 79 | // This method is useful, when you want to do some optional preparation |
| 80 | // after you have called .step(), so that the time for that optional |
| 81 | // preparation will *not* be added to the duration of the step. |
| 82 | pub fn (mut b Benchmark) step_restart() { |
| 83 | b.step_timer.restart() |
| 84 | } |
| 85 | |
| 86 | // fail increases the fail count by 1 and stops the internal timer. |
| 87 | pub fn (mut b Benchmark) fail() { |
| 88 | b.step_timer.stop() |
| 89 | b.ntotal++ |
| 90 | b.nfail++ |
| 91 | } |
| 92 | |
| 93 | // ok increases the ok count by 1 and stops the internal timer. |
| 94 | pub fn (mut b Benchmark) ok() { |
| 95 | b.step_timer.stop() |
| 96 | b.ntotal++ |
| 97 | b.nok++ |
| 98 | } |
| 99 | |
| 100 | // skip increases the skip count by 1 and stops the internal timer. |
| 101 | pub fn (mut b Benchmark) skip() { |
| 102 | b.step_timer.stop() |
| 103 | b.ntotal++ |
| 104 | b.nskip++ |
| 105 | } |
| 106 | |
| 107 | // fail_many increases the fail count by `n` and stops the internal timer. |
| 108 | pub fn (mut b Benchmark) fail_many(n int) { |
| 109 | b.step_timer.stop() |
| 110 | b.ntotal += n |
| 111 | b.nfail += n |
| 112 | } |
| 113 | |
| 114 | // ok_many increases the ok count by `n` and stops the internal timer. |
| 115 | pub fn (mut b Benchmark) ok_many(n int) { |
| 116 | b.step_timer.stop() |
| 117 | b.ntotal += n |
| 118 | b.nok += n |
| 119 | } |
| 120 | |
| 121 | // neither_fail_nor_ok stops the internal timer. |
| 122 | pub fn (mut b Benchmark) neither_fail_nor_ok() { |
| 123 | b.step_timer.stop() |
| 124 | } |
| 125 | |
| 126 | // start returns a new, running, instance of `Benchmark`. |
| 127 | // This is a shorthand for calling `new_benchmark().step()`. |
| 128 | pub fn start() Benchmark { |
| 129 | mut b := new_benchmark() |
| 130 | b.step() |
| 131 | return b |
| 132 | } |
| 133 | |
| 134 | // measure prints the current time spent doing `label`, since the benchmark was started, or since its last call. |
| 135 | pub fn (mut b Benchmark) measure(label string) i64 { |
| 136 | b.ok() |
| 137 | res := b.step_timer.elapsed().microseconds() |
| 138 | println(b.step_message_with_label(b_spent, 'in ${label}')) |
| 139 | b.step() |
| 140 | return res |
| 141 | } |
| 142 | |
| 143 | // record_measure stores the current time doing `label`, since the benchmark was started, or since the last call to `b.record_measure`. |
| 144 | // It is similar to `b.measure`, but unlike it, will not print the measurement |
| 145 | // immediately, just record it for later. You can call `b.all_recorded_measures` |
| 146 | // to retrieve all measures stored by `b.record_measure` calls. |
| 147 | pub fn (mut b Benchmark) record_measure(label string) i64 { |
| 148 | b.ok() |
| 149 | res := b.step_timer.elapsed().microseconds() |
| 150 | b.measured_steps << b.step_message_with_label(b_spent, 'in ${label}') |
| 151 | if label !in b.step_data { |
| 152 | b.step_data[label] = []f64{} |
| 153 | } |
| 154 | b.step_data[label] << f64(res) |
| 155 | b.step() |
| 156 | return res |
| 157 | } |
| 158 | |
| 159 | // MessageOptions allows passing an optional preparation time too to each label method. |
| 160 | // If it is set, the preparation time (compile time) will be shown before the measured runtime. |
| 161 | @[params] |
| 162 | pub struct MessageOptions { |
| 163 | pub: |
| 164 | preparation time.Duration // the duration of the preparation time for the step |
| 165 | } |
| 166 | |
| 167 | // step_message_with_label_and_duration returns a string describing the current step. |
| 168 | pub fn (b &Benchmark) step_message_with_label_and_duration(label string, msg string, sduration time.Duration, |
| 169 | opts MessageOptions) string { |
| 170 | timed_line := b.tdiff_in_ms(msg, sduration.microseconds()) |
| 171 | flabel := format_step_label(label) |
| 172 | if b.nexpected_steps > 1 { |
| 173 | mut sprogress := '' |
| 174 | if b.nexpected_steps < 10 { |
| 175 | sprogress = if b.no_cstep { |
| 176 | 'TMP1/${b.nexpected_steps:1d}' |
| 177 | } else { |
| 178 | '${b.cstep:1d}/${b.nexpected_steps:1d}' |
| 179 | } |
| 180 | } else if b.nexpected_steps >= 10 && b.nexpected_steps < 100 { |
| 181 | sprogress = if b.no_cstep { |
| 182 | 'TMP2/${b.nexpected_steps:2d}' |
| 183 | } else { |
| 184 | '${b.cstep:2d}/${b.nexpected_steps:2d}' |
| 185 | } |
| 186 | } else if b.nexpected_steps >= 100 && b.nexpected_steps < 1000 { |
| 187 | sprogress = if b.no_cstep { |
| 188 | 'TMP3/${b.nexpected_steps:3d}' |
| 189 | } else { |
| 190 | '${b.cstep:3d}/${b.nexpected_steps:3d}' |
| 191 | } |
| 192 | } else { |
| 193 | sprogress = if b.no_cstep { |
| 194 | 'TMP4/${b.nexpected_steps:4d}' |
| 195 | } else { |
| 196 | '${b.cstep:4d}/${b.nexpected_steps:4d}' |
| 197 | } |
| 198 | } |
| 199 | if opts.preparation > 0 { |
| 200 | return '${flabel} [${sprogress}] C: ${f64(opts.preparation.microseconds()) / 1_000.0:7.1F} ms, R: ${timed_line}' |
| 201 | } |
| 202 | return '${flabel} [${sprogress}] ${timed_line}' |
| 203 | } |
| 204 | return '${flabel}${timed_line}' |
| 205 | } |
| 206 | |
| 207 | fn format_step_label(label string) string { |
| 208 | visible_len := term.strip_ansi(label).len |
| 209 | if visible_len >= step_label_width { |
| 210 | return label |
| 211 | } |
| 212 | return label + ' '.repeat(step_label_width - visible_len) |
| 213 | } |
| 214 | |
| 215 | // step_message_with_label returns a string describing the current step using current time as duration. |
| 216 | pub fn (b &Benchmark) step_message_with_label(label string, msg string, opts MessageOptions) string { |
| 217 | return b.step_message_with_label_and_duration(label, msg, b.step_timer.elapsed(), opts) |
| 218 | } |
| 219 | |
| 220 | // step_message returns a string describing the current step. |
| 221 | pub fn (b &Benchmark) step_message(msg string, opts MessageOptions) string { |
| 222 | return b.step_message_with_label('', msg, opts) |
| 223 | } |
| 224 | |
| 225 | // step_message_ok returns a string describing the current step with an standard "OK" label. |
| 226 | pub fn (b &Benchmark) step_message_ok(msg string, opts MessageOptions) string { |
| 227 | return b.step_message_with_label(b_ok, msg, opts) |
| 228 | } |
| 229 | |
| 230 | // step_message_fail returns a string describing the current step with an standard "FAIL" label. |
| 231 | pub fn (b &Benchmark) step_message_fail(msg string, opts MessageOptions) string { |
| 232 | return b.step_message_with_label(b_fail, msg, opts) |
| 233 | } |
| 234 | |
| 235 | // step_message_skip returns a string describing the current step with an standard "SKIP" label. |
| 236 | pub fn (b &Benchmark) step_message_skip(msg string, opts MessageOptions) string { |
| 237 | return b.step_message_with_label(b_skip, msg, opts) |
| 238 | } |
| 239 | |
| 240 | // total_message returns a string with total summary of the benchmark run. |
| 241 | pub fn (b &Benchmark) total_message(msg string) string { |
| 242 | the_label := term.colorize(term.gray, msg) |
| 243 | mut tmsg := term.colorize(term.bold, 'Summary for ${the_label}:') + ' ' |
| 244 | if b.nfail > 0 { |
| 245 | tmsg += term.colorize(term.bold, term.colorize(term.red, '${b.nfail} failed')) + ', ' |
| 246 | } |
| 247 | if b.nok > 0 { |
| 248 | tmsg += term.colorize(term.bold, term.colorize(term.green, '${b.nok} passed')) + ', ' |
| 249 | } |
| 250 | if b.nskip > 0 { |
| 251 | tmsg += term.colorize(term.bold, term.colorize(term.yellow, '${b.nskip} skipped')) + ', ' |
| 252 | } |
| 253 | mut njobs_label := '' |
| 254 | if b.njobs > 0 { |
| 255 | if b.njobs == 1 { |
| 256 | njobs_label = ', on ${term.colorize(term.bold, 1.str())} job' |
| 257 | } else { |
| 258 | njobs_label = ', on ${term.colorize(term.bold, b.njobs.str())} parallel jobs' |
| 259 | } |
| 260 | } |
| 261 | tmsg += '${b.ntotal} total. ${term.colorize(term.bold, 'Elapsed time:')} ${b.bench_timer.elapsed().microseconds() / 1000} ms${njobs_label}.' |
| 262 | if msg in b.step_data && b.step_data[msg].len > 1 { |
| 263 | min := arrays.min(b.step_data[msg]) or { 0 } / 1000.0 |
| 264 | max := arrays.max(b.step_data[msg]) or { 0 } / 1000.0 |
| 265 | avg := (arrays.sum(b.step_data[msg]) or { 0 } / b.step_data[msg].len) / 1000.0 |
| 266 | tmsg += ' Min: ${min:.3f} ms. Max: ${max:.3f} ms. Avg: ${avg:.3f} ms' |
| 267 | } |
| 268 | return tmsg |
| 269 | } |
| 270 | |
| 271 | // all_recorded_measures returns a string, that contains all the recorded measure messages, done by individual calls to `b.record_measure`. |
| 272 | pub fn (b &Benchmark) all_recorded_measures() string { |
| 273 | return b.measured_steps.join_lines() |
| 274 | } |
| 275 | |
| 276 | // total_duration returns the duration in ms. |
| 277 | pub fn (b &Benchmark) total_duration() i64 { |
| 278 | return b.bench_timer.elapsed().milliseconds() |
| 279 | } |
| 280 | |
| 281 | // tdiff_in_ms prefixes `s` with a time difference calculation. |
| 282 | fn (b &Benchmark) tdiff_in_ms(s string, tdiff i64) string { |
| 283 | if b.verbose { |
| 284 | return '${f64(tdiff) / 1000.0:9.3f} ms ${s}' |
| 285 | } |
| 286 | return s |
| 287 | } |
| 288 | |