Dump traversal time with other style statistics.

components/style/context.rs

@@ -25,6 +25,7 @@ use std::sync::{Arc, Mutex};
 use std::sync::mpsc::Sender;
 use stylist::Stylist;
 use thread_state;
+use time;
 use timer::Timer;
 
 /// This structure is used to create a local style context from a shared one.
@@ -120,17 +121,22 @@ pub struct TraversalStatistics {
     pub elements_matched: u32,
     /// The number of cache hits from the StyleSharingCache.
     pub styles_shared: u32,
+    /// Time spent in the traversal, in milliseconds.
+    pub traversal_time_ms: f64,
 }
 
 /// Implementation of Add to aggregate statistics across different threads.
 impl<'a> Add for &'a TraversalStatistics {
     type Output = TraversalStatistics;
     fn add(self, other: Self) -> TraversalStatistics {
+        debug_assert!(self.traversal_time_ms == 0.0 && other.traversal_time_ms == 0.0,
+                      "traversal_time_ms should be set at the end by the caller");
         TraversalStatistics {
             elements_traversed: self.elements_traversed + other.elements_traversed,
             elements_styled: self.elements_styled + other.elements_styled,
             elements_matched: self.elements_matched + other.elements_matched,
             styles_shared: self.styles_shared + other.styles_shared,
+            traversal_time_ms: 0.0,
         }
     }
 }
@@ -139,11 +145,13 @@ impl<'a> Add for &'a TraversalStatistics {
 /// See https://bugzilla.mozilla.org/show_bug.cgi?id=1331856#c2
 impl fmt::Display for TraversalStatistics {
     fn fmt(&self, f: &mut fmt::Formatter) -> fmt::Result {
+        debug_assert!(self.traversal_time_ms != 0.0, "should have set traversal time");
         try!(writeln!(f, "[PERF] perf block start"));
         try!(writeln!(f, "[PERF],elements_traversed,{}", self.elements_traversed));
         try!(writeln!(f, "[PERF],elements_styled,{}", self.elements_styled));
         try!(writeln!(f, "[PERF],elements_matched,{}", self.elements_matched));
         try!(writeln!(f, "[PERF],styles_shared,{}", self.styles_shared));
+        try!(writeln!(f, "[PERF],traversal_time_ms,{}", self.traversal_time_ms));
         writeln!(f, "[PERF] perf block end")
     }
 }
@@ -165,6 +173,11 @@ impl TraversalStatistics {
     pub fn should_dump() -> bool {
         *DUMP_STYLE_STATISTICS || opts::get().style_sharing_stats
     }
+
+    /// Computes the traversal time given the start time in seconds.
+    pub fn compute_traversal_time(&mut self, start: f64) {
+        self.traversal_time_ms = (time::precise_time_s() - start) * 1000.0;
+    }
 }
 
 /// A task to be run in sequential mode on the parent (non-worker) thread. This

components/style/parallel.rs

@@ -27,6 +27,7 @@ use dom::{OpaqueNode, SendNode, TElement, TNode};
 use rayon;
 use scoped_tls::ScopedTLS;
 use std::borrow::Borrow;
+use time;
 use traversal::{DomTraversal, PerLevelTraversalData, PreTraverseToken};
 
 /// The chunk size used to split the parallel traversal nodes.
@@ -44,6 +45,9 @@ pub fn traverse_dom<E, D>(traversal: &D,
     where E: TElement,
           D: DomTraversal<E>,
 {
+    let dump_stats = TraversalStatistics::should_dump();
+    let start_time = if dump_stats { Some(time::precise_time_s()) } else { None };
+
     debug_assert!(traversal.is_parallel());
     // Handle Gecko's eager initial styling. We don't currently support it
     // in conjunction with bottom-up traversal. If we did, we'd need to put
@@ -74,14 +78,15 @@ pub fn traverse_dom<E, D>(traversal: &D,
     });
 
     // Dump statistics to stdout if requested.
-    if TraversalStatistics::should_dump() {
+    if dump_stats {
         let slots = unsafe { tls.unsafe_get() };
-        let aggregate = slots.iter().fold(TraversalStatistics::default(), |acc, t| {
+        let mut aggregate = slots.iter().fold(TraversalStatistics::default(), |acc, t| {
             match *t.borrow() {
                 None => acc,
                 Some(ref cx) => &cx.borrow().statistics + &acc,
             }
         });
+        aggregate.compute_traversal_time(start_time.unwrap());
         println!("{}", aggregate);
     }
 }

components/style/sequential.rs

@@ -8,7 +8,8 @@
 
 use context::TraversalStatistics;
 use dom::{TElement, TNode};
-use std::borrow::Borrow;
+use std::borrow::BorrowMut;
+use time;
 use traversal::{DomTraversal, PerLevelTraversalData, PreTraverseToken};
 
 /// Do a sequential DOM traversal for layout or styling, generic over `D`.
@@ -18,6 +19,9 @@ pub fn traverse_dom<E, D>(traversal: &D,
     where E: TElement,
           D: DomTraversal<E>,
 {
+    let dump_stats = TraversalStatistics::should_dump();
+    let start_time = if dump_stats { Some(time::precise_time_s()) } else { None };
+
     debug_assert!(!traversal.is_parallel());
     debug_assert!(token.should_traverse());
 
@@ -62,8 +66,9 @@ pub fn traverse_dom<E, D>(traversal: &D,
     }
 
     // Dump statistics to stdout if requested.
-    let tlsc = tlc.borrow();
-    if TraversalStatistics::should_dump() {
+    if dump_stats {
+        let tlsc = tlc.borrow_mut();
+        tlsc.statistics.compute_traversal_time(start_time.unwrap());
         println!("{}", tlsc.statistics);
     }
 }