From 4596312de1ece7e28ac3f1d50a4767c7cbe6a21d Mon Sep 17 00:00:00 2001 From: Bobby Holley Date: Wed, 15 Feb 2017 03:05:07 -0800 Subject: [PATCH] servo: Merge #15557 - stylo: various fixes to improve style logging in opt builds (from bholley:opt_logging); r=emilio This adds a traversal time entry to the style statistics, and switches to warn! as discussed in [1]. [1] https://bugzilla.mozilla.org/show_bug.cgi?id=1339176 Source-Repo: https://github.com/servo/servo Source-Revision: 715a16423095e1bba2c192c0aebecb8f6aaffab3 --HG-- extra : subtree_source : https%3A//hg.mozilla.org/projects/converted-servo-linear extra : subtree_revision : 945c58dec89fcbd5f4e59729a37aacddf368b983 --- servo/components/style/context.rs | 13 ++++++++ servo/components/style/parallel.rs | 9 ++++-- .../components/style/properties/gecko.mako.rs | 10 ++---- .../style/properties/helpers.mako.rs | 4 +-- servo/components/style/restyle_hints.rs | 2 +- servo/components/style/rule_tree/mod.rs | 2 +- servo/components/style/sequential.rs | 11 +++++-- .../components/style/values/specified/url.rs | 2 +- servo/ports/geckolib/glue.rs | 32 +++++++++++-------- 9 files changed, 54 insertions(+), 31 deletions(-) diff --git a/servo/components/style/context.rs b/servo/components/style/context.rs index d4b0d9c9c2d8..bbf3a7ed61cc 100644 --- a/servo/components/style/context.rs +++ b/servo/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/servo/components/style/parallel.rs b/servo/components/style/parallel.rs index dc3d31f53143..8f4a1d1b92df 100644 --- a/servo/components/style/parallel.rs +++ b/servo/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/servo/components/style/properties/gecko.mako.rs b/servo/components/style/properties/gecko.mako.rs index 7e702f913e31..2d707f7638da 100644 --- a/servo/components/style/properties/gecko.mako.rs +++ b/servo/components/style/properties/gecko.mako.rs @@ -610,15 +610,11 @@ impl ${style_struct.gecko_struct_name} { % for longhand in stub_longhands: #[allow(non_snake_case)] pub fn set_${longhand.ident}(&mut self, _: longhands::${longhand.ident}::computed_value::T) { - if cfg!(debug_assertions) { - println!("stylo: Unimplemented property setter: ${longhand.name}"); - } + warn!("stylo: Unimplemented property setter: ${longhand.name}"); } #[allow(non_snake_case)] pub fn copy_${longhand.ident}_from(&mut self, _: &Self) { - if cfg!(debug_assertions) { - println!("stylo: Unimplemented property setter: ${longhand.name}"); - } + warn!("stylo: Unimplemented property setter: ${longhand.name}"); } % if longhand.need_clone: #[allow(non_snake_case)] @@ -2628,7 +2624,7 @@ clip-path clip_path.mType = StyleShapeSourceType::None; match v { - ShapeSource::Url(..) => println!("stylo: clip-path: url() not yet implemented"), + ShapeSource::Url(..) => warn!("stylo: clip-path: url() not yet implemented"), ShapeSource::None => {} // don't change the type ShapeSource::Box(reference) => { clip_path.mReferenceBox = reference.into(); diff --git a/servo/components/style/properties/helpers.mako.rs b/servo/components/style/properties/helpers.mako.rs index 3d84c4a81903..e89ebaeb21ac 100644 --- a/servo/components/style/properties/helpers.mako.rs +++ b/servo/components/style/properties/helpers.mako.rs @@ -119,7 +119,7 @@ % if allow_empty: try!(dest.write_str("none")); % else: - error!("Found empty value for property ${name}"); + warn!("Found empty value for property ${name}"); % endif } for i in iter { @@ -146,7 +146,7 @@ % if allow_empty: try!(dest.write_str("none")); % else: - error!("Found empty value for property ${name}"); + warn!("Found empty value for property ${name}"); % endif } for i in iter { diff --git a/servo/components/style/restyle_hints.rs b/servo/components/style/restyle_hints.rs index cc2549ee684c..00a39b995e99 100644 --- a/servo/components/style/restyle_hints.rs +++ b/servo/components/style/restyle_hints.rs @@ -103,7 +103,7 @@ impl From for RestyleHint { // FIXME(bholley): Finish aligning the binary representations here and // then .expect() the result of the checked version. if Self::from_bits(raw_bits).is_none() { - error!("stylo: dropping unsupported restyle hint bits"); + warn!("stylo: dropping unsupported restyle hint bits"); } Self::from_bits_truncate(raw_bits) diff --git a/servo/components/style/rule_tree/mod.rs b/servo/components/style/rule_tree/mod.rs index 77cf7d176975..1ecd0a0cb14e 100644 --- a/servo/components/style/rule_tree/mod.rs +++ b/servo/components/style/rule_tree/mod.rs @@ -471,7 +471,7 @@ impl RuleNode { } None => { if indent != 0 { - error!("How has this happened?"); + warn!("How has this happened?"); } let _ = write!(writer, "(root)"); } diff --git a/servo/components/style/sequential.rs b/servo/components/style/sequential.rs index a11bbd52d987..8e8f0f99b8f8 100644 --- a/servo/components/style/sequential.rs +++ b/servo/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); } } diff --git a/servo/components/style/values/specified/url.rs b/servo/components/style/values/specified/url.rs index 9ce58980050d..41af5a16dea0 100644 --- a/servo/components/style/values/specified/url.rs +++ b/servo/components/style/values/specified/url.rs @@ -101,7 +101,7 @@ impl SpecifiedUrl { // FIXME(heycam) should ensure we always have a principal, etc., // when parsing style attributes and re-parsing due to CSS // Variables. - println!("stylo: skipping declaration without ParserContextExtraData"); + warn!("stylo: skipping declaration without ParserContextExtraData"); return Err(()) }, }; diff --git a/servo/ports/geckolib/glue.rs b/servo/ports/geckolib/glue.rs index b8fd181b4578..dcfeaaad5365 100644 --- a/servo/ports/geckolib/glue.rs +++ b/servo/ports/geckolib/glue.rs @@ -6,12 +6,13 @@ use app_units::Au; use atomic_refcell::AtomicRefMut; use cssparser::Parser; use cssparser::ToCss as ParserToCss; -use env_logger; +use env_logger::LogBuilder; use euclid::Size2D; use parking_lot::RwLock; use selectors::Element; use servo_url::ServoUrl; use std::borrow::Cow; +use std::env; use std::fmt::Write; use std::mem; use std::ptr; @@ -91,10 +92,13 @@ use stylesheet_loader::StylesheetLoader; #[no_mangle] pub extern "C" fn Servo_Initialize() -> () { - // Enable standard Rust logging. - // - // See https://doc.rust-lang.org/log/env_logger/index.html for instructions. - env_logger::init().unwrap(); + // Initialize logging. + let mut builder = LogBuilder::new(); + let default_level = if cfg!(debug_assertions) { "warn" } else { "error" }; + match env::var("RUST_LOG") { + Ok(v) => builder.parse(&v).init().unwrap(), + _ => builder.parse(default_level).init().unwrap(), + }; // Pretend that we're a Servo Layout thread, to make some assertions happy. thread_state::initialize(thread_state::LAYOUT); @@ -318,8 +322,8 @@ pub extern "C" fn Servo_AnimationValues_Populate(anim: RawGeckoAnimationValueLis // we should have gone through both iterators if iter.next().is_some() || geckoiter.next().is_some() { - error!("stylo: Mismatched sizes of Gecko and Servo \ - array during animation value construction"); + warn!("stylo: Mismatched sizes of Gecko and Servo \ + array during animation value construction"); } } @@ -671,7 +675,7 @@ pub extern "C" fn Servo_ResolvePseudoStyle(element: RawGeckoElementBorrowed, // FIXME(bholley): Assert against this. if data.get_styles().is_none() { - error!("Calling Servo_ResolvePseudoStyle on unstyled element"); + warn!("Calling Servo_ResolvePseudoStyle on unstyled element"); return if is_probe { Strong::null() } else { @@ -962,7 +966,7 @@ pub extern "C" fn Servo_DeclarationBlock_AddPresValue(declarations: RawServoDecl let long = match prop { Ok(PropertyId::Longhand(long)) => long, _ => { - error!("stylo: unknown presentation property with id {:?}", property); + warn!("stylo: unknown presentation property with id {:?}", property); return } }; @@ -977,7 +981,7 @@ pub extern "C" fn Servo_DeclarationBlock_AddPresValue(declarations: RawServoDecl ) )) } else { - error!("stylo: got unexpected non-integer value for font-size presentation attribute"); + warn!("stylo: got unexpected non-integer value for font-size presentation attribute"); return } } @@ -990,12 +994,12 @@ pub extern "C" fn Servo_DeclarationBlock_AddPresValue(declarations: RawServoDecl } )) } else { - error!("stylo: got unexpected non-integer value for color presentation attribute"); + warn!("stylo: got unexpected non-integer value for color presentation attribute"); return } } _ => { - error!("stylo: cannot handle longhand {:?} from presentation attribute", long); + warn!("stylo: cannot handle longhand {:?} from presentation attribute", long); return } }; @@ -1116,7 +1120,7 @@ pub extern "C" fn Servo_TakeChangeHint(element: RawGeckoElementBorrowed) -> nsCh data.clear_restyle(); d } else { - error!("Trying to get change hint from unstyled element"); + warn!("Trying to get change hint from unstyled element"); GeckoRestyleDamage::empty() }; @@ -1134,7 +1138,7 @@ pub extern "C" fn Servo_ResolveStyle(element: RawGeckoElementBorrowed, let data = unsafe { element.ensure_data() }.borrow_mut(); if !data.has_current_styles() { - error!("Resolving style on unstyled element with lazy computation forbidden."); + warn!("Resolving style on unstyled element with lazy computation forbidden."); let per_doc_data = PerDocumentStyleData::from_ffi(raw_data).borrow(); return per_doc_data.default_computed_values().clone().into_strong(); }