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 490347 99cc3c6f76ef81913aea6d0a7d785e02e55f4648
parent 490346 7037075929099a8d88ef702257e88d15cbe3ab59
child 490348 61bdac71c45c07c9f5f6c3adfcd2c9919b93f7fd
push id247
push userfmarier@mozilla.com
push dateSat, 27 Oct 2018 01:06:44 +0000
reviewersemilio
bugs1500260, 20757
milestone64.0a1
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