Meaning of Choreographer messages in Logcat [duplicate]

Question

Choreographer lets apps to connect themselves to the vsync, and properly time things to improve performance.

Android view animations internally uses Choreographer for the same purpose: to properly time the animations and possibly improve performance.

Since Choreographer is told about every vsync events, it can tell if one of the Runnables passed along by the Choreographer.post* apis doesn't finish in one frame's time, causing frames to be skipped.

In my understanding Choreographer can only detect the frame skipping. It has no way of telling why this happens.

The message "The application may be doing too much work on its main thread." could be misleading.

I'm late to the party, but hopefully this is a useful addition to the other answers here...

Answering the Question / tl:dr;

I need to know how I can determine what "too much work" my application may be doing as all my processing is done in AsyncTasks.

The following are all candidates:

• IO or expensive processing on the main thread (loading drawables, inflating layouts, and setting Uri's on ImageView's all constitute IO on the main thread)
• Rendering large/complex/deep View hierarchies
• Invalidating large portions of a View hierarchy
• Expensive onDraw methods in custom View's
• Expensive calculations in animations
• Running "worker" threads at too high a priority to be considered "background" (AsyncTask's are "background" by default, java.lang.Thread is not)
• Generating lots of garbage, causing the garbage collector to "stop the world" - including the main thread - while it cleans up

To actually determine the specific cause you'll need to profile your app.

More Detail

I've been trying to understand Choreographer by experimenting and looking at the code.

The documentation of Choreographer opens with "Coordinates the timing of animations, input and drawing." which is actually a good description, but the rest goes on to over-emphasize animations.

The Choreographer is actually responsible for executing 3 types of callbacks, which run in this order:

1. input-handling callbacks (handling user-input such as touch events)
2. animation callbacks for tweening between frames, supplying a stable frame-start-time to any/all animations that are running. Running these callbacks 2nd means any animation-related calculations (e.g. changing positions of View's) have already been made by the time the third type of callback is invoked...
3. view traversal callbacks for drawing the view hierarchy.

The aim is to match the rate at which invalidated views are re-drawn (and animations tweened) with the screen vsync - typically 60fps.

The warning about skipped frames looks like an afterthought: The message is logged if a single pass through the 3 steps takes more than 30x the expected frame duration, so the smallest number you can expect to see in the log messages is "skipped 30 frames"; If each pass takes 50% longer than it should you will still skip 30 frames (naughty!) but you won't be warned about it.

From the 3 steps involved its clear that it isn't only animations that can trigger the warning: Invalidating a significant portion of a large View hierarchy or a View with a complicated onDraw method might be enough.

For example this will trigger the warning repeatedly:

public class AnnoyTheChoreographerActivity extends Activity {

    @Override
    protected void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);

        setContentView(R.layout.simple_linear_layout);

        ViewGroup root = (ViewGroup) findViewById(R.id.root);

        root.addView(new TextView(this){
            @Override
            protected void onDraw(Canvas canvas) {
                super.onDraw(canvas);
                long sleep = (long)(Math.random() * 1000L);
                setText("" + sleep);
                try {
                    Thread.sleep(sleep);
                } catch (Exception exc) {}
            }
        });
    }
}

... which produces logging like this:

11-06 09:35:15.865  13721-13721/example I/Choreographer﹕ Skipped 42 frames!  The application may be doing too much work on its main thread.
11-06 09:35:17.395  13721-13721/example I/Choreographer﹕ Skipped 59 frames!  The application may be doing too much work on its main thread.
11-06 09:35:18.030  13721-13721/example I/Choreographer﹕ Skipped 37 frames!  The application may be doing too much work on its main thread.

You can see from the stack during onDraw that the choreographer is involved regardless of whether you are animating:

at example.AnnoyTheChoreographerActivity$1.onDraw(AnnoyTheChoreographerActivity.java:25) at android.view.View.draw(View.java:13759)

... quite a bit of repetition ...

at android.view.ViewGroup.drawChild(ViewGroup.java:3169) at android.view.ViewGroup.dispatchDraw(ViewGroup.java:3039) at android.view.View.draw(View.java:13762) at android.widget.FrameLayout.draw(FrameLayout.java:467) at com.android.internal.policy.impl.PhoneWindow$DecorView.draw(PhoneWindow.java:2396) at android.view.View.getDisplayList(View.java:12710) at android.view.View.getDisplayList(View.java:12754) at android.view.HardwareRenderer$GlRenderer.draw(HardwareRenderer.java:1144) at android.view.ViewRootImpl.draw(ViewRootImpl.java:2273) at android.view.ViewRootImpl.performDraw(ViewRootImpl.java:2145) at android.view.ViewRootImpl.performTraversals(ViewRootImpl.java:1956) at android.view.ViewRootImpl.doTraversal(ViewRootImpl.java:1112) at android.view.ViewRootImpl$TraversalRunnable.run(ViewRootImpl.java:4472) at android.view.Choreographer$CallbackRecord.run(Choreographer.java:725) at android.view.Choreographer.doCallbacks(Choreographer.java:555) at android.view.Choreographer.doFrame(Choreographer.java:525) at android.view.Choreographer$FrameDisplayEventReceiver.run(Choreographer.java:711) at android.os.Handler.handleCallback(Handler.java:615) at android.os.Handler.dispatchMessage(Handler.java:92) at android.os.Looper.loop(Looper.java:137) at android.app.ActivityThread.main(ActivityThread.java:4898)

Finally, if there is contention from other threads that reduce the amount of work the main thread can get done, the chance of skipping frames increases dramatically even though you aren't actually doing the work on the main thread.

In this situation it might be considered misleading to suggest that the app is doing too much on the main thread, but Android really wants worker threads to run at low priority so that they are prevented from starving the main thread. If your worker threads are low priority the only way to trigger the Choreographer warning really is to do too much on the main thread.

This if an Info message that could pop in your LogCat on many situations.

In my case, it happened when I was inflating several views from XML layout files programmatically. The message is harmless by itself, but could be the sign of a later problem that would use all the RAM your App is allowed to use and cause the mega-evil Force Close to happen. I have grown to be the kind of Developer that likes to see his Log WARN/INFO/ERROR Free. ;)

So, this is my own experience:

I got the message:

10-09 01:25:08.373: I/Choreographer(11134): Skipped XXX frames!  The application may be doing too much work on its main thread.

... when I was creating my own custom "super-complex multi-section list" by inflating a view from XML and populating its fields (images, text, etc...) with the data coming from the response of a REST/JSON web service (without paging capabilities) this views would act as rows, sub-section headers and section headers by adding all of them in the correct order to a LinearLayout (with vertical orientation inside a ScrollView). All of that to simulate a listView with clickable elements... but well, that's for another question.

As a responsible Developer you want to make the App really efficient with the system resources, so the best practice for lists (when your lists are not so complex) is to use a ListActivity or ListFragment with a Loader and fill the ListView with an Adapter, this is supposedly more efficient, in fact it is and you should do it all the time, again... if your list is not so complex.

Solution: I implemented paging on my REST/JSON web service to prevent "big response sizes" and I wrapped the code that added the "rows", "section headers" and "sub-section headers" views on an AsyncTask to keep the Main Thread cool.

So... I hope my experience helps someone else that is cracking their heads open with this Info message.

Happy hacking!

This usually happens when debugging using the emulator, which is known to be slow anyway.

In my case I have these messages when I show the sherlock action bar inderterminate progressbar. Since its not my library, I decided to hide the Choreographer outputs.

You can hide the Choreographer outputs onto the Logcat view, using this filter expression :

tag:^((?!Choreographer).*)$

I used a regex explained elsewhere : Regular expression to match a line that doesn't contain a word?