Wednesday, June 8, 2011

Exploring Memory Allocation on an Android Launcher using ADB

I recently started getting into Android application development, and an annoying issue with the launcher on my Android phone provided me with a nice learning experience in regards to debugging the Android system using adb (Android Debug Bridge).  Considering how much searching I had to do on the internet to figure some of these things out, I figured I'd blog about it and post all relevant links and info for others to use.

ADW Launcher
I first got an Android phone last year, the Samsung Epic 4G on Sprint, with Android 2.1 (Éclair).  My brother has been raving about Android for a long while so I figured it was time to take the plunge, since I was tired of my Blackberry and had no plans to get an Apple product.  He suggested I use the ADW Launcher in place of the default launcher, as it is more customizable and cooler, etc etc.  So I downloaded it and it worked great.

However, recently Sprint pushed the Android 2.2 (Froyo) update to the Epic 4G and ever since then, I've occasionally had problems with the phone being sluggish when coming out of the lock screen or changing the orientation (rotating) when on the home screens.  Since other applications were not evincing any lag while rotating the phone, I narrowed it down to the launcher itself.  Over time, something was causing it to become sluggish, taking 2-3 seconds to respond to a command.

This became somewhat irritating when I started missing calls because it would lock up when I tried to answer them.  Since I already had the Android SDK and was delving into development, I decided to figure out how to debug my phone using ADB at my bro's suggestion.

adb (Android Debug Bridge) is a tool that can be used to monitor and manage the state of the Android OS, either on a device or through an emulator.  It's a simple command line tool, though its output can also be viewed through the Eclipse IDE (used for development in the Android SDK).  There are a variety of commands you can issue to adb, but for this I'm primarily concerned with the logcat command, which is specific to debugging.

logcat prints system log info directly to the screen.  As the Android OS processes, pretty much everything it does can be displayed through the logcat function, each action appearing on a separate line.  It can be a very useful tool in determining where a particular application is getting hung up or suffering performance, especially when memory is involved, as you can see the log output while using the application itself.

In order to get adb working properly for my particular handset model (Samsung Epic 4G), I had to find the proper ADB Interface driver.  After much searching online I found it on the Samsung website itself.  I won't go into the installation and configuration itself, but here's a good overview of the process if you need it.  In any event, I got it installed and finally started looking at some logs.

Garbage Collection
What I noticed immediately upon running logcat while tilting the phone, was that a number of log entries like the following were appearing:

04-22 16:19:35.829 D/dalvikvm(32653): GC_FOR_MALLOC freed 11731 objects / 759624 bytes in 52ms

Every time I tilted the phone, I would see around 6-10 of these in a row.  I even made a video of it, for all to enjoy (watch on full screen if you want to actually read the logcat output):

So what do those lines mean?  We'll start with the actual action itself, GC_FOR_MALLOC.

I did more searching and found a succinct explanation on about it.  The Android OS actively manages memory on its own, and will free up memory as needed, depending on what types of activities you are performing.  Normally you will see logs of GC_EXPLICIT or GC_EXTERNAL_ALLOC, which are normal for OS memory management.  GC_FOR_MALLOC, however, is called when there's not enough memory on the heap for an allocation to be performed.  The system is forced to call it because memory is scarce – the application is not calling it explicitly as part of its internal memory management (that was coded into the application).

The next step was to make sure that the GC_FOR_MALLOC calls were related to the ADW Launcher itself, which I suspected, but hadn't confirmed.  So I had to do more investigating to decipher the entire log line.

Deciphering the logcat output
The first part of each logcat line is obvious: date and time.  I used the following command to specify that I wanted timestamp detail as part of the output:

adb logcat –v time

There are a variety of filters you can use at the command line (see the link in the adb section for more info on that), but I found that one the most useful for this particular exercise.  The next part of the line is a little more esoteric:


The first letter is the priority of the log message.  Here are the different priorities (link in adb section):
  • V — Verbose (lowest priority)
  • D — Debug
  • I — Info
  • W — Warning
  • E — Error
  • F — Fatal
  • S — Silent (highest priority, on which nothing is ever printed)
The number is the PID (Process ID) of the application or process in question.  So the message says that the Dalvik VM (Virtual Machine), upon which the Android OS runs, has a Debug message for an application with a PID of 32653.  But how do you know what application is tied to the PID?

Unfortunately there is no simple way (that I could find) to get a list of all running services and applications with their PIDs.  PID may not be unique to a specific application and could be shared by more than one, which can make it even more confusing.  There is a command that could help, though:

adb shell ps

This command prints out a list of processes with their PIDs.  However, it doesn't print all of them... because when I did it, PID 32653 did not appear on the list.  Here is an example of the output:

USER     PID   PPID  VSIZE  RSS     WCHAN    PC         NAME
root      8393  2     0      0     ffffffff 00000000 S loop2
root      8396  2     0      0     ffffffff 00000000 S kdmflush
root      8397  2     0      0     ffffffff 00000000 S kcryptd_io
root      8398  2     0      0     ffffffff 00000000 S kcryptd
radio     13305 2351  206764 13108 ffffffff 00000000 S
app_15    26629 2351  255896 28732 ffffffff 00000000 S
system    29346 2351  217088 17828 ffffffff 00000000 S

What to do?  I did a search in the log output for PID 32653, looking for the first time it appeared, and I found this:

I/ActivityManager(2453): Start proc android.process.acore for activity org.adw.launcher/.Launcher: pid=32653 uid=10088 gids={1015}

This clearly shows ADW Launcher activity (an activity in Android is basically a program, or a thread) starting, with a PID of 32653.  So it's confirmed that that is the culprit!  Apparently the launcher is using a lot of memory and when you rotate the phone, Android actually kills and recreates the view on the screen each time (this is how the OS works), so at some point there doesn't seem to be enough memory to help the launcher recreate the home view each time.  So it's forced to garbage collect.

The Solution and Other Observations
In the end, it appears to be some kind of incompatibility between ADW Launcher and the Froyo version of Android.  Launchers are memory hogs, I've discovered, and depending on how many home screens, widgets and shortcuts you have, performance can vary.  I found two solutions to the problem, one for rooted phones (mine is not), and one for non-rooted phones (which merely involves changing some of the settings for the launcher).

For rooted phones, follow the instructions I found here, on a Launcher Pro forum.  That process fixes the launcher in memory, so it's never lost and the OS is not forced to recreate it when you rotate the handset.

For non-rooted phones, try playing with the launcher settings.  This post on specifies exactly what settings to focus on.  I changed those and I have not had half as many problems with lag as before.  Occasionally it gets slow, but not as bad as it was before (as demonstrated in my video).

No comments:

Post a Comment