HOW TO: troubleshoot bad battery life with logcat

[FLT]

What is logcat?

Logcat is the command to view the internal logs of the Android system. Viewing logs is often the best way to diagnose a problem, and is required for many issues. This way you'll find out what apps are doing in the background without you noticing.


How do I install it?

1. 1. Make sure you've enabled on USB debugging on your phone in Settings -> Application -> Development
2. 2. Get the Android SDK here: Android SDK | Android Developers
3. 3. Extract the folder to C:\Android\ (using this path in this example, you can extract it where you would like)
4. 4. Download this file: RapidShare: 1-CLICK Web hosting - Easy Filehosting and extract the 'usb_driver' folder to C:\Android\
5. 5. Connect the phone with the USB cable
6. 6. Windows will ask for the drivers
   If you have WinXP follow these steps: USB Driver for Windows | Android Developers
   If you have Win7 or Vista follow these steps: USB Driver for Windows | Android Developers
   
   The folder you need to browse to for the driver is C:\Android\usb_driver

Everything installed? Continuing...

Now how to actually access the log, everything in italic are commands you need to enter.

1. 1. Open the 'run' dialog by pressing the 'Windows' + 'r' buttons on your keyboard (minimize the browser & other non-windows programs)
2. 2. cmd (this will open a DOS prompt)
3. 3. cd c:\Android\tools (go to the directory where you extracted the SDK)
4. 4. adb shell
5. 5. Now you'll see just a '$'
6. 6. logcat

You can now just press the power button on your phone to see what happens. It displays everything the device is doing.

So the thing is: leave your device connected for a while and see what is actually going on when you're not using it.


I'm seeing all sort of things I don't really understand...

Here are 2 little examples to clarify things a bit more:
1. My phone was a sleep and the Google weather widget was set to refresh every 30min

[B]=> nothing special going here, just Android doing it's thing freeing up some objects[/B]

D/dalvikvm( 1687): GC freed 6580 objects / 309496 bytes in 57
D/dalvikvm( 1560): GC freed 25 objects / 1800 bytes in 102ms

[B] => weather widget activates[/B]

D/NetworkLocationProvider(   75): addListener(): apps.genie.geniewidget
D/NetworkLocationProvider(   75): setMinTime: 0
D/NetworkLocationProvider(   75): enableLocationTracking(): true
D/NetworkLocationProvider(   75): onCellLocationChanged [****]
D/LocationMasfClient(   75): getNetworkLocation(): Returning cache location with
 accuracy 5000.0
D/LocationManager( 1287): removeUpdates: listener = com.google.android.apps.geni
e.geniewidget.util.GenieLocationProvider$1@447d31d0
D/NetworkLocationProvider(   75): removeListener(): apps.genie.geniewidget
D/NetworkLocationProvider(   75): enableLocationTracking(): false
D/Genie   ( 1287): Got updated location: ****
D/Genie   ( 1287): Requesting data...
D/Genie   ( 1287): Got response: GeniePayload: isCached: false payload: 1 and up
dated model: READY: showing news 0 of 0 weather=Mostly Cloudy at, 14:01, 4 Febru
ary with timestamp: 14:01, 4 February next auto-refresh time = 0
D/Genie   ( 1287): Refresh Complete, notifying success.
D/Genie   ( 1287): Updating weather database: WEATHER: Mostly Cloudy
D/Genie   ( 1287): Commited FileCache, deleted 0 obselete files and kept 100 fil
es.

[B] => weather widget is done updating, back to normal Android stuff[/B]

D/dalvikvm( 1287): GC freed 11459 objects / 731832 bytes in 66ms
D/dalvikvm(  230): GC freed 135 objects / 6056 bytes in 67ms

And then the same process repeated 30min laters which means my phone isn't doing anything I don't want it to.

2. Twidroid auto refreshing my Tweets

[B] => again nothing special[/B]

D/dalvikvm(   75): GC freed 40165 objects / 1974768 bytes in 91ms
D/dalvikvm( 1560): GC freed 25 objects / 1800 bytes in 53ms
D/dalvikvm( 1687): GC freed 7551 objects / 330032 bytes in 102ms

[B] => Twidroid doing it's thing[/B]

I/ActivityManager(   75): Start proc com.twidroidpro:remote for service com.twidroid
...

[B] => back to freeing up the objects[/B]

D/dalvikvm( 1287): GC freed 3 objects / 72 bytes in 95ms
D/dalvikvm( 1253): GC freed 281 objects / 12688 bytes in 91ms

If you're seeing apps that are constantly busy when they shouldn't that means they're draining battery because of bugs in the app/ bad coding/ ...

Example of a buggy app:

D/dalvikvm( 1287): GC freed 3 objects / 72 bytes in 92ms
D/dalvikvm( 2216): GC freed 6646 objects / 313032 bytes in 104ms
D/NetworkLocationProvider(   75): onCellLocationChanged [***]
D/LocationManager( 2216): removeUpdates: listener = com.levelup.beautifulwidgets
.UpdateWeather$2@447843d8
D/dalvikvm( 1253): GC freed 281 objects / 12688 bytes in 93ms
D/NetworkLocationProvider(   75): onCellLocationChanged [***]
D/LocationManager( 2216): removeUpdates: listener = com.levelup.beautifulwidgets
.UpdateWeather$2@447843d8
D/dalvikvm(   75): GC freed 41839 objects / 1963448 bytes in 88ms
D/dalvikvm( 1287): GC freed 3 objects / 72 bytes in 94ms
D/NetworkLocationProvider(   75): onCellLocationChanged [***]
D/LocationManager( 2216): removeUpdates: listener = com.levelup.beautifulwidgets
.UpdateWeather$2@447843d8
D/dalvikvm( 2216): GC freed 6657 objects / 314648 bytes in 35ms
D/NetworkLocationProvider(   75): onCellLocationChanged [***]
D/LocationManager( 2216): removeUpdates: listener = com.levelup.beautifulwidgets
.UpdateWeather$2@447843d8
D/dalvikvm( 1253): GC freed 279 objects / 12640 bytes in 94ms
D/NetworkLocationProvider(   75): onCellLocationChanged [***]
D/LocationManager( 2216): removeUpdates: listener = com.levelup.beautifulwidgets
.UpdateWeather$2@447843d8
D/dalvikvm( 1287): GC freed 3 objects / 72 bytes in 60ms
D/dalvikvm( 2216): GC freed 6661 objects / 314192 bytes in 104ms
D/NetworkLocationProvider(   75): onCellLocationChanged [***]
D/LocationManager( 2216): removeUpdates: listener = com.levelup.beautifulwidgets
.UpdateWeather$2@447843d8

As you can see the app (BeautifulWidgets) was constantly trying to remove the same updates and thus draining my battery for no reason. This was happening every 10seconds (!!).

Uninstalling those crappy apps should help your battery life (and hope a future update of that app fixes it)

The less you see in the logcat the better


Starting with a fresh log

If you want to clear the log and only see what's happening on your phone from now on, go to adb shell (step 4) and then type logcat -c. This clears the log and then type logcat

 

[rori]

thanx a lot for the tutorial, I will try it step by step...

Edit: after a while I got it running, nice, and no real battery drainers found
thanx again!

 

[t0ph0id]

Mine does this sequence every 3 1/2 mins

D/BatteryWidget( 3228): Updating Views
D/dalvikvm( 3228): GC freed 372 objects / 66248 bytes in 92ms
D/dalvikvm( 3245): GC freed 6537 objects / 308080 bytes in 95ms
D/dalvikvm( 3245): GC freed 6537 objects / 307864 bytes in 95ms
D/dalvikvm( 2063): GC freed 18203 objects / 1660312 bytes in 53ms
D/BatteryWidget( 3228): Updating Views
D/dalvikvm( 3228): GC freed 278 objects / 36448 bytes in 88ms
D/dalvikvm( 3245): GC freed 6537 objects / 307968 bytes in 95ms
D/dalvikvm( 3245): GC freed 6537 objects / 307984 bytes in 95ms
D/BatteryWidget( 3228): Updating Views

Is that normal then?

 

[FLT]

I would say no unless your battery drops 1% every 3 1/2mins or you've set the widget to check the battery every 3 1/2mins. If not it's a useless update of the widget and therefore draining battery without reason.

 

[michael.nights]

Does this kind of analysis work also for other devices?

 

[FLT]

Does this kind of analysis work also for other devices?

Yes ofcourse, this will work on any android device

 

[ramkivelpuri]

For my battery drain tests, I would like to capture logcat logs via adb shell. When I plug USB cable, it's charging my HTC ADP2
Android phone.

Duroing capturing logs, I don't want charging my battery, so that I can find out any code needs to be optmized for improving
battery life.
Any tips are greatly appreciated for this scenario..