From d7d697914436dc7a7bff8b93145223ec88a5522c Mon Sep 17 00:00:00 2001 From: Bobby Holley Date: Tue, 14 Feb 2017 16:13:21 -0800 Subject: [PATCH] Dump traversal time with other style statistics. --- components/style/context.rs | 13 +++++++++++++ components/style/parallel.rs | 9 +++++++-- components/style/sequential.rs | 11 ++++++++--- 3 files changed, 28 insertions(+), 5 deletions(-) diff --git a/components/style/context.rs b/components/style/context.rs index d4b0d9c9c2d8..bbf3a7ed61cc 100644 --- a/components/style/context.rs +++ b/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 diff --git a/components/style/parallel.rs b/components/style/parallel.rs index dc3d31f53143..8f4a1d1b92df 100644 --- a/components/style/parallel.rs +++ b/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(traversal: &D, where E: TElement, D: DomTraversal, { + 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(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); } } diff --git a/components/style/sequential.rs b/components/style/sequential.rs index a11bbd52d987..8e8f0f99b8f8 100644 --- a/components/style/sequential.rs +++ b/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(traversal: &D, where E: TElement, D: DomTraversal, { + 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(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); } }