Don't reset the perf counter after reading (#467)

This reduces the accumulated error and avoid triggering a kernel bug.

Author: caizixian

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 = {version = "0.0.8", optional = true}
+pfm = {version = "0.0.9", optional = true}
 
 [dev-dependencies]
 crossbeam = "0.7.3"

src/memory_manager.rs

@@ -61,7 +61,7 @@ pub fn gc_init<VM: VMBinding>(mmtk: &'static mut MMTK<VM>, heap_size: usize) {
             if split[0] == "Threads:" {
                 let threads = split[1].parse::<i32>().unwrap();
                 if threads != 1 {
-                    warn!("Current process has {} threads, process-wide perf event measurement will only include child threads spawned from this threadas", threads);
+                    warn!("Current process has {} threads, process-wide perf event measurement will only include child threads spawned from this thread", threads);
                 }
             }
         }

src/scheduler/work_counter.rs

@@ -189,16 +189,16 @@ mod perf_event {
     impl WorkCounter for WorkPerfEvent {
         fn start(&mut self) {
             self.running = true;
-            self.pe.reset();
-            self.pe.enable();
+            self.pe.reset().expect("Failed to reset perf event");
+            self.pe.enable().expect("Failed to enable perf event");
         }
         fn stop(&mut self) {
             self.running = true;
             let perf_event_value = self.pe.read().unwrap();
             self.base.merge_val(perf_event_value.value as f64);
             // assert not multiplexing
             assert_eq!(perf_event_value.time_enabled, perf_event_value.time_running);
-            self.pe.disable();
+            self.pe.disable().expect("Failed to disable perf event");
         }
         fn name(&self) -> String {
             self.event_name.to_owned()

src/util/statistics/counter/event_counter.rs

@@ -80,10 +80,6 @@ impl Counter for EventCounter {
         self.running = false;
     }
 
-    /**
-     * The phase has changed (from GC to mutator or mutator to GC).
-     * Take action with respect to the last phase if necessary.
-     */
     fn phase_change(&mut self, old_phase: usize) {
         if self.running {
             self.count[old_phase] = self.current_count;
@@ -100,14 +96,14 @@ impl Counter for EventCounter {
         }
     }
 
-    fn print_total(&self, mutator: Option<bool>) {
-        match mutator {
+    fn get_total(&self, other: Option<bool>) -> u64 {
+        match other {
             None => {
                 let mut total = 0;
                 for p in 0..=self.stats.get_phase() {
                     total += self.count[p];
                 }
-                self.print_value(total);
+                total
             }
             Some(m) => {
                 let mut total = 0;
@@ -116,13 +112,17 @@ impl Counter for EventCounter {
                     total += self.count[p];
                     p += 2;
                 }
-                self.print_value(total);
+                total
             }
-        };
+        }
+    }
+
+    fn print_total(&self, other: Option<bool>) {
+        self.print_value(self.get_total(other));
     }
 
-    fn print_min(&self, mutator: bool) {
-        let mut p = if mutator { 0 } else { 1 };
+    fn print_min(&self, other: bool) {
+        let mut p = if other { 0 } else { 1 };
         let mut min = self.count[p];
         while p < self.stats.get_phase() {
             if self.count[p] < min {
@@ -133,8 +133,8 @@ impl Counter for EventCounter {
         self.print_value(min);
     }
 
-    fn print_max(&self, mutator: bool) {
-        let mut p = if mutator { 0 } else { 1 };
+    fn print_max(&self, other: bool) {
+        let mut p = if other { 0 } else { 1 };
         let mut max = self.count[p];
         while p < self.stats.get_phase() {
             if self.count[p] > max {

src/util/statistics/counter/long_counter.rs

@@ -28,6 +28,7 @@ impl<T: Diffable> Counter for LongCounter<T> {
         }
         debug_assert!(!self.running);
         self.running = true;
+        self.diffable.start();
         self.start_value = Some(self.diffable.current_value());
     }
 
@@ -37,6 +38,7 @@ impl<T: Diffable> Counter for LongCounter<T> {
         }
         debug_assert!(self.running);
         self.running = false;
+        self.diffable.stop();
         let current_value = self.diffable.current_value();
         let delta = T::diff(&current_value, self.start_value.as_ref().unwrap());
         self.count[self.stats.get_phase()] += delta;
@@ -62,23 +64,27 @@ impl<T: Diffable> Counter for LongCounter<T> {
         }
     }
 
-    fn print_total(&self, mutator: Option<bool>) {
-        match mutator {
-            None => self.print_value(self.total_count),
+    fn get_total(&self, other: Option<bool>) -> u64 {
+        match other {
+            None => self.total_count,
             Some(m) => {
                 let mut total = 0;
                 let mut p = if m { 0 } else { 1 };
                 while p <= self.stats.get_phase() {
                     total += self.count[p];
                     p += 2;
                 }
-                self.print_value(total);
+                total
             }
-        };
+        }
+    }
+
+    fn print_total(&self, other: Option<bool>) {
+        self.print_value(self.get_total(other));
     }
 
-    fn print_min(&self, mutator: bool) {
-        let mut p = if mutator { 0 } else { 1 };
+    fn print_min(&self, other: bool) {
+        let mut p = if other { 0 } else { 1 };
         let mut min = self.count[p];
         while p < self.stats.get_phase() {
             if self.count[p] < min {
@@ -89,8 +95,8 @@ impl<T: Diffable> Counter for LongCounter<T> {
         self.print_value(min);
     }
 
-    fn print_max(&self, mutator: bool) {
-        let mut p = if mutator { 0 } else { 1 };
+    fn print_max(&self, other: bool) {
+        let mut p = if other { 0 } else { 1 };
         let mut max = self.count[p];
         while p < self.stats.get_phase() {
             if self.count[p] > max {

src/util/statistics/counter/mod.rs

@@ -12,26 +12,73 @@ pub use self::long_counter::{LongCounter, Timer};
 pub use self::perf_event::PerfEventDiffable;
 pub use self::size_counter::SizeCounter;
 
+/// An abstraction over how a specific Diffable value is counted
+///
+/// For example, we can just collect the values, and store the cummulative sum,
+/// or we can derive some kind of histogram, etc.
 pub trait Counter {
+    /// Start the counter
     fn start(&mut self);
+    /// Stop the counter
     fn stop(&mut self);
+    /// Signal a change in GC phase.
+    ///
+    /// The phase number starts from 0 and is strictly increasing.
+    /// Even numbers mean mutators are running (`other`) while odd numbers mean
+    /// stop-the-world pauses (`stw`).
+    /// Take action with respect to the last phase if necessary.
     fn phase_change(&mut self, old_phase: usize);
+    /// Print the counter value for a particular phase
+    ///
+    /// If the counter merges the phases, the printing value will include
+    /// the specified phase and the next phase
     fn print_count(&self, phase: usize);
-    fn print_total(&self, mutator: Option<bool>);
-    fn print_min(&self, mutator: bool);
-    fn print_max(&self, mutator: bool);
+    /// Get the total count over past phases
+    ///
+    /// If the argument is None, count all phases.
+    /// Otherwise, count only `other` phases if true, or `stw` phases if false
+    fn get_total(&self, other: Option<bool>) -> u64;
+    /// Print the total count over past phases
+    ///
+    /// If the argument is None, count all phases.
+    /// Otherwise, count only `other` phases if true, or `stw` phases if false
+    fn print_total(&self, other: Option<bool>);
+    /// Print the minimum count of the past phases
+    ///
+    /// Consider only `other` phases if true, or `stw` phases if false
+    fn print_min(&self, other: bool);
+    /// Print the maximum count of the past phases
+    ///
+    /// Consider only `other` phases if true, or `stw` phases if false
+    fn print_max(&self, other: bool);
+    /// Print the count of the last phases
     fn print_last(&self);
+    /// Whether the counter merges other and stw phases.
     fn merge_phases(&self) -> bool;
+    /// Whether the counter starts implicitly after creation
+    ///
+    /// FIXME currently unused
     fn implicitly_start(&self) -> bool;
+    /// Get the name of the counter
     fn name(&self) -> &String;
 }
 
+/// An abstraction over some changing values that we want to measure.
+///
 /// A Diffable object could be stateless (e.g. a timer that reads the wall
 /// clock), or stateful (e.g. holds reference to a perf event fd)
 pub trait Diffable {
+    /// The type of each reading
     type Val;
+    /// Start the Diffable
+    fn start(&mut self);
+    /// Stop the Diffable
+    fn stop(&mut self);
+    /// Read the current value
     fn current_value(&mut self) -> Self::Val;
+    /// Compute the difference between two readings
     fn diff(current: &Self::Val, earlier: &Self::Val) -> u64;
+    /// Print the difference in a specific format
     fn print_diff(val: u64);
 }
 
@@ -40,6 +87,12 @@ pub struct MonotoneNanoTime;
 impl Diffable for MonotoneNanoTime {
     type Val = Instant;
 
+    /// nop for the wall-clock time
+    fn start(&mut self) {}
+
+    /// nop for the wall-clock time
+    fn stop(&mut self) {}
+
     fn current_value(&mut self) -> Instant {
         Instant::now()
     }

src/util/statistics/counter/perf_event.rs

@@ -22,17 +22,24 @@ impl PerfEventDiffable {
 impl Diffable for PerfEventDiffable {
     type Val = PerfEventValue;
 
+    fn start(&mut self) {
+        self.pe.reset().expect("Failed to reset perf evet");
+        self.pe.enable().expect("Failed to enable perf evet");
+    }
+
+    fn stop(&mut self) {
+        self.pe.disable().expect("Failed to disable perf evet");
+    }
+
     fn current_value(&mut self) -> Self::Val {
-        let val = self.pe.read().unwrap();
-        self.pe.enable();
-        self.pe.reset();
+        let val = self.pe.read().expect("Failed to read perf evet");
+        assert_eq!(val.time_enabled, val.time_running, "perf event multiplexed");
         val
     }
 
-    fn diff(current: &Self::Val, _earlier: &Self::Val) -> u64 {
-        // earlier value is not used as the counter is reset after each use
-        assert_eq!(current.time_enabled, current.time_running);
-        current.value as u64
+    fn diff(current: &Self::Val, earlier: &Self::Val) -> u64 {
+        assert!(current.value >= earlier.value, "perf event overflowed");
+        current.value as u64 - earlier.value as u64
     }
 
     fn print_diff(val: u64) {

src/util/statistics/stats.rs

@@ -14,7 +14,7 @@ use std::sync::Mutex;
 pub const MAX_PHASES: usize = 1 << 12;
 pub const MAX_COUNTERS: usize = 100;
 
-// Shared with each counter
+/// GC stats shared among counters
 pub struct SharedStats {
     phase: AtomicUsize,
     gathering_stats: AtomicBool,
@@ -38,6 +38,10 @@ impl SharedStats {
     }
 }
 
+/// GC statistics
+///
+/// The struct holds basic GC statistics, like the GC count,
+/// and an array of counters.
 pub struct Stats {
     gc_count: AtomicUsize,
     total_time: Arc<Mutex<Timer>>,
@@ -54,6 +58,8 @@ pub struct Stats {
 impl Stats {
     #[allow(unused)]
     pub fn new(options: &Options) -> Self {
+        // Create a perfmon instance and initialize it
+        // we use perfmon to parse perf event names
         #[cfg(feature = "perf_counter")]
         let perfmon = {
             let mut perfmon: Perfmon = Default::default();
@@ -65,6 +71,7 @@ impl Stats {
             gathering_stats: AtomicBool::new(false),
         });
         let mut counters: Vec<Arc<Mutex<dyn Counter + Send>>> = vec![];
+        // We always have a time counter enabled
         let t = Arc::new(Mutex::new(LongCounter::new(
             "time".to_string(),
             shared.clone(),
@@ -73,6 +80,8 @@ impl Stats {
             MonotoneNanoTime {},
         )));
         counters.push(t.clone());
+        // Read from the MMTK option for a list of perf events we want to
+        // measure, and create corresponding counters
         #[cfg(feature = "perf_counter")]
         for e in &options.phase_perf_events.events {
             counters.push(Arc::new(Mutex::new(LongCounter::new(