#676 performance: csipsimple triggering periodic CPU spikes while registered

[Anonymous]

Originally created by: fander...@gmail.com
Originally owned by: r3gis...@gmail.com

This is a continuation of Comment 46 in Issue 81.  In summary, csipsimple is periodically triggering high CPU spikes while registered and running in the background.  In Android 2.2, the spikes show up as coming from the system_server process.  In Android 2.3 they instead come from the systemui process, which provides a clue as to what's causing them.

The interesting thing about these spikes is that they don't happen when csipsimple is first started.  They gradually grow in duration and severity over several hours, and eventually get to the point that the spikes use up 80-90% for 5-10 seconds.  The spikes seem to happen about once a minute or so, which I assume is linked to my registration/keepalive values (60s/50s, with the first enforced by the provider).  These spikes cause various problems and have an especially bad impact during calls.

From what I understand, the most likely cause of high systemui CPU is setting/manipulating notifications.  Maybe this is enough information to determine what csipsimple could be doing to cause this behavior.

[Anonymous]

Originally posted by: r3gis...@gmail.com

Issue 675 has been merged into this issue.

[Anonymous]

Originally posted by: fander...@gmail.com

This problem is causing regular crashes of systemui:

W/ActivityManager(  150): Timeout of broadcast BroadcastRecord{4096a188 android.intent.action.TIME_TICK} - receiver=android.os.BinderProxy@407b3098, started 10
004ms ago
W/ActivityManager(  150): Receiver during timeout: BroadcastFilter{409ac058 ReceiverList{409abfe0 15785 com.android.systemui/1000 remote:407b3098}}
E/ActivityManager(  150): ANR in com.android.systemui
E/ActivityManager(  150): Reason: Broadcast of Intent { act=android.intent.action.TIME_TICK flg=0x40000004 (has extras) }
E/ActivityManager(  150): Load: 36.32 / 18.02 / 14.3
E/ActivityManager(  150): CPU usage from 5149ms to 0ms ago with 99% awake:
E/ActivityManager(  150):   81% 15785/com.android.systemui: 80% user + 0.5% kernel / faults: 283 minor
E/ActivityManager(  150):   14% 150/system_server: 14% user + 0.7% kernel / faults: 215 minor
E/ActivityManager(  150):   4.2% 14893/com.csipsimple: 3.8% user + 0.3% kernel / faults: 115 minor 2 major
E/ActivityManager(  150): 100% TOTAL: 98% user + 1.3% kernel
E/ActivityManager(  150): CPU usage from 2563ms to 3163ms later:
E/ActivityManager(  150):   86% 15785/com.android.systemui: 86% user + 0% kernel
E/ActivityManager(  150):     84% 15785/ndroid.systemui: 84% user + 0% kernel
E/ActivityManager(  150):   8.4% 150/system_server: 3.3% user + 5% kernel
E/ActivityManager(  150):     10% 164/ActivityManager: 3.3% user + 6.7% kernel
E/ActivityManager(  150):   3.3% 14893/com.csipsimple: 3.3% user + 0% kernel / faults: 7 minor
E/ActivityManager(  150):     3.3% 14904/UAStateAsyncWor: 3.3% user + 0% kernel
E/ActivityManager(  150): 100% TOTAL: 93% user + 6.6% kernel
I/WindowManager(  150): WINDOW DIED Window{40b05690 StatusBar paused=false}
I/WindowManager(  150): WINDOW DIED Window{408c4f10 TrackingView paused=false}
I/ActivityManager(  150): Process com.android.systemui (pid 15785) has died.
W/ActivityManager(  150): Scheduling restart of crashed service com.android.systemui/.statusbar.StatusBarService in 5000ms
I/ActivityManager(  150): Start proc com.android.systemui for restart com.android.systemui: pid=15810 uid=1000 gids={1015, 3002, 3001, 3003}
W/ActivityManager(  150): Failure sending broadcast Intent { act=android.intent.action.TIME_TICK flg=0x40000004 (has extras) }
W/ActivityManager(  150): android.os.DeadObjectException
W/ActivityManager(  150):       at android.os.BinderProxy.transact(Native Method)
W/ActivityManager(  150):       at android.content.IIntentReceiver$Stub$Proxy.performReceive(IIntentReceiver.java:121)
W/ActivityManager(  150):       at com.android.server.am.ActivityManagerService.performReceiveLocked(ActivityManagerService.java:10813)
W/ActivityManager(  150):       at com.android.server.am.ActivityManagerService.deliverToRegisteredReceiverLocked(ActivityManagerService.java:10875)
W/ActivityManager(  150):       at com.android.server.am.ActivityManagerService.processNextBroadcast(ActivityManagerService.java:11081)
W/ActivityManager(  150):       at com.android.server.am.ActivityManagerService.finishReceiver(ActivityManagerService.java:10625)
W/ActivityManager(  150):       at android.app.LoadedApk$ReceiverDispatcher$Args.run(LoadedApk.java:731)
W/ActivityManager(  150):       at android.os.Handler.handleCallback(Handler.java:587)
W/ActivityManager(  150):       at android.os.Handler.dispatchMessage(Handler.java:92)
W/ActivityManager(  150):       at android.os.Looper.loop(Looper.java:123)
W/ActivityManager(  150):       at com.android.server.ServerThread.run(SystemServer.java:575)
I/StatusBarManagerService(  150): registerStatusBar bar=com.android.internal.statusbar.IStatusBar$Stub$Proxy@40649c80

[Anonymous]

Originally posted by: r3gis...@gmail.com

Could you test latest trunk version : http://nightlies.csipsimple.com/trunk/
I made some changes to ensure there is no remaining open locks.
I'd be interested by feedback on it.

Thx

[Anonymous]

Originally posted by: fander...@gmail.com

This problem still exists in [r685].  It looks like csipsimple is abusing systemui somehow in the way it handles status bar / notification updates (this is almost always the cause of high systemui CPU).  This is an important thing to fix as it disrupts normal operation of the phone and most users will never know that it's being caused by csipsimple.

[Anonymous]

Originally posted by: r3gis...@gmail.com

Are you sure that's due to CSipSimple ?

Regarding the log you get it has nothing to do with CSipSimple. The ANR list csipsimple in his process list but does not seems to be due to CSipSimple.

The broadcast that fail is not one I register to (android.intent.action.TIME_TICK).

Could be interesting to uninstall CSipSimple and see if problem still exists.
Also could be interesting to install an older version of csipsimple and also test.

But the stack trace and the ANR does not explicitly point out something wrong in CSipSimple (CSipSimple when the ANR appear use only 3.3% of the CPU while com.android.systemui is using 81 %).

If I don't mistake you are using a ROM that is a portage of android 2.3... maybe something to check with the ROM authors?

[Anonymous]

Originally posted by: fander...@gmail.com

Yes, the problem is caused by csipsimple (you may want to re-read the first comment and the related comments in issue 81) and has been happening for as long as I can remember (at least [r500] or so).

It is not surprising that the stack trace from the ANR is unrelated to csipsimple.  All csipsimple is doing is causing high CPU spikes of systemui, and when they get bad enough it makes systemui crash with an ANR (because the CPU gets 100% pegged).  In Android versions prior to 2.3, the high CPU shows up as coming from the system_server process, because in 2.3 systemui was decoupled from system_server.

We have troubleshot similar problems with other apps, and spoken to Google engineers familiar with systemui, and the response is always the same: high systemui CPU is caused by apps misusing the status bar/notification APIs.  For example, we have seen this same kind of problem caused when apps try to "animate" status bar icons (although the csipsimple problem is more severe than the others I've seen, and I can't explain why the CPU spikes start out low and gradually grow worse and longer over the time that csipsimple is up/registered).

[Anonymous]

Originally posted by: r3gis...@gmail.com

If you disable "show in notification bar" option (in User interface options in expert mode). Does it helps?

[Anonymous]

Originally posted by: r3gis...@gmail.com

Also, is there a widget on your home screen?

[Anonymous]

Originally posted by: fander...@gmail.com

No widget on the home screen.  I'll try disabling "show in notification bar" and see what happens.  Currently I'm working around this problem by killing/restarting csipsimple about once every 6-8 hours.

If I had to guess, I'd say this is caused by some kind of notification manipulation that csipsimple does as part of re-registering, and maybe there's some resource leak that makes it get worse over time...

[Anonymous]

Originally posted by: fander...@gmail.com

Disabling the "Display icon in status bar" setting definitely prevents this problem - so there's definitely something bad happening in the notification code path.

You should be able to reproduce the problem by:

1. Enabling "Display icon in status bar"
2. Using re-reg/keepalive timeouts of 60s/50s to make it more visible
3. Leave the phone registered for about 8 hours
4. Run "top -m 5" from a shell on the phone and observe it for about 5 minutes

You should then see systemui (Android 2.3) or system_server (Android <= 2.2) jump to the top of the CPU list once every minute or so and burn a lot of CPU for 10-15 seconds.

Choosing a slower phone (or just underclocking) may also make the problem more visible.

[Anonymous]

Originally posted by: r3gis...@gmail.com

Ok excellent, thanks a lot for testing.
I'll have a very close look on the way I use notification system so.

Hopefully load tests using my wrapper on the notification system will underline the leak even on a Nexus One :)

Labels: -Priority-Medium Priority-High
Owner: r3gis.3R
Status: Accepted

[Anonymous]

Originally posted by: r3gis...@gmail.com

Sounds related to : https://code.google.com/p/android/issues/detail?id=13941
If you talk again with Google engineer, they really really should have a look to this issue. Cause the weird thing sounds on their side !!

I try to do things cleanly recycling my view and regarding this issue it may cause a leak... :S ....

[Anonymous]

Originally posted by: r3gis...@gmail.com

This issue was closed by revision [r690].

Status: Fixed

[Anonymous]

Originally posted by: r3gis...@gmail.com

Well fix consists in re-creating the RemoteView each time we have to notify.

Strange but seems it reduce CPU usage when load testing.

It sounds a problem on Android systemui management of remote views. I think they assume developer will not try to recycle RemoteViews... So in this case, trying to do optimized things was a bad idea ;).
I guess there is a good reason for that on systemui side, but they really should write that into SDK !

[Anonymous]

Originally posted by: fander...@gmail.com

This does fix the problem, and for me also leads to a significant drop in battery consumption. Thanks!

[Anonymous]

Originally posted by: r3gis...@gmail.com

Excellent :) Many thanks to you for pointing this out :).

Your issues help me a lot to improve the app quality. So thx goes to you ;)

[Anonymous]

Originally posted by: LinJunLi...@gmail.com

http://blog.csdn.net/leehong2005/article/details/7298989
请参考该连接 后面是我的回复。
是真的3.0以后就不会出现这个bug了吗，现在就是一直更新notification只有nexu s（4.1.1）能正常运行完毕。
其他机器三星、摩托罗拉、htc（2.2、2.3）的机器都不能正常运行完毕，暂时只好把通知去掉，这些机器也能正常运行完毕了。