From 5477da3577902e0f6517a066959039f09ec09aaa Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 14:15:50 +1000 Subject: [PATCH 01/15] Add perfmon to Stats --- Cargo.toml | 1 + src/util/statistics/stats.rs | 5 +++++ 2 files changed, 6 insertions(+) diff --git a/Cargo.toml b/Cargo.toml index 785bd78997..e07fc3fa66 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -33,6 +33,7 @@ atomic-traits = "0.2.0" atomic = "0.4.6" spin = "0.5.2" env_logger = "0.8.2" +pfm = "0.0.3" [dev-dependencies] crossbeam = "0.7.3" diff --git a/src/util/statistics/stats.rs b/src/util/statistics/stats.rs index b0e5099616..abc335e744 100644 --- a/src/util/statistics/stats.rs +++ b/src/util/statistics/stats.rs @@ -6,6 +6,7 @@ use std::collections::HashMap; use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; use std::sync::Arc; use std::sync::Mutex; +use pfm::Perfmon; pub const MAX_PHASES: usize = 1 << 12; pub const MAX_COUNTERS: usize = 100; @@ -37,6 +38,7 @@ impl SharedStats { pub struct Stats { gc_count: AtomicUsize, total_time: Arc>, + perfmon: Perfmon, pub shared: Arc, counters: Mutex>>>, @@ -55,9 +57,12 @@ impl Stats { true, false, ))); + let mut perfmon: Perfmon = Default::default(); + perfmon.initialize().expect("Perfmon failed to initialize"); Stats { gc_count: AtomicUsize::new(0), total_time: t.clone(), + perfmon, shared, counters: Mutex::new(vec![t]), From e6aa5d3504c7bb95dcab890c6f991c36b64b6953 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 19:02:01 +1000 Subject: [PATCH 02/15] Refactor worker stat type --- Cargo.toml | 2 +- src/scheduler/stat.rs | 189 +++++++++++++++++++++++------------------- 2 files changed, 104 insertions(+), 87 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index e07fc3fa66..20999640bf 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -33,7 +33,7 @@ atomic-traits = "0.2.0" atomic = "0.4.6" spin = "0.5.2" env_logger = "0.8.2" -pfm = "0.0.3" +pfm = "0.0.5" [dev-dependencies] crossbeam = "0.7.3" diff --git a/src/scheduler/stat.rs b/src/scheduler/stat.rs index 9b5a8ca7ac..b5ff6b397d 100644 --- a/src/scheduler/stat.rs +++ b/src/scheduler/stat.rs @@ -1,56 +1,88 @@ use std::any::TypeId; use std::collections::HashMap; use std::sync::atomic::{AtomicBool, Ordering}; -use std::time::{Duration, SystemTime}; +use std::time::SystemTime; #[derive(Default)] pub struct SchedulerStat { work_id_name_map: HashMap, work_counts: HashMap, - work_durations: HashMap>, + work_durations: HashMap>, } -impl SchedulerStat { - /// Extract the work-packet name from the full type name. - /// i.e. simplifies `crate::scheduler::gc_work::SomeWorkPacket` to `SomeWorkPacket`. - fn work_name(&self, name: &str) -> String { - let end_index = name.find('<').unwrap_or_else(|| name.len()); - let name = name[..end_index].to_owned(); - match name.rfind(':') { - Some(start_index) => name[(start_index + 1)..end_index].to_owned(), - _ => name, +trait SimpleCounter { + // TODO: consolidate with crate::util::statistics::counter::Counter; + fn start(&mut self); + fn stop(&mut self); +} + +#[derive(Copy, Clone)] +struct WorkDuration { + total: f64, + min: f64, + max: f64, + start_value: Option, + running: bool, +} + +impl WorkDuration { + fn new() -> Self { + WorkDuration { + total: 0.0, + min: f64::INFINITY, + max: f64::NEG_INFINITY, + start_value: None, + running: false, } } - fn geomean(&self, values: &[f64]) -> f64 { - // Geomean(xs, N=xs.len()) = (PI(xs))^(1/N) = e^{log{PI(xs)^(1/N)}} = e^{ (1/N) * sum_{x \in xs}{ log(x) } } - let logs = values.iter().map(|v| v.ln()); - let sum_logs = logs.sum::(); - (sum_logs / values.len() as f64).exp() + fn process_duration(&mut self, duration: f64) { + self.min = self.min.min(duration); + self.max = self.max.max(duration); + self.total = self.total + duration; } - fn min(&self, values: &[f64]) -> f64 { - let mut min = values[0]; - for v in values { - if *v < min { - min = *v - } + fn merge_duration(&self, other: &Self) -> Self { + let min = self.min.min(other.min); + let max = self.max.max(other.max); + let total = self.total + other.total; + WorkDuration { + total, + min, + max, + start_value: None, + running: false, } - min } - fn max(&self, values: &[f64]) -> f64 { - let mut max = values[0]; - for v in values { - if *v > max { - max = *v - } - } - max + fn merge_duration_inplace(&mut self, other: &Self) { + self.min = self.min.min(other.min); + self.max = self.max.max(other.max); + self.total = self.total + other.total; + } +} +impl SimpleCounter for WorkDuration { + fn start(&mut self) { + self.start_value = Some(SystemTime::now()); + self.running = true; } - fn sum(&self, values: &[f64]) -> f64 { - values.iter().sum() + fn stop(&mut self) { + let duration = self.start_value.unwrap().elapsed().unwrap().as_nanos() as f64; + self.process_duration(duration); + } +} + +impl SchedulerStat { + /// Extract the work-packet name from the full type name. + /// i.e. simplifies `crate::scheduler::gc_work::SomeWorkPacket` to `SomeWorkPacket`. + fn work_name(&self, name: &str) -> String { + let end_index = name.find('<').unwrap_or_else(|| name.len()); + let name = name[..end_index].to_owned(); + match name.rfind(':') { + Some(start_index) => name[(start_index + 1)..end_index].to_owned(), + _ => name, + } } pub fn harness_stat(&self) -> HashMap { @@ -67,52 +99,40 @@ impl SchedulerStat { } stat.insert("total-work.count".to_owned(), format!("{}", total_count)); // Work execution times - let mut total_durations = vec![]; + let mut duration_overall = WorkDuration::new(); for (t, durations) in &self.work_durations { - for d in durations { - total_durations.push(*d); - } let n = self.work_id_name_map[t]; - let geomean = self.geomean( - &durations - .iter() - .map(|d| d.as_nanos() as f64) - .collect::>(), - ); - stat.insert( - format!("work.{}.time.geomean", self.work_name(n)), - format!("{:.2}", geomean), - ); - let sum = self.sum( - &durations - .iter() - .map(|d| d.as_nanos() as f64) - .collect::>(), - ); - stat.insert( - format!("work.{}.time.sum", self.work_name(n)), - format!("{:.2}", sum), - ); - } - let durations = total_durations - .iter() - .map(|d| d.as_nanos() as f64) - .collect::>(); - if !durations.is_empty() { + let fold = durations + .iter() + .fold(WorkDuration::new(), |acc, x| acc.merge_duration(x)); + duration_overall.merge_duration_inplace(&fold); stat.insert( - "total-work.time.geomean".to_owned(), - format!("{:.2}", self.geomean(&durations)), + format!("work.{}.time.total", self.work_name(n)), + format!("{:.2}", fold.total), ); stat.insert( - "total-work.time.min".to_owned(), - format!("{:.2}", self.min(&durations)), + format!("work.{}.time.min", self.work_name(n)), + format!("{:.2}", fold.min), ); stat.insert( - "total-work.time.max".to_owned(), - format!("{:.2}", self.max(&durations)), + format!("work.{}.time.max", self.work_name(n)), + format!("{:.2}", fold.max), ); } + stat.insert( + "total-work.time.total".to_owned(), + format!("{:.2}", duration_overall.total), + ); + stat.insert( + "total-work.time.min".to_owned(), + format!("{:.2}", duration_overall.min), + ); + stat.insert( + "total-work.time.max".to_owned(), + format!("{:.2}", duration_overall.max), + ); + stat } @@ -127,15 +147,11 @@ impl SchedulerStat { self.work_counts.insert(*id, *count); } } - for (id, durations) in &stat.work_durations { - if self.work_durations.contains_key(id) { - let work_durations = self.work_durations.get_mut(id).unwrap(); - for d in durations { - work_durations.push(*d); - } - } else { - self.work_durations.insert(*id, durations.clone()); - } + for (id, duration) in &stat.work_durations { + self.work_durations + .entry(*id) + .and_modify(|v| v.push(*duration)) + .or_insert(vec![*duration]); } } } @@ -143,7 +159,6 @@ impl SchedulerStat { pub struct WorkStat { type_id: TypeId, type_name: &'static str, - start_time: SystemTime, } impl WorkStat { @@ -156,12 +171,10 @@ impl WorkStat { .work_id_name_map .insert(self.type_id, self.type_name); *worker_stat.work_counts.entry(self.type_id).or_insert(0) += 1; - let duration = self.start_time.elapsed().unwrap(); worker_stat .work_durations .entry(self.type_id) - .or_insert_with(Vec::new) - .push(duration); + .and_modify(|v| v.stop()); } } @@ -169,7 +182,7 @@ impl WorkStat { pub struct WorkerLocalStat { work_id_name_map: HashMap, work_counts: HashMap, - work_durations: HashMap>, + work_durations: HashMap, enabled: AtomicBool, } @@ -184,10 +197,14 @@ impl WorkerLocalStat { } #[inline] pub fn measure_work(&mut self, work_id: TypeId, work_name: &'static str) -> WorkStat { - WorkStat { + let stat = WorkStat { type_id: work_id, type_name: work_name, - start_time: SystemTime::now(), - } + }; + self.work_durations + .entry(work_id) + .or_insert(WorkDuration::new()) + .start(); + stat } } From ca1bf18ddc9505932659a2d83670f34dcb9702df Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 19:28:15 +1000 Subject: [PATCH 03/15] Revert "Add perfmon to Stats" This reverts commit ce0c3f97a81a36e6ca61ed4d68ed00541a529248. --- Cargo.toml | 1 - src/util/statistics/stats.rs | 5 ----- 2 files changed, 6 deletions(-) diff --git a/Cargo.toml b/Cargo.toml index 20999640bf..785bd78997 100644 --- a/Cargo.toml +++ b/Cargo.toml @@ -33,7 +33,6 @@ atomic-traits = "0.2.0" atomic = "0.4.6" spin = "0.5.2" env_logger = "0.8.2" -pfm = "0.0.5" [dev-dependencies] crossbeam = "0.7.3" diff --git a/src/util/statistics/stats.rs b/src/util/statistics/stats.rs index abc335e744..b0e5099616 100644 --- a/src/util/statistics/stats.rs +++ b/src/util/statistics/stats.rs @@ -6,7 +6,6 @@ use std::collections::HashMap; use std::sync::atomic::{AtomicBool, AtomicUsize, Ordering}; use std::sync::Arc; use std::sync::Mutex; -use pfm::Perfmon; pub const MAX_PHASES: usize = 1 << 12; pub const MAX_COUNTERS: usize = 100; @@ -38,7 +37,6 @@ impl SharedStats { pub struct Stats { gc_count: AtomicUsize, total_time: Arc>, - perfmon: Perfmon, pub shared: Arc, counters: Mutex>>>, @@ -57,12 +55,9 @@ impl Stats { true, false, ))); - let mut perfmon: Perfmon = Default::default(); - perfmon.initialize().expect("Perfmon failed to initialize"); Stats { gc_count: AtomicUsize::new(0), total_time: t.clone(), - perfmon, shared, counters: Mutex::new(vec![t]), From 6fccad58e518f8c37d2ec579ea457427d8446733 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 20:28:36 +1000 Subject: [PATCH 04/15] Implement as trait object --- src/scheduler/stat.rs | 176 ++++++++++++++++++++++++++++-------------- 1 file changed, 116 insertions(+), 60 deletions(-) diff --git a/src/scheduler/stat.rs b/src/scheduler/stat.rs index b5ff6b397d..e96f31718a 100644 --- a/src/scheduler/stat.rs +++ b/src/scheduler/stat.rs @@ -7,61 +7,90 @@ use std::time::SystemTime; pub struct SchedulerStat { work_id_name_map: HashMap, work_counts: HashMap, - work_durations: HashMap>, -} - -trait SimpleCounter { - // TODO: consolidate with crate::util::statistics::counter::Counter; - fn start(&mut self); - fn stop(&mut self); + work_counters: HashMap>>>, } #[derive(Copy, Clone)] -struct WorkDuration { +struct WorkCounterBase { total: f64, min: f64, max: f64, - start_value: Option, - running: bool, } -impl WorkDuration { - fn new() -> Self { - WorkDuration { +impl Default for WorkCounterBase { + fn default() -> Self { + WorkCounterBase { total: 0.0, min: f64::INFINITY, max: f64::NEG_INFINITY, - start_value: None, - running: false, } } +} - fn process_duration(&mut self, duration: f64) { - self.min = self.min.min(duration); - self.max = self.max.max(duration); - self.total = self.total + duration; - } - - fn merge_duration(&self, other: &Self) -> Self { +impl WorkCounterBase { + fn merge(&self, other: &Self) -> Self { let min = self.min.min(other.min); let max = self.max.max(other.max); let total = self.total + other.total; - WorkDuration { - total, - min, - max, - start_value: None, - running: false, - } + WorkCounterBase { total, min, max } } - fn merge_duration_inplace(&mut self, other: &Self) { + fn merge_inplace(&mut self, other: &Self) { self.min = self.min.min(other.min); self.max = self.max.max(other.max); self.total = self.total + other.total; } + + fn merge_val(&mut self, val: f64) { + self.min = self.min.min(val); + self.max = self.max.max(val); + self.total = self.total + val; + } } -impl SimpleCounter for WorkDuration { + +trait WorkCounter: WorkCounterClone { + // TODO: consolidate with crate::util::statistics::counter::Counter; + fn start(&mut self); + fn stop(&mut self); + fn name(&self) -> &'static str; + fn get_base(&self) -> &WorkCounterBase; + fn get_base_mut(&mut self) -> &mut WorkCounterBase; +} + +trait WorkCounterClone { + fn clone_box(&self) -> Box; +} + +impl WorkCounterClone for T { + fn clone_box(&self) -> Box { + Box::new(self.clone()) + } +} + +impl Clone for Box { + fn clone(&self) -> Box { + self.clone_box() + } +} + +#[derive(Copy, Clone)] +struct WorkDuration { + base: WorkCounterBase, + start_value: Option, + running: bool, +} + +impl WorkDuration { + fn new() -> Self { + WorkDuration { + base: Default::default(), + start_value: None, + running: false, + } + } +} + +impl WorkCounter for WorkDuration { fn start(&mut self) { self.start_value = Some(SystemTime::now()); self.running = true; @@ -69,7 +98,19 @@ impl SimpleCounter for WorkDuration { fn stop(&mut self) { let duration = self.start_value.unwrap().elapsed().unwrap().as_nanos() as f64; - self.process_duration(duration); + self.base.merge_val(duration); + } + + fn name(&self) -> &'static str { + "time" + } + + fn get_base(&self) -> &WorkCounterBase { + &self.base + } + + fn get_base_mut(&mut self) -> &mut WorkCounterBase { + &mut self.base } } @@ -99,25 +140,30 @@ impl SchedulerStat { } stat.insert("total-work.count".to_owned(), format!("{}", total_count)); // Work execution times - let mut duration_overall = WorkDuration::new(); - for (t, durations) in &self.work_durations { + let mut duration_overall: WorkCounterBase = Default::default(); + for (t, vs) in &self.work_counters { let n = self.work_id_name_map[t]; - let fold = durations - .iter() - .fold(WorkDuration::new(), |acc, x| acc.merge_duration(x)); - duration_overall.merge_duration_inplace(&fold); - stat.insert( - format!("work.{}.time.total", self.work_name(n)), - format!("{:.2}", fold.total), - ); - stat.insert( - format!("work.{}.time.min", self.work_name(n)), - format!("{:.2}", fold.min), - ); - stat.insert( - format!("work.{}.time.max", self.work_name(n)), - format!("{:.2}", fold.max), - ); + for v in vs.iter() { + let fold = v + .iter() + .fold(Default::default(), |acc: WorkCounterBase, x| { + acc.merge(x.get_base()) + }); + duration_overall.merge_inplace(&fold); + let name = v.first().unwrap().name(); + stat.insert( + format!("work.{}.{}.total", self.work_name(n), name), + format!("{:.2}", fold.total), + ); + stat.insert( + format!("work.{}.{}.min", self.work_name(n), name), + format!("{:.2}", fold.min), + ); + stat.insert( + format!("work.{}.{}.max", self.work_name(n), name), + format!("{:.2}", fold.max), + ); + } } stat.insert( @@ -147,11 +193,14 @@ impl SchedulerStat { self.work_counts.insert(*id, *count); } } - for (id, duration) in &stat.work_durations { - self.work_durations + for (id, counters) in &stat.work_counters { + let vs = self + .work_counters .entry(*id) - .and_modify(|v| v.push(*duration)) - .or_insert(vec![*duration]); + .or_insert(vec![vec![]; counters.len()]); + for (v, c) in vs.iter_mut().zip(counters.iter()) { + v.push(c.clone()); + } } } } @@ -172,9 +221,11 @@ impl WorkStat { .insert(self.type_id, self.type_name); *worker_stat.work_counts.entry(self.type_id).or_insert(0) += 1; worker_stat - .work_durations + .work_counters .entry(self.type_id) - .and_modify(|v| v.stop()); + .and_modify(|v| { + v.iter_mut().for_each(|c| c.stop()); + }); } } @@ -182,7 +233,7 @@ impl WorkStat { pub struct WorkerLocalStat { work_id_name_map: HashMap, work_counts: HashMap, - work_durations: HashMap, + work_counters: HashMap>>, enabled: AtomicBool, } @@ -201,10 +252,15 @@ impl WorkerLocalStat { type_id: work_id, type_name: work_name, }; - self.work_durations + self.work_counters .entry(work_id) - .or_insert(WorkDuration::new()) - .start(); + .or_insert(WorkerLocalStat::counter_set()) + .iter_mut() + .for_each(|c| c.start()); stat } + + fn counter_set() -> Vec> { + vec![Box::new(WorkDuration::new())] + } } From dfd64e3588337a483084c908b1b67f73916beb7d Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 22:26:40 +1000 Subject: [PATCH 05/15] Fix test --- src/scheduler/scheduler.rs | 1 + 1 file changed, 1 insertion(+) diff --git a/src/scheduler/scheduler.rs b/src/scheduler/scheduler.rs index c461fc8f69..6ff6736b52 100644 --- a/src/scheduler/scheduler.rs +++ b/src/scheduler/scheduler.rs @@ -410,6 +410,7 @@ mod tests { // println!("Original: {:?}", data); SCHEDULER.initialize(NUM_WORKERS, &(), VMThread::UNINITIALIZED); + SCHEDULER.enable_stat(); SCHEDULER.work_buckets[WorkBucketStage::Unconstrained] .add(Sort(unsafe { &mut *(data as *mut _) })); SCHEDULER.wait_for_completion(); From fcb7dc7556a185aa6f6b61dd39739822f3b7e072 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 22:30:08 +1000 Subject: [PATCH 06/15] Fix clippy --- src/scheduler/stat.rs | 8 ++++---- 1 file changed, 4 insertions(+), 4 deletions(-) diff --git a/src/scheduler/stat.rs b/src/scheduler/stat.rs index e96f31718a..f10521f386 100644 --- a/src/scheduler/stat.rs +++ b/src/scheduler/stat.rs @@ -38,13 +38,13 @@ impl WorkCounterBase { fn merge_inplace(&mut self, other: &Self) { self.min = self.min.min(other.min); self.max = self.max.max(other.max); - self.total = self.total + other.total; + self.total += other.total; } fn merge_val(&mut self, val: f64) { self.min = self.min.min(val); self.max = self.max.max(val); - self.total = self.total + val; + self.total += val; } } @@ -197,7 +197,7 @@ impl SchedulerStat { let vs = self .work_counters .entry(*id) - .or_insert(vec![vec![]; counters.len()]); + .or_insert_with(|| vec![vec![]; counters.len()]); for (v, c) in vs.iter_mut().zip(counters.iter()) { v.push(c.clone()); } @@ -254,7 +254,7 @@ impl WorkerLocalStat { }; self.work_counters .entry(work_id) - .or_insert(WorkerLocalStat::counter_set()) + .or_insert_with(WorkerLocalStat::counter_set) .iter_mut() .for_each(|c| c.start()); stat From 973503b3f03e9ea4d4bf9c3b40e10f33d5d1734b Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 22:57:21 +1000 Subject: [PATCH 07/15] Refactor out work counters --- src/scheduler/mod.rs | 2 + src/scheduler/stat.rs | 106 +--------------------------------- src/scheduler/work_counter.rs | 105 +++++++++++++++++++++++++++++++++ 3 files changed, 108 insertions(+), 105 deletions(-) create mode 100644 src/scheduler/work_counter.rs diff --git a/src/scheduler/mod.rs b/src/scheduler/mod.rs index 3ae8bb05ce..e7c986339a 100644 --- a/src/scheduler/mod.rs +++ b/src/scheduler/mod.rs @@ -35,3 +35,5 @@ pub use gc_work::ProcessEdgesWork; // We should do some refactoring related to Scanning::SCAN_MUTATORS_IN_SAFEPOINT // to make sure this type is not exposed to the bindings. pub use gc_work::ScanStackRoot; + +mod work_counter; \ No newline at end of file diff --git a/src/scheduler/stat.rs b/src/scheduler/stat.rs index f10521f386..f1bf6e3c3b 100644 --- a/src/scheduler/stat.rs +++ b/src/scheduler/stat.rs @@ -1,7 +1,7 @@ +use super::work_counter::{WorkCounter, WorkCounterBase, WorkDuration}; use std::any::TypeId; use std::collections::HashMap; use std::sync::atomic::{AtomicBool, Ordering}; -use std::time::SystemTime; #[derive(Default)] pub struct SchedulerStat { @@ -10,110 +10,6 @@ pub struct SchedulerStat { work_counters: HashMap>>>, } -#[derive(Copy, Clone)] -struct WorkCounterBase { - total: f64, - min: f64, - max: f64, -} - -impl Default for WorkCounterBase { - fn default() -> Self { - WorkCounterBase { - total: 0.0, - min: f64::INFINITY, - max: f64::NEG_INFINITY, - } - } -} - -impl WorkCounterBase { - fn merge(&self, other: &Self) -> Self { - let min = self.min.min(other.min); - let max = self.max.max(other.max); - let total = self.total + other.total; - WorkCounterBase { total, min, max } - } - - fn merge_inplace(&mut self, other: &Self) { - self.min = self.min.min(other.min); - self.max = self.max.max(other.max); - self.total += other.total; - } - - fn merge_val(&mut self, val: f64) { - self.min = self.min.min(val); - self.max = self.max.max(val); - self.total += val; - } -} - -trait WorkCounter: WorkCounterClone { - // TODO: consolidate with crate::util::statistics::counter::Counter; - fn start(&mut self); - fn stop(&mut self); - fn name(&self) -> &'static str; - fn get_base(&self) -> &WorkCounterBase; - fn get_base_mut(&mut self) -> &mut WorkCounterBase; -} - -trait WorkCounterClone { - fn clone_box(&self) -> Box; -} - -impl WorkCounterClone for T { - fn clone_box(&self) -> Box { - Box::new(self.clone()) - } -} - -impl Clone for Box { - fn clone(&self) -> Box { - self.clone_box() - } -} - -#[derive(Copy, Clone)] -struct WorkDuration { - base: WorkCounterBase, - start_value: Option, - running: bool, -} - -impl WorkDuration { - fn new() -> Self { - WorkDuration { - base: Default::default(), - start_value: None, - running: false, - } - } -} - -impl WorkCounter for WorkDuration { - fn start(&mut self) { - self.start_value = Some(SystemTime::now()); - self.running = true; - } - - fn stop(&mut self) { - let duration = self.start_value.unwrap().elapsed().unwrap().as_nanos() as f64; - self.base.merge_val(duration); - } - - fn name(&self) -> &'static str { - "time" - } - - fn get_base(&self) -> &WorkCounterBase { - &self.base - } - - fn get_base_mut(&mut self) -> &mut WorkCounterBase { - &mut self.base - } -} - impl SchedulerStat { /// Extract the work-packet name from the full type name. /// i.e. simplifies `crate::scheduler::gc_work::SomeWorkPacket` to `SomeWorkPacket`. diff --git a/src/scheduler/work_counter.rs b/src/scheduler/work_counter.rs new file mode 100644 index 0000000000..42b52c8aba --- /dev/null +++ b/src/scheduler/work_counter.rs @@ -0,0 +1,105 @@ +use std::time::SystemTime; + +#[derive(Copy, Clone)] +pub(super) struct WorkCounterBase { + pub(super) total: f64, + pub(super) min: f64, + pub(super) max: f64, +} + +pub(super) trait WorkCounterClone { + fn clone_box(&self) -> Box; +} + +impl WorkCounterClone for T { + fn clone_box(&self) -> Box { + Box::new(self.clone()) + } +} + +pub(super) trait WorkCounter: WorkCounterClone { + // TODO: consolidate with crate::util::statistics::counter::Counter; + fn start(&mut self); + fn stop(&mut self); + fn name(&self) -> &'static str; + fn get_base(&self) -> &WorkCounterBase; + fn get_base_mut(&mut self) -> &mut WorkCounterBase; +} + +impl Clone for Box { + fn clone(&self) -> Box { + self.clone_box() + } +} + +impl Default for WorkCounterBase { + fn default() -> Self { + WorkCounterBase { + total: 0.0, + min: f64::INFINITY, + max: f64::NEG_INFINITY, + } + } +} + +impl WorkCounterBase { + pub(super) fn merge(&self, other: &Self) -> Self { + let min = self.min.min(other.min); + let max = self.max.max(other.max); + let total = self.total + other.total; + WorkCounterBase { total, min, max } + } + + pub(super) fn merge_inplace(&mut self, other: &Self) { + self.min = self.min.min(other.min); + self.max = self.max.max(other.max); + self.total += other.total; + } + + pub(super) fn merge_val(&mut self, val: f64) { + self.min = self.min.min(val); + self.max = self.max.max(val); + self.total += val; + } +} + +#[derive(Copy, Clone)] +pub(super) struct WorkDuration { + base: WorkCounterBase, + start_value: Option, + running: bool, +} + +impl WorkDuration { + pub(super) fn new() -> Self { + WorkDuration { + base: Default::default(), + start_value: None, + running: false, + } + } +} + +impl WorkCounter for WorkDuration { + fn start(&mut self) { + self.start_value = Some(SystemTime::now()); + self.running = true; + } + + fn stop(&mut self) { + let duration = self.start_value.unwrap().elapsed().unwrap().as_nanos() as f64; + self.base.merge_val(duration); + } + + fn name(&self) -> &'static str { + "time" + } + + fn get_base(&self) -> &WorkCounterBase { + &self.base + } + + fn get_base_mut(&mut self) -> &mut WorkCounterBase { + &mut self.base + } +} From c39b82494967a26eba88ca281508e99c4b7c4661 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Tue, 18 May 2021 23:09:06 +1000 Subject: [PATCH 08/15] Make counter name a String --- src/scheduler/work_counter.rs | 6 +++--- 1 file changed, 3 insertions(+), 3 deletions(-) diff --git a/src/scheduler/work_counter.rs b/src/scheduler/work_counter.rs index 42b52c8aba..7382ad462e 100644 --- a/src/scheduler/work_counter.rs +++ b/src/scheduler/work_counter.rs @@ -21,7 +21,7 @@ pub(super) trait WorkCounter: WorkCounterClone { // TODO: consolidate with crate::util::statistics::counter::Counter; fn start(&mut self); fn stop(&mut self); - fn name(&self) -> &'static str; + fn name(&self) -> String; fn get_base(&self) -> &WorkCounterBase; fn get_base_mut(&mut self) -> &mut WorkCounterBase; } @@ -91,8 +91,8 @@ impl WorkCounter for WorkDuration { self.base.merge_val(duration); } - fn name(&self) -> &'static str { - "time" + fn name(&self) -> String { + "time".to_owned() } fn get_base(&self) -> &WorkCounterBase { From ffb1f709c5696fa30cedf4390b239e16acc576e0 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Wed, 19 May 2021 18:04:12 +1000 Subject: [PATCH 09/15] Don't insert counters when stat is disabled --- src/scheduler/stat.rs | 12 +++++++----- src/scheduler/work_counter.rs | 6 +++--- 2 files changed, 10 insertions(+), 8 deletions(-) diff --git a/src/scheduler/stat.rs b/src/scheduler/stat.rs index f1bf6e3c3b..6d83c85eac 100644 --- a/src/scheduler/stat.rs +++ b/src/scheduler/stat.rs @@ -148,11 +148,13 @@ impl WorkerLocalStat { type_id: work_id, type_name: work_name, }; - self.work_counters - .entry(work_id) - .or_insert_with(WorkerLocalStat::counter_set) - .iter_mut() - .for_each(|c| c.start()); + if self.is_enabled() { + self.work_counters + .entry(work_id) + .or_insert_with(WorkerLocalStat::counter_set) + .iter_mut() + .for_each(|c| c.start()); + } stat } diff --git a/src/scheduler/work_counter.rs b/src/scheduler/work_counter.rs index 7382ad462e..9a0cb91b8c 100644 --- a/src/scheduler/work_counter.rs +++ b/src/scheduler/work_counter.rs @@ -1,6 +1,6 @@ use std::time::SystemTime; -#[derive(Copy, Clone)] +#[derive(Copy, Clone, Debug)] pub(super) struct WorkCounterBase { pub(super) total: f64, pub(super) min: f64, @@ -17,7 +17,7 @@ impl WorkCounterClone for T { } } -pub(super) trait WorkCounter: WorkCounterClone { +pub(super) trait WorkCounter: WorkCounterClone + std::fmt::Debug { // TODO: consolidate with crate::util::statistics::counter::Counter; fn start(&mut self); fn stop(&mut self); @@ -63,7 +63,7 @@ impl WorkCounterBase { } } -#[derive(Copy, Clone)] +#[derive(Copy, Clone, Debug)] pub(super) struct WorkDuration { base: WorkCounterBase, start_value: Option, From 61bd95cfb02515944a136297375354e2993fe5fd Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Thu, 20 May 2021 21:31:40 +1000 Subject: [PATCH 10/15] Fix rustfmt --- src/scheduler/mod.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/scheduler/mod.rs b/src/scheduler/mod.rs index e7c986339a..808ab91edf 100644 --- a/src/scheduler/mod.rs +++ b/src/scheduler/mod.rs @@ -36,4 +36,4 @@ pub use gc_work::ProcessEdgesWork; // to make sure this type is not exposed to the bindings. pub use gc_work::ScanStackRoot; -mod work_counter; \ No newline at end of file +mod work_counter; From 55fcf855ac1023db1a55ebaa671b1f3be5245a75 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Thu, 20 May 2021 22:35:31 +1000 Subject: [PATCH 11/15] Document work counters --- src/scheduler/mod.rs | 3 +-- src/scheduler/work_counter.rs | 25 +++++++++++++++++++++++++ 2 files changed, 26 insertions(+), 2 deletions(-) diff --git a/src/scheduler/mod.rs b/src/scheduler/mod.rs index 808ab91edf..9fd45e30cc 100644 --- a/src/scheduler/mod.rs +++ b/src/scheduler/mod.rs @@ -15,6 +15,7 @@ pub(crate) use scheduler::MMTkScheduler; pub(self) use scheduler::Scheduler; mod stat; +mod work_counter; mod work; pub use work::CoordinatorWork; @@ -35,5 +36,3 @@ pub use gc_work::ProcessEdgesWork; // We should do some refactoring related to Scanning::SCAN_MUTATORS_IN_SAFEPOINT // to make sure this type is not exposed to the bindings. pub use gc_work::ScanStackRoot; - -mod work_counter; diff --git a/src/scheduler/work_counter.rs b/src/scheduler/work_counter.rs index 9a0cb91b8c..be011481d3 100644 --- a/src/scheduler/work_counter.rs +++ b/src/scheduler/work_counter.rs @@ -1,5 +1,14 @@ +//! Counter for work packets +//! +//! Provides an abstraction and implementations of counters for collecting +//! work-packet level statistics +//! +//! See [crate::util::statistics] for collecting statistics over a GC cycle use std::time::SystemTime; +/// Common struct for different work counters +/// +/// Stores the total, min and max of counter readings #[derive(Copy, Clone, Debug)] pub(super) struct WorkCounterBase { pub(super) total: f64, @@ -7,7 +16,9 @@ pub(super) struct WorkCounterBase { pub(super) max: f64, } +/// Make WorkCounter trait objects cloneable pub(super) trait WorkCounterClone { + /// Clone the object fn clone_box(&self) -> Box; } @@ -17,12 +28,18 @@ impl WorkCounterClone for T { } } +/// An abstraction of work counters pub(super) trait WorkCounter: WorkCounterClone + std::fmt::Debug { // TODO: consolidate with crate::util::statistics::counter::Counter; + /// Start the counter fn start(&mut self); + /// Stop the counter fn stop(&mut self); + /// Name of counter fn name(&self) -> String; + /// Return a reference to [WorkCounterBase] fn get_base(&self) -> &WorkCounterBase; + /// Return a mutatable reference to [WorkCounterBase] fn get_base_mut(&mut self) -> &mut WorkCounterBase; } @@ -43,6 +60,8 @@ impl Default for WorkCounterBase { } impl WorkCounterBase { + /// Merge two [WorkCounterBase], keep the semantics of the fields, + /// and return a new object pub(super) fn merge(&self, other: &Self) -> Self { let min = self.min.min(other.min); let max = self.max.max(other.max); @@ -50,12 +69,15 @@ impl WorkCounterBase { WorkCounterBase { total, min, max } } + /// Merge two [WorkCounterBase], modify the current object in place, + /// and keep the semantics of the fields pub(super) fn merge_inplace(&mut self, other: &Self) { self.min = self.min.min(other.min); self.max = self.max.max(other.max); self.total += other.total; } + /// Update the object based on a single value pub(super) fn merge_val(&mut self, val: f64) { self.min = self.min.min(val); self.max = self.max.max(val); @@ -63,6 +85,9 @@ impl WorkCounterBase { } } +/// Measure the durations of work packets +/// +/// Timing is based on [SystemTime] #[derive(Copy, Clone, Debug)] pub(super) struct WorkDuration { base: WorkCounterBase, From fc44c4bdd77556f4f425f6748129dbd6418bfc22 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Thu, 20 May 2021 22:47:04 +1000 Subject: [PATCH 12/15] Revert "Fix test" This reverts commit dfd64e3588337a483084c908b1b67f73916beb7d. --- src/scheduler/scheduler.rs | 1 - 1 file changed, 1 deletion(-) diff --git a/src/scheduler/scheduler.rs b/src/scheduler/scheduler.rs index 6ff6736b52..c461fc8f69 100644 --- a/src/scheduler/scheduler.rs +++ b/src/scheduler/scheduler.rs @@ -410,7 +410,6 @@ mod tests { // println!("Original: {:?}", data); SCHEDULER.initialize(NUM_WORKERS, &(), VMThread::UNINITIALIZED); - SCHEDULER.enable_stat(); SCHEDULER.work_buckets[WorkBucketStage::Unconstrained] .add(Sort(unsafe { &mut *(data as *mut _) })); SCHEDULER.wait_for_completion(); From 63e257d1a3d555d75c2657a2aaa27531a3ee3ea5 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Thu, 20 May 2021 23:04:25 +1000 Subject: [PATCH 13/15] More documentation --- src/scheduler/stat.rs | 43 +++++++++++++++++++++++++++++++++-- src/scheduler/work_counter.rs | 19 ++++++++++------ 2 files changed, 53 insertions(+), 9 deletions(-) diff --git a/src/scheduler/stat.rs b/src/scheduler/stat.rs index 6d83c85eac..974715e1cf 100644 --- a/src/scheduler/stat.rs +++ b/src/scheduler/stat.rs @@ -1,12 +1,23 @@ +//! Statistics for work packets use super::work_counter::{WorkCounter, WorkCounterBase, WorkDuration}; use std::any::TypeId; use std::collections::HashMap; use std::sync::atomic::{AtomicBool, Ordering}; +/// Merge and print the work-packet level statistics from all worker threads #[derive(Default)] pub struct SchedulerStat { + /// Map work packet type IDs to work packet names work_id_name_map: HashMap, + /// Count the number of work packets executed for different types work_counts: HashMap, + /// Collect work counters from work threads. + /// Two dimensional vectors are used. + /// The first dimension is for different types of work counters. + /// The second dimension if for work counters of the same type but from + /// different threads. + /// We assume different threads have the same set of work counters + /// (in the same order). work_counters: HashMap>>>, } @@ -22,6 +33,7 @@ impl SchedulerStat { } } + /// Used during statistics printing at [`crate::memory_manager::harness_end`] pub fn harness_stat(&self) -> HashMap { let mut stat = HashMap::new(); // Work counts @@ -38,13 +50,18 @@ impl SchedulerStat { // Work execution times let mut duration_overall: WorkCounterBase = Default::default(); for (t, vs) in &self.work_counters { + // Name of the work packet type let n = self.work_id_name_map[t]; + // Iterate through different types of work counters for v in vs.iter() { + // Aggregate work counters of the same type but from different + // worker threads let fold = v .iter() .fold(Default::default(), |acc: WorkCounterBase, x| { acc.merge(x.get_base()) }); + // Update the overall execution time duration_overall.merge_inplace(&fold); let name = v.first().unwrap().name(); stat.insert( @@ -61,7 +78,7 @@ impl SchedulerStat { ); } } - + // Print out overall execution time stat.insert( "total-work.time.total".to_owned(), format!("{:.2}", duration_overall.total), @@ -77,11 +94,13 @@ impl SchedulerStat { stat } - + /// Merge work counters from different worker threads pub fn merge(&mut self, stat: &WorkerLocalStat) { + // Merge work packet type ID to work packet name mapping for (id, name) in &stat.work_id_name_map { self.work_id_name_map.insert(*id, *name); } + // Merge work count for different work packet types for (id, count) in &stat.work_counts { if self.work_counts.contains_key(id) { *self.work_counts.get_mut(id).unwrap() += *count; @@ -89,11 +108,21 @@ impl SchedulerStat { self.work_counts.insert(*id, *count); } } + // Merge work counter for different work packet types for (id, counters) in &stat.work_counters { + // Initialize the two dimensional vector + // [ + // [], // foo counter + // [], // bar counter + // ] let vs = self .work_counters .entry(*id) .or_insert_with(|| vec![vec![]; counters.len()]); + // [ + // [counters[0] of type foo], + // [counters[1] of type bar] + // ] for (v, c) in vs.iter_mut().zip(counters.iter()) { v.push(c.clone()); } @@ -101,21 +130,27 @@ impl SchedulerStat { } } +/// Describing a single work packet pub struct WorkStat { type_id: TypeId, type_name: &'static str, } impl WorkStat { + /// Stop all work counters for the work packet type of the just executed + /// work packet #[inline(always)] pub fn end_of_work(&self, worker_stat: &mut WorkerLocalStat) { if !worker_stat.is_enabled() { return; }; + // Insert type ID, name pair worker_stat .work_id_name_map .insert(self.type_id, self.type_name); + // Increment work count *worker_stat.work_counts.entry(self.type_id).or_insert(0) += 1; + // Stop counters worker_stat .work_counters .entry(self.type_id) @@ -125,6 +160,7 @@ impl WorkStat { } } +/// Worker thread local counterpart of [`SchedulerStat`] #[derive(Default)] pub struct WorkerLocalStat { work_id_name_map: HashMap, @@ -142,6 +178,8 @@ impl WorkerLocalStat { pub fn enable(&self) { self.enabled.store(true, Ordering::SeqCst); } + /// Measure the execution of a work packet by starting all counters for that + /// type #[inline] pub fn measure_work(&mut self, work_id: TypeId, work_name: &'static str) -> WorkStat { let stat = WorkStat { @@ -158,6 +196,7 @@ impl WorkerLocalStat { stat } + // The set of work counters for all work packet types fn counter_set() -> Vec> { vec![Box::new(WorkDuration::new())] } diff --git a/src/scheduler/work_counter.rs b/src/scheduler/work_counter.rs index be011481d3..79829121ee 100644 --- a/src/scheduler/work_counter.rs +++ b/src/scheduler/work_counter.rs @@ -3,7 +3,7 @@ //! Provides an abstraction and implementations of counters for collecting //! work-packet level statistics //! -//! See [crate::util::statistics] for collecting statistics over a GC cycle +//! See [`crate::util::statistics`] for collecting statistics over a GC cycle use std::time::SystemTime; /// Common struct for different work counters @@ -16,7 +16,7 @@ pub(super) struct WorkCounterBase { pub(super) max: f64, } -/// Make WorkCounter trait objects cloneable +/// Make [`WorkCounter`] trait objects cloneable pub(super) trait WorkCounterClone { /// Clone the object fn clone_box(&self) -> Box; @@ -29,6 +29,11 @@ impl WorkCounterClone for T { } /// An abstraction of work counters +/// +/// Use for trait objects, as we have might have types of work counters for +/// the same work packet and the types are not statically known.alloc +/// The overhead should be negligible compared with the cost of executing +/// a work packet. pub(super) trait WorkCounter: WorkCounterClone + std::fmt::Debug { // TODO: consolidate with crate::util::statistics::counter::Counter; /// Start the counter @@ -37,9 +42,9 @@ pub(super) trait WorkCounter: WorkCounterClone + std::fmt::Debug { fn stop(&mut self); /// Name of counter fn name(&self) -> String; - /// Return a reference to [WorkCounterBase] + /// Return a reference to [`WorkCounterBase`] fn get_base(&self) -> &WorkCounterBase; - /// Return a mutatable reference to [WorkCounterBase] + /// Return a mutatable reference to [`WorkCounterBase`] fn get_base_mut(&mut self) -> &mut WorkCounterBase; } @@ -60,7 +65,7 @@ impl Default for WorkCounterBase { } impl WorkCounterBase { - /// Merge two [WorkCounterBase], keep the semantics of the fields, + /// Merge two [`WorkCounterBase`], keep the semantics of the fields, /// and return a new object pub(super) fn merge(&self, other: &Self) -> Self { let min = self.min.min(other.min); @@ -69,7 +74,7 @@ impl WorkCounterBase { WorkCounterBase { total, min, max } } - /// Merge two [WorkCounterBase], modify the current object in place, + /// Merge two [`WorkCounterBase`], modify the current object in place, /// and keep the semantics of the fields pub(super) fn merge_inplace(&mut self, other: &Self) { self.min = self.min.min(other.min); @@ -87,7 +92,7 @@ impl WorkCounterBase { /// Measure the durations of work packets /// -/// Timing is based on [SystemTime] +/// Timing is based on [`SystemTime`] #[derive(Copy, Clone, Debug)] pub(super) struct WorkDuration { base: WorkCounterBase, From 76c5b6edc3360dd12b3d738eaf53c141ffe57513 Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Fri, 21 May 2021 10:38:13 +1000 Subject: [PATCH 14/15] Fix typo Co-authored-by: Yi Lin --- src/scheduler/work_counter.rs | 2 +- 1 file changed, 1 insertion(+), 1 deletion(-) diff --git a/src/scheduler/work_counter.rs b/src/scheduler/work_counter.rs index 79829121ee..eea7c08b1b 100644 --- a/src/scheduler/work_counter.rs +++ b/src/scheduler/work_counter.rs @@ -31,7 +31,7 @@ impl WorkCounterClone for T { /// An abstraction of work counters /// /// Use for trait objects, as we have might have types of work counters for -/// the same work packet and the types are not statically known.alloc +/// the same work packet and the types are not statically known. /// The overhead should be negligible compared with the cost of executing /// a work packet. pub(super) trait WorkCounter: WorkCounterClone + std::fmt::Debug { From 10a80e1ae0632959b51707e286b6a4d963532cfb Mon Sep 17 00:00:00 2001 From: Zixian Cai Date: Fri, 28 May 2021 14:10:08 +1000 Subject: [PATCH 15/15] Better documentation for `work_counters` --- src/scheduler/stat.rs | 10 +++++++--- 1 file changed, 7 insertions(+), 3 deletions(-) diff --git a/src/scheduler/stat.rs b/src/scheduler/stat.rs index 974715e1cf..2cc21da41f 100644 --- a/src/scheduler/stat.rs +++ b/src/scheduler/stat.rs @@ -12,10 +12,14 @@ pub struct SchedulerStat { /// Count the number of work packets executed for different types work_counts: HashMap, /// Collect work counters from work threads. - /// Two dimensional vectors are used. - /// The first dimension is for different types of work counters. + /// Two dimensional vectors are used, e.g. + /// `[[foo_0, ..., foo_n], ..., [bar_0, ..., bar_n]]`. + /// The first dimension is for different types of work counters, + /// (`foo` and `bar` in the above example). /// The second dimension if for work counters of the same type but from - /// different threads. + /// different threads (`foo_0` and `bar_0` are from the same thread). + /// The order of insertion is determined by when [`SchedulerStat::merge`] is + /// called for each [`WorkerLocalStat`]. /// We assume different threads have the same set of work counters /// (in the same order). work_counters: HashMap>>>,