Meaning of Choreographer messages in Logcat [duplicate]
Asked Answered
E

5

198

I installed the latest versions of SDK (API 16) and got the latest ADT. I'm now seeing these messages in the logcat, that I'm quite sure, I haven't seen before. Does anyone have an idea about this?

06-29 23:11:17.796: I/Choreographer(691): Skipped 647 frames! The application may be doing too much work on its main thread.

I did a search and found this link: http://developer.android.com/reference/android/view/Choreographer.html. This is a new class introduced in API 16.

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.

Endmost answered 29/6, 2012 at 17:44 Comment(7)
from your link : Coordinates the timing of animations, input and drawing. Looks like its used for doing animations in the UI.Limbic
are you running in the emulator?Crassus
Yes, I am. I understand the Choreographer is probably the component that handles animations and when it doesn't get enough cpu cycles, it skips some frames and outputs this debug message. What worries me is what in my main thread could be causing this and how I track that. AFAIK all my processing happens in background threads.Endmost
I have some code that runs in a worker thread doing some heavy computations, and it periodically posts updates to the UI thread. While this does not block the UI thread, the user's inputs are queued up and don't show on the display until the end of the current increment of worker computation. While this is occurring, I get constant messages from Choreographer like "Skipped 37 frames!," etc. There has been an attempt to make Jelly Bean "buttery smooth" and I suspect that these messages are a part of encouraging us to not have any kind of jerkiness in our displays.Strepitous
Actually,I don't care if 'x' frames are skipped. I just don't want this messages to appear in my logcat...its irritating me a lot!!!Implausibility
@Elenasys You've marked this question as a duplicate of a question that was asked much later on Feb 3 '13. Doesn't sound fair to me :)Endmost
The question this is marked as a duplicate of was asked later, has fewer votes, has no accepted answer, and its best/most popular answer is a simple copy of the Android docs. Is it possible for someone with sufficient rep to reverse the duplication flag?Albers
O
139

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.

Orthopteran answered 4/7, 2012 at 12:34 Comment(4)
+1 for the "could be misleading". My app doesn't use any animations whatsoever and actually doesn't use any graphics, yet I get these messages. At some point Google Maps (not my app) force-closes... Also another Google app service (not my app!) freezes... I have no idea what Google was thinking when introducing this new Jelly Bean stuff that break things that still work wonderfully on Froyo.Stag
If too much work is done on main thread, Android might not be as deterministic as it intends to be, but does not kill any tasks right ?Johnnyjohnnycake
I think " I can tell if one of the Runnables passed along by the Choreographer.post* apis doesnt finish in one frame's time, causing frames to be skipped." is not that correct. I just had a look at the Choreographer's code, it performs all the runnables whose dueTime <= now when it receives a VSYNC.Which means all the runnables post to the Choreographer whose perform time is less then current time don't finish in one frame time will cause frames to be skipped.Xanthene
What's more, I doubt whether it will case skipping frames or just lag due to the tripple buffer.Xanthene
A
67

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.

Albers answered 6/11, 2013 at 12:16 Comment(3)
it was a great answer, in my case, i do have maulti-threads for handling the other works, and repeatedly i access the main-ui-thread from those other threads. Those accesses are necessary, what can be a solution for this in your opinion ?Marylandmarylee
"repeatedly I access the main-ui-thread" -- you mean you are using View.post, Activity.runOnUiThread, or directly using a Handler to send work to the main thread? If it isn't UI work, don't give it to the main thread to do :). If it is UI work you have no choice, and if it is causing dropped frames you probably need to look at other ways to optimise your UI code. Perhaps you have a case worth posting as a new question?Albers
I have already posted actually, now i will add some code to it. #29768497Marylandmarylee
C
23

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!

Coomb answered 9/11, 2012 at 2:16 Comment(1)
How do you use AsyncTask to avoid this problem?Indecipherable
S
11

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

Section answered 10/8, 2012 at 18:57 Comment(4)
i get that on my phone's log also sometimes.Keffer
yes, the process is very slow when this message prints in the logcat. It seems that dvm will ignore if we run in release mode by changing the debugvalue to false.Transpierce
This happened on a real phone for me: Motorola Droid BionicMavilia
For my app, even on my slowest, old hardware device I never get the "Skipped" log messages. But I always get those messages when running on the emulator (specifically, the Genymotion emulator).Dye
G
11

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?

Genip answered 16/11, 2012 at 13:41 Comment(0)

© 2022 - 2024 — McMap. All rights reserved.