Fix animation start jank due to expensive layout operations.
The Choreographer carefully schedules animation updates to occur
after input but before traversals occur. This ensures that the
effects of animations are perceived immediately in the next frame.
The start time of animation is usually set the moment the animator
first runs. The start time serves as a reference for timing the
remainder of the animation.
Setting the start time during the animation callback works well except
when traversals take a long time to complete. In that case, we may
end up drawing the initial frame of the animation then skipping several
following frames (because a lot of time has already passed since the
animation start time was set), effectively shortening the duration
of the animation.
To resolve this issue, we introduce a new COMMIT phase within the
Choreographer. The COMMIT callback runs after traversals complete
and may provide an updated frame time that more accurately reflects
the time when the frame finished drawing.
In the case where an animation is just starting, we note the fact
that its initial start time has not yet been committed (the user
hasn't actually seen anything on screen yet). Then, during the
COMMIT phase, we adjust the animation start time to better reflect
the time when the animation's first frame was drawn, effectively
causing the animation actually start after the expensive traversal
operations occurred such that no frames will be skipped.
Bug: 17258911
Change-Id: I279603d01fd4ed1de8f51a77c62f4fec5e9b746a
diff --git a/core/java/android/animation/TimeAnimator.java b/core/java/android/animation/TimeAnimator.java
index 1738ade..1ba68df 100644
--- a/core/java/android/animation/TimeAnimator.java
+++ b/core/java/android/animation/TimeAnimator.java
@@ -51,6 +51,7 @@
public void setCurrentPlayTime(long playTime) {
long currentTime = AnimationUtils.currentAnimationTimeMillis();
mStartTime = Math.max(mStartTime, currentTime - playTime);
+ mStartTimeCommitted = true; // do not allow start time to be compensated for jank
animationFrame(currentTime);
}
diff --git a/core/java/android/animation/ValueAnimator.java b/core/java/android/animation/ValueAnimator.java
index 85dc832..2386007 100644
--- a/core/java/android/animation/ValueAnimator.java
+++ b/core/java/android/animation/ValueAnimator.java
@@ -20,6 +20,7 @@
import android.os.Looper;
import android.os.Trace;
import android.util.AndroidRuntimeException;
+import android.util.Log;
import android.view.Choreographer;
import android.view.animation.AccelerateDecelerateInterpolator;
import android.view.animation.AnimationUtils;
@@ -64,6 +65,8 @@
*/
@SuppressWarnings("unchecked")
public class ValueAnimator extends Animator {
+ private static final String TAG = "ValueAnimator";
+ private static final boolean DEBUG = false;
/**
* Internal constants
@@ -85,12 +88,30 @@
* to clone() to make deep copies of them.
*/
- // The first time that the animation's animateFrame() method is called. This time is used to
- // determine elapsed time (and therefore the elapsed fraction) in subsequent calls
- // to animateFrame()
+ /**
+ * The first time that the animation's animateFrame() method is called. This time is used to
+ * determine elapsed time (and therefore the elapsed fraction) in subsequent calls
+ * to animateFrame().
+ *
+ * Whenever mStartTime is set, you must also update mStartTimeCommitted.
+ */
long mStartTime;
/**
+ * When true, the start time has been firmly committed as a chosen reference point in
+ * time by which the progress of the animation will be evaluated. When false, the
+ * start time may be updated when the first animation frame is committed so as
+ * to compensate for jank that may have occurred between when the start time was
+ * initialized and when the frame was actually drawn.
+ *
+ * This flag is generally set to false during the first frame of the animation
+ * when the animation playing state transitions from STOPPED to RUNNING or
+ * resumes after having been paused. This flag is set to true when the start time
+ * is firmly committed and should not be further compensated for jank.
+ */
+ boolean mStartTimeCommitted;
+
+ /**
* Set when setCurrentPlayTime() is called. If negative, animation is not currently seeked
* to a value.
*/
@@ -528,6 +549,7 @@
* value makes it easier to compose statements together that construct and then set the
* duration, as in <code>ValueAnimator.ofInt(0, 10).setDuration(500).start()</code>.
*/
+ @Override
public ValueAnimator setDuration(long duration) {
if (duration < 0) {
throw new IllegalArgumentException("Animators cannot have negative duration: " +
@@ -547,6 +569,7 @@
*
* @return The length of the animation, in milliseconds.
*/
+ @Override
public long getDuration() {
return mUnscaledDuration;
}
@@ -608,6 +631,7 @@
long seekTime = (long) (mDuration * fraction);
long currentTime = AnimationUtils.currentAnimationTimeMillis();
mStartTime = currentTime - seekTime;
+ mStartTimeCommitted = true; // do not allow start time to be compensated for jank
if (mPlayingState != RUNNING) {
mSeekFraction = fraction;
mPlayingState = SEEKED;
@@ -644,7 +668,7 @@
* @hide
*/
@SuppressWarnings("unchecked")
- protected static class AnimationHandler implements Runnable {
+ protected static class AnimationHandler {
// The per-thread list of all active animations
/** @hide */
protected final ArrayList<ValueAnimator> mAnimations = new ArrayList<ValueAnimator>();
@@ -667,6 +691,7 @@
private final Choreographer mChoreographer;
private boolean mAnimationScheduled;
+ private long mLastFrameTime;
private AnimationHandler() {
mChoreographer = Choreographer.getInstance();
@@ -679,7 +704,9 @@
scheduleAnimation();
}
- private void doAnimationFrame(long frameTime) {
+ void doAnimationFrame(long frameTime) {
+ mLastFrameTime = frameTime;
+
// mPendingAnimations holds any animations that have requested to be started
// We're going to clear mPendingAnimations, but starting animation may
// cause more to be added to the pending list (for example, if one animation
@@ -700,6 +727,7 @@
}
}
}
+
// Next, process animations currently sitting on the delayed queue, adding
// them to the active animations if they are ready
int numDelayedAnims = mDelayedAnims.size();
@@ -740,6 +768,9 @@
mEndingAnims.clear();
}
+ // Schedule final commit for the frame.
+ mChoreographer.postCallback(Choreographer.CALLBACK_COMMIT, mCommit, null);
+
// If there are still active or delayed animations, schedule a future call to
// onAnimate to process the next frame of the animations.
if (!mAnimations.isEmpty() || !mDelayedAnims.isEmpty()) {
@@ -747,19 +778,37 @@
}
}
- // Called by the Choreographer.
- @Override
- public void run() {
- mAnimationScheduled = false;
- doAnimationFrame(mChoreographer.getFrameTime());
+ void commitAnimationFrame(long frameTime) {
+ final long adjustment = frameTime - mLastFrameTime;
+ final int numAnims = mAnimations.size();
+ for (int i = 0; i < numAnims; ++i) {
+ mAnimations.get(i).commitAnimationFrame(adjustment);
+ }
}
private void scheduleAnimation() {
if (!mAnimationScheduled) {
- mChoreographer.postCallback(Choreographer.CALLBACK_ANIMATION, this, null);
+ mChoreographer.postCallback(Choreographer.CALLBACK_ANIMATION, mAnimate, null);
mAnimationScheduled = true;
}
}
+
+ // Called by the Choreographer.
+ final Runnable mAnimate = new Runnable() {
+ @Override
+ public void run() {
+ mAnimationScheduled = false;
+ doAnimationFrame(mChoreographer.getFrameTime());
+ }
+ };
+
+ // Called by the Choreographer.
+ final Runnable mCommit = new Runnable() {
+ @Override
+ public void run() {
+ commitAnimationFrame(mChoreographer.getFrameTime());
+ }
+ };
}
/**
@@ -768,6 +817,7 @@
*
* @return the number of milliseconds to delay running the animation
*/
+ @Override
public long getStartDelay() {
return mUnscaledStartDelay;
}
@@ -778,6 +828,7 @@
* @param startDelay The amount of the delay, in milliseconds
*/
+ @Override
public void setStartDelay(long startDelay) {
this.mStartDelay = (long)(startDelay * sDurationScale);
mUnscaledStartDelay = startDelay;
@@ -1148,6 +1199,7 @@
long currentPlayTime = currentTime - mStartTime;
long timeLeft = mDuration - currentPlayTime;
mStartTime = currentTime - timeLeft;
+ mStartTimeCommitted = true; // do not allow start time to be compensated for jank
mReversing = !mReversing;
} else if (mStarted) {
end();
@@ -1254,9 +1306,9 @@
}
long deltaTime = currentTime - mDelayStartTime;
if (deltaTime > mStartDelay) {
- // startDelay ended - start the anim and record the
- // mStartTime appropriately
- mStartTime = currentTime - (deltaTime - mStartDelay);
+ // startDelay ended - start the anim and record the mStartTime appropriately
+ mStartTime = mDelayStartTime + mStartDelay;
+ mStartTimeCommitted = true; // do not allow start time to be compensated for jank
mPlayingState = RUNNING;
return true;
}
@@ -1264,6 +1316,22 @@
}
/**
+ * Applies an adjustment to the animation to compensate for jank between when
+ * the animation first ran and when the frame was drawn.
+ */
+ void commitAnimationFrame(long adjustment) {
+ if (!mStartTimeCommitted) {
+ mStartTimeCommitted = true;
+ if (mPlayingState == RUNNING && adjustment > 0) {
+ mStartTime += adjustment;
+ if (DEBUG) {
+ Log.d(TAG, "Adjusted start time by " + adjustment + " ms: " + toString());
+ }
+ }
+ }
+ }
+
+ /**
* This internal function processes a single animation frame for a given animation. The
* currentTime parameter is the timing pulse sent by the handler, used to calculate the
* elapsed duration, and therefore
@@ -1303,6 +1371,8 @@
mCurrentIteration += (int) fraction;
fraction = fraction % 1f;
mStartTime += mDuration;
+ // Note: We do not need to update the value of mStartTimeCommitted here
+ // since we just added a duration offset.
} else {
done = true;
fraction = Math.min(fraction, 1.0f);
@@ -1334,6 +1404,7 @@
mStartTime = frameTime - seekTime;
mSeekFraction = -1;
}
+ mStartTimeCommitted = false; // allow start time to be compensated for jank
}
if (mPaused) {
if (mPauseTime < 0) {
@@ -1345,6 +1416,7 @@
if (mPauseTime > 0) {
// Offset by the duration that the animation was paused
mStartTime += (frameTime - mPauseTime);
+ mStartTimeCommitted = false; // allow start time to be compensated for jank
}
}
// The frame time might be before the start time during the first frame of
diff --git a/core/java/android/view/Choreographer.java b/core/java/android/view/Choreographer.java
index c8149d9..79a8489 100644
--- a/core/java/android/view/Choreographer.java
+++ b/core/java/android/view/Choreographer.java
@@ -71,7 +71,12 @@
*/
public final class Choreographer {
private static final String TAG = "Choreographer";
- private static final boolean DEBUG = false;
+
+ // Prints debug messages about jank which was detected (low volume).
+ private static final boolean DEBUG_JANK = false;
+
+ // Prints debug messages about every frame and callback registered (high volume).
+ private static final boolean DEBUG_FRAMES = false;
// The default amount of time in ms between animation frames.
// When vsync is not enabled, we want to have some idea of how long we should
@@ -139,6 +144,7 @@
private boolean mCallbacksRunning;
private long mLastFrameTimeNanos;
private long mFrameIntervalNanos;
+ private boolean mDebugPrintNextFrameTimeDelta;
/**
* Contains information about the current frame for jank-tracking,
@@ -166,13 +172,25 @@
public static final int CALLBACK_ANIMATION = 1;
/**
- * Callback type: Traversal callback. Handles layout and draw. Runs last
+ * Callback type: Traversal callback. Handles layout and draw. Runs
* after all other asynchronous messages have been handled.
* @hide
*/
public static final int CALLBACK_TRAVERSAL = 2;
- private static final int CALLBACK_LAST = CALLBACK_TRAVERSAL;
+ /**
+ * Callback type: Commit callback. Handles post-draw operations for the frame.
+ * Runs after traversal completes. The {@link #getFrameTime() frame time} reported
+ * during this callback may be updated to reflect delays that occurred while
+ * traversals were in progress in case heavy layout operations caused some frames
+ * to be skipped. The frame time reported during this callback provides a better
+ * estimate of the start time of the frame in which animations (and other updates
+ * to the view hierarchy state) actually took effect.
+ * @hide
+ */
+ public static final int CALLBACK_COMMIT = 3;
+
+ private static final int CALLBACK_LAST = CALLBACK_COMMIT;
private Choreographer(Looper looper) {
mLooper = looper;
@@ -332,7 +350,7 @@
private void postCallbackDelayedInternal(int callbackType,
Object action, Object token, long delayMillis) {
- if (DEBUG) {
+ if (DEBUG_FRAMES) {
Log.d(TAG, "PostCallback: type=" + callbackType
+ ", action=" + action + ", token=" + token
+ ", delayMillis=" + delayMillis);
@@ -376,7 +394,7 @@
}
private void removeCallbacksInternal(int callbackType, Object action, Object token) {
- if (DEBUG) {
+ if (DEBUG_FRAMES) {
Log.d(TAG, "RemoveCallbacks: type=" + callbackType
+ ", action=" + action + ", token=" + token);
}
@@ -492,7 +510,7 @@
if (!mFrameScheduled) {
mFrameScheduled = true;
if (USE_VSYNC) {
- if (DEBUG) {
+ if (DEBUG_FRAMES) {
Log.d(TAG, "Scheduling next frame on vsync.");
}
@@ -509,7 +527,7 @@
} else {
final long nextFrameTime = Math.max(
mLastFrameTimeNanos / TimeUtils.NANOS_PER_MS + sFrameDelay, now);
- if (DEBUG) {
+ if (DEBUG_FRAMES) {
Log.d(TAG, "Scheduling next frame in " + (nextFrameTime - now) + " ms.");
}
Message msg = mHandler.obtainMessage(MSG_DO_FRAME);
@@ -526,6 +544,12 @@
return; // no work to do
}
+ if (DEBUG_JANK && mDebugPrintNextFrameTimeDelta) {
+ mDebugPrintNextFrameTimeDelta = false;
+ Log.d(TAG, "Frame time delta: "
+ + ((frameTimeNanos - mLastFrameTimeNanos) * 0.000001f) + " ms");
+ }
+
long intendedFrameTimeNanos = frameTimeNanos;
startNanos = System.nanoTime();
final long jitterNanos = startNanos - frameTimeNanos;
@@ -536,7 +560,7 @@
+ "The application may be doing too much work on its main thread.");
}
final long lastFrameOffset = jitterNanos % mFrameIntervalNanos;
- if (DEBUG) {
+ if (DEBUG_JANK) {
Log.d(TAG, "Missed vsync by " + (jitterNanos * 0.000001f) + " ms "
+ "which is more than the frame interval of "
+ (mFrameIntervalNanos * 0.000001f) + " ms! "
@@ -547,7 +571,7 @@
}
if (frameTimeNanos < mLastFrameTimeNanos) {
- if (DEBUG) {
+ if (DEBUG_JANK) {
Log.d(TAG, "Frame time appears to be going backwards. May be due to a "
+ "previously skipped frame. Waiting for next vsync.");
}
@@ -569,7 +593,9 @@
mFrameInfo.markPerformTraversalsStart();
doCallbacks(Choreographer.CALLBACK_TRAVERSAL, frameTimeNanos);
- if (DEBUG) {
+ doCallbacks(Choreographer.CALLBACK_COMMIT, frameTimeNanos);
+
+ if (DEBUG_FRAMES) {
final long endNanos = System.nanoTime();
Log.d(TAG, "Frame " + frame + ": Finished, took "
+ (endNanos - startNanos) * 0.000001f + " ms, latency "
@@ -583,16 +609,43 @@
// We use "now" to determine when callbacks become due because it's possible
// for earlier processing phases in a frame to post callbacks that should run
// in a following phase, such as an input event that causes an animation to start.
- final long now = SystemClock.uptimeMillis();
- callbacks = mCallbackQueues[callbackType].extractDueCallbacksLocked(now);
+ final long now = System.nanoTime();
+ callbacks = mCallbackQueues[callbackType].extractDueCallbacksLocked(
+ now / TimeUtils.NANOS_PER_MS);
if (callbacks == null) {
return;
}
mCallbacksRunning = true;
+
+ // Update the frame time if necessary when committing the frame.
+ // We only update the frame time if we are more than 2 frames late reaching
+ // the commit phase. This ensures that the frame time which is observed by the
+ // callbacks will always increase from one frame to the next and never repeat.
+ // We never want the next frame's starting frame time to end up being less than
+ // or equal to the previous frame's commit frame time. Keep in mind that the
+ // next frame has most likely already been scheduled by now so we play it
+ // safe by ensuring the commit time is always at least one frame behind.
+ if (callbackType == Choreographer.CALLBACK_COMMIT) {
+ final long jitterNanos = now - frameTimeNanos;
+ if (jitterNanos >= 2 * mFrameIntervalNanos) {
+ final long lastFrameOffset = jitterNanos % mFrameIntervalNanos
+ + mFrameIntervalNanos;
+ if (DEBUG_JANK) {
+ Log.d(TAG, "Commit callback delayed by " + (jitterNanos * 0.000001f)
+ + " ms which is more than twice the frame interval of "
+ + (mFrameIntervalNanos * 0.000001f) + " ms! "
+ + "Setting frame time to " + (lastFrameOffset * 0.000001f)
+ + " ms in the past.");
+ mDebugPrintNextFrameTimeDelta = true;
+ }
+ frameTimeNanos = now - lastFrameOffset;
+ mLastFrameTimeNanos = frameTimeNanos;
+ }
+ }
}
try {
for (CallbackRecord c = callbacks; c != null; c = c.next) {
- if (DEBUG) {
+ if (DEBUG_FRAMES) {
Log.d(TAG, "RunCallback: type=" + callbackType
+ ", action=" + c.action + ", token=" + c.token
+ ", latencyMillis=" + (SystemClock.uptimeMillis() - c.dueTime));
