What are my Android apps doing behind the scenes?

[Natey2]

I installed an app called aLogCat which allows me to look at my Android logs dynamically.
When I start using some of my installed apps, I see some pretty interesting stuff getting written to the logs, that can give me an idea what the app is trying to do behind the scenes.
If you have been a [Java] Developer, this is something you probably do in your daily work. If you aren't, Welcome to the backstage of software development!

Deadlocks are a bad thing, and here's a snippet of my logs when I turned on my Android Background Data Synch:

02-19 09:44:33.375 E/AccountManager(15869): calling this from your main thread can lead to deadlock and/or ANRs
02-19 09:44:33.375 E/AccountManager(15869): java.lang.IllegalStateException: calling this from your main thread can lead to deadlock
02-19 09:44:33.375 E/AccountManager(15869): at android.accounts.AccountManager.ensureNotOnMainThread(AccountManager.java:1119)

I'm going to check out what my apps are doing and that may help explain why my phone starts behaving strange at times...


Sent from my DROIDX using DroidForums App

 

[hookbill]

I'd get rid of that app, and not worry about what your apps are doing. If your phone is acting up, and I have no idea what you mean by that, then it is probably an app. But I don't think that app will help you discover what it is.

Do you use a task killer?

 

[BayouFlyFisher]

I agree with Hook on this. Don't worry about what the apps, that you are not using, are doing.

Define "phone starts behaving strange at times..." and perhaps we can help.

I do know the following:

Third party Task Managers cause problems.
Anti-virus apps all cause problems.
Reboot your phone once every day or so.
Charging with the wrong charger causes issues quite often.
Using a non-standard usb cable can cause issues too.

Here's an excellent link for the X and any android phone for that matter: Abe21599 - http://www.droidforums.net/forum/dr...4604-new-android-droid-x-users-check-out.html

 

[Natey2]

I'd get rid of that app, and not worry about what your apps are doing. If your phone is acting up, and I have no idea what you mean by that, then it is probably an app. But I don't think that app will help you discover what it is.

Do you use a task killer?

In the short time I've used aLogCat, I've identified:
An app that repeatedly tries to load an application bitmap resource that does not exist (developer probably didn't package the app with that bitmap),
An app that repeatedly throws an XML-parsing error,
A Google app that is logging all kinds of things (too many) at ERROR level, that really should (IMHO) be logged at DEBUG level.

I have ATK installed, but auto-kill disabled.

Sent from my DROIDX using DroidForums App

 

[hookbill]

I'd get rid of that app, and not worry about what your apps are doing. If your phone is acting up, and I have no idea what you mean by that, then it is probably an app. But I don't think that app will help you discover what it is.

Do you use a task killer?

In the short time I've used aLogCat, I've identified:
An app that repeatedly tries to load an application bitmap resource that does not exist (developer probably didn't package the app with that bitmap),
An app that repeatedly throws an XML-parsing error,
A Google app that is logging all kinds of things (too many) at ERROR level, that really should (IMHO) be logged at DEBUG level.

I have ATK installed, but auto-kill disabled.


Sent from my DROIDX using DroidForums App

That's OK with that set up. But you're still worrying about the apps in the background, just trust that your Droid knows what to do about them. They aren't really running anyway, it's more like they are "at the ready" to launch. Sort of sleeping but there.

And you still haven't told us what your phone is doing when it acts up.

 

[Natey2]

Define "phone starts behaving strange at times..." and perhaps we can help.

I do know the following:

Third party Task Managers cause problems.
Anti-virus apps all cause problems.
Reboot your phone once every day or so.
Charging with the wrong charger causes issues quite often.
Using a non-standard usb cable can cause issues too.

Here's an excellent link for the X and any android phone for that matter: Abe21599 - http://www.droidforums.net/forum/dr...4604-new-android-droid-x-users-check-out.html

Thanks for the link above.
My phone tends to refresh the app drawer and home screens (slowly) after some extended use (many days).
My phone system uptime is at 460 hours now. The last unexpected warm boot (occurred during a usb connect session) didn't reset that timer, but fixed the slow app drawer refresh (the one where the icons don't appear for a while).

Rebooting daily is something I believe Microsoft recommended in the days of Windows 3.x
Android is supposed to be Linux-based, and is there any Linux user who feels Linux should be rebooted daily?
Rebooting daily masks the problem too. I'm waiting for my phone to slow down again, and I'd like to take a look at what is going on in the logs when that occurs.

Sent from my DROIDX using DroidForums App

 

[Natey2]

I have discovered an app (possibly Motorola synch routine) that is causing an error (in the logs) on background data syncs:

02-22 05:53:01.034 V/BlurSyncProtocolHandler( 6951): executeSync: handlerName: BlurSetupSyncHandler, isForced: false
02-22 05:53:01.058 E/Cursor ( 6951): Finalizing a Cursor that has not been deactivated or closed. database = /data/data/com.motorola.blur.setupprovider/databases/serviceaccounts.db, table = active_services, query = SELECT provider, email_address, password, account, pwd_storage_policy, providers.pretty_name AS pret
02-22 05:53:01.058 E/Cursor ( 6951): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here


Sent from my DROIDX using DroidForums App

 

[albackore]

maybe if you sent those errors to the developer they might fix them?

Sent from my DROIDX using DroidForums App

 

[Natey2]

I notice that when my phone is getting charged, at 90% charge, the following is logged, a couple of times:

02-22 21:19:04.180 I/BATTD ( 1157): set_charge_current=1300
02-22 21:19:06.132 I/BATTD ( 1157): set_charge_current=800
02-22 21:19:11.992 I/BATTD ( 1157): set_charge_current=1300
02-22 21:19:25.672 I/BATTD ( 1157): set_charge_current=800
02-22 21:19:29.579 I/BATTD ( 1157): set_charge_current=1300
02-22 21:19:31.531 I/BATTD ( 1157): set_charge_current=800
02-22 21:19:33.484 I/BATTD ( 1157): set_charge_current=1300
02-22 21:19:35.437 I/BATTD ( 1157): set_charge_current=800
02-22 21:19:37.390 I/BATTD ( 1157): set_charge_current=1300
02-22 21:19:47.156 I/BATTD ( 1157): set_charge_current=800
02-22 21:19:51.070 I/BATTD ( 1157): set_charge_current=1300

It looks like it is alternating between a 1300mA charge and a 800mA charge. Is this some kind of trickle-charge algorithm to prevent overcharging the battery?

Edit (2/26/2012, almost a year later, now using Android 2.3.4):

When the battery is fully charged, we see current alternating between 700, 800 and 1800 mA:

02-26 06:45:43.430 I/BATTD ( 1217): set_charge_current=700
02-26 06:45:45.383 I/BATTD ( 1217): set_charge_current=800
02-26 06:45:47.336 I/BATTD ( 1217): set_charge_current=700
02-26 06:45:49.290 I/BATTD ( 1217): set_charge_current=1800
02-26 06:45:57.110 I/BATTD ( 1217): set_charge_current=800
02-26 06:45:59.055 I/BATTD ( 1217): set_charge_current=1800
02-26 06:46:08.829 I/BATTD ( 1217): set_charge_current=700

Sent from my DROIDX using DroidForums App

 

[Natey2]

maybe if you sent those errors to the developer they might fix them?

Sent from my DROIDX using DroidForums App

I'd like to see the source code first, if available. I only have the SDK installed at work, and I'm tied up with other things there.

An error thrown during finalization is a bad thing.
Finalization is when Java tries to release memory used by objects that (it thinks) are no longer needed. If something is holding on to those Cursor(s), the memory can't be released and reclaimed during the Garbage Collect (GC) routine(s).
Hopefully, something will close that Cursor. If it doesn't, and if this occurs repeatedly, it will manifest itself as a memory leak.
This is where inspecting a periodic heap dump would help, but I can't tie up my phone to my PC and SDK at work for days.
I need to check the frequency of GCs that occur over time. If there is a memory leak, the poor phone would be trying very aggressively to GC very often as it finds less usable memory to work with, and that might explain why my phone gets sluggish over time.
Rebooting the phone daily will mask this problem.

Sent from my DROIDX using DroidForums App

 

[piquat]

That's pretty neat. It kind of looks like I have a clock widget that's not happy.

 

[Natey2]

Another instance of an unclosed cursor:

02-23 21:36:32.788 W/SQLiteCompiledSql(25737): Releasing statement in a finalizer. Please ensure that you explicitly call close() on your cursor: SELECT _id, entity, _data, mimetype, destination, visibility, destination, control, status, lastmod,
02-23 21:36:32.788 W/SQLiteCompiledSql(25737): android.database.sqlite.DatabaseObjectNotClosedException: Application did not close the cursor or database object that was opened here


Sent from my DROIDX using DroidForums App

 

[Natey2]

I'm not having any obviously overt problem with GoogleVoice that I can see, but why is GoogleVoice logging an INVALID AUTHENTICATION TOKEN repeatedly?
It first logs it as a Warning, then it logs it as an Error:

02-23 22:05:15.366 D/GoogleVoice( 8017): Using PreferenceStoreFroyoAndEarlier
02-23 22:05:15.428 W/System.err( 8017): com.google.android.apps.googlevoice.net.VoiceServiceException: Voice service failed [INVALID_AUTH_TOKEN]
02-23 22:05:15.428 W/System.err( 8017): at com.google.android.apps.googlevoice.net.masf.MASFVoiceService.checkCredentials(MASFVoiceService.java:103)
02-23 22:05:15.428 W/System.err( 8017): at com.google.android.apps.googlevoice.net.masf.MASFVoiceService.getAuthToken(MASFVoiceService.java:91)
02-23 22:05:15.428 W/System.err( 8017): at com.google.android.apps.googlevoice.net.masf.MASFGetBackendInfoRpc.createRequestPayload(MASFGetBackendInfoRpc.java:34)
02-23 22:05:15.428 W/System.err( 8017): at com.google.android.apps.googlevoice.net.masf.MASFApiRpc.requestSubmit(MASFApiRpc.java:143)
02-23 22:05:15.428 W/System.err( 8017): at com.google.android.apps.googlevoice.net.masf.MASFApiRpc.run(MASFApiRpc.java:124)
02-23 22:05:15.428 W/System.err( 8017): at com.googlex.common.task.AbstractTask.run(Unknown Source)
02-23 22:05:15.428 W/System.err( 8017): at com.googlex.common.task.AbstractTask.runInternal(Unknown Source)
02-23 22:05:15.428 W/System.err( 8017): at com.googlex.common.task.TaskRunner.run(Unknown Source)
02-23 22:05:15.428 W/System.err( 8017): at com.googlex.common.lang.BaseThreadFactory$ThreadImpl.run(Unknown Source)
02-23 22:05:15.428 E/GoogleVoice( 8017): ShadowNumberRefreshService: Failed to get backend info!
02-23 22:05:15.428 E/GoogleVoice( 8017): com.google.android.apps.googlevoice.net.VoiceServiceException: Voice service failed [INVALID_AUTH_TOKEN]
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.google.android.apps.googlevoice.net.masf.MASFVoiceService.checkCredentials(MASFVoiceService.java:103)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.google.android.apps.googlevoice.net.masf.MASFVoiceService.getAuthToken(MASFVoiceService.java:91)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.google.android.apps.googlevoice.net.masf.MASFGetBackendInfoRpc.createRequestPayload(MASFGetBackendInfoRpc.java:34)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.google.android.apps.googlevoice.net.masf.MASFApiRpc.requestSubmit(MASFApiRpc.java:143)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.google.android.apps.googlevoice.net.masf.MASFApiRpc.run(MASFApiRpc.java:124)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.googlex.common.task.AbstractTask.run(Unknown Source)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.googlex.common.task.AbstractTask.runInternal(Unknown Source)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.googlex.common.task.TaskRunner.run(Unknown Source)
02-23 22:05:15.428 E/GoogleVoice( 8017): at com.googlex.common.lang.BaseThreadFactory$ThreadImpl.run(Unknown Source)


Sent from my DROIDX using DroidForums App

 

[Natey2]

Some applications improperly use Ads, and cause errors:

02-25 03:27:50.719 E/AdMobSDK(20854): Unhandled exception placing AdContainer into AdView.
02-25 03:27:50.719 E/AdMobSDK(20854): java.lang.IllegalStateException: The specified child already has a parent. You must call removeView() on the child's parent first.
02-25 03:27:50.719 E/AdMobSDK(20854): at android.view.ViewGroup.addViewInner(ViewGroup.java:1970)


Sent from my DROIDX using DroidForums App

 

[Natey2]

I'm waiting for my phone to slow down again, and I'd like to take a look at what is going on in the logs when that occurs.

My phone system uptime is 595 hours now, and the home screen refresh is consistently slow.

I've found the point where my phone slows down when it tries to refresh the home screen icons: it looks like it does many Garbage Collects, and that is what is slowing it down:

02-25 03:06:43.939 D/HomeLoaders(21144): ----> items cloned, ready to refresh UI
02-25 03:06:44.196 D/dalvikvm(20754): GC_FOR_MALLOC freed 11757 objects / 555128 bytes in 304ms
02-25 03:06:44.470 D/dalvikvm(21144): GC_EXPLICIT freed 5788 objects / 346016 bytes in 117ms
02-25 03:06:45.673 D/dalvikvm(21144): GC_EXPLICIT freed 2528 objects / 124912 bytes in 109ms
02-25 03:06:46.071 D/dalvikvm(21154): GC_EXTERNAL_ALLOC freed 2296 objects / 113848 bytes in 54ms
02-25 03:06:46.134 D/dalvikvm(21154): GC_EXTERNAL_ALLOC freed 1526 objects / 77640 bytes in 35ms
[...and many more GCs...]


Sent from my DROIDX using DroidForums App