Auto merge of #15557 - bholley:opt_logging, r=emilio

stylo: various fixes to improve style logging in opt builds

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

<!-- Reviewable:start -->
---
This change is [<img src="https://reviewable.io/review_button.svg" height="34" align="absmiddle" alt="Reviewable"/>](https://reviewable.io/reviews/servo/servo/15557)
<!-- Reviewable:end -->

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/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();

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 {

components/style/restyle_hints.rs

@@ -103,7 +103,7 @@ impl From<nsRestyleHint> 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)

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)");
             }

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);
     }
 }

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(())
             },
         };