builder: implement b.timing_start/1 and b.timing_measure/1

vlib/v/builder/builder.v

@@ -26,6 +26,7 @@ pub mut:
 	parsed_files        []ast.File
 	cached_msvc         MsvcResult
 	table               &table.Table
+	timers              &util.Timers
 }
 
 pub fn new_builder(pref &pref.Preferences) Builder {
@@ -61,6 +62,7 @@ pub fn new_builder(pref &pref.Preferences) Builder {
 			100
 		}
 		cached_msvc: msvc
+		timers: util.new_timers(pref.show_timings || pref.is_verbose)
 	}
 	// max_nr_errors: pref.error_limit ?? 100 TODO potential syntax?
 }
@@ -356,12 +358,10 @@ fn verror(s string) {
 	util.verror('builder error', s)
 }
 
-pub fn (mut b Builder) timing_message(msg string, ms i64) {
-	value := util.bold('$ms')
-	formatted_message := '$msg: $value ms'
-	if b.pref.show_timings {
-		println(formatted_message)
-	} else {
-		b.info(formatted_message)
-	}
+pub fn (mut b Builder) timing_start(label string) {
+	b.timers.start(label)
+}
+
+pub fn (mut b Builder) timing_measure(label string) {
+	b.timers.show(label)
 }

vlib/v/builder/c.v

@@ -1,34 +1,29 @@
 module builder
 
-import time
 import os
 import v.parser
 import v.pref
 import v.gen
 
 pub fn (mut b Builder) gen_c(v_files []string) string {
-	t0 := time.ticks()
+	b.timing_start('PARSE')
 	b.parsed_files = parser.parse_files(v_files, b.table, b.pref, b.global_scope)
 	b.parse_imports()
-	t1 := time.ticks()
-	parse_time := t1 - t0
-	b.timing_message('PARSE', parse_time)
+	b.timing_measure('PARSE')
 	if b.pref.only_check_syntax {
 		return ''
 	}
 	//
+	b.timing_start('CHECK')
 	b.generic_struct_insts_to_concrete()
 	b.checker.check_files(b.parsed_files)
-	t2 := time.ticks()
-	check_time := t2 - t1
-	b.timing_message('CHECK', check_time)
+	b.timing_measure('CHECK')
+	//
 	b.print_warnings_and_errors()
-	// println('starting cgen...')
 	// TODO: move gen.cgen() to c.gen()
+	b.timing_start('C GEN')
 	res := gen.cgen(b.parsed_files, b.table, b.pref)
-	t3 := time.ticks()
-	gen_time := t3 - t2
-	b.timing_message('C GEN', gen_time)
+	b.timing_measure('C GEN')
 	// println('cgen done')
 	// println(res)
 	return res

vlib/v/builder/cc.v

@@ -4,7 +4,6 @@
 module builder
 
 import os
-import time
 import v.cflag
 import v.pref
 import v.util
@@ -531,7 +530,8 @@ fn (mut v Builder) cc() {
 		tried_compilation_commands << cmd
 		v.show_cc(cmd, response_file, response_file_content)
 		// Run
-		ticks := time.ticks()
+		ccompiler_label := 'C ${os.file_name(ccompiler):3}'
+		v.timing_start(ccompiler_label)
 		res := os.exec(cmd) or {
 			// C compilation failed.
 			// If we are on Windows, try msvc
@@ -547,8 +547,7 @@ fn (mut v Builder) cc() {
 			verror(err)
 			return
 		}
-		diff := time.ticks() - ticks
-		v.timing_message('C ${ccompiler:3}', diff)
+		v.timing_measure(ccompiler_label)
 		if v.pref.show_c_output {
 			v.show_c_compiler_output(res)
 		}
@@ -579,7 +578,7 @@ fn (mut v Builder) cc() {
 		}
 		// Print the C command
 		if v.pref.is_verbose {
-			println('$ccompiler took $diff ms')
+			println('$ccompiler')
 			println('=========\n')
 		}
 		break

vlib/v/builder/js.v

@@ -1,6 +1,5 @@
 module builder
 
-import time
 import os
 import v.parser
 import v.pref
@@ -8,21 +7,20 @@ import v.gen
 import v.gen.js
 
 pub fn (mut b Builder) gen_js(v_files []string) string {
-	t0 := time.ticks()
+	b.timing_start('PARSE')
 	b.parsed_files = parser.parse_files(v_files, b.table, b.pref, b.global_scope)
 	b.parse_imports()
-	t1 := time.ticks()
-	parse_time := t1 - t0
-	b.timing_message('PARSE', parse_time)
+	b.timing_measure('PARSE')
+	//
+	b.timing_start('CHECK')
 	b.checker.check_files(b.parsed_files)
-	t2 := time.ticks()
-	check_time := t2 - t1
-	b.timing_message('CHECK', check_time)
+	b.timing_measure('CHECK')
+	//
 	b.print_warnings_and_errors()
+	//
+	b.timing_start('JS GEN')
 	res := js.gen(b.parsed_files, b.table, b.pref)
-	t3 := time.ticks()
-	gen_time := t3 - t2
-	b.timing_message('JS GEN', gen_time)
+	b.timing_measure('JS GEN')
 	return res
 }
 

vlib/v/builder/msvc.v

@@ -1,7 +1,6 @@
 module builder
 
 import os
-import time
 import v.pref
 import v.cflag
 
@@ -296,14 +295,13 @@ pub fn (mut v Builder) cc_msvc() {
 	// It is hard to see it at first, but the quotes above ARE balanced :-| ...
 	// Also the double quotes at the start ARE needed.
 	v.show_cc(cmd, out_name_cmd_line, args)
-	ticks := time.ticks()
+	v.timing_start('C msvc')
 	res := os.exec(cmd) or {
 		println(err)
 		verror('msvc error')
 		return
 	}
-	diff := time.ticks() - ticks
-	v.timing_message('C msvc', diff)
+	v.timing_measure('C msvc')
 	if v.pref.show_c_output {
 		v.show_c_compiler_output(res)
 	} else {

vlib/v/builder/x64.v

@@ -1,6 +1,5 @@
 module builder
 
-import time
 import v.parser
 import v.pref
 import v.gen
@@ -11,20 +10,18 @@ pub fn (mut b Builder) build_x64(v_files []string, out_file string) {
 		println('v -x64 can only generate Linux binaries for now')
 		println('You are not on a Linux system, so you will not ' + 'be able to run the resulting executable')
 	}
-	t0 := time.ticks()
+	b.timing_start('PARSE')
 	b.parsed_files = parser.parse_files(v_files, b.table, b.pref, b.global_scope)
 	b.parse_imports()
-	t1 := time.ticks()
-	parse_time := t1 - t0
-	b.timing_message('PARSE', parse_time)
+	b.timing_measure('PARSE')
+	//
+	b.timing_start('CHECK')
 	b.checker.check_files(b.parsed_files)
-	t2 := time.ticks()
-	check_time := t2 - t1
-	b.timing_message('CHECK', check_time)
+	b.timing_measure('CHECK')
+	//
+	b.timing_start('x64 GEN')
 	x64.gen(b.parsed_files, b.table, out_file, b.pref)
-	t3 := time.ticks()
-	gen_time := t3 - t2
-	b.timing_message('x64 GEN', gen_time)
+	b.timing_measure('x64 GEN')
 }
 
 pub fn (mut b Builder) compile_x64() {

vlib/v/util/timers.v

@@ -0,0 +1,57 @@
+// Copyright (c) 2019-2020 Alexander Medvednikov. All rights reserved.
+// Use of this source code is governed by an MIT license
+// that can be found in the LICENSE file.
+module util
+
+import time
+
+[ref_only]
+pub struct Timers {
+mut:
+	swatches     map[string]time.StopWatch
+	should_print bool
+}
+
+pub fn new_timers(should_print bool) &Timers {
+	return &Timers{
+		swatches: map[string]time.StopWatch{}
+		should_print: should_print
+	}
+}
+
+pub fn (mut t Timers) start(name string) {
+	sw := time.new_stopwatch({})
+	t.swatches[name] = sw
+}
+
+pub fn (mut t Timers) measure(name string) i64 {
+	if name !in t.swatches {
+		timer_keys := t.swatches.keys()
+		eprintln('> Timer `$name` was NOT started.')
+		eprintln('>   Available timers:')
+		eprintln('>   $timer_keys')
+	}
+	ms := t.swatches[name].elapsed().milliseconds()
+	return ms
+}
+
+pub fn (mut t Timers) message(name string) string {
+	ms := t.measure(name)
+	value := bold('$ms')
+	formatted_message := '$name: $value ms'
+	return formatted_message
+}
+
+pub fn (mut t Timers) show(label string) {
+	formatted_message := t.message(label)
+	if t.should_print {
+		println(formatted_message)
+	}
+}
+
+pub fn (mut t Timers) dump_all() {
+	for k, _ in t.swatches {
+		elapsed := t.message(k)
+		println(elapsed)
+	}
+}