Avoiding excessive GC in simple apps

by Ivan.Memruk  on  2. August 2010 10:54

If you started your mobile development on a platform like Java ME, you will probably appreciate the heap sizes that Android gives to its apps. In fact, the minimum heap size that the Android compatibility guide requires is 16 Mb, and the more typical size is 24 Mb. This seems to be large enough for a typical app, so you should rarely run into out of memory issues with simple apps.

That, however, doesn't mean that we may forget we're dealing with Java, a language that includes garbage collection as one of its pillars. Unlike many other platforms, Java takes the memory management task on itself, thus freeing you from the burden of keeping track of your allocations. That approach also prevents typical memory leak scenarios. However, the price we pay is the garbage collection process that activates at relatively random moments and, generally speaking, pauses the entire application for intervals that are often noticeable to the end user.

When looking at Android logs, you surely saw the following kind of messages:

07-22 21:00:17.903: DEBUG/dalvikvm(2098): GC freed 5240 objects / 54656 bytes in 41ms

It's normal to see this happening from time to time in any app, but what if the app does not seem to be doing anything special, yet GC seems to be working hard for no particular reason?

In this article we will review a very simple yet typical case of a UI application that does a pretty innocent thing that eventually makes the JVM constantly garbage collect like crazy. We will identify the problem and develop a simple workaround. Of course, this is a specific case, but I will try to demonstrate the general approach to overcoming such issues.

The problematic app

Let's say for one of my apps I want a text view that will just display how much time has elapsed since some point, for example since the app was started. Something like this:

As you can see, it's a simple TextView that is updated, say, every 100 ms. We can use a Handler to implement the periodic update. That gives us a solution like this:

public class TestActivity extends Activity implements Runnable {
   
    private static final int DELAY_MS = 100;
   
    private TextView elapsedView;

    private Handler handler;
   
    private long startTime;
   
    private boolean destroyed;

       
    @Override
    public void onCreate(Bundle savedInstanceState) {
        super.onCreate(savedInstanceState);
        setContentView(R.layout.test_activity);
       
        elapsedView = (TextView) findViewById(R.id.elapsed);

        // Output the PID to let us be sure we're looking at the
        // relevant log messages:
        Log.d("***", "Our PID is: " + Process.myPid());

        // We use a Handler rather than a Timer to cycle updates
        // Read more about this approach:
        // http://developer.android.com/resources/articles/timed-ui-updates.html
        handler = new Handler();
        handler.postDelayed(this, DELAY_MS);
       
        // SystemClock is a better way to get time on Android
        startTime = SystemClock.elapsedRealtime();
    }

    @Override
    protected void onDestroy() {
        destroyed = true;
        super.onDestroy();
    }

    @Override
    public void run() {
        long currentTime = SystemClock.elapsedRealtime();
        double timeSec = (currentTime - startTime) / 1000.0;
       
        elapsedView.setText(String.format("Time spent: %1.2f sec", timeSec));
       
        // cycle the updates if the activity is still on
        // in production, we also have to check if we are paused
        // and restart on resume
        if (! destroyed) {
            handler.postDelayed(this, DELAY_MS);
        }
    }
}

This seems like a piece of cake and there's nothing suspicious about this code at the first side. However, once you run it, have a look at the log:

07-22 16:00:03.184: DEBUG/***(10178): Our PID is: 10178
07-22 16:00:07.590: DEBUG/dalvikvm(10178): GC freed 9811 objects / 504584 bytes in 77ms
07-22 16:00:12.840: DEBUG/dalvikvm(10178): GC freed 11116 objects / 546888 bytes in 74ms
07-22 16:00:17.903: DEBUG/dalvikvm(10178): GC freed 10640 objects / 524656 bytes in 81ms
07-22 16:00:22.950: DEBUG/dalvikvm(10178): GC freed 10609 objects / 523840 bytes in 86ms
07-22 16:00:27.973: DEBUG/dalvikvm(10178): GC freed 10631 objects / 524528 bytes in 82ms
07-22 16:00:33.020: DEBUG/dalvikvm(10178): GC freed 10633 objects / 524552 bytes in 86ms

 

What's impressive here is not only the fact that GC happens every 5-6 seconds, but the amount of heap recollected at every iteration. Half a megabyte at every GC!

In this simple, isolated example you don't need any tools to understand that the problem is probably here:

elapsedView.setText(String.format("Time spent: %1.2f sec", timeSec));
 

String.format() is indeed a very handy method, but at the same time it is a complex, heavyweight algorithm that obviously allocates some temporary memory in addition to the string it finally produces.

The solution

Obviously, String.format() might be a little too memory-intensive for running in a 100 ms interval cycle. Can we develop a better solution, perhaps using a StringBuilder to avoid temporary String instances, and dropping String.format() to do formatting manually?

// let's reuse the same string builder every time
private StringBuilder builder = new StringBuilder(128);

/*…*/

@Override
public void run() {
    long currentTime = SystemClock.elapsedRealtime();
    double timeSec = (currentTime - startTime) / 1000.0;
   
    builder.setLength(0); // reset the builder
    builder.append("Time spent: ");
    builder.append(Math.round(timeSec * 100.0) / 100.0);
    builder.append(" sec");
    elapsedView.setText(builder.toString());

/*…*/
 

This is much better now. GC cleanups still happen from time to time, but much more rarely:

07-22 21:27:40.687: DEBUG/dalvikvm(2657): GC freed 8056 objects / 505392 bytes in 107ms
07-22 21:28:55.930: DEBUG/dalvikvm(2657): GC freed 8955 objects / 547880 bytes in 87ms
07-22 21:30:08.312: DEBUG/dalvikvm(2657): GC freed 8546 objects / 524248 bytes in 78ms

Obviously, while we do not produce any temporary strings when building the message, we still create a new string every time at the following point:

 

elapsedView.setText(builder.toString());
 

Still, that was a pretty big improvement, and even if we continue trying to avoid allocations (e.g. using char[] arrays instead of strings, etc.), we probably will never get to the point when nothing is allocated within that cycle. The reason is that we use the API such as TextView.setText() which most definitely allocates something directly or indirectly when we invoke it. Thus, we should do as much as we can, and in many cases that will allow us to avoid GC overdrive.

If you have your own GC story or a question, feel free to use the comments for sharing those.

 

Author:

Ivan Memruk
mindtherobot.com

 

Related articles

Use MVC and develop a simple Star Rating widget on Android
The MVC (model-view-controller) pattern has been extremely popular in web application frameworks, bu...
Correct thread management in Android apps
Android supports almost the API of Java SE almost completely (except the Swing classes and som...
Making a simple custom Android UI animation
Animations are a great way to spice up the UI of your app. Although using too many animations can fr...

blog comments powered by Disqus
� 2010 WiseAndroid lightdir.com