Are ANRs related to "Key dispatching timed out sending to <null>" messages true ANRs?

[Nick Smith]

I've noticed that there is an bug reported for Android related to the
key dispatching not finding the original window that the key press was
triggered on (see http://code.google.com/p/android/issues/detail?id=5729).

I'm seeing this a lot on an Eclair device when you transition from one
activity to another. These ANRs seem like false positives because the
window for which the key event was triggered is no longer available
and has closed successfully. So it ends up blaming the currently
active window for the ANR.

See the example logs below and you can see in the "DIspatch state"
message below that the BACK key event was triggered in the camera app.
However, it ANRs in the MMS app.

It seems the root of this problem would be that the key dispatching
for this event doesn't get cancelled or removed correctly. However,
would it be ok to change the ActivityManagerService to not generate
these type of ANRs when the target window no longer exists?


Example logs:

09-17 20:18:47.785 I/TestEngine( 1894): [1;36m(action) [0mPressing
key 'KEYCODE_BACK' on activity 'com.android.camera/.Camera;1'

09-17 20:18:47.795 E/QualcommCameraHardware( 1189): native_set_parm:
error (Unknown error: 0): fd 9, type 37, length 1, status 0

09-17 20:18:47.795 D/CameraService( 1189): startPreview (pid 12637)

09-17 20:18:47.795 D/CameraService( 1189): startCameraMode(0) (pid
12637)

09-17 20:18:47.795 D/CameraService( 1189): startPreviewMode (pid
12637)

09-17 20:18:47.795 D/QualcommCameraHardware( 1189):
mBufferSize=230400, mAlignedBufferSize=233472

09-17 20:18:47.795 D/QualcommCameraHardware( 1189): num_buffers = 4

09-17 20:18:47.905 D/QualcommCameraHardware( 1189): frame_thread E

09-17 20:18:48.105 D/QualcommCameraHardware( 1189): ctrlCmd.value = 59

09-17 20:18:48.105 D/QualcommCameraHardware( 1189): Maximum zoom value
is 59

09-17 20:18:48.165 D/TestEngineEventGenerator(12637): sendEvent:
PreviewStarted, []

09-17 20:18:48.165 D/TestEngineEventGenerator(12637): sending

09-17 20:18:48.205 D/camera (12637): surfaceChanged

09-17 20:18:48.285 D/TestEngineEventGenerator(12637): sendEvent: Idle,
[4838]

09-17 20:18:48.295 D/TestEngineEventGenerator(12637): sending

09-17 20:18:48.315 D/dalvikvm(12467): GC freed 2597 objects / 105000
bytes in 285ms

09-17 20:18:49.305 D/TestEngineEventGenerator( 1820): sendEvent: Key,
[4, 0, , com.android.camera/.Camera, 1, 2]

09-17 20:18:49.305 D/TestEngineEventGenerator( 1820): sending

09-17 20:18:49.365 D/camera (12637): KEYCODE_BACK mStatus = 1

09-17 20:18:50.380 D/TestEngineEventGenerator( 1820): sendEvent: Key,
[4, 1, , com.android.camera/.Camera, 1, 2]

09-17 20:18:50.380 D/TestEngineEventGenerator( 1820): sending

09-17 20:18:50.405 D/camera (12637): onPause

09-17 20:18:50.405 V/SensorManager(12637): unregisterListener 4

09-17 20:18:50.405 V/SensorManager(12637): unregisterListener 6

09-17 20:18:50.405 V/SensorService( 1820): enableSensor Accelerometer
sensor(#0) -1

09-17 20:18:50.415 V/SensorService( 1820): enable = -1 ==
SENSOR_DISABLE = -1

09-17 20:18:50.415 V/SensorService( 1820): enable = -1 !=
SENSOR_DISABLE = -1 || return of activate is not null

09-17 20:18:50.415 V/SensorService( 1820): minDelay2 = -1

09-17 20:18:50.415 V/SensorService( 1820): enable = -1 ==
SENSOR_DISABLE = -1

09-17 20:18:50.415 V/SensorService( 1820): deactivateIfUnused

09-17 20:18:50.415 V/SensorService( 1820): l.mSensors == 0

09-17 20:18:50.415 V/SensorService( 1820): minDelay = 1000

09-17 20:18:50.415 V/SensorService( 1820): listener,mDelay = 200

09-17 20:18:50.415 V/SensorService( 1820): call
_sensors_control_set_delay() when unregisterListener

09-17 20:18:50.435 V/MediaPlayer(12637): setListener

09-17 20:18:50.435 V/MediaPlayer(12637): disconnect

09-17 20:18:50.435 I/MediaPlayer(12637): is_music status Set
already : 0

09-17 20:18:50.435 V/MediaPlayerService( 1189): disconnect(178) from
pid 12637

09-17 20:18:50.445 V/MediaPlayer(12637): destructor

09-17 20:18:50.445 I/MediaPlayer(12637): is_music status Set
already : 0

09-17 20:18:50.445 V/MediaPlayer(12637): disconnect

09-17 20:18:50.445 I/MediaPlayer(12637): is_music status Set
already : 0

09-17 20:18:50.445 V/MediaPlayerService( 1189): Client(178) destructor
pid = 12637

09-17 20:18:50.445 V/AudioSink( 1189): close

09-17 20:18:50.445 V/MediaPlayerService( 1189): disconnect(178) from
pid 12637

09-17 20:18:50.475 V/MediaPlayer(12637): setListener

09-17 20:18:50.475 V/MediaPlayer(12637): disconnect

09-17 20:18:50.475 I/MediaPlayer(12637): is_music status Set
already : 0

09-17 20:18:50.475 V/MediaPlayerService( 1189): disconnect(179) from
pid 12637

09-17 20:18:50.475 V/MediaPlayer(12637): destructor

09-17 20:18:50.475 I/MediaPlayer(12637): is_music status Set
already : 0

09-17 20:18:50.475 V/MediaPlayer(12637): disconnect

09-17 20:18:50.475 I/MediaPlayer(12637): is_music status Set
already : 0

09-17 20:18:50.475 V/MediaPlayerService( 1189): Client(179) destructor
pid = 12637

09-17 20:18:50.485 V/AudioSink( 1189): close

09-17 20:18:50.485 V/MediaPlayerService( 1189): disconnect(179) from
pid 12637

09-17 20:18:50.485 D/camera (12637): onPause closeCamera

09-17 20:18:50.485 D/camera (12637): closeCamera CameraHolder release

09-17 20:18:50.485 D/CameraHolder(12637): release mUsers = 1

09-17 20:18:50.505 D/CameraService( 1189): stopPreview (pid 12637)

09-17 20:18:50.505 D/QualcommCameraHardware( 1189):
cancelAutoFocusInternal E

09-17 20:18:50.648 I/QualcommCameraHardware( 1189): deinitPreview E

09-17 20:18:50.648 I/QualcommCameraHardware( 1189): deinitPreview X

09-17 20:18:50.648 D/CameraService( 1189): stopPreview(), hardware
stopped OK

09-17 20:18:50.655 D/QualcommCameraHardware( 1189): frame_thread X

09-17 20:18:50.665 D/CameraHolder(12637): releaseCamera mUsers = 0

09-17 20:18:50.665 D/CameraHolder(12637): Actually releasing camera.
mUsers = 0

09-17 20:18:50.665 D/Camera-JNI(12637): release camera

09-17 20:18:50.665 D/CameraService( 1189): Client (0x2d780) E
disconnect from (12637)

09-17 20:18:50.665 D/CameraService( 1189): hardware teardown

09-17 20:18:50.665 D/QualcommCameraHardware( 1189): release E

09-17 20:18:50.715 D/QualcommCameraHardware( 1189): release X

09-17 20:18:50.715 D/QualcommCameraHardware( 1189):
~QualcommCameraHardware E

09-17 20:18:50.715 D/QualcommCameraHardware( 1189):
~QualcommCameraHardware X

09-17 20:18:50.715 D/CameraService( 1189): removeClient (pid 12637)
done

09-17 20:18:50.715 D/CameraService( 1189): Client::disconnect() X (pid
12637)

09-17 20:18:50.725 I/WindowManager( 1820): Setting rotation to 0,
animFlags=0

09-17 20:18:50.735 D/CameraService( 1189): Client::~Client E (pid
1189, client 0x2d780)

09-17 20:18:50.745 I/ISystemManager( 2414):
BnSystemManager::onTransact()

09-17 20:18:50.745 I/ISystemManager( 2414):
BnSystemManager::onTransact() done

09-17 20:18:50.755 D/WindowManager( 1820): ro.product.carrier=twn

09-17 20:18:50.775 D/CameraService( 1189): Client (0x2d780) E
disconnect from (1189)

09-17 20:18:50.775 D/CameraService( 1189): Client::~Client X (pid
1189)

09-17 20:18:50.785 D/WindowManager( 1820): ro.product.carrier=twn

09-17 20:18:50.795 I/ActivityManager( 1820): Config changed:
{ scale=1.0 imsi=310/260 loc=en_US dayNightMode=2 carrier=twn touch=3
keys=1/1/2 nav=2/1 orien=1 layout=18}

09-17 20:18:50.835 D/Proximity( 3941): upadteProximitySensorMode:
state = IDLE

09-17 20:18:50.965 W/PowerManagerService( 1820):
setScreenBrightnessMode: 1 , true

09-17 20:18:50.965 D/WindowManager( 1820): ro.product.carrier=twn

09-17 20:18:51.025 D/camera (12637): surfaceDestroyed

09-17 20:18:51.025 D/camera (12637): stopPreview

09-17 20:18:51.045 V/SystemSettingsObserver( 2101): ---- System
settings ----

09-17 20:18:51.055 V/SettingsObserver( 2101): Screen Timeout = 60000-
>60000

09-17 20:18:51.055 V/SettingsObserver( 2101): Screen Auto Brightness =
1->1

09-17 20:18:51.065 V/SettingsObserver( 2101): Screen Brightness = 105-
>105

09-17 20:18:51.065 V/SettingsObserver( 2101): Airplane Mode = 0->0

09-17 20:18:51.065 V/SettingsObserver( 2101): Data Connection = On->On

09-17 20:18:51.065 V/SystemSettingsObserver( 2101): ---- System
settings ----

09-17 20:18:51.295 D/camera (12637): Camera: onStop

09-17 20:18:51.295 D/camera (12637): onDestroy

09-17 20:18:51.525 D/TestEngineEventGenerator( 1820): sendEvent: Focus
Changed, [com.garmin.android.launcher/.Launcher, 1]

09-17 20:18:51.525 D/TestEngineEventGenerator( 1820): sending

09-17 20:18:51.555 I/TestEngine( 1894): [1;34m(info) [0mWaiting
for animation to complete

09-17 20:18:51.635 W/IInputConnectionWrapper(12637): showStatusIcon on
inactive InputConnection

09-17 20:18:51.655 I/ActivityManager( 1820): Start proc
com.android.music for broadcast
com.android.music/.MediaAppWidgetProvider: pid=12674 uid=10024
gids={3003, 1015}

09-17 20:18:52.051 D/TestEngineEventGenerator( 9903): sendEvent: Idle,
[4839]

09-17 20:18:52.051 D/TestEngineEventGenerator( 9903): sending

09-17 20:18:52.405 I/ActivityManager( 1820): Process
com.android.camera (pid 12637) has died.

09-17 20:18:53.075 I/TestEngine( 1894): [1;36m(action) [0mMade it
back to: 'com.android.launcher/.Launcher;1|
com.android.launcher/.Launcher;1|com.android.launcher/.Launcher;1'

09-17 20:18:53.605 I/TestEngine( 1894): [1;36m(action) [0mClicking
on 'Messaging' index 1 on activity 'com.android.launcher/.Launcher;1|
com.android.launcher/.Launcher;1|com.android.launcher/.Launcher;1'

09-17 20:18:53.625 D/dalvikvm( 1820): GC freed 4112 objects / 187856
bytes in 463ms

09-17 20:18:53.635 D/TestEngineEventGenerator( 9903): sendEvent: Idle,
[4840]

09-17 20:18:53.635 D/TestEngineEventGenerator( 9903): sending

09-17 20:18:55.015 D/dalvikvm( 1894): GC freed 8544 objects / 544528
bytes in 173ms

09-17 20:18:55.035 D/TestEngineEventGenerator( 1820): sendEvent:
Mouse, [120, 377, 1, com.android.launcher/.Launcher, 1, 1]

09-17 20:18:55.035 D/TestEngineEventGenerator( 1820): sending

09-17 20:18:55.055 I/TestEngine( 1894): [1;34m(info) [0mFound
Messaging at (120, 377)

09-17 20:18:55.125 D/Launcher( 9903): not in vehicle mount

09-17 20:18:55.135 I/ActivityManager( 1820): Starting activity: Intent
{ act=android.intent.action.MAIN
cat=[android.intent.category.LAUNCHER] flg=0x10200000
cmp=com.android.mms/.ui.ConversationList bnds=[83,338][157,417] }

09-17 20:18:55.185 D/WindowManager( 1820): ro.product.carrier=twn

09-17 20:18:55.715 D/TestEngineEventGenerator( 1820): sendEvent: Focus
Changed, [com.android.mms/.ui.ConversationList, 1]

09-17 20:18:55.715 D/TestEngineEventGenerator( 1820): sending

09-17 20:18:55.765 D/MORELOG (12568): calling endMmsConnectivity() in
processPendingTransaction()

09-17 20:18:55.805 D/ConnectivityService( 1820): ignoring
stopUsingNetworkFeature - not a live request

09-17 20:18:55.805 I/ActivityManager( 1820): Displayed activity
com.android.mms/.ui.ConversationList: 626 ms (total 626 ms)

09-17 20:18:56.735 D/TestEngineEventGenerator(12568): sendEvent: Idle,
[4841]

09-17 20:18:56.745 D/TestEngineEventGenerator(12568): sending

09-17 20:18:56.745 I/TestEngine( 1894): [1;36m(action) [0mClicking
on 'com.android.mms:id/button_new' index 1 on activity
'com.android.mms/.ui.ConversationList;1'

09-17 20:18:58.605 I/TestEngine( 1894): [1;34m(info) [0mFound
com.android.mms:id/button_new at (160, 71)

09-17 20:18:58.735 D/TestEngineEventGenerator( 1820): sendEvent:
Mouse, [160, 71, 1, com.android.mms/.ui.ConversationList, 1, 1]

09-17 20:18:58.735 D/TestEngineEventGenerator( 1820): sending

09-17 20:18:58.785 I/ActivityManager( 1820): Starting activity: Intent
{ cmp=com.android.mms/.ui.ComposeMessageActivity (has extras) }

09-17 20:18:58.805 D/WindowManager( 1820): ro.product.carrier=twn

09-17 20:18:59.095 D/dalvikvm(12568): GC freed 6008 objects / 402144
bytes in 130ms

09-17 20:18:59.275 D/KY_MMS (12568): Operator name:TWN

09-17 20:18:59.275 D/KY_MMS (12568): SMS Gateway=

09-17 20:18:59.555 V/BubbleEditText(12568): onSelectionChanged() -
selStart: 0 selEnd: 0

09-17 20:18:59.565 V/BubbleEditText(12568): onSelectionChanged() -
selStart: 0 selEnd: 0

09-17 20:18:59.565 V/BubbleEditText(12568): onSelectionChanged() -
selStart: 0 selEnd: 0

09-17 20:19:03.815 W/WindowManager( 1820): Key dispatching timed out
sending to <null>

09-17 20:19:03.825 W/WindowManager( 1820): Dispatch state:
{{KeyEvent{action=1 code=4 repeat=0 meta=0 scancode=0 mFlags=8} to
Window{2e8692d0 com.android.camera/com.android.camera.Camera
paused=false} @ 1284772730390 lw=Window{2e8692d0 com.android.camera/
com.android.camera.Camera paused=false}
lb=android.os.BinderProxy@2ea78708 fin=false gfw=true ed=true tts=0
wf=false fp=false mcf=null}}

09-17 20:19:03.825 I/WindowManager( 1820): focus null mToken is null
at event dispatch!

09-17 20:19:03.825 W/WindowManager( 1820): Current state: {{null to
null @ 1284772743831 lw=null lb=null fin=true gfw=true ed=true tts=0
wf=false fp=false mcf=null}}

09-17 20:19:03.975 D/dalvikvm(12682): GC freed 4532 objects / 373928
bytes in 415ms

09-17 20:19:04.085 I/ActivityManager( 1820): ANR in process:
com.android.mms (last in com.android.mms)

09-17 20:19:04.085 I/ActivityManager( 1820): Annotation:
keyDispatchingTimedOut

09-17 20:19:04.085 I/ActivityManager( 1820): CPU usage:

09-17 20:19:04.085 I/ActivityManager( 1820): Load: 8.4 / 8.13 / 7.87

09-17 20:19:04.085 I/ActivityManager( 1820): CPU usage from 8393ms to
240ms ago:

09-17 20:19:04.085 I/ActivityManager( 1820): procstat: 15% = 1% user
+ 14% kernel / faults: 2073 minor

09-17 20:19:04.085 I/ActivityManager( 1820): com.android.mms: 8% =
6% user + 1% kernel / faults: 2229 minor 51 major

09-17 20:19:04.085 I/ActivityManager( 1820): system_server: 4% = 2%
user + 2% kernel / faults: 462 minor

09-17 20:19:04.085 I/ActivityManager( 1820): adbd: 1% = 0% user + 0%
kernel

09-17 20:19:04.085 I/ActivityManager( 1820): ands.testengine: 1% =
0% user + 0% kernel / faults: 23 minor

09-17 20:19:04.085 I/ActivityManager( 1820): mmcqd: 0% = 0% user +
0% kernel

09-17 20:19:04.085 I/ActivityManager( 1820): kswapd0: 0% = 0% user +
0% kernel

09-17 20:19:04.085 I/ActivityManager( 1820): garminos: 0% = 0% user
+ 0% kernel / faults: 117 minor

09-17 20:19:04.085 I/ActivityManager( 1820): logdog: 0% = 0% user +
0% kernel / faults: 14 minor

09-17 20:19:04.085 I/ActivityManager( 1820): logcat: 0% = 0% user +
0% kernel / faults: 15 minor

09-17 20:19:04.085 I/ActivityManager( 1820): rpcrotuer_smd_x: 0% =
0% user + 0% kernel

09-17 20:19:04.085 I/ActivityManager( 1820): zygote: 0% = 0% user +
0% kernel / faults: 29 minor

09-17 20:19:04.085 I/ActivityManager( 1820): logcat: 0% = 0% user +
0% kernel / faults: 6 minor

09-17 20:19:04.085 I/ActivityManager( 1820): m.android.phone: 0% =
0% user + 0% kernel / faults: 49 minor

09-17 20:19:04.085 I/ActivityManager( 1820): +s.handset.email: 0% =
0% user + 0% kernel

09-17 20:19:04.085 I/ActivityManager( 1820): +sleep: 0% = 0% user +
0% kernel

09-17 20:19:04.085 I/ActivityManager( 1820): -sleep: 0% = 0% user +
0% kernel

09-17 20:19:04.085 I/ActivityManager( 1820): TOTAL: 81% = 16% user +
24% kernel + 40% iowait + 0% softirq

09-17 20:19:04.095 I/ActivityManager( 1820): Removing old ANR trace
file from /data/anr/traces.txt

09-17 20:19:04.115 I/Process ( 1820): Sending signal. PID: 12568 SIG:
3

09-17 20:19:04.115 I/dalvikvm(12568): threadid=7: reacting to signal 3

09-17 20:19:04.115 I/ActivityManager( 1820): Process com.android.music
(pid 12674) has died.

09-17 20:19:04.165 I/dalvikvm(12568): Wrote stack trace to '/data/anr/
traces.txt'

09-17 20:19:04.185 D/TestEngineEventGenerator( 1820): sendEvent: Focus
Changed, [com.android.mms/.ui.ComposeMessageActivity, 1]

09-17 20:19:04.185 D/TestEngineEventGenerator( 1820): sending

09-17 20:19:04.325 I/Process ( 1820): Sending signal. PID: 1820 SIG: 3

09-17 20:19:04.325 I/dalvikvm( 1820): threadid=7: reacting to signal 3

09-17 20:19:04.575 I/dalvikvm( 1820): Wrote stack trace to '/data/anr/
traces.txt'

09-17 20:19:04.575 I/Process ( 1820): Sending signal. PID: 12682 SIG:
3

09-17 20:19:04.575 I/dalvikvm(12682): threadid=7: reacting to signal 3

09-17 20:19:04.625 I/ActivityManager( 1820): Displayed activity
com.android.mms/.ui.ComposeMessageActivity: 5820 ms (total 5820 ms)

[Nick Smith]

Sorry I meant WindowManagerService instead of ActivityManagerService.

On Sep 22, 10:59 am, Nick Smith <nickp...@gmail.com> wrote:
> I've noticed that there is an bug reported for Android related to the
> key dispatching not finding the original window that the key press was

> triggered on (seehttp://code.google.com/p/android/issues/detail?id=5729).

[Ganesh Sonthi]

Hi Nick,

I am very sorry to interrupt you because i am not able to provide solution and instead asking u a query.

i am a started in this android. on seeing ur logs my basic understanding on seeing ur logs is u r sending key events to camera. Right?

if so can you please tell me how to send that events to camera. why because i have a test requirement to open camera and take picture using key/touch event. i already posted this in groups but no response.

if possible please help. Thanks in advance.

Sincerely!
- Ganesh SG,
Software Engineer - Testing
+91-9535635056

--
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]

During an app switch, the window manager pauses its event dispatching while it waits for the next application's window to attach to it.  A null target means it is waiting for a window to become available that can receive input.  This can just as well be due to an app actually not be responding, if it is being unresponsive at phases before its window is given to the window manager.

In a case of ANRs, the first thing to do should always be to do "adb shell cat /data/anr/traces.txt | more" to look at the stacks of the apps and see what they are doing.  Only if the apps aren't doing anything (sitting in the event loop waiting for a message) would you start to look for a platform bug.

--
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.

[Chuck Lega]

But what if the app in question does not have a window, e.g. a
broadcast receiver just starting a service? Where will the events go
then? Will we have an ANR?
/Chuck

On Sep 23, 9:53 am, Dianne Hackborn <hack...@android.com> wrote:
> During an app switch, the window manager pauses its event dispatching while
> it waits for the next application's window to attach to it.  A null target
> means it is waiting for a window to become available that can receive input.
>  This can just as well be due to an app actually not be responding, if it is
> being unresponsive at phases before its window is given to the window
> manager.
>
> In a case of ANRs, the first thing to do should always be to do "adb shell
> cat /data/anr/traces.txt | more" to look at the stacks of the apps and see
> what they are doing.  Only if the apps aren't doing anything (sitting in the
> event loop waiting for a message) would you start to look for a platform
> bug.
>

> On Wed, Sep 22, 2010 at 8:59 AM, Nick Smith <nickp...@gmail.com> wrote:
> > I've noticed that there is an bug reported for Android related to the
> > key dispatching not finding the original window that the key press was

> > triggered on (seehttp://code.google.com/p/android/issues/detail?id=5729).

> ...
>
> read more »

[Nick Smith]

Hi Dianne,

I can confirm that for these instances the ANR traces file is showing
the non-focused app for which the key event is associated to is
waiting on messages (see pid 2562 in snippet below). The focused and
currently viewed activity (see pid 22939 in snippet below) is doing
some work as you would expect. However, the key event causing the
timeout is not for this activity but the previous activity. In some
cases, I've seen the device go to another activity before the ANR
appears.

What other sorts of info could I examine to try and identify why this
is occurring?

Thanks,

Nick


NOTE: This is taken from a different example above but its logs
follows the same pattern.

//**********************************
// Log
//**********************************
09-22 08:00:42.818 W/WindowManager( 1273): Key dispatching timed out
sending to <null>
09-22 08:00:42.818 W/WindowManager( 1273): Dispatch state:
{{KeyEvent{action=0 code=4 repeat=0 meta=0 scancode=158 mFlags=72} to
Window{2eaafbb0 com.garmin.android.apps.navigation/
com.garmin.android.apps.navigation.map.NavigationMapActivity
paused=false} @ 1285160434257 lw=Window{2eaafbb0
com.garmin.android.apps.navigation/
com.garmin.android.apps.navigation.map.NavigationMapActivity
paused=false} lb=android.os.BinderProxy@2ea65ad8 fin=false gfw=true

ed=true tts=0 wf=false fp=false mcf=null}}

09-22 08:00:42.818 I/WindowManager( 1273): focus null mToken is null
at event dispatch!
09-22 08:00:42.828 W/WindowManager( 1273): Current state:
{{KeyEvent{action=1 code=4 repeat=0 meta=0 scancode=158 mFlags=72} to
null @ 1285160442827 lw=null lb=null fin=true gfw=true ed=true tts=0
wf=false fp=false mcf=null}}
09-22 08:00:42.908 I/ActivityManager( 1273): ANR in process:
android.process.acore (last in android.process.acore)
09-22 08:00:42.908 I/ActivityManager( 1273): Annotation:
keyDispatchingTimedOut

//**********************************
// ANR traces.txt
//**********************************

----- pid 22939 at 2010-09-22 08:00:44 -----
Cmd line: android.process.acore

DALVIK THREADS:
"main" prio=5 tid=3 NATIVE
| group="main" sCount=1 dsCount=0 s=N obj=0x2aaca4e8 self=0xc160
| sysTid=22939 nice=0 sched=0/0 cgrp=unknown handle=1877228228
at android.os.BinderProxy.transact(Native Method)
at
android.content.ContentProviderProxy.bulkQuery(ContentProviderNative.java:
358)
at
android.content.ContentProviderProxy.query(ContentProviderNative.java:
379)
at android.content.ContentResolver.query(ContentResolver.java:201)
at android.provider.Settings$NameValueCache.getString(Settings.java:
499)
at android.provider.Settings$System.getString(Settings.java:604)
at android.provider.Settings$System.getInt(Settings.java:653)
at
android.text.method.TextKeyListener.updatePrefs(TextKeyListener.java:
287)
at android.text.method.TextKeyListener.access
$200(TextKeyListener.java:37)
at android.text.method.TextKeyListener
$SettingsObserver.onChange(TextKeyListener.java:277)
at android.database.ContentObserver
$NotificationRunnable.run(ContentObserver.java:48)
at android.os.Handler.handleCallback(Handler.java:587)
at android.os.Handler.dispatchMessage(Handler.java:92)
at android.os.Looper.loop(Looper.java:123)
at android.app.ActivityThread.main(ActivityThread.java:4380)
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:860)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:618)
at dalvik.system.NativeStart.main(Native Method)
....
----- pid 2562 at 2010-09-22 08:00:54 -----
Cmd line: com.garmin.android.apps.navigation

DALVIK THREADS:
"main" prio=5 tid=3 TIMED_WAIT
| group="main" sCount=1 dsCount=0 s=Y obj=0x2aaca4e8 self=0xc160
| sysTid=2562 nice=0 sched=3/0 cgrp=unknown handle=1877228228
at java.lang.Object.wait(Native Method)
at java.lang.Object.wait(Object.java:326)
at android.os.MessageQueue.next(MessageQueue.java:144)
at android.os.Looper.loop(Looper.java:110)
at android.app.ActivityThread.main(ActivityThread.java:4380)
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:860)
at com.android.internal.os.ZygoteInit.main(ZygoteInit.java:618)
at dalvik.system.NativeStart.main(Native Method)

On Sep 23, 2:53 am, Dianne Hackborn <hack...@android.com> wrote:
> During an app switch, the window manager pauses its event dispatching while
> it waits for the next application's window to attach to it.  A null target
> means it is waiting for a window to become available that can receive input.
>  This can just as well be due to an app actually not be responding, if it is
> being unresponsive at phases before its window is given to the window
> manager.
>
> In a case of ANRs, the first thing to do should always be to do "adb shell
> cat /data/anr/traces.txt | more" to look at the stacks of the apps and see
> what they are doing.  Only if the apps aren't doing anything (sitting in the
> event loop waiting for a message) would you start to look for a platform
> bug.
>

> On Wed, Sep 22, 2010 at 8:59 AM, Nick Smith <nickp...@gmail.com> wrote:
> > I've noticed that there is an bug reported for Android related to the
> > key dispatching not finding the original window that the key press was

> > triggered on (seehttp://code.google.com/p/android/issues/detail?id=5729).

> ...
>
> read more »

[Dianne Hackborn]

On Thu, Sep 23, 2010 at 5:50 AM, Chuck Lega <chuck...@gmail.com> wrote:

But what if the app in question does not have a window, e.g. a
broadcast receiver just starting a service? Where will the events go
then? Will we have an ANR?
/Chuck

These are totally unrelated.  Key event ANRs are due to key event dispatching.  Broadcast ANRs are the activity manager waiting for a broadcast (and on user builds won't be shown to the user but just result in the app being killed).

There are no input events involved in broadcasts and services.  They have nothing to do with each other.  The only possible relation is if you spend a lot of time on the main thread of one of these and something else in your process is also showing a window and can't run because you have gotten the main thread doing something else.

[Dianne Hackborn]

On Thu, Sep 23, 2010 at 10:10 AM, Nick Smith <nick...@gmail.com> wrote:

I can confirm that for these instances the ANR traces file is showing
the non-focused app for which the key event is associated to is
waiting on messages (see pid 2562 in snippet below). The focused and
currently viewed activity (see pid 22939 in snippet below) is doing
some work as you would expect. However, the key event causing the
timeout is not for this activity but the previous activity.  In some
cases, I've seen the device go to another activity before the ANR
appears.

When you are in the middle of an app switch, you have two apps that could potentially ANR.  The platform arbitrarily picks one of them to report the ANR, but the problem could be in the other.  If you are seeing one of them busy doing stuff and not ready to handle messages, that is probably the problem.

[Nick Smith]

That makes sense for an app switch between activity A & B.

However, I don't think that makes sense for the situation that I
originally posted about. That situation is generating a key
dispatching ANR for a key event that occurred a couple activities ago.
See the sequence of events below where a BACK key press in the Camera
app is triggering the ANR 16 seconds after the device has displayed 2
other activities.

Why would that key event still be dispatched? It seems like it should
have already been processed since we already displayed a couple
activities.

Sequence of events from first post:

1. BACK key hit while on the Camera app

09-17 20:18:47.785 I/TestEngine( 1894): [1;36m(action) [0mPressing
key 'KEYCODE_BACK' on activity 'com.android.camera/.Camera;1'

2. Camera process died

09-17 20:18:52.405 I/ActivityManager( 1820): Process
com.android.camera (pid 12637) has died.

3. Launcher app displayed

09-17 20:18:53.075 I/TestEngine( 1894): [1;36m(action) [0mMade it
back to: 'com.android.launcher/.Launcher;1|
com.android.launcher/.Launcher;1|com.android.launcher/.Launcher;1'

4. Messaging app launched and displayed

09-17 20:18:55.805 I/ActivityManager( 1820): Displayed activity
com.android.mms/.ui.ConversationList: 626 ms (total 626 ms)

5. Compose new message started

09-17 20:18:58.785 I/ActivityManager( 1820): Starting activity: Intent
{ cmp=com.android.mms/.ui.ComposeMessageActivity (has extras) }

6. Key dispatching timeout triggered for the BACK key sent to the
Camera
09-17 20:19:03.815 W/WindowManager( 1820): Key dispatching timed out
sending to <null>
09-17 20:19:03.825 W/WindowManager( 1820): Dispatch state:

{{KeyEvent{action=1 code=4 repeat=0 meta=0 scancode=0 mFlags=8} to
Window{2e8692d0 com.android.camera/com.android.camera.Camera
paused=false} @ 1284772730390 lw=Window{2e8692d0 com.android.camera/
com.android.camera.Camera paused=false}

lb=android.os.BinderProxy@2ea78708 fin=false gfw=true ed=true tts=0
wf=false fp=false mcf=null}}

7. ANR generated for MMS

09-17 20:19:04.085 I/ActivityManager( 1820): ANR in process:
com.android.mms (last in com.android.mms)

On Sep 23, 5:35 pm, Dianne Hackborn <hack...@android.com> wrote:

> On Thu, Sep 23, 2010 at 10:10 AM, Nick Smith <nickp...@gmail.com> wrote:
> > I can confirm that for these instances the ANR traces file is showing
> > the non-focused app for which the key event is associated to is
> > waiting on messages (see pid 2562 in snippet below). The focused and
> > currently viewed activity (see pid 22939 in snippet below) is doing
> > some work as you would expect. However, the key event causing the
> > timeout is not for this activity but the previous activity.  In some
> > cases, I've seen the device go to another activity before the ANR
> > appears.
>
> When you are in the middle of an app switch, you have two apps that could
> potentially ANR.  The platform arbitrarily picks one of them to report the
> ANR, but the problem could be in the other.  If you are seeing one of them
> busy doing stuff and not ready to handle messages, that is probably the
> problem.
>
> --
> Dianne Hackborn
> Android framework engineer

> hack...@android.com

[Dianne Hackborn]

Hm, what you quote makes no sense.  If events have been processed after that, there is no ANR that can happen for the previous app (let alone that the process crashing will clear any dispatching state associated with it).

If you have steps to repro, it would be interesting to look at.  OTOH the entire event dispatching code is being significantly redone so this would mostly be to verify that the problem doesn't happen in the new code.

--
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

[Christopher Tate]

Nick, you're using Eclair, right? I believe Froyo has a few scattered
fixes to the event dispatch and ANR logic relative to Eclair. It is
not impossible that you're seeing a bona fide bug.

--
chris

[Nick Smith]

@Chris - Yes, I'm seeing this on Eclair. I can see if pulling in some
of the event dispatch and ANR logic fixes from Froyo do anything to
help.

@Dianne - I don't really have good steps to reproduce but we usually
see this when doing automated tests that stress the device. If I can
isolate the steps to reproduce, I'll let you know so you can test on
the new code. Unfortunately, our automated tests are using a custom
test engine that injects events so I really cannot give you the exact
scripts that we are running since they would only work on our
devices. I can also see if we can get some logs with all the
debugging flags enabled in the WindowManagerService if that would
help.

On Sep 24, 3:24 pm, Christopher Tate <ct...@google.com> wrote:
> Nick, you're using Eclair, right?  I believe Froyo has a few scattered
> fixes to the event dispatch and ANR logic relative to Eclair.  It is
> not impossible that you're seeing a bona fide bug.
>
> --
> chris
>
>
>
> On Fri, Sep 24, 2010 at 1:18 PM, Dianne Hackborn <hack...@android.com> wrote:
> > Hm, what you quote makes no sense.  If events have been processed after
> > that, there is no ANR that can happen for the previous app (let alone that
> > the process crashing will clear any dispatching state associated with it).
> > If you have steps to repro, it would be interesting to look at.  OTOH the
> > entire event dispatching code is being significantly redone so this would
> > mostly be to verify that the problem doesn't happen in the new code.
>

[Dianne Hackborn]

On Fri, Sep 24, 2010 at 9:56 PM, Nick Smith <nick...@gmail.com> wrote:

I can also see if we can get some logs with all the
debugging flags enabled in the WindowManagerService if that would
help.

I probably won't be able to spend time digging through logs.  Even if this is reproducible on the current release, as I said the event dispatching code is going through some significant rework so whatever is found there would not be applicable to later versions of the platform.

--
Dianne Hackborn
Android framework engineer

hac...@android.com