Bug 1500260 - More useful logging for transition-related stuff. r=emilio
authorEmilio Cobos Álvarez <emilio@crisal.io>
Sun, 06 May 2018 18:45:16 +0200
changeset 500549 99cc3c6f76ef81913aea6d0a7d785e02e55f4648
parent 500548 7037075929099a8d88ef702257e88d15cbe3ab59
child 500550 61bdac71c45c07c9f5f6c3adfcd2c9919b93f7fd
push id1864
push userffxbld-merge
push dateMon, 03 Dec 2018 15:51:40 +0000
treeherdermozilla-release@f040763d99ad [default view] [failures only]
perfherder[talos] [build metrics] [platform microbench] (compared to previous push)
reviewersemilio
bugs1500260, 20757
milestone64.0a1
first release with
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
last release without
nightly linux32
nightly linux64
nightly mac
nightly win32
nightly win64
Bug 1500260 - More useful logging for transition-related stuff. r=emilio Transitions are still broken, but I found these messages more helpful than the previous ones when diagnosing problems. This cherry-picks part of servo/servo#20757.
servo/components/style/animation.rs
servo/components/style/matching.rs
servo/components/style/properties/helpers/animated_properties.mako.rs
--- a/servo/components/style/animation.rs
+++ b/servo/components/style/animation.rs
@@ -433,30 +433,37 @@ pub fn start_transitions_if_applicable(
             // transition is the same as that of a transition that's already
             // running on the same node.
             //
             // [1]: https://drafts.csswg.org/css-transitions/#starting
             if possibly_expired_animations
                 .iter()
                 .any(|animation| animation.has_the_same_end_value_as(&property_animation))
             {
+                debug!(
+                    "Not initiating transition for {}, other transition \
+                     found with the same end value",
+                    property_animation.property_name()
+                );
                 continue;
             }
 
+            debug!("Kicking off transition of {:?}", property_animation);
+
             // Kick off the animation.
             let box_style = new_style.get_box();
             let now = timer.seconds();
             let start_time = now + (box_style.transition_delay_mod(i).seconds() as f64);
             new_animations_sender
                 .send(Animation::Transition(
                     opaque_node,
                     start_time,
                     AnimationFrame {
                         duration: box_style.transition_duration_mod(i).seconds() as f64,
-                        property_animation: property_animation,
+                        property_animation,
                     },
                 )).unwrap();
 
             had_animations = true;
         }
     }
 
     had_animations
@@ -652,41 +659,36 @@ pub fn update_style_for_animation<E>(
     context: &SharedStyleContext,
     animation: &Animation,
     style: &mut Arc<ComputedValues>,
     font_metrics_provider: &FontMetricsProvider,
 ) -> AnimationUpdate
 where
     E: TElement,
 {
-    debug!("update_style_for_animation: entering");
+    debug!("update_style_for_animation: {:?}", animation);
     debug_assert!(!animation.is_expired());
 
     match *animation {
         Animation::Transition(_, start_time, ref frame) => {
-            debug!("update_style_for_animation: transition found");
             let now = context.timer.seconds();
             let mut new_style = (*style).clone();
             let updated_style =
                 update_style_for_animation_frame(&mut new_style, now, start_time, frame);
             if updated_style {
                 *style = new_style
             }
             // FIXME(emilio): Should check before updating the style that the
             // transition_property still transitions this, or bail out if not.
             //
             // Or doing it in process_animations, only if transition_property
             // changed somehow (even better).
             AnimationUpdate::Regular
         },
         Animation::Keyframes(_, ref animation, ref name, ref state) => {
-            debug!(
-                "update_style_for_animation: animation found: \"{}\", {:?}",
-                name, state
-            );
             let duration = state.duration;
             let started_at = state.started_at;
 
             let now = match state.running_state {
                 KeyframesRunningState::Running => context.timer.seconds(),
                 KeyframesRunningState::Paused(progress) => started_at + duration * progress,
             };
 
@@ -711,21 +713,16 @@ where
             if total_progress < 0. {
                 warn!("Negative progress found for animation {:?}", name);
                 return AnimationUpdate::Regular;
             }
             if total_progress > 1. {
                 total_progress = 1.;
             }
 
-            debug!(
-                "update_style_for_animation: anim \"{}\", steps: {:?}, state: {:?}, progress: {}",
-                name, animation.steps, state, total_progress
-            );
-
             // Get the target and the last keyframe position.
             let last_keyframe_position;
             let target_keyframe_position;
             match state.current_direction {
                 AnimationDirection::Normal => {
                     target_keyframe_position = animation
                         .steps
                         .iter()
@@ -860,16 +857,17 @@ pub fn complete_expired_transitions(
 ) -> bool {
     let had_animations_to_expire;
     {
         let all_expired_animations = context.expired_animations.read();
         let animations_to_expire = all_expired_animations.get(&node);
         had_animations_to_expire = animations_to_expire.is_some();
         if let Some(ref animations) = animations_to_expire {
             for animation in *animations {
+                debug!("Updating expired animation {:?}", animation);
                 // TODO: support animation-fill-mode
                 if let Animation::Transition(_, _, ref frame) = *animation {
                     frame.property_animation.update(Arc::make_mut(style), 1.0);
                 }
             }
         }
     }
 
--- a/servo/components/style/matching.rs
+++ b/servo/components/style/matching.rs
@@ -599,41 +599,30 @@ trait PrivateMatchMethods: TElement {
             .get(&this_opaque)
             .is_some();
         if !had_running_animations {
             return;
         }
 
         let mut all_running_animations = context.running_animations.write();
         for mut running_animation in all_running_animations.get_mut(&this_opaque).unwrap() {
-            // This shouldn't happen frequently, but under some circumstances
-            // mainly huge load or debug builds, the constellation might be
-            // delayed in sending the `TickAllAnimations` message to layout.
-            //
-            // Thus, we can't assume all the animations have been already
-            // updated by layout, because other restyle due to script might be
-            // triggered by layout before the animation tick.
-            //
-            // See #12171 and the associated PR for an example where this
-            // happened while debugging other release panic.
-            if running_animation.is_expired() {
+            if let Animation::Transition(_, _, ref frame) = *running_animation {
+                possibly_expired_animations.push(frame.property_animation.clone());
                 continue;
             }
 
             let update = animation::update_style_for_animation::<Self>(
                 context,
                 &mut running_animation,
                 style,
                 font_metrics,
             );
 
             match *running_animation {
-                Animation::Transition(_, _, ref frame) => {
-                    possibly_expired_animations.push(frame.property_animation.clone())
-                }
+                Animation::Transition(..) => unreachable!(),
                 Animation::Keyframes(_, _, _, ref mut state) => {
                     match update {
                         AnimationUpdate::Regular => {},
                         AnimationUpdate::AnimationCanceled => {
                             state.expired = true;
                         }
                     }
                 }
--- a/servo/components/style/properties/helpers/animated_properties.mako.rs
+++ b/servo/components/style/properties/helpers/animated_properties.mako.rs
@@ -122,27 +122,32 @@ pub enum AnimatedProperty {
             %>
             /// ${prop.name}
             ${prop.camel_case}(${value_type}, ${value_type}),
         % endif
     % endfor
 }
 
 impl AnimatedProperty {
-    /// Get the name of this property.
-    pub fn name(&self) -> &'static str {
+    /// Get the id of the property we're animating.
+    pub fn id(&self) -> LonghandId {
         match *self {
             % for prop in data.longhands:
-                % if prop.animatable and not prop.logical:
-                    AnimatedProperty::${prop.camel_case}(..) => "${prop.name}",
-                % endif
+            % if prop.animatable and not prop.logical:
+            AnimatedProperty::${prop.camel_case}(..) => LonghandId::${prop.camel_case},
+            % endif
             % endfor
         }
     }
 
+    /// Get the name of this property.
+    pub fn name(&self) -> &'static str {
+        self.id().name()
+    }
+
     /// Whether this interpolation does animate, that is, whether the start and
     /// end values are different.
     pub fn does_animate(&self) -> bool {
         match *self {
             % for prop in data.longhands:
                 % if prop.animatable and not prop.logical:
                     AnimatedProperty::${prop.camel_case}(ref from, ref to) => from != to,
                 % endif