Donate to e Foundation | Murena handsets with /e/OS | Own a part of Murena! Learn more

Commit 2feb2214 authored by Greg Kaiser's avatar Greg Kaiser
Browse files

BouncyBall: Detect dropped frames via Choreographer 

We use Choreographer.FrameCallback to find out within the app
when we've dropped a frame.  Since our doFrame() callback is
only invoked when a new display frame is being rendered, we
only get data at (about) the resolution of the targeted frame
time.

So this data is good enough to detect dropped frames, but not
helpful for seeing how close we are to dropping, or how much
over deadline we were.  We'll be using perfetto to get that
data.  But these changes allow the app to self-report the most
basic of data.

We upgrade a couple log messages from Debug to Info, since they
are rare (only at startup), and lets folks know what frame rate
we're testing at.

We add (off-by-default) logic to drop occasional frames, and
to log on every frame, to aid in debugging and testing the
process itself.

Bug: 408044970
Test: Ran with and without FORCE_DROPPED_FRAMES and LOG_EVERY_FRAME, getting the expected behavior in all cases.
Flag: EXEMPT for test app
Change-Id: I275ae8775af275d1743ecdecacb628a556e3a9d6
parent 2a85664a

tests/BouncyBall/README

+3 −1
Original line number Diff line number Diff line 
This is a simple graphics app which draws a ball bouncing around a screen.



This app is intended for use in automated testing (for example, to make sure

no frames are dropped while running).

no frames are dropped while running).  It can also be run manually, but there's

a fundamental assumption that this is the only foreground app running on the

device while testing.





From the top of tree, in a shell that has been set up for building, this app

tests/BouncyBall/app/src/main/java/com/prefabulated/bouncyball/BouncyBallActivity.java

+78 −5
Original line number Diff line number Diff line
@@ -20,6 +20,7 @@ import android.hardware.display.DisplayManager; 
import android.os.Bundle;

import android.os.Trace;

import android.util.Log;

import android.view.Choreographer;

import android.view.Display;

import android.view.Window;

import android.view.WindowManager;
@@ -29,11 +30,26 @@ import androidx.appcompat.app.AppCompatActivity; 
import java.util.concurrent.Executors;



public class BouncyBallActivity extends AppCompatActivity {

    // Since logging (to logcat) takes system resources, we chose not to log

    // data every frame by default.

    private static final boolean LOG_EVERY_FRAME = false;

    // To help with debugging and verifying behavior when frames are dropped,

    // this will drop one in every 64 frames.

    private static final boolean FORCE_DROPPED_FRAMES = false;



    private static final String LOG_TAG = "BouncyBall";

    private static final float DESIRED_FRAME_RATE = 60.0f;



    // Our focus isn't smoothness on startup; it's smoothness once we're

    // running.  So we ignore frame drops in the first 0.1 seconds.

    private static final int INITIAL_FRAMES_TO_IGNORE = 6;



    private int mDisplayId = -1;

    private float mFrameRate;

    private long mFrameMaxDurationNanos;

    private int mNumFramesDropped = 0;

    private Choreographer mChoreographer;



    private final DisplayManager.DisplayListener mDisplayListener =

            new DisplayManager.DisplayListener() {
@@ -48,8 +64,46 @@ public class BouncyBallActivity extends AppCompatActivity { 
                    if (displayId != mDisplayId) {

                        return;

                    }

                    mFrameRate = getDisplay().getMode().getRefreshRate();

                    Log.d(LOG_TAG, "Using frame rate " + mFrameRate + "Hz");

                    setFrameRate(getDisplay().getMode().getRefreshRate());

                    Log.i(LOG_TAG, "Using frame rate " + mFrameRate + "Hz");

                }

            };



    private final Choreographer.FrameCallback mFrameCallback =

            new Choreographer.FrameCallback() {



                private long mLastFrameTimeNanos = -1;

                private int mFrameCount = 0;



                @Override

                public void doFrame(long frameTimeNanos) {

                    if (mFrameCount >= INITIAL_FRAMES_TO_IGNORE) {

                        long elapsedNanos = frameTimeNanos - mLastFrameTimeNanos;

                        if (elapsedNanos > mFrameMaxDurationNanos) {

                            mNumFramesDropped++;

                            Log.e(LOG_TAG, "FRAME DROPPED (total " + mNumFramesDropped

                                    + "): Took " + nanosToMillis(elapsedNanos) + "ms");

                        } else if (LOG_EVERY_FRAME) {

                            Log.d(LOG_TAG, "Frame took " + nanosToMillis(elapsedNanos) + "ms");

                        }

                    }

                    mLastFrameTimeNanos = frameTimeNanos;

                    mFrameCount++;

                    if (FORCE_DROPPED_FRAMES) {

                        dropFrameSometimes();

                    }

                    // Request the next frame callback

                    mChoreographer.postFrameCallback(this);

                }



                private void dropFrameSometimes() {

                    if ((mFrameCount % 64) == 0) {

                        try {

                            Thread.sleep((long) nanosToMillis(mFrameMaxDurationNanos) + 1);

                        } catch (InterruptedException ex) {

                            Thread.currentThread().interrupt();

                        }

                    }

                }

            };
@@ -66,6 +120,8 @@ public class BouncyBallActivity extends AppCompatActivity { 
                                        mDisplayListener);



        setFrameRatePreference();

        mChoreographer = Choreographer.getInstance();

        mChoreographer.postFrameCallback(mFrameCallback);

        Trace.endSection();

    }
@@ -85,9 +141,9 @@ public class BouncyBallActivity extends AppCompatActivity { 
        Display display = getDisplay();

        Display.Mode currentMode = display.getMode();

        mDisplayId = display.getDisplayId();

        mFrameRate = currentMode.getRefreshRate();

        setFrameRate(currentMode.getRefreshRate());

        if (mFrameRate == DESIRED_FRAME_RATE) {

            Log.d(LOG_TAG, "Already running at " + mFrameRate + "Hz");

            Log.i(LOG_TAG, "Already running at " + mFrameRate + "Hz");

            // We're already using what we want.  Nothing to do here.

            return;

        }
@@ -115,11 +171,28 @@ public class BouncyBallActivity extends AppCompatActivity { 
            String msg = "No display mode with at least " + DESIRED_FRAME_RATE + "Hz";

            throw new RuntimeException(msg);

        }

        Log.d(LOG_TAG, "Changing preferred rate from " + mFrameRate + "Hz to "

        Log.i(LOG_TAG, "Changing preferred rate from " + mFrameRate + "Hz to "

                + preferredRate + "Hz");

        Window window = getWindow();

        WindowManager.LayoutParams params = window.getAttributes();

        params.preferredRefreshRate = preferredRate;

        window.setAttributes(params);

    }



    private void setFrameRate(float frameRate) {

        mFrameRate = frameRate;

        float frameMaxDurationMillis = 1_000.0f / mFrameRate;

        // There is a little +/- of when our callback is called.  So we allow

        // up to 25% beyond this before considering it a frame drop.  Since

        // a frame drop should mean getting a value near double (or higher),

        // allowing 25% shouldn't have us missing legitimate drops.

        frameMaxDurationMillis *= 1.25f;

        // We store as nanoseconds, to avoid per-frame floating point math in

        // the common case.

        mFrameMaxDurationNanos = ((long) frameMaxDurationMillis) * 1_000_000;

    }



    private float nanosToMillis(long nanos) {

        return nanos / (1_000_000.0f);

    }

}