v.util, v.builder, v.cgen: add thread timing stats too, on -show-timings -stats

vlib/v/builder/rebuilding.v

@@ -8,6 +8,7 @@ import strings
 import v.util
 import v.pref
 import v.vcache
+import runtime
 
 pub fn (mut b Builder) rebuild_modules() {
 	if !b.pref.use_cache || b.pref.build_mode == .build_module {
@@ -359,7 +360,8 @@ pub fn (mut b Builder) rebuild(backend_cb FnBackend) {
 		//
 		vlines_per_second := int(1_000_000.0 * f64(all_v_source_lines) / f64(compilation_time_micros))
 		svlines_per_second := util.bold(vlines_per_second.str())
-		println('compilation took: ${scompilation_time_ms} ms, compilation speed: ${svlines_per_second} vlines/s')
+		used_cgen_threads := if b.pref.no_parallel { 1 } else { runtime.nr_jobs() }
+		println('compilation took: ${scompilation_time_ms} ms, compilation speed: ${svlines_per_second} vlines/s, cgen threads: ${used_cgen_threads}')
 	}
 }
 

vlib/v/gen/c/cgen.v

@@ -667,6 +667,11 @@ pub fn gen(files []&ast.File, mut table ast.Table, pref_ &pref.Preferences) (str
 
 fn cgen_process_one_file_cb(mut p pool.PoolProcessor, idx int, wid int) &Gen {
 	file := p.get_item[&ast.File](idx)
+	timing_label_for_thread := 'C GEN thread ${wid}'
+	util.timing_start(timing_label_for_thread)
+	defer {
+		util.timing_measure_cumulative(timing_label_for_thread)
+	}
 	mut global_g := unsafe { &Gen(p.get_shared_context()) }
 	mut g := &Gen{
 		file:                  file

vlib/v/util/timers.v

@@ -12,7 +12,7 @@ __global g_timers = new_timers(should_print: false, label: 'g_timers')
 pub struct Timers {
 	label string
 pub mut:
-	swatches     map[string]time.StopWatch
+	swatches     shared map[string]time.StopWatch
 	should_print bool
 	// already_shown records for which of the swatches .show() or .show_if_exists() had been called already
 	already_shown []string
@@ -59,52 +59,43 @@ pub fn timing_set_should_print(should_print bool) {
 }
 
 pub fn (mut t Timers) start(name string) {
-	mut sw := t.swatches[name] or { time.new_stopwatch() }
+	mut sw := t.tsafe_get_sw(name) or { time.new_stopwatch() }
 	sw.start()
-	t.swatches[name] = sw
+	t.tsafe_set_sw(name, sw)
 }
 
 pub fn (mut t Timers) measure(name string) i64 {
-	if name !in t.swatches {
-		timer_keys := t.swatches.keys()
+	mut sw := t.tsafe_get_sw(name) or {
+		timer_keys := t.tsafe_get_keys()
 		eprintln('> Timer `${name}` was NOT started.')
 		eprintln('>   Available timers:')
 		eprintln('>   ${timer_keys}')
+		time.new_stopwatch()
 	}
-	mut sw := t.swatches[name]
 	ms := sw.elapsed().microseconds()
 	sw.pause()
-	t.swatches[name] = sw
+	t.tsafe_set_sw(name, sw)
 	return ms
 }
 
 pub fn (mut t Timers) measure_cumulative(name string) i64 {
 	ms := t.measure(name)
-	if name !in t.swatches {
-		return ms
-	}
-	mut sw := t.swatches[name]
+	mut sw := t.tsafe_get_sw(name) or { return ms }
 	sw.pause()
-	t.swatches[name] = sw
+	t.tsafe_set_sw(name, sw)
 	return ms
 }
 
 pub fn (mut t Timers) measure_pause(name string) {
-	if name !in t.swatches {
-		return
-	}
-	mut sw := t.swatches[name]
+	mut sw := t.tsafe_get_sw(name) or { return }
 	sw.pause()
-	t.swatches[name] = sw
+	t.tsafe_set_sw(name, sw)
 }
 
 pub fn (mut t Timers) measure_resume(name string) {
-	if name !in t.swatches {
-		return
-	}
-	mut sw := t.swatches[name]
+	mut sw := t.tsafe_get_sw(name) or { return }
 	sw.start()
-	t.swatches[name] = sw
+	t.tsafe_set_sw(name, sw)
 }
 
 pub fn (mut t Timers) message(name string) string {
@@ -128,15 +119,14 @@ pub fn (mut t Timers) show(label string) {
 }
 
 pub fn (mut t Timers) show_if_exists(label string) {
-	if label !in t.swatches {
-		return
-	}
+	t.tsafe_get_sw(label) or { return }
 	t.show(label)
 	t.already_shown << label
 }
 
 pub fn (mut t Timers) show_remaining() {
-	for k, _ in t.swatches {
+	keys := t.tsafe_get_keys()
+	for k in keys {
 		if k in t.already_shown {
 			continue
 		}
@@ -145,8 +135,34 @@ pub fn (mut t Timers) show_remaining() {
 }
 
 pub fn (mut t Timers) dump_all() {
-	for k, _ in t.swatches {
+	keys := t.tsafe_get_keys()
+	for k in keys {
 		elapsed := t.message(k)
 		println(elapsed)
 	}
 }
+
+//
+
+fn (mut t Timers) tsafe_get_keys() []string {
+	keys := rlock t.swatches {
+		t.swatches.keys()
+	}
+	return keys
+}
+
+fn (mut t Timers) tsafe_set_sw(name string, sw time.StopWatch) {
+	lock t.swatches {
+		t.swatches[name] = sw
+	}
+}
+
+fn (mut t Timers) tsafe_get_sw(name string) ?time.StopWatch {
+	rlock t.swatches {
+		if name !in t.swatches {
+			return none
+		}
+		return t.swatches[name]
+	}
+	return none
+}