v,gen,checker: implement `-d time_checking -d time_cgening -d time_v`

cmd/v/help/build.txt

@@ -119,6 +119,12 @@ The build flags are shared by the build and run commands:
          C GEN: 103ms
          C tcc: 95ms
          
+      Related to -show-timings, is the ability to compile a special instrumented 
+      v compiler with this command: 
+      `v -d time_parsing -d time_checking -d time_cgening -d time_v self`
+      The instrumented version will print detailed timing stats while processing
+      each .v file.
+
    -w
       Hide all warnings.
 

cmd/v/v.v

@@ -37,6 +37,14 @@ const (
 )
 
 fn main() {
+	timers_should_print := $if time_v ? { true } $else { false }
+	mut timers := util.new_timers(timers_should_print)
+	timers.start('v total')
+	defer {
+		timers.show('v total')
+	}
+	timers.start('v start')
+	timers.show('v start')
 	args := os.args[1..]
 	// args = 123
 	if args.len == 0 || args[0] in ['-', 'repl'] {

vlib/v/checker/checker.v

@@ -66,13 +66,16 @@ mut:
 	vweb_gen_types                   []table.Type // vweb route checks
 	prevent_sum_type_unwrapping_once bool // needed for assign new values to sum type, stopping unwrapping then
 	loop_label                       string // set when inside a labelled for loop
+	timers                           &util.Timers
 }
 
 pub fn new_checker(table &table.Table, pref &pref.Preferences) Checker {
+	timers_should_print := $if time_checking ? { true } $else { false }
 	return Checker{
 		table: table
 		pref: pref
 		cur_fn: 0
+		timers: util.new_timers(timers_should_print)
 	}
 }
 
@@ -130,6 +133,7 @@ pub fn (mut c Checker) check_files(ast_files []ast.File) {
 	mut files_from_main_module := []&ast.File{}
 	for i in 0 .. ast_files.len {
 		file := unsafe {&ast_files[i]}
+		c.timers.start('checker_check $file.path')
 		c.check(file)
 		if file.mod.name == 'main' {
 			files_from_main_module << file
@@ -138,6 +142,7 @@ pub fn (mut c Checker) check_files(ast_files []ast.File) {
 				has_main_fn = true
 			}
 		}
+		c.timers.show('checker_check $file.path')
 	}
 	if has_main_mod_file && !has_main_fn && files_from_main_module.len > 0 {
 		if c.pref.is_script && !c.pref.is_test {
@@ -154,6 +159,7 @@ pub fn (mut c Checker) check_files(ast_files []ast.File) {
 			has_main_fn = true
 		}
 	}
+	c.timers.start('checker_post_process_generic_fns')
 	// post process generic functions. must be done after all files have been
 	// checked, to eunsure all generic calls are processed as this information
 	// is needed when the generic type is auto inferred from the call argument
@@ -165,7 +171,12 @@ pub fn (mut c Checker) check_files(ast_files []ast.File) {
 			c.post_process_generic_fns()
 		}
 	}
+	c.timers.show('checker_post_process_generic_fns')
+	//
+	c.timers.start('checker_verify_all_vweb_routes')
 	c.verify_all_vweb_routes()
+	c.timers.show('checker_verify_all_vweb_routes')
+	//
 	// Make sure fn main is defined in non lib builds
 	if c.pref.build_mode == .build_module || c.pref.is_test {
 		return

vlib/v/gen/cgen.v

@@ -129,6 +129,7 @@ mut:
 	aggregate_type_idx               int
 	returned_var_name                string // to detect that a var doesn't need to be freed since it's being returned
 	branch_parent_pos                int // used in BranchStmt (continue/break) for autofree stop position
+	timers                           &util.Timers
 }
 
 const (
@@ -151,6 +152,7 @@ pub fn cgen(files []ast.File, table &table.Table, pref &pref.Preferences) string
 				'.')
 		}
 	}
+	timers_should_print := $if time_cgening ? { true } $else { false }
 	mut g := Gen{
 		out: strings.new_builder(1000)
 		cheaders: strings.new_builder(8192)
@@ -178,16 +180,19 @@ pub fn cgen(files []ast.File, table &table.Table, pref &pref.Preferences) string
 		autofree: true
 		indent: -1
 		module_built: module_built
+		timers: util.new_timers(timers_should_print)
 	}
 	for mod in g.table.modules {
 		g.inits[mod] = strings.new_builder(100)
 		g.cleanups[mod] = strings.new_builder(100)
 	}
+	g.timers.start('cgen common')
 	g.init()
 	//
 	mut tests_inited := false
 	mut autofree_used := false
 	for file in files {
+		g.timers.start('cgen_file $file.path')
 		g.file = file
 		if g.pref.is_vlines {
 			g.vlines_path = util.vlines_escape_path(file.path, g.pref.ccompiler)
@@ -213,6 +218,7 @@ pub fn cgen(files []ast.File, table &table.Table, pref &pref.Preferences) string
 			tests_inited = true
 		}
 		g.stmts(file.stmts)
+		g.timers.show('cgen_file $file.path')
 	}
 	if autofree_used {
 		g.autofree = true // so that void _vcleanup is generated
@@ -308,6 +314,7 @@ pub fn cgen(files []ast.File, table &table.Table, pref &pref.Preferences) string
 	b.writeln('\n// V out')
 	b.write(g.out.str())
 	b.writeln('\n// THE END.')
+	g.timers.show('cgen common')
 	return b.str()
 }
 

vlib/v/util/timers.v

@@ -31,13 +31,13 @@ pub fn (mut t Timers) measure(name string) i64 {
 		eprintln('>   Available timers:')
 		eprintln('>   $timer_keys')
 	}
-	ms := t.swatches[name].elapsed().milliseconds()
+	ms := t.swatches[name].elapsed().microseconds()
 	return ms
 }
 
 pub fn (mut t Timers) message(name string) string {
-	ms := t.measure(name)
+	ms := f64(t.measure(name)) / 1000.0
-	value := bold('$ms')
+	value := bold('${ms:.3f}')
 	formatted_message := '$name: $value ms'
 	return formatted_message
 }