738619 - SDK1.4.2 or higher data.load causing addon not receive key events during local file load

Status: RESOLVED INCOMPLETE

(Add-on SDK Graveyard :: General, defect, P2)

Description

[Mingyi Liu]

Attachment: FastestSearch.zip

User Agent: Mozilla/5.0 (Windows NT 6.1; WOW64; rv:13.0) Gecko/20120322 Firefox/13.0a2
Build ID: 20120322042009

Steps to reproduce:

My addon Fastest Search allows user to do Find-as-you-type text search on webpage (it allows regular expression/whole-word/all-tabs search, if you wonder why not use Firefox's own FAYT). It works fine in all FF versions including FF13.0a2 when packed with SDK 1.3 or lower.  But not so when packed with SDK1.5 or 1.6rc1.  Using the attached zip file which contains the exact same version of FS packed with SDK1.3 or SDK1.5:

Unpacked thee zip file and install the addon, then click on addon icon, then click on 'Text Search Settings'. Check 'Find-as-you-type on page'.
Now go to http://news.google.com, type 'new' relatively fast (how a programmer usually types) on a normal powered machine (first-gen i7 or lower).


Actual results:

In SDK1.5 packed addon, most of the time one only see 'n' got typed, the 'ew' both went missing as my addon did not receive those key events during the computationally intensive text search.
In SDK1.3 packed addon, the entire word 'new' always got received and text search properly done, even if user has a slow machine and text search returns slow.


Expected results:

When user typed 'new', my addon should've been notified of all 3 characters, 'n', 'e', 'w'. SDK1.3 or lower had no bug like SDK1.5. I tested SDK1.6rc1, same issue with SDK1.5.

Comment 1

[Irakli Gozalishvili [:irakli] [:gozala] [@gozala]]

Hi Mingyi,

I have tried to reproduce the bug with the an addo-on attached by you. I don't know if my machine is too fast or I'm too slow but I have not managed to reproduce issue you report. Every now and then I see delays in key reports but they are in fact reported.

Also I have noticed following errors in the console:
Error: uncaught exception: TypeError: allBoxes[idx] is undefined
Error: uncaught exception: TypeError: iv.ub is null

Which makes me believe that you may have some exceptions that prevent your addon to process same keystrokes.

Finally it looks like you don't even use our shortcut API, but register key event handlers on all chrome window documents manually, so if my understanding of your code is correct and even if some key events get lost that would be a bug in platform component rather than SDK bug.

Either way providing some reduced test case would help a lot, your add-on code is huge and it's not easy to figure out what's going on there.

Comment 2

[Mingyi Liu]

Thanks for testing out!  The allBoxes[idx] exception was sth. I introduced in this unreleased FS version.  iv.ub is a long standing issue that ONLY happens if the user opens error console (FS will try to set a few important variables at the time but error console is a special window that causes some code to fail). Since it never happens elsewhere and is not harmful at all, I did not bother to fix this one for a while.

Regardless my unreleased v2.10 is pretty bug free and extensively tested in FF13a2 (none of the above errors or any error show), and I still could very faithfully reproduce this issue.

I just realized that I forgot to mention in this report that to fend off this problem, I set the minimum length for FAYT to 2, which means FAYT does not start until you typed at least 2 characters. In this case, indeed this performance issue does not happen much.  If you left click on FS icon, click on the "Text Search Settings" and then set "Minimum keyword length for FAYT" to 1, I believe you should easily see the performance issue.

Indeed FS is handling text-search all by itself using almost just platform APIs, so this looks like a platform issue. But, as I said, SDK 1.3 or lower were fine with ANY FF version, which means it's directly related to SDK.

My code in FS is very large (it contains features that amount to more than the addition of several popular/featured FF addons) and semi-intentionally disorganized.  I'll try to reduce to only the needed part to make a test addon for this issue.  Thank you so much for your effort to work on it despite the difficulty!

Comment 3

[Irakli Gozalishvili [:irakli] [:gozala] [@gozala]]

Hi Mingyi,

Unless you're planning to provide a reduced test case I'd like to close this bug, as I can't reproduce neither we got any complains from anyone else, to say nothing that you don't even use our APIs to do any of this.

Comment 4

[Mingyi Liu]

Yes I do plan to provide a reduced test case, as this issue is rather bothering for any Find-as-you-type users.  I just didn't have time to do that yet.

As I said, indeed there's barely any use of SDK APIs for this functionality in my addon, but my addon packed with lower SDK version worked just fine using the same addon code, the same FF version. So there's some interaction of newer SDK + FF that led to this issue.

I estimate that it'll take me a week or so to have enough time to work out a much reduced version as test case. You can decide if you want to close this bug and I open a new one when I got the test case, or wait for a few days till I create the test version.  Thanks either way!

Comment 5

[Mingyi Liu]

I just did a profiling and found that the performance of the findAllNodes function of mine was significantly impacted by the SDK version, despite that the function was merely using snapshotItem iterating over an Xpath query, as well as using general dom/array methods and object access.  The rough timing was for a medium sized page with multiple iframes, the function used (when it's packed with the indicated SDK version):
When it's packed with SDK 1.2.1: ~138 ms
SDK 1.3: ~147 ms
SDK 1.4.2: 167-294 ms (this as I just found is the first version where my addon starts to fail to receive key events, thus missing keys in searching). Surprisingly, this SDK is the only one with rather inconsistent speed b/w runs, and even when it finishes run in 167 ms, which is hardly different than 147 ms, the key events were missing.
SDK 1.5: ~210 ms
SDK 1.6.1: ~210 ms

I wonder if SDK placed some hooks or changed prototypes of some internal functions? Clearly it's affecting the performance of the native client (FF) depending on the SDK version.

I will continue to work on an abridged version that helps debug. Right now the performance issue described here is not necessarily the reason for key events went missing. It only means that SDK does change the native client's performance, even when code doesn't use SDK's API.

Comment 6

[Mingyi Liu]

Attachment: Zip file containing SDK 1.6.1- or 1.3-packed test addons

I reduced Fastest Search to close to minimum to demo a working Find-as-you-type feature (code is 1/5 of previous code). Then I packed the new code with either 1.6.1 or 1.3, and the performance (or rather key-event-lost) issue was very clear with the 1.6.1 while non-existent with 1.3.

Comment 7

[Mingyi Liu]

BTW to test it, just install 1.6.1 version, go to news.google.com, try type 'new' really fast. Most likely you'll see 'nw' searched, and in the console message (use console2 to view chrome messages), you see that ONLY 'n' and 'w' was registered for the keypress event.  Now install the SDK 1.3-packed version, type as fast as you want, you ALWAYS see 'new' searched, and 'n', 'e', 'w' reported in the console.

BTW, after each search you can press 'esc' key to get rid of the search result display.

Interestingly, performance might not be related, as I suggested above. But rather, sth. else in SDK caused the events go missing. Sometimes the SDK1.3-packed version ran slower in some tests, but still it just doesn't miss key events. SDK 1.6.1 packed would miss events whenever you type really fast.

If you can't reproduce the issue, you might have a too-fast computer, so either try type REALLY fast, or go to a bigger (and as complex) page than news.google.com and test it out. I reproduced in on Win7, WinXP, Linux, fast and slow computers. You should be able to reproduce it as long as you type really fast.

BTW this version I included is the minimum, with less than 1/5 of the original code. Only the code needed for the find-as-you-type remain. I know it's still quite some code - if it was easy there has to be other regex- AND fayt-supporting addons already!

This new test case addon's code manageable as some codes are needed for addon start up/clean up, some code for displaying search results, some codes actually running the search.  There's no way to reduce it further without running into the risk that it's not a complete test case and might not reproduce the issue.

Please take a look and thanks for your efforts!

Comment 8

[Mingyi Liu]

Eureka! I decided to take some more time to track it down, and found the culprit! It's the data.load function in SDK 1.4.2+ that hung the key events, causing my addon to not receive all the keypress events.
 
By comparing the self-maker.js in v1.3 vs. self!.js in v1.4.2, I found that in v1.3, data.load was using file.read, while data.load in v1.4.2 use synchronous XMLHttpRequest.  From v1.4.2 to v1.6.1, data.load no longer changed, and the problem persisted through these versions.

So it's now as clear as day and night - the data.load change in v1.4.2 caused keypress events to be dropped. Unless there's a really good reason to use the synchronous XMLHttpRequest I'd suggest a reverse of the code.  For now, I'll just switch from data.load to file.read myself to fix this issue in my own addon.

I'll try to work out a full example that has maybe only 100 lines or so for you to debug.

Comment 9

[Mingyi Liu]

Two things: 

1. My diagnose above stands, and my solution worked. I changed to use file.read, and the keypress event not received issue in FS packed with SDK1.6.1 is gone! Not seen ever again, however fast I type, however big the page is.
2. I was not able to reproduce a really simple example. A simple combination of keypress, data.load and a computation intensive simple loop failed to reproduce this issue. Maybe that's why this issue wasn't discovered before.  Despite the new data.load performance (or responsiveness?) issue, it probably take some other computationally intensive tasks to expose this issue. My FAYT feature uses xpath, snapshot loops and other dom functions a lot, and the combination of these intensive tasks and keypress and data.load exposed data.load's issue.

To confirm what I said, simply first reproduce the missing key events issue. I don't know why your computer failed to reproduce this, but try using WindowsXP or Win7, Firefox 11 to 13. Then just change the line:
var tmps = dataLoad("find.css");
to sth. like
var tmps = '';
or more properly, based on SDK1.3 code change it to:
var tmps = file.read(url.toFilename(data.url("find.css")));

voila, the keypress dropping problem is gone and everything works well!

Comment 10

[Jeff Griffiths (:canuckistani) (:⚡︎)]

Mingyi: that's awesome - we really appreciate your tenacity in hunting these bugs down!

Comment 11

[Mingyi Liu]

Sure, my pleasure too.

I just want to note that given this problem, this real issue is actually platform code it seems, where the synchronous nsIXMLHttpRequest hangs browser event dispatching during intensive DOM access.  As long as SDK reverts back to file.read, there's no need to worry about this from SDK side.  Maybe this thread should be moved to platform bug side?

For the platform developers to debug easily, I've made a 152-line version that is close to the bare minimum to demo this bug. It should be helpful for them to debug the issue, if needed.

Comment 12

[Mingyi Liu]

Attachment: SDK1.6.1-packed test case for platform developers to debug the issue

To see this issue where synchronous nsIXMLHttpRequest followed by heavy dom access (like in the findAllNodes in the attachment) would cause keypress event(s) to get lost - event handler does not receive the event at all sometimes): 

Install the attached addon, go to news.google.com, try type 'new' really fast. In the console message (use console2 to view chrome messages), you see that ONLY 'n' and 'w' was registered for the keypress event, or if you type really fast, you only see 'n'.  The other keypress event(s) were lost.

As I reported, this issue requires the use of synchronous nsIXMLHttpRequest, the keypress event handler (maybe other key handler demos the issue too but I didn't check) and a heavy DOM access function to show up. I tried using a simple loop with Math.log calls to replace findAllNodes function in attached code, but the issue does not show up even if the loop takes more time than findAllNodes.  There might be some really intensive/hanging code in the dom access/xpath functions used in findAllNodes too.  Either way the issue's on the platform code. Hopefully it could be tracked down.  Thanks!

Comment 13

[Irakli Gozalishvili [:irakli] [:gozala] [@gozala]]

Hi Mingyi,

Thanks for tracking this bug down. The fact that sync XHR causes it makes sense as I believe parallel event loop is spawned in such cases to avoid blocking a main one. As a matter of fact we were planning to switch to non XHR reading so this will fix that.

Now that being said, it feels to me that you're abusing data.load it would be for the best if you've minimized cases where you do blocking IO reads. It's specially not a good idea to do it during intensive tasks. Can't you cache read results or do async reads ?

As of platform bug, please create one.

Thanks!

Comment 14

[Mingyi Liu]

Had I known that reading a 2kb local file sync-ly would be a problem, I would've tried the workaround you suggested. But both workarounds have minor issues (cache being basically barring power users to alter the css file manually while addon's running; async has a theoretical risk of showing results with a weird color until the css file is loaded) so naturally they were not my first choice.

BTW, my code wasn't doing file read DURING intensive task. The sync-ed small file read happens BEFORE the data-intensive task. If it was truly sync, it wouldn't be an issue at all. The fact that file.read worked fine proves my point.

Comment 15

[Irakli Gozalishvili [:irakli] [:gozala] [@gozala]]

One Bug 748086 lands, we'll fix this by using common `readURI` function that won't use sync XHR.

Comment 16

[Erik Vold [:erikvold] (please needinfo? me)]

Hey Irakli, are you working on this one? if not could you please unassign yourself.

Comment 17

[Firefox Bug Husbandry Bot]

https://bugzilla.mozilla.org/show_bug.cgi?id=1399562