SystemServer anr detected by Watchdog.java

1,496 views
Skip to first unread message

sharon.hou

unread,
Sep 12, 2010, 10:24:22 AM9/12/10
to android-platform
Hi,

Could you help check below trace.txt? Phone screen is turned off and
do not response any key input and no way to turn screen on or power
off phone till the battery is exhausted.

From log, Watchdog.java detected one minute deadlock and SystemServer
is finally
killed by Watchdog, but don't know why the system server is not
reboot.

From this trace.txt (only anr for first 30s deadlock), I can see NOT
see any waiting for any lock in trace, only clue is "ProcessStatus" is
running on
native android.os.Process.readProcFile(/proc/1347/stat) which is
triggered by ActivityManagerService.updateCpuStatsNow(). And from
logcat log, nothing is helpful for this anr, but I can see
DeviceStorageMonitorService().checkMemory() stopped running at its
original 1
minute (no relative memory log printed out).

Does it mean android.os.Process.readProcFile(/proc/1347/stat) is
pending (blocked)
here ,it made this anr happened? Why
DeviceStorageMonitorService().checkMemory() stopped running when anr
happened?

Regards
Sharon

----- pid 1347 at 2010-09-01 17:37:10 -----
Cmd line: system_server

DALVIK THREADS:
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x40020998 self=0xce38
| sysTid=1347 nice=0 sched=0/0 cgrp=default handle=-1345017744
| schedstat=( 3235443151 6409942602 7537 )
at com.android.server.SystemServer.init1(Native Method)
at com.android.server.SystemServer.main(SystemServer.java:645)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:521)
at com.android.internal.os.ZygoteInit
$MethodAndArgsCaller.run(ZygoteInit.java:868)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
at dalvik.system.NativeStart.main(Native Method)

"RefQueu...@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@4620d790"
daemon prio=5 tid=39 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4623cc00 self=0x2eaf20
| sysTid=2753 nice=0 sched=0/0 cgrp=default handle=965376
| schedstat=( 915526 387268067 35 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4620bf50> (a java.lang.ref.ReferenceQueue)
at java.lang.Object.wait(Object.java:326)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:107)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:80)
at
org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:
102)
at java.lang.Thread.run(Thread.java:1096)

"Binder Thread #16" prio=5 tid=65 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x460ff8b8 self=0x53c548
| sysTid=2104 nice=0 sched=0/0 cgrp=default handle=5467368
| schedstat=( 2456939686 5572998013 5919 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #15" prio=5 tid=64 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x46113bf8 self=0x4bed98
| sysTid=2103 nice=0 sched=0/0 cgrp=default handle=3217280
| schedstat=( 2348052985 4837036116 6020 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #14" prio=5 tid=63 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x462c3528 self=0x4912e0
| sysTid=2098 nice=0 sched=0/0 cgrp=default handle=2382568
| schedstat=( 2599365220 5410583482 6071 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #13" prio=5 tid=62 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x462e2f70 self=0x53bd90
| sysTid=2097 nice=0 sched=0/0 cgrp=default handle=5487952
| schedstat=( 2827056885 5703491226 6683 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #12" prio=5 tid=61 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461b4a68 self=0x53aba0
| sysTid=2096 nice=0 sched=0/0 cgrp=default handle=3800088
| schedstat=( 2317626927 5139099148 6456 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #11" prio=5 tid=60 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x46226dc0 self=0x39fad8
| sysTid=2095 nice=0 sched=0/0 cgrp=default handle=4785016
| schedstat=( 2118530291 4803741448 5622 )
at dalvik.system.NativeStart.run(Native Method)

"NetworkLocationProvider" prio=5 tid=59 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4619b940 self=0x2dbd18
| sysTid=1535 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=3794960
| schedstat=( 194976766 45991058388 2001 )
at java.lang.Object.wait(Native Method)
- waiting on <0x46188df0> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at
com.google.android.location.NetworkLocationProvider.run(NetworkLocationProvider.java:
1091)
at java.lang.Thread.run(Thread.java:1096)

"Thread-64" prio=5 tid=58 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4608cb10 self=0x339640
| sysTid=1533 nice=0 sched=0/0 cgrp=default handle=3381120
| schedstat=( 32196041 2324493409 351 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460f0e60> (a java.lang.Object)
at java.lang.Object.wait(Object.java:288)
at com.google.common.async.AsyncHttpRequestFactory.run((null):-1)
at com.google.common.lang.ThreadFactory$ThreadImpl.run((null):-1)

"Thread-63" prio=5 tid=57 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x46086818 self=0x338bb0
| sysTid=1532 nice=0 sched=0/0 cgrp=default handle=3378416
| schedstat=( 3845215 2501739501 225 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460f0e60> (a java.lang.Object)
at java.lang.Object.wait(Object.java:288)
at com.google.common.async.AsyncHttpRequestFactory.run((null):-1)
at com.google.common.lang.ThreadFactory$ThreadImpl.run((null):-1)

"Thread-62" prio=5 tid=56 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460fe898 self=0x3380d8
| sysTid=1531 nice=0 sched=0/0 cgrp=default handle=3375640
| schedstat=( 3540042 2516601565 226 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460f0e60> (a java.lang.Object)
at java.lang.Object.wait(Object.java:288)
at com.google.common.async.AsyncHttpRequestFactory.run((null):-1)
at com.google.common.lang.ThreadFactory$ThreadImpl.run((null):-1)

"Thread-61" prio=5 tid=55 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460ae130 self=0x5a8bd8
| sysTid=1530 nice=0 sched=0/0 cgrp=default handle=3061584
| schedstat=( 8209222 2323974610 235 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4612c078> (a java.lang.Object)
at java.lang.Object.wait(Object.java:288)
at com.google.common.task.TaskRunner.waitForSomethingToDo((null):-1)
at com.google.common.task.TaskRunner.run((null):-1)
at com.google.common.lang.ThreadFactory$ThreadImpl.run((null):-1)

"Thread-60" prio=5 tid=54 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460ac0c0 self=0x505770
| sysTid=1524 nice=0 sched=0/0 cgrp=default handle=2416808
| schedstat=( 4974367 2302185053 221 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460c6938> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at com.google.android.gsf.Gservices$1.run(Gservices.java:78)

"GpsLocationProvider" prio=5 tid=53 TIMED_WAIT
| group="main" sCount=1 dsCount=0 s=Y obj=0x461bee10 self=0x5aa888
| sysTid=1518 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=5865432
| schedstat=( 111480718 71912902828 5294 )
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:326)
at android.os.MessageQueue.next(MessageQueue.java:142)
at android.os.Looper.loop(Looper.java:123)
at com.android.internal.location.GpsLocationProvider
$GpsLocationProviderThread.run(GpsLocationProvider.java:1668)

"Binder Thread #10" prio=5 tid=52 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4620 self=0x596010
| sysTid=1504 nice=0 sched=0/0 cgrp=default handle=5857232
| schedstat=( 2687255886 5897857625 6482 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #9" prio=5 tid=51 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4560 self=0x5952b8
| sysTid=1502 nice=0 sched=0/0 cgrp=default handle=5853640
| schedstat=( 3319763195 7295349134 7689 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #8" prio=5 tid=50 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a43d0 self=0x594400
| sysTid=1499 nice=0 sched=0/0 cgrp=default handle=5850048
| schedstat=( 2996093805 5978912358 7410 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #7" prio=5 tid=49 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4310 self=0x5936a8
| sysTid=1496 nice=0 sched=0/0 cgrp=default handle=5846456
| schedstat=( 2966094999 5945648183 6793 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #6" prio=5 tid=48 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4180 self=0x5927f0
| sysTid=1487 nice=0 sched=0/0 cgrp=default handle=5842864
| schedstat=( 2738647423 6239379931 6938 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #5" prio=5 tid=47 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a2f80 self=0x591a98
| sysTid=1484 nice=0 sched=0/0 cgrp=default handle=5819008
| schedstat=( 3255493166 6178985598 7137 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #4" prio=5 tid=46 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a0250 self=0x57a9d8
| sysTid=1477 nice=0 sched=0/0 cgrp=default handle=5744896
| schedstat=( 2759368964 6115051222 6889 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #3" prio=5 tid=45 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4619c368 self=0x5781f8
| sysTid=1473 nice=0 sched=0/0 cgrp=default handle=5731648
| schedstat=( 2924407989 6901855484 6976 )
at dalvik.system.NativeStart.run(Native Method)

"ThrottleService" prio=5 tid=44 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x46181348 self=0x56e820
| sysTid=1438 nice=0 sched=0/0 cgrp=default handle=5695840
| schedstat=( 171112063 2621520998 500 )
at java.lang.Object.wait(Native Method)
- waiting on <0x461826e8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"LocationManagerService" prio=5 tid=43 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x461805b0 self=0x56dda0
| sysTid=1436 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=5693152
| schedstat=( 32531728 16865295424 356 )
at java.lang.Object.wait(Native Method)
- waiting on <0x46181518> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at
com.android.server.LocationManagerService.run(LocationManagerService.java:
571)
at java.lang.Thread.run(Thread.java:1096)

"watchdog" prio=5 tid=42 NATIVE
| group="main" sCount=1 dsCount=0 s=Y obj=0x45d4aa88 self=0x312990
| sysTid=1434 nice=0 sched=0/0 cgrp=default handle=3021672
| schedstat=( 40771471 2349151628 1662 )
at android.os.Process.sendSignal(Native Method)
at
com.android.server.am.ActivityManagerService.dumpStackTraces(ActivityManagerService.java:
5123)
at com.android.server.Watchdog.run(Watchdog.java:853)

"RefQueu...@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@4604ea38"
daemon prio=5 tid=38 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460e3b70 self=0x2a0620
| sysTid=1428 nice=0 sched=0/0 cgrp=default handle=3027528
| schedstat=( 4333496 2289031983 220 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45fed6e0> (a java.lang.ref.ReferenceQueue)
at java.lang.Object.wait(Object.java:326)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:107)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:80)
at
org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:
102)
at java.lang.Thread.run(Thread.java:1096)

"SuplReceiver" prio=5 tid=36 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461341d0 self=0x2cfa50
| sysTid=1389 nice=0 sched=0/0 cgrp=default handle=2947984
| schedstat=( 8483886 2783905033 241 )
at android.net.LocalSocketImpl.readba_native(Native Method)
at android.net.LocalSocketImpl.access$400(LocalSocketImpl.java:29)
at android.net.LocalSocketImpl
$SocketInputStream.read(LocalSocketImpl.java:92)
at com.motorola.android.locationproxy.Supl.readSocket(Supl.java:238)
at com.motorola.android.locationproxy.Supl.readCommandId(Supl.java:
254)
at com.motorola.android.locationproxy.Supl.readSuplMessage(Supl.java:
280)
at com.motorola.android.locationproxy.Supl.access$000(Supl.java:206)
at com.motorola.android.locationproxy.Supl
$SuplReceiver.run(Supl.java:370)
at java.lang.Thread.run(Thread.java:1096)

"backup" prio=5 tid=35 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x46051b68 self=0x24cba0
| sysTid=1400 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=2964448
| schedstat=( 4028328 10831085193 218 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45e17c20> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"SoundPool" prio=5 tid=34 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x4611b4d0 self=0x24b640
| sysTid=1391 nice=0 sched=0/0 cgrp=default handle=2717632
| schedstat=( 4547124 2261199947 219 )
at dalvik.system.NativeStart.run(Native Method)

"SoundPoolThread" prio=5 tid=33 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x46125810 self=0x3233c8
| sysTid=1392 nice=0 sched=0/0 cgrp=default handle=2961264
| schedstat=( 6256094 2263641348 248 )
at dalvik.system.NativeStart.run(Native Method)

"AudioService" prio=5 tid=32 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x46133ab0 self=0x251940
| sysTid=1387 nice=0 sched=0/0 cgrp=default handle=2948720
| schedstat=( 27648925 2273376472 314 )
at java.lang.Object.wait(Native Method)
- waiting on <0x46127b70> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.media.AudioService
$AudioSystemThread.run(AudioService.java:1573)

"LocationProxyService" prio=5 tid=30 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x46125150 self=0x27f2c0
| sysTid=1386 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=2619152
| schedstat=( 84289561 11490631102 278 )
at java.lang.Object.wait(Native Method)
- waiting on <0x46133c78> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at
com.motorola.server.LocationProxyService.run(LocationProxyService.java:
343)
at java.lang.Thread.run(Thread.java:1096)

"MotLocationManagerService" prio=5 tid=31 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4611d0d0 self=0x280180
| sysTid=1385 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=2622144
| schedstat=( 11077885 11162841790 236 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4611fca8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at
com.motorola.gps.MotLocationManagerService.run(MotLocationManagerService.java:
620)
at java.lang.Thread.run(Thread.java:1096)

"com.android.server.NativeDaemonConnector" prio=5 tid=29 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x46112660 self=0x278cf0
| sysTid=1383 nice=0 sched=0/0 cgrp=default handle=2592304
| schedstat=( 15045164 2282165529 243 )
at android.net.LocalSocketImpl.readba_native(Native Method)
at android.net.LocalSocketImpl.access$400(LocalSocketImpl.java:29)
at android.net.LocalSocketImpl
$SocketInputStream.read(LocalSocketImpl.java:92)
at
com.android.server.NativeDaemonConnector.listenToSocket(NativeDaemonConnector.java:
109)
at
com.android.server.NativeDaemonConnector.run(NativeDaemonConnector.java:
83)
at java.lang.Thread.run(Thread.java:1096)

"MountService" prio=5 tid=28 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x461121b0 self=0x277748
| sysTid=1382 nice=0 sched=0/0 cgrp=default handle=2589168
| schedstat=( 3387460 2244293203 224 )
at java.lang.Object.wait(Native Method)
- waiting on <0x46112450> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"Tethering" prio=5 tid=27 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4610cf18 self=0x276d98
| sysTid=1381 nice=0 sched=0/0 cgrp=default handle=3243232
| schedstat=( 11749260 2290069581 271 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4610d0e8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"Cell Info Handler Thread" prio=5 tid=26 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460edf48 self=0x38a498
| sysTid=1380 nice=0 sched=0/0 cgrp=default handle=3712472
| schedstat=( 3936767 2257171633 224 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460f5448> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"MotWifiScan" prio=5 tid=25 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460ecc98 self=0x388bd8
| sysTid=1379 nice=0 sched=0/0 cgrp=default handle=3706136
| schedstat=( 87982187 2368804921 419 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460ecf30> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"WifiService" prio=5 tid=24 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460eb690 self=0x3a13c8
| sysTid=1378 nice=0 sched=0/0 cgrp=default handle=3807816
| schedstat=( 459625244 3313537595 597 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460eb928> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"ConnectivityThread" prio=5 tid=23 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x46082298 self=0x28fbd8
| sysTid=1376 nice=0 sched=0/0 cgrp=default handle=2814224
| schedstat=( 719299319 4269256565 1978 )
at java.lang.Object.wait(Native Method)
- waiting on <0x46096020> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at com.android.server.ConnectivityServiceExt
$ConnectivityThread.run(ConnectivityServiceExt.java:165)

"com.android.server.NativeDaemonConnector" prio=5 tid=22 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x46088aa0 self=0x2442e0
| sysTid=1375 nice=0 sched=0/0 cgrp=default handle=2728280
| schedstat=( 217071539 2862823484 987 )
at android.net.LocalSocketImpl.readba_native(Native Method)
at android.net.LocalSocketImpl.access$400(LocalSocketImpl.java:29)
at android.net.LocalSocketImpl
$SocketInputStream.read(LocalSocketImpl.java:92)
at
com.android.server.NativeDaemonConnector.listenToSocket(NativeDaemonConnector.java:
109)
at
com.android.server.NativeDaemonConnector.run(NativeDaemonConnector.java:
83)
at java.lang.Thread.run(Thread.java:1096)

"InputDispatcher" prio=5 tid=21 TIMED_WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460acf18 self=0x3bf720
| sysTid=1374 nice=-8 sched=0/0 cgrp=default handle=3926256
| schedstat=( 591156008 2665313716 1180 )
at java.lang.Object.wait(Native Method)
- waiting on <0x46068a28> (a com.android.server.KeyInputQueue
$QueuedEvent)
at java.lang.Object.wait(Object.java:326)
at com.android.server.KeyInputQueue.getEvent(KeyInputQueue.java:
1217)
at com.android.server.WindowManagerService
$InputDispatcherThread.process(WindowManagerService.java:6929)
at com.android.server.WindowManagerService
$InputDispatcherThread.run(WindowManagerService.java:6893)

"WindowManagerPolicy" prio=5 tid=20 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460ad0e8 self=0x3a2428
| sysTid=1373 nice=-2 sched=0/0 cgrp=default handle=3810664
| schedstat=( 8085723909 11680847132 19359 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4608b180> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at com.android.server.WindowManagerService
$PolicyThread.run(WindowManagerService.java:637)

"InputDeviceReader" prio=5 tid=19 NATIVE
| group="main" sCount=1 dsCount=0 s=Y obj=0x46063b30 self=0x39a8a0
| sysTid=1372 nice=-8 sched=0/0 cgrp=default handle=3779040
| schedstat=( 1735198991 3040649437 4547 )
at com.android.server.KeyInputQueue.readEvent(Native Method)
at com.android.server.KeyInputQueue.access$000(KeyInputQueue.java:
51)
at com.android.server.KeyInputQueue$1.run(KeyInputQueue.java:550)

"WindowManager" prio=5 tid=18 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x45f50d08 self=0x394e80
| sysTid=1371 nice=-4 sched=0/0 cgrp=default handle=3755968
| schedstat=( 2414794956 4622497546 5848 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45fd70d8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at com.android.server.WindowManagerService
$WMThread.run(WindowManagerService.java:601)

"AlarmManager" prio=5 tid=17 NATIVE
| group="main" sCount=1 dsCount=0 s=Y obj=0x460a7178 self=0x391b30
| sysTid=1370 nice=0 sched=0/0 cgrp=default handle=3678704
| schedstat=( 297393794 3224517828 791 )
at com.android.server.AlarmManagerService.waitForAlarm(Native
Method)
at com.android.server.AlarmManagerService.access
$100(AlarmManagerService.java:54)
at com.android.server.AlarmManagerService
$AlarmThread.run(AlarmManagerService.java:643)

"PowerManagerService" prio=5 tid=16 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x45f20638 self=0x358fc0
| sysTid=1369 nice=0 sched=0/0 cgrp=default handle=3510528
| schedstat=( 1923522937 4832916274 6651 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45ff55c8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"UEventObserver" prio=5 tid=15 NATIVE
| group="main" sCount=1 dsCount=0 s=Y obj=0x45fe98b8 self=0x3576a0
| sysTid=1368 nice=0 sched=0/0 cgrp=default handle=3504096
| schedstat=( 507751488 3401153558 1519 )
at android.os.UEventObserver.next_event(Native Method)
at android.os.UEventObserver.access$100(UEventObserver.java:39)
at android.os.UEventObserver$UEventThread.run(UEventObserver.java:
102)

"SyncHandlerThread" prio=5 tid=14 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4604df38 self=0x2aed60
| sysTid=1367 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=2813600
| schedstat=( 400695791 24729278560 1878 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45f3d798> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"AccountManagerService" prio=5 tid=13 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460a7eb8 self=0x294d40
| sysTid=1365 nice=0 sched=0/0 cgrp=default handle=568152
| schedstat=( 5035397 2161987300 225 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460327e8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"FileObserver" prio=5 tid=12 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x45e7a160 self=0x256128
| sysTid=1364 nice=0 sched=0/0 cgrp=default handle=2393208
| schedstat=( 8422851 2159423821 222 )
at android.os.FileObserver$ObserverThread.observe(Native Method)
at android.os.FileObserver$ObserverThread.run(FileObserver.java:88)

"PackageManager" prio=5 tid=11 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x45dfb680 self=0x2ad038
| sysTid=1363 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=2794424
| schedstat=( 450561509 14496551529 730 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45dff128> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"ProcessStats" prio=5 tid=10 NATIVE
| group="main" sCount=1 dsCount=0 s=Y obj=0x45df6ea8 self=0x2a43d8
| sysTid=1362 nice=0 sched=0/0 cgrp=default handle=2306544
| schedstat=( 20801879848 35533264206 288160 )
at android.os.Process.readProcFile(Native Method)
at com.android.server.ProcessStats.collectStats(ProcessStats.java:
337)
at com.android.server.ProcessStats.collectStats(ProcessStats.java:
365)
at com.android.server.ProcessStats.update(ProcessStats.java:266)
at
com.android.server.am.ActivityManagerService.updateCpuStatsNow(ActivityManagerService.java:
1737)
at com.android.server.am.ActivityManagerService
$3.run(ActivityManagerService.java:1690)

"ActivityManager" prio=5 tid=9 TIMED_WAIT
| group="main" sCount=1 dsCount=0 s=Y obj=0x45d4e1c8 self=0x237b78
| sysTid=1361 nice=-2 sched=0/0 cgrp=default handle=2325688
| schedstat=( 3182189950 10662445054 8576 )
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:326)
at android.os.MessageQueue.next(MessageQueue.java:142)
at android.os.Looper.loop(Looper.java:123)
at com.android.server.am.ActivityManagerService
$AThread.run(ActivityManagerService.java:1578)

"android.server.ServerThread" prio=5 tid=8 RUNNABLE
| group="main" sCount=1 dsCount=0 s=Y obj=0x45d42048 self=0x232218
| sysTid=1356 nice=-2 sched=0/0 cgrp=default handle=2302808
| schedstat=( 155198121661 86660917653 3302429 )
at android.view.View.resolveSize(View.java:~8279)
at android.widget.RelativeLayout.onMeasure(RelativeLayout.java:463)
at android.view.View.measure(View.java:8173)
at android.widget.LinearLayout.measureHorizontal(LinearLayout.java:
863)
at android.widget.LinearLayout.onMeasure(LinearLayout.java:306)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at android.widget.FrameLayout.onMeasure(FrameLayout.java:245)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at
android.widget.LinearLayout.measureChildBeforeLayout(LinearLayout.java:
1012)
at android.widget.LinearLayout.measureVertical(LinearLayout.java:
381)
at android.widget.LinearLayout.onMeasure(LinearLayout.java:304)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at
android.widget.LinearLayout.measureChildBeforeLayout(LinearLayout.java:
1012)
at android.widget.LinearLayout.measureVertical(LinearLayout.java:
381)
at android.widget.LinearLayout.onMeasure(LinearLayout.java:304)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at
android.widget.LinearLayout.measureChildBeforeLayout(LinearLayout.java:
1012)
at android.widget.LinearLayout.measureVertical(LinearLayout.java:
381)
at android.widget.LinearLayout.onMeasure(LinearLayout.java:304)
at android.view.View.measure(View.java:8173)
at android.widget.ScrollView.measureChildWithMargins(ScrollView.java:
989)
at android.widget.FrameLayout.onMeasure(FrameLayout.java:245)
at android.widget.ScrollView.onMeasure(ScrollView.java:286)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at android.widget.FrameLayout.onMeasure(FrameLayout.java:245)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at
android.widget.LinearLayout.measureChildBeforeLayout(LinearLayout.java:
1012)
at android.widget.LinearLayout.measureVertical(LinearLayout.java:
381)
at android.widget.LinearLayout.onMeasure(LinearLayout.java:304)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at android.widget.FrameLayout.onMeasure(FrameLayout.java:245)
at android.view.View.measure(View.java:8173)
at android.view.ViewGroup.measureChildWithMargins(ViewGroup.java:
3132)
at android.widget.FrameLayout.onMeasure(FrameLayout.java:245)
at android.view.View.measure(View.java:8173)
at android.view.ViewRoot.performTraversals(ViewRoot.java:810)
at android.view.ViewRoot.handleMessage(ViewRoot.java:1736)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:143)
at com.android.server.ServerThread.run(SystemServer.java:576)

"Binder Thread #2" prio=5 tid=7 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x45d40de8 self=0x11db90
| sysTid=1353 nice=0 sched=0/0 cgrp=default handle=1165064
| schedstat=( 2895751970 6007904072 7036 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #1" prio=5 tid=6 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x45d3fc98 self=0x10fae8
| sysTid=1352 nice=0 sched=0/0 cgrp=default handle=1252864
| schedstat=( 3571258587 6588073701 7327 )
at dalvik.system.NativeStart.run(Native Method)

"Compiler" daemon prio=5 tid=5 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x45d3e348 self=0x125028
| sysTid=1351 nice=0 sched=0/0 cgrp=default handle=1200104
| schedstat=( 7075042772 14931640565 35123 )
at dalvik.system.NativeStart.run(Native Method)

"JDWP" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x45d3e2a0 self=0x11d150
| sysTid=1350 nice=0 sched=0/0 cgrp=default handle=1164504
| schedstat=( 6683357 2102691648 225 )
at dalvik.system.NativeStart.run(Native Method)

"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 s=N obj=0x45d3e1e8 self=0x11c2e8
| sysTid=1349 nice=0 sched=0/0 cgrp=default handle=1243568
| schedstat=( 196010258518 516740046652 22372672 )
at dalvik.system.NativeStart.run(Native Method)

"HeapWorker" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x441be1e8 self=0x1228a0
| sysTid=1348 nice=0 sched=0/0 cgrp=default handle=1243504
| schedstat=( 2504425076 4698944045 5402 )
at dalvik.system.NativeStart.run(Native Method)

----- end 1347 -----

Christopher Tate

unread,
Sep 12, 2010, 2:27:31 PM9/12/10
to android-...@googlegroups.com
The watchdog restarts the Android framework runtime when the
system_server process's primary looper thread has been unresponsive
for one minute. That primary looper thread is called "ServerThread".
If you look at the log you quoted, this is what was running on that
thread at the time the watchdog fired:

Are you sure that this is the stack trace taken when the watchdog
actually fired? Double check the timestamps on the sets of stack
traces. In Android 2.2 ("froyo"), a watchdog event will result in
*two* sets of system-process stack traces in the traces file: one
taken after 30 seconds of unresponsiveness, and the other taken after
the full minute. Look at both of them to see whether the looper
thread is totally blocked, or is making slow progress, etc.

It looks like you might have a malformed layout being displayed by
code that runs in the system process. There isn't much UI done within
the system process other than the status bar -- have you modified the
way that Notifications are laid out or drawn, or put some kind of
fancy custom views into them?

Measurement plus layout should only take a very short amount of time.
We typically see it taking under 100 ms for normal views and layouts,
even complex layouts. The above stack trace shows that you're doing
something very strange (plus the fact that the layouts are nested ten
deep is bad in itself; deep nesting is inefficient and usually means a
bad design of the overall layout).

--
chris tate
android framework engineer

> --
> You received this message because you are subscribed to the Google Groups "android-platform" group.
> To post to this group, send email to android-...@googlegroups.com.
> To unsubscribe from this group, send email to android-platfo...@googlegroups.com.
> For more options, visit this group at http://groups.google.com/group/android-platform?hl=en.
>
>

sharon.hou

unread,
Sep 12, 2010, 11:21:57 PM9/12/10
to android-platform
I ensure this trace was happened when watchdog is fired after
halfwait(30s) because the first SIGNAL 3 for dumping the trace was
sent from watchdog thread (1434). Not sure why the trace file was
written at a very late time (after 12minutes).

I do see the 2nd system_server anr triggered from watchdog, but it is
not triggered by one minute, instead it happened after 12.5 minute
from the first anr. Seemed system was working at a very low speed. I
ensure this 2nd anr was triggered by watchdog also because there is
one watchdog event recorded in log.event.txt.

I am thinking that maybe the issue happend in 1st anr was triggering
2nd anr. I will do more investigation on 2nd anr trace (one dead lock
here). I am not familar with layout and measurement and not sure what
they are doing. This issue can be seen only at two phone units so far
and not easy to reproduce. When this first anr happened, a TTY call
was ongoing, then screen turned black suddenly and no response again
for any keyinput till battery was exhausted.

Any comments from below 2nd trace ?

//for 1st system_server anr triggered by watchdog, but dalvikvm write
the trace in a very late time.
09-01 17:37:10.061 1347 1434 I Process : Sending signal. PID: 1347
SIG: 3
09-01 17:37:10.061 1347 1349 I dalvikvm: threadid=3: reacting to
signal 3
09-01 17:49:10.147 1347 1349 I dalvikvm: Wrote stack traces to '/
data/anr/traces.txt'

// for 2nd system_server anr triggered by watchdog.
09-01 17:49:40.155 1347 1434 I watchdog:
com.android.server.PowerManagerService

2nd system_server anr Trace.txt:
----- pid 1347 at 2010-09-01 17:49:40 -----
Cmd line: system_server

DALVIK THREADS:
"main" prio=5 tid=1 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x40020998 self=0xce38
| sysTid=1347 nice=0 sched=0/0 cgrp=default handle=-1345017744
| schedstat=( 3237457311 6415679906 7540 )
at com.android.server.SystemServer.init1(Native Method)
at com.android.server.SystemServer.main(SystemServer.java:645)
at java.lang.reflect.Method.invokeNative(Native Method)
at java.lang.reflect.Method.invoke(Method.java:521)
at com.android.internal.os.ZygoteInit
$MethodAndArgsCaller.run(ZygoteInit.java:868)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:626)
at dalvik.system.NativeStart.main(Native Method)

"android.hardware.SensorManager$SensorThread" prio=5 tid=37 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x461de368 self=0x352c68
| sysTid=3002 nice=-8 sched=0/0 cgrp=default handle=6700720
| schedstat=( 762941 9857176 67 )
at android.hardware.SensorManager$SensorThread
$SensorThreadRunnable.run(SensorManager.java:~405)
- waiting to lock <0x40082850> (a java.util.ArrayList) held by
threadid=20 (WindowManagerPolicy)
at java.lang.Thread.run(Thread.java:1096)

"RefQueu...@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@4620d790"
daemon prio=5 tid=39 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4623cc00 self=0x2eaf20
| sysTid=2753 nice=0 sched=0/0 cgrp=default handle=965376
| schedstat=( 915526 387268067 35 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4620bf50> (a java.lang.ref.ReferenceQueue)
at java.lang.Object.wait(Object.java:326)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:107)
at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:80)
at
org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:
102)
at java.lang.Thread.run(Thread.java:1096)

"Binder Thread #16" prio=5 tid=65 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x460ff8b8 self=0x53c548
| sysTid=2104 nice=0 sched=0/0 cgrp=default handle=5467368
| schedstat=( 2457763661 5572998013 5921 )
at
com.android.server.am.BatteryStatsService.notePhoneSignalStrength(BatteryStatsService.java:~187)
- waiting to lock <0x45d519c0> (a
com.android.internal.os.BatteryStatsImpl) held by threadid=15
(UEventObserver)
at
com.android.server.TelephonyRegistry.broadcastSignalStrengthChanged(TelephonyRegistry.java:
495)
at
com.android.server.TelephonyRegistry.notifySignalStrength(TelephonyRegistry.java:
293)
at com.android.internal.telephony.ITelephonyRegistry
$Stub.onTransact(ITelephonyRegistry.java:95)
at android.os.Binder.execTransact(Binder.java:304)
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #15" prio=5 tid=64 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x46113bf8 self=0x4bed98
| sysTid=2103 nice=0 sched=0/0 cgrp=default handle=3217280
| schedstat=( 2348541265 4837036116 6022 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #14" prio=5 tid=63 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x462c3528 self=0x4912e0
| sysTid=2098 nice=0 sched=0/0 cgrp=default handle=2382568
| schedstat=( 2604980456 5411926254 6082 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #13" prio=5 tid=62 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x462e2f70 self=0x53bd90
| sysTid=2097 nice=0 sched=0/0 cgrp=default handle=5487952
| schedstat=( 2828002929 5703491226 6685 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #12" prio=5 tid=61 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461b4a68 self=0x53aba0
| sysTid=2096 nice=0 sched=0/0 cgrp=default handle=3800088
| schedstat=( 2317748997 5139129665 6458 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #11" prio=5 tid=60 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x46226dc0 self=0x39fad8
| sysTid=2095 nice=0 sched=0/0 cgrp=default handle=4785016
| schedstat=( 2118713396 4803741448 5624 )
"GpsLocationProvider" prio=5 tid=53 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x461bee10 self=0x5aa888
| sysTid=1518 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=5865432
| schedstat=( 111572271 71978668208 5295 )
at java.lang.Object.wait(Native Method)
- waiting on <0x4610cd90> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at com.android.internal.location.GpsLocationProvider
$GpsLocationProviderThread.run(GpsLocationProvider.java:1668)

"Binder Thread #10" prio=5 tid=52 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4620 self=0x596010
| sysTid=1504 nice=0 sched=0/0 cgrp=default handle=5857232
| schedstat=( 2687255886 5897857625 6482 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #9" prio=5 tid=51 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4560 self=0x5952b8
| sysTid=1502 nice=0 sched=0/0 cgrp=default handle=5853640
| schedstat=( 3320373547 7295654310 7691 )
at
com.android.server.am.ActivityManagerService.startServiceLocked(ActivityManagerService.java:~11900)
- waiting to lock <0x45d519c0> (a
com.android.internal.os.BatteryStatsImpl) held by threadid=15
(UEventObserver)
at
com.android.server.am.ActivityManagerService.startService(ActivityManagerService.java:
11921)
at
android.app.ActivityManagerNative.onTransact(ActivityManagerNative.java:
619)
at
com.android.server.am.ActivityManagerService.onTransact(ActivityManagerService.java:
1704)
at android.os.Binder.execTransact(Binder.java:304)
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #8" prio=5 tid=50 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a43d0 self=0x594400
| sysTid=1499 nice=0 sched=0/0 cgrp=default handle=5850048
| schedstat=( 2996093805 5978912358 7410 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #7" prio=5 tid=49 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4310 self=0x5936a8
| sysTid=1496 nice=0 sched=0/0 cgrp=default handle=5846456
| schedstat=( 2966186552 5951354970 6795 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #6" prio=5 tid=48 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a4180 self=0x5927f0
| sysTid=1487 nice=0 sched=0/0 cgrp=default handle=5842864
| schedstat=( 2738647423 6240142870 6939 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #5" prio=5 tid=47 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a2f80 self=0x591a98
| sysTid=1484 nice=0 sched=0/0 cgrp=default handle=5819008
| schedstat=( 3257019045 6198455813 7143 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #4" prio=5 tid=46 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x461a0250 self=0x57a9d8
| sysTid=1477 nice=0 sched=0/0 cgrp=default handle=5744896
| schedstat=( 2759704658 6115112256 6891 )
| schedstat=( 92620828 2493286158 10023 )
at android.os.Process.sendSignal(Native Method)
at
com.android.server.am.ActivityManagerService.dumpStackTraces(ActivityManagerService.java:
5123)
at com.android.server.Watchdog.run(Watchdog.java:871)
"WindowManagerPolicy" prio=5 tid=20 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x460ad0e8 self=0x3a2428
| sysTid=1373 nice=-2 sched=0/0 cgrp=default handle=3810664
| schedstat=( 8097473176 11736450159 19368 )
at
com.android.server.am.BatteryStatsService.noteStartSensor(BatteryStatsService.java:~112)
- waiting to lock <0x45d519c0> (a
com.android.internal.os.BatteryStatsImpl) held by threadid=15
(UEventObserver)
at com.android.server.SensorService.enableSensor(SensorService.java:
152)
at
android.hardware.SensorManager.registerListener(SensorManager.java:
943)
at
android.hardware.SensorManager.registerListener(SensorManager.java:
880)
at
com.android.server.PowerManagerService.enableLightSensor(PowerManagerService.java:
3087)
at
com.android.server.PowerManagerService.setScreenStateLocked(PowerManagerService.java:
1566)
at
com.android.server.PowerManagerService.setPowerState(PowerManagerService.java:
1675)
at
com.android.server.PowerManagerService.setPowerState(PowerManagerService.java:
1587)
at
com.android.server.PowerManagerService.acquireWakeLockLocked(PowerManagerService.java:
830)
at
com.android.server.PowerManagerService.acquireWakeLock(PowerManagerService.java:
754)
at android.os.PowerManager$WakeLock.acquire(PowerManager.java:255)
at
com.android.internal.policy.impl.KeyguardViewMediator.pokeWakelock(KeyguardViewMediator.java:
904)
at
com.android.internal.policy.impl.KeyguardViewMediator.pokeWakelock(KeyguardViewMediator.java:
896)
at
com.android.internal.policy.impl.LockPatternKeyguardView.wakeWhenReadyTq(LockPatternKeyguardView.java:
674)
at
com.android.internal.policy.impl.KeyguardViewManager.wakeWhenReadyTq(KeyguardViewManager.java:
229)
at
com.android.internal.policy.impl.KeyguardViewMediator.handleWakeWhenReady(KeyguardViewMediator.java:
1217)
at com.android.internal.policy.impl.KeyguardViewMediator.access
$1800(KeyguardViewMediator.java:110)
at com.android.internal.policy.impl.KeyguardViewMediator
$2.handleMessage(KeyguardViewMediator.java:989)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:143)
at com.android.server.WindowManagerService
$PolicyThread.run(WindowManagerService.java:637)

"InputDeviceReader" prio=5 tid=19 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x46063b30 self=0x39a8a0
| sysTid=1372 nice=-8 sched=0/0 cgrp=default handle=3779040
| schedstat=( 1736358659 3043792747 4552 )
at
com.android.server.PowerManagerService.setKeyboardVisibility(PowerManagerService.java:~2694)
- waiting to lock <0x45d49ee0> (a
com.android.server.PowerManagerService$LockList) held by threadid=20
(WindowManagerPolicy)
at
com.android.internal.policy.impl.PhoneWindowManager.updateRotation(PhoneWindowManager.java:
2568)
at
com.android.internal.policy.impl.PhoneWindowManager.preprocessInputEventTq(PhoneWindowManager.java:
1824)
at com.android.server.WindowManagerService
$KeyQ.preprocessEvent(WindowManagerService.java:6740)
at com.android.server.KeyInputQueue$1.run(KeyInputQueue.java:613)

"WindowManager" prio=5 tid=18 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x45f50d08 self=0x394e80
| sysTid=1371 nice=-4 sched=0/0 cgrp=default handle=3755968
| schedstat=( 2414794956 4622497546 5848 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45fd70d8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at com.android.server.WindowManagerService
$WMThread.run(WindowManagerService.java:601)

"AlarmManager" prio=5 tid=17 NATIVE
| group="main" sCount=1 dsCount=0 s=Y obj=0x460a7178 self=0x391b30
| sysTid=1370 nice=0 sched=0/0 cgrp=default handle=3678704
| schedstat=( 302520746 3263488776 1189 )
at com.android.server.AlarmManagerService.waitForAlarm(Native
Method)
at com.android.server.AlarmManagerService.access
$100(AlarmManagerService.java:54)
at com.android.server.AlarmManagerService
$AlarmThread.run(AlarmManagerService.java:643)

"PowerManagerService" prio=5 tid=16 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x45f20638 self=0x358fc0
| sysTid=1369 nice=0 sched=0/0 cgrp=default handle=3510528
| schedstat=( 1923553454 4842956557 6652 )
at com.android.server.PowerManagerService
$LightAnimator.run(PowerManagerService.java:~2022)
- waiting to lock <0x45d49ee0> (a
com.android.server.PowerManagerService$LockList) held by threadid=20
(WindowManagerPolicy)
at android.os.Handler.handleCallback(Handler.java:587)
at android.os.Handler.dispatchMessage(Handler.java:92)
at android.os.Looper.loop(Looper.java:143)
at android.os.HandlerThread.run(HandlerThread.java:60)

"UEventObserver" prio=5 tid=15 RUNNABLE
| group="main" sCount=1 dsCount=0 s=Y obj=0x45fe98b8 self=0x3576a0
| sysTid=1368 nice=0 sched=0/0 cgrp=default handle=3504096
| schedstat=( 9900696386 24410979655 1002008 )
at com.android.internal.os.BatteryStatsImpl
$Timer.writeSummaryFromParcelLocked(BatteryStatsImpl.java:~522)
at
com.android.internal.os.BatteryStatsImpl.writeSummaryToParcel(BatteryStatsImpl.java:
3430)
at
com.android.internal.os.BatteryStatsImpl.writeLocked(BatteryStatsImpl.java:
3079)
at
com.android.internal.os.BatteryStatsImpl.setOnBattery(BatteryStatsImpl.java:
2801)
at
com.android.server.am.BatteryStatsService.setOnBattery(BatteryStatsService.java:
326)
at com.android.server.BatteryService.sendIntent(BatteryService.java:
361)
at com.android.server.BatteryService.update(BatteryService.java:313)
at com.android.server.BatteryService.access$000(BatteryService.java:
73)
at com.android.server.BatteryService$1.onUEvent(BatteryService.java:
179)
at android.os.UEventObserver$UEventThread.run(UEventObserver.java:
108)

"SyncHandlerThread" prio=5 tid=14 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x4604df38 self=0x2aed60
| sysTid=1367 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=2813600
| schedstat=( 400695791 24729278560 1878 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45f3d798> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"AccountManagerService" prio=5 tid=13 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x460a7eb8 self=0x294d40
| sysTid=1365 nice=0 sched=0/0 cgrp=default handle=568152
| schedstat=( 5035397 2161987300 225 )
at java.lang.Object.wait(Native Method)
- waiting on <0x460327e8> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"FileObserver" prio=5 tid=12 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x45e7a160 self=0x256128
| sysTid=1364 nice=0 sched=0/0 cgrp=default handle=2393208
| schedstat=( 8575438 2159515373 224 )
at android.os.FileObserver$ObserverThread.observe(Native Method)
at android.os.FileObserver$ObserverThread.run(FileObserver.java:88)

"PackageManager" prio=5 tid=11 WAIT
| group="main" sCount=1 dsCount=0 s=N obj=0x45dfb680 self=0x2ad038
| sysTid=1363 nice=10 sched=0/0 cgrp=bg_non_interactive
handle=2794424
| schedstat=( 450561509 14496551529 730 )
at java.lang.Object.wait(Native Method)
- waiting on <0x45dff128> (a android.os.MessageQueue)
at java.lang.Object.wait(Object.java:288)
at android.os.MessageQueue.next(MessageQueue.java:146)
at android.os.Looper.loop(Looper.java:123)
at android.os.HandlerThread.run(HandlerThread.java:60)

"ProcessStats" prio=5 tid=10 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x45df6ea8 self=0x2a43d8
| sysTid=1362 nice=0 sched=0/0 cgrp=default handle=2306544
| schedstat=( 20935241690 36201110860 300082 )
at
com.android.server.am.ActivityManagerService.updateCpuStatsNow(ActivityManagerService.java:~1766)
- waiting to lock <0x45d519c0> (a
com.android.internal.os.BatteryStatsImpl) held by threadid=15
(UEventObserver)
at com.android.server.am.ActivityManagerService
$3.run(ActivityManagerService.java:1690)

"ActivityManager" prio=5 tid=9 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x45d4e1c8 self=0x237b78
| sysTid=1361 nice=-2 sched=0/0 cgrp=default handle=2325688
| schedstat=( 3205017107 10719207741 10372 )
at com.android.server.am.ActivityManagerService
$2.handleMessage(ActivityManagerService.java:~1193)
- waiting to lock <0x45d4e3c8> (a
com.android.server.am.ActivityManagerService) held by threadid=51
(Binder Thread #9)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:143)
at com.android.server.am.ActivityManagerService
$AThread.run(ActivityManagerService.java:1578)

"android.server.ServerThread" prio=5 tid=8 MONITOR
| group="main" sCount=1 dsCount=0 s=N obj=0x45d42048 self=0x232218
| sysTid=1356 nice=-2 sched=0/0 cgrp=default handle=2302808
| schedstat=( 155207795739 86718199142 3302876 )
at
com.android.server.PowerManagerService.monitor(PowerManagerService.java:~2937)
- waiting to lock <0x45d49ee0> (a
com.android.server.PowerManagerService$LockList) held by threadid=20
(WindowManagerPolicy)
at com.android.server.Watchdog
$HeartbeatHandler.handleMessage(Watchdog.java:325)
at android.os.Handler.dispatchMessage(Handler.java:99)
at android.os.Looper.loop(Looper.java:143)
at com.android.server.ServerThread.run(SystemServer.java:576)

"Binder Thread #2" prio=5 tid=7 NATIVE
| group="main" sCount=1 dsCount=0 s=Y obj=0x45d40de8 self=0x11db90
| sysTid=1353 nice=0 sched=0/0 cgrp=default handle=1165064
| schedstat=( 2895843523 6008667011 7037 )
at dalvik.system.NativeStart.run(Native Method)

"Binder Thread #1" prio=5 tid=6 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x45d3fc98 self=0x10fae8
| sysTid=1352 nice=0 sched=0/0 cgrp=default handle=1252864
| schedstat=( 3571258587 6588073701 7327 )
at dalvik.system.NativeStart.run(Native Method)

"Compiler" daemon prio=5 tid=5 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x45d3e348 self=0x125028
| sysTid=1351 nice=0 sched=0/0 cgrp=default handle=1200104
| schedstat=( 7109252985 14987945494 35416 )
at dalvik.system.NativeStart.run(Native Method)

"JDWP" daemon prio=5 tid=4 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x45d3e2a0 self=0x11d150
| sysTid=1350 nice=0 sched=0/0 cgrp=default handle=1164504
| schedstat=( 6683357 2102691648 225 )
at dalvik.system.NativeStart.run(Native Method)

"Signal Catcher" daemon prio=5 tid=3 RUNNABLE
| group="system" sCount=0 dsCount=0 s=N obj=0x45d3e1e8 self=0x11c2e8
| sysTid=1349 nice=0 sched=0/0 cgrp=default handle=1243568
| schedstat=( 439047833093 987995318756 49385360 )
at dalvik.system.NativeStart.run(Native Method)

"HeapWorker" daemon prio=5 tid=2 VMWAIT
| group="system" sCount=1 dsCount=0 s=N obj=0x441be1e8 self=0x1228a0
| sysTid=1348 nice=0 sched=0/0 cgrp=default handle=1243504
| schedstat=( 2504425076 4698944045 5402 )
at dalvik.system.NativeStart.run(Native Method)

----- end 1347 -----

> > "RefQueueWor...@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@4620d790"
> ...
>
> read more »

sharon.hou

unread,
Sep 13, 2010, 5:22:43 AM9/13/10
to android-platform
From 2nd trace file, I can see UEeventObserver is under RUNNABLE state
at BatteryStasImpl$Timer.writeSummaryFromParcelLocked(), and
serverthread/PowerManagerService/ActivityManager/InputDeviceReader..
are being blocked by this UEVentObserver or WindownManagerPolicy
(blocked by UEventObserver).

I can find nothing from both BatteryService.update() and
BatteryStatsImpl.writeLocked(). Do you see any issue for them? I
believe the battery status is backed up in a regular interval and
works well. But why this time battery update ( in rare case) is
blocked?
> "RefQueueWor...@org.apache.http.impl.conn.tsccm.ConnPoolByRoute@4620d790"
> daemon prio=5 tid=39 WAIT
>   | group="main" sCount=1 dsCount=0 s=N obj=0x4623cc00 self=0x2eaf20
>   | sysTid=2753 nice=0 sched=0/0 cgrp=default handle=965376
>   | schedstat=( 915526 387268067 35 )
>   at java.lang.Object.wait(Native Method)
>   - waiting on <0x4620bf50> (a java.lang.ref.ReferenceQueue)
>   at java.lang.Object.wait(Object.java:326)
>   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:107)
>   at java.lang.ref.ReferenceQueue.remove(ReferenceQueue.java:80)
>   at
> org.apache.http.impl.conn.tsccm.RefQueueWorker.run(RefQueueWorker.java:
> 102)
>   at java.lang.Thread.run(Thread.java:1096)
>
> ...
>
> read more »

Sharon HouW

unread,
Sep 14, 2010, 10:10:42 AM9/14/10
to android-platform
What's your comments for below two patches for this anr issue? In BatteryStatsService.java patch, to move the noteStart/StopSensor() into a separate thread since it is blocking others from trace file.   Another patch is to add one 50ms wait during a for-loop because I can see another block in onRotationChanged().
(Posted through email since I can not login the website.) 
 
====== Patch-1
diff --git a/services/java/com/android/server/am/BatteryStatsService.java b/services/java/com/android/server/am/BatteryStatsService.java
index 33bbc13..2d0d438 100644
--- a/services/java/com/android/server/am/BatteryStatsService.java
+++ b/services/java/com/android/server/am/BatteryStatsService.java
@@ -25,6 +25,13 @@ import android.os.Process;
 import android.os.ServiceManager;
 import android.telephony.SignalStrength;
 import android.util.Slog;
+import android.os.HandlerThread;
+import android.os.Message;
+import android.util.Log;
+import android.os.Looper;
+import android.os.Handler;
 
 import com.android.internal.app.IBatteryStats;
 import com.android.internal.os.BatteryStatsImpl;
@@ -43,10 +50,58 @@ public final class BatteryStatsService extends IBatteryStats.Stub {
     final BatteryStatsImpl mStats;
     Context mContext;
 
+    public static final int NOTE_START_SENSOR = 1;
+    public static final int NOTE_STOP_SENSOR = 2;
+
+    NoteBatteryStatsHandler mNoteBatteryStatsHandler;
+
+
     BatteryStatsService(String filename) {
         mStats = new BatteryStatsImpl(filename);
+
+        // create handlers
+        HandlerThread noteThread = new HandlerThread("NoteBatteryStatus");
+        noteThread.start();
+        mNoteBatteryStatsHandler  = new NoteBatteryStatsHandler(noteThread.getLooper());
     }
-   
+
+    private class   NoteBatteryStatsHandler extends Handler {
+        /*
+         * Handler that allows posting to the noteThread.
+         */
+
+        public NoteBatteryStatsHandler(Looper looper) {
+            super(looper);
+        }
+
+        @Override
+        public void handleMessage(Message msg) {
+           try {
+                switch (msg.what) {
+                    case NOTE_START_SENSOR:
+                         synchronized(mStats) {
+                             Log.e("a16543", "received note_start_sensor");
+                             mStats.getUidStatsLocked(msg.arg1).noteStartSensor(msg.arg2);
+                         }
+                    break;
+
+                    case NOTE_STOP_SENSOR:
+                         synchronized(mStats) {
+                             Log.e("a16543", "received note_stop_sensor");
+                             mStats.getUidStatsLocked(msg.arg1).noteStopSensor(msg.arg2);
+                         }
+                    break;
+                }
+           }catch (Throwable t) {Log.e("a16543", "error happened in NoteThreadHandler.handleMessage");}
+        }
+    }
+
     public void publish(Context context) {
         mContext = context;
         ServiceManager.addService("batteryinfo", asBinder());
@@ -110,14 +165,20 @@ public final class BatteryStatsService extends IBatteryStats.Stub {
     public void noteStartSensor(int uid, int sensor) {
         enforceCallingPermission();
         synchronized (mStats) {
-            mStats.getUidStatsLocked(uid).noteStartSensor(sensor);
+            Message msg = mNoteBatteryStatsHandler.obtainMessage(NOTE_START_SENSOR, uid, sensor);
+            mNoteBatteryStatsHandler.sendMessage(msg);
         }
     }
    
     public void noteStopSensor(int uid, int sensor) {
         enforceCallingPermission();
         synchronized (mStats) {
-            mStats.getUidStatsLocked(uid).noteStopSensor(sensor);
+            Message msg = mNoteBatteryStatsHandler.obtainMessage(NOTE_STOP_SENSOR, uid, sensor);
+            mNoteBatteryStatsHandler.sendMessage(msg);
         }
     }
    
=========== Patch-2:
diff --git a/services/java/com/android/server/WindowManagerService.java b/services/java/com/android/server/WindowManagerService.java
index e0e9b24..3d30920 100755
--- a/services/java/com/android/server/WindowManagerService.java
+++ b/services/java/com/android/server/WindowManagerService.java
@@ -4627,9 +4627,19 @@ public class WindowManagerService extends IWindowManager.Stub
                     w.mOrientationChanging = true;
                 }
             }
-            for (int i=mRotationWatchers.size()-1; i>=0; i--) {
+
+            // clone the mRotationWatchers and walkthrough on it with 100ms sleep to let others running.
+            ArrayList<IRotationWatcher> tmpRotationWatchers = (ArrayList<IRotationWatcher>)mRotationWatchers.clone();
+
+            for (int i=tmpRotationWatchers.size()-1; i>=0; i--) {
                 try {
-                    mRotationWatchers.get(i).onRotationChanged(rotation);
+                    tmpRotationWatchers.get(i).onRotationChanged(rotation);
+                    try {
+                        mWindowMap.wait(50);
+                    } catch (InterruptedException ex) {
+                    }
                 } catch (RemoteException e) {
                 }
             }
 
Sharon

Dianne Hackborn

unread,
Sep 14, 2010, 1:11:50 PM9/14/10
to android-...@googlegroups.com
No, that isn't the problem.  You need to figure out why this function is stuck (presumably stuck in some kind of infinite loop):

"UEventObserver" prio=5 tid=15 RUNNABLE

 | group="main" sCount=1 dsCount=0 s=Y obj=0x45fe98b8 self=0x3576a0
 | sysTid=1368 nice=0 sched=0/0 cgrp=default handle=3504096
 | schedstat=( 9900696386 24410979655 1002008 )
 at com.android.internal.os.BatteryStatsImpl
$Timer.writeSummaryFromParcelLocked(BatteryStatsImpl.java:~522)
 at
com.android.internal.os.BatteryStatsImpl.writeSummaryToParcel(BatteryStatsImpl.java:
3430)
 at
com.android.internal.os.BatteryStatsImpl.writeLocked(BatteryStatsImpl.java:
3079)
 at
com.android.internal.os.BatteryStatsImpl.setOnBattery(BatteryStatsImpl.java:
2801)
 at
com.android.server.am.BatteryStatsService.setOnBattery(BatteryStatsService.java:
326)
 at com.android.server.BatteryService.sendIntent(BatteryService.java:
361)
 at com.android.server.BatteryService.update(BatteryService.java:313)
 at com.android.server.BatteryService.access$000(BatteryService.java:
73)
 at com.android.server.BatteryService$1.onUEvent(BatteryService.java:
179)
 at android.os.UEventObserver$UEventThread.run(UEventObserver.java:
108)
--
You received this message because you are subscribed to the Google Groups "android-platform" group.
To post to this group, send email to android-...@googlegroups.com.
To unsubscribe from this group, send email to android-platfo...@googlegroups.com.
For more options, visit this group at http://groups.google.com/group/android-platform?hl=en.



--
Dianne Hackborn
Android framework engineer
hac...@android.com

Note: please don't send private questions to me, as I don't have time to provide private support, and so won't reply to such e-mails.  All such questions should be posted on public forums, where I and others can see and answer them.

Reply all
Reply to author
Forward
Message has been deleted
0 new messages