715009 - Typing in Google search field is hideously slow

Status: RESOLVED DUPLICATE of bug 713282

(Firefox for Android Graveyard :: General, defect)

Description

[Kartikaya Gupta (email:[e-mail])]

Attachment: logcat

Ehsan had a device on which trying to type in the Google search field on google.ca was hideously slow - it would take several seconds for each character to register. Fennec also crashed after a couple of minutes of entering text. I grabbed logcat output which has multiple suspicious things in it. Specifically, there are a lot of these InputConnectionWrapper timeouts:

W/InputConnectionWrapper.ICC(  293): Timed out waiting on IInputContextCallback
D/LatinIME(  293): mLongPressDelay = 400
D/dalvikvm( 4936): GC_EXPLICIT freed 204K, 47% free 3342K/6279K, external 1971K/6020K, paused 25ms
I/InputConnectionWrapper.ICC(  293): Got out-of-sequence callback 857 (expected 858) in setExtractedText, ignoring.
D/dalvikvm( 4949): GC_EXPLICIT freed 283K, 50% free 3078K/6087K, external 0K/0K, paused 18ms
W/InputConnectionWrapper.ICC(  293): Timed out waiting on IInputContextCallback
D/LatinKeyboardBaseView(  293): mLongPressDelay = 400
D/PointerTracker(  293): mLongPressKeyTimeout = 400

There's also a lot of exceptions being reported from Sync:

E/GeckoConsole( 4936): 1325633907185    Sync.Engine.History WARN    Failed to reconcile incoming record i1Jqv91IpQHj
E/GeckoConsole( 4936): 1325633907186    Sync.Engine.History WARN    Encountered exception: PlacesUtils.history is undefined JS Stack trace: ("SELECT url, title, frecency FROM moz_places WHERE guid = :guid")@history.js:116 < ()@history.js:177 < HistStore__findURLByGUID("i1Jqv91IpQHj")@history.js:201 < HistStore_itemExists("i1Jqv91IpQHj")@history.js:366 < SyncEngine__reconcile([object Object])@engines.js:1081 < ([object Object])@engines.js:884 < ()@record.js:834 < Channel_onDataAvail([object XPCWrappedNative_NoHelper],null,[object XPCWrappedNative_NoHelper],0,24365)@resource.js:579

but that may be unrelated to this issue. Finally, when Fennec dies due to ANR, the following is dumped to the log:

E/ActivityManager(  205): ANR in org.mozilla.fennec (org.mozilla.fennec/.App)
E/ActivityManager(  205): Reason: keyDispatchingTimedOut
E/ActivityManager(  205): Load: 4.29 / 3.9 / 2.82
E/ActivityManager(  205): CPU usage from 7653ms to 0ms ago:
E/ActivityManager(  205):   73% 4949/com.android.browser: 64% user + 9.3% kernel / faults: 1709 minor 1 major
E/ActivityManager(  205):   13% 4936/org.mozilla.fennec: 7.4% user + 5.7% kernel / faults: 34137 minor 3 major
E/ActivityManager(  205):   5.7% 17/kswapd0: 0% user + 5.7% kernel
E/ActivityManager(  205):   5.3% 205/system_server: 3.9% user + 1.3% kernel / faults: 130 minor
E/ActivityManager(  205):   2.3% 103/yaffs-bg-1: 0% user + 2.3% kernel
E/ActivityManager(  205):   0.4% 3032/com.android.systemui: 0.2% user + 0.1% kernel / faults: 6 minor
E/ActivityManager(  205):   0% 9/sync_supers: 0% user + 0% kernel
E/ActivityManager(  205):   0.1% 31/vsync_workqueue: 0% user + 0.1% kernel
E/ActivityManager(  205):   0% 54/gp2a_wq: 0% user + 0% kernel
E/ActivityManager(  205):   0.1% 131/pvr_workqueue: 0% user + 0.1% kernel
E/ActivityManager(  205): 99% TOTAL: 74% user + 24% kernel + 0.1% softirq
E/ActivityManager(  205): CPU usage from 621ms to 1148ms later:
E/ActivityManager(  205):   78% 4949/com.android.browser: 69% user + 9.6% kernel / faults: 135 minor
E/ActivityManager(  205):     17% 4985/Binder Thread #: 17% user + 0% kernel
E/ActivityManager(  205):     17% 5024/Binder Thread #: 15% user + 1.9% kernel
E/ActivityManager(  205):     15% 4960/Binder Thread #: 13% user + 1.9% kernel
E/ActivityManager(  205):     13% 4967/Binder Thread #: 11% user + 1.9% kernel
E/ActivityManager(  205):     3.8% 4959/Binder Thread #: 3.8% user + 0% kernel
E/ActivityManager(  205):     3.8% 4968/Binder Thread #: 0% user + 3.8% kernel
E/ActivityManager(  205):     3.8% 4969/Binder Thread #: 1.9% user + 1.9% kernel
E/ActivityManager(  205):     1.9% 4971/Binder Thread #: 1.9% user + 0% kernel
E/ActivityManager(  205):     1.9% 4980/Binder Thread #: 0% user + 1.9% kernel
E/ActivityManager(  205):     1.9% 5146/Binder Thread #: 1.9% user + 0% kernel
E/ActivityManager(  205):   9.6% 4936/org.mozilla.fennec: 3.2% user + 6.4% kernel / faults: 2062 minor
E/ActivityManager(  205):     4.8% 4946/Thread-12: 1.6% user + 3.2% kernel
E/ActivityManager(  205):     3.2% 4947/Thread-13: 3.2% user + 0% kernel
E/ActivityManager(  205):     1.6% 4936/.mozilla.fennec: 1.6% user + 0% kernel
E/ActivityManager(  205):     1.6% 4987/Binder Thread #: 1.6% user + 0% kernel
E/ActivityManager(  205):   5.6% 205/system_server: 1.8% user + 3.7% kernel / faults: 4 minor
E/ActivityManager(  205):     1.8% 212/Binder Thread #: 1.8% user + 0% kernel
E/ActivityManager(  205):     1.8% 240/InputDispatcher: 0% user + 1.8% kernel
E/ActivityManager(  205):     1.8% 320/Binder Thread #: 0% user + 1.8% kernel
E/ActivityManager(  205):     1.8% 3513/Binder Thread #: 1.8% user + 0% kernel
E/ActivityManager(  205):   2.8% 103/yaffs-bg-1: 0% user + 2.8% kernel
E/ActivityManager(  205): 100% TOTAL: 78% user + 21% kernel

which indicates the stock browser is chewing up a lot of CPU, possibly causing the keyDispatchingTimedOut.

Full logs attached.

Comment 1

[Kartikaya Gupta (email:[e-mail])]

Attachment: device system log (under /dev/log/system)

Comment 2

[Alex Pakhotin (:alexp)]

It looks like just a general system slowdown, not really related to text input. ANR with keyDispatchingTimedOut Reason is a usual visible outcome in such situation - that "reason" is more like a consequence.
According to the logs, the ANR happens in different places - the first one was while browsing (typing in Google?), the second one was in AwesomeBar, which text input implementation is completely different (that's a standard Android edit box).

Were there any CPU-intensive tasks running at that time? Was the Sync working? Not sure about the current implementation, but previously Sync caused major slowdowns.

Comment 3

[(no longer active)]

I can almost always reproduce this, with no unusual background app running.

Comment 4

[Alex Pakhotin (:alexp)]

(In reply to Ehsan Akhgari [:ehsan] from comment #3)
> I can almost always reproduce this, with no unusual background app running.

Is Fennec that slow on anything else, or is it just typing? If it's a slow typing, is that only on Google, or in any edit box on any page like this one: http://people.mozilla.org/~alexp/test/edit.htm?

Comment 5

[(no longer active)]

Almost all of the UI operations are slow.  The only things which are fast are panning and zooming, except for the fact that panning quickly leaves a checkerboard on part of the screen for 2-3 seconds.  Typing on various websites is slow.  This had practically prevented me from dogfooding Fennec in the past few weeks.

Comment 6

[Kartikaya Gupta (email:[e-mail])]

Adding mbrubeck to CC list; on IRC he mentioned seeing similar behaviour on a recent nightly and speculated it might be profile migrator-related.

Comment 7

[Aaron Train [:aaronmt]]

See also bug 713851 where I am also experiencing a poor input experience.

Comment 8

[Gian-Carlo Pascutto [:gcp]]

Does clearing the data in the Android application menu (i.e. clearing the profile) make the problem disappear?

Comment 9

[Gian-Carlo Pascutto [:gcp]]

Even better (and less destructive), can you go to

/mnt/sdcard/Android/data/org.mozilla.fennec/files/mozilla/8dvuhniv.default/places.sqlite

and temporarily move that file out of the way, and see it it fixes things? You might need root for that.

Comment 10

[(no longer active)]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #8)
> Does clearing the data in the Android application menu (i.e. clearing the
> profile) make the problem disappear?

Yes, it did.  Still I get very poor performance in the awesomebar.

Comment 11

[Gian-Carlo Pascutto [:gcp]]

>Yes, it did.  Still I get very poor performance in the awesomebar.

The title of this bug is "Typing in Google search field is hideously slow". If this is fixed by removing places, this bug is a duplicate of bug 713282. If it's not fixed, Profile Migrator has nothing to do with it and the cause is something else.

Comment 12

[(no longer active)]

(In reply to Gian-Carlo Pascutto (:gcp) from comment #11)
> >Yes, it did.  Still I get very poor performance in the awesomebar.
> 
> The title of this bug is "Typing in Google search field is hideously slow".
> If this is fixed by removing places, this bug is a duplicate of bug 713282.
> If it's not fixed, Profile Migrator has nothing to do with it and the cause
> is something else.

The problem that I told kats about was fennec being slow.  This was just one piece.  I filed bug 715264 about the awesomebar piece.  Should I file individual bugs about the rest as well?

Comment 13

[Gian-Carlo Pascutto [:gcp]]

>Should I file individual bugs about the rest as well?

If there's areas where it's still unacceptably slow and that aren't obviously related to 713282 or 715264, sure. There appear to be multiple causes, let's try to slice them off into separate bugs if we can.