Closed Bug 1349632 Opened 8 years ago Closed 8 years ago

If Edge is running, importing bookmarks from Edge hangs the mainthread for 10 or 20 seconds (10 seconds for each time we try to talk to the Edge database)

Categories

(Firefox :: Migration, defect)

45 Branch
All
Windows 10
defect
Not set
normal

Tracking

()

VERIFIED FIXED
Firefox 55
Tracking Status
firefox53 --- verified
firefox54 --- verified
firefox55 --- verified

People

(Reporter: Gijs, Assigned: Gijs)

References

Details

Attachments

(1 file)

+++ This bug was initially created as a clone of Bug #1344644 +++ In bug 1344644 we fixed the hang that shows up when trying to get the import wizard to show up... by not talking to the Edge database when opening the wizard. That's nice. But we will still try to talk to that database if we actually try to import from Edge, and the results are craptastic. Observe: https://mzl.la/2mtpREK Those beautiful peaks are at 10 and 20s, respectively, because in some cases we'll try to read readinglist information too. Every call to JetGetDatabaseFileInfoW takes a full 10 seconds to return. And no, there's no documentation about this on https://msdn.microsoft.com/en-us/library/gg269239(v=exchg.10).aspx or anywhere else I've been able to find. It seems we can detect whether this is going to happen (and avoid the 10s mainthread hang...) by trying to just open the file with exclusive read access before trying to use the ESE APIs. I'm working on a patch right now.
Assignee: nobody → gijskruitbosch+bugs
Status: NEW → ASSIGNED
This is relatively easy to fix so we should probably uplift however far we can.
Summary: If Edge is running, importing bookmarks from Edge hangs for 20 seconds (10 seconds for each time we try to talk to the Edge database) → If Edge is running, importing bookmarks from Edge hangs the mainthread for 10 or 20 seconds (10 seconds for each time we try to talk to the Edge database)
Just to get this straight, we're currently failing after 10 seconds if Edge is running, we don't end up importing stuff?
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to Dão Gottwald [::dao] from comment #3) > Just to get this straight, we're currently failing after 10 seconds if Edge > is running, we don't end up importing stuff? Yes, the JetGetDatabaseFileInfoW call does return an error (-1032, the one I added a description for in the patch) but it takes 10 seconds to do so. We're just wasting time because that API is apparently particularly... unusable?
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to :Gijs from comment #4) > (In reply to Dão Gottwald [::dao] from comment #3) > > Just to get this straight, we're currently failing after 10 seconds if Edge > > is running, we don't end up importing stuff? > > Yes, the JetGetDatabaseFileInfoW call does return an error (-1032, the one I > added a description for in the patch) but it takes 10 seconds to do so. > We're just wasting time because that API is apparently particularly... > unusable? So, to be completely clear, this throws after a 10s hang: https://dxr.mozilla.org/mozilla-central/rev/05bfa2831c0ba4a26fa72328ffe6a99aba9c356a/browser/components/migration/ESEDBReader.jsm#272-273 which we catch, log and rethrow here: https://dxr.mozilla.org/mozilla-central/rev/05bfa2831c0ba4a26fa72328ffe6a99aba9c356a/browser/components/migration/ESEDBReader.jsm#308-314 which means _init for the ESEDB instance fails: https://dxr.mozilla.org/mozilla-central/rev/05bfa2831c0ba4a26fa72328ffe6a99aba9c356a/browser/components/migration/ESEDBReader.jsm#261-267 which means the constructor fails, which means the ESEDBReader.openDB call throws: https://dxr.mozilla.org/mozilla-central/rev/05bfa2831c0ba4a26fa72328ffe6a99aba9c356a/browser/components/migration/ESEDBReader.jsm#579-581 which means we catch and rethrow here: https://dxr.mozilla.org/mozilla-central/rev/05bfa2831c0ba4a26fa72328ffe6a99aba9c356a/browser/components/migration/EdgeProfileMigrator.js#70 which will eventually reach the point where we will call the callback migrate() with `false` for aSuccess.
Comment on attachment 8850120 [details] Bug 1349632 - fix hangs when trying to import bookmarks from Edge, https://reviewboard.mozilla.org/r/122814/#review125322 ::: browser/components/migration/ESEDBReader.jsm:587 (Diff revision 1) > // ESE is really picky about the trailing slashes according to the docs, > // so we do as we're told and ensure those are there: > return new ESEDB(rootDir.path + "\\", dbFilePath, logDir.path + "\\"); > }, > > + async dbAvailable(dbFile) { nit: Rename to dbLocked since that's how you describe it in our error messages? ::: browser/components/migration/ESEDBReader.jsm:590 (Diff revision 1) > }, > > + async dbAvailable(dbFile) { > + let options = {winShare: OS.Constants.Win.FILE_SHARE_READ}; > + let available = false; > + await OS.File.open(dbFile.path, {read: true}, options).then(openFile => { nit: openFile reads a bit weird, it sounds like the name of a function. Could just say file, or maybe openedFile or fileHandle to differentiate it from dbFile. ::: browser/components/migration/ESEDBReader.jsm:592 (Diff revision 1) > + async dbAvailable(dbFile) { > + let options = {winShare: OS.Constants.Win.FILE_SHARE_READ}; > + let available = false; > + await OS.File.open(dbFile.path, {read: true}, options).then(openFile => { > + available = true; > + // Return the close promise so we wait for the file to be closed again. Why do we need to wait for the file to be closed again?
Attachment #8850120 - Flags: review?(dao+bmo) → review+
(In reply to Dão Gottwald [::dao] from comment #6) > ::: browser/components/migration/ESEDBReader.jsm:592 > (Diff revision 1) > > + async dbAvailable(dbFile) { > > + let options = {winShare: OS.Constants.Win.FILE_SHARE_READ}; > > + let available = false; > > + await OS.File.open(dbFile.path, {read: true}, options).then(openFile => { > > + available = true; > > + // Return the close promise so we wait for the file to be closed again. > > Why do we need to wait for the file to be closed again? Because we've just opened it with exclusive access and won't be able to use the DB APIs to access it until we've closed it again - at least, that's what I expected...
(In reply to :Gijs from comment #7) > (In reply to Dão Gottwald [::dao] from comment #6) > > ::: browser/components/migration/ESEDBReader.jsm:592 > > (Diff revision 1) > > > + async dbAvailable(dbFile) { > > > + let options = {winShare: OS.Constants.Win.FILE_SHARE_READ}; > > > + let available = false; > > > + await OS.File.open(dbFile.path, {read: true}, options).then(openFile => { > > > + available = true; > > > + // Return the close promise so we wait for the file to be closed again. > > > > Why do we need to wait for the file to be closed again? > > Because we've just opened it with exclusive access and won't be able to use > the DB APIs to access it until we've closed it again - at least, that's what > I expected... Okay.
Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/fff5c87922e6 fix hangs when trying to import bookmarks from Edge, r=dao
Backed out for failing xpcshell test test_Edge_db_migration.js: https://hg.mozilla.org/integration/autoland/rev/d29de0ac3a323fede92671c9025f4e864994082e Push running xpcshell tests and showing the failures: https://treeherder.mozilla.org/#/jobs?repo=autoland&revision=24d718f4a6c244aad50b982518118e498e0953ed&filter-resultStatus=testfailed&filter-resultStatus=busted&filter-resultStatus=exception&filter-resultStatus=retry&filter-resultStatus=usercancel&filter-resultStatus=runnable Failure log: https://treeherder.mozilla.org/logviewer.html#?job_id=85932771&repo=autoland 09:01:03 INFO - TEST-START | browser/components/migration/tests/unit/test_Edge_db_migration.js 09:01:08 WARNING - TEST-UNEXPECTED-FAIL | browser/components/migration/tests/unit/test_Edge_db_migration.js | xpcshell return code: 0 09:01:08 INFO - TEST-INFO took 4616ms 09:01:08 INFO - >>>>>>> 09:01:08 INFO - (xpcshell/head.js) | test MAIN run_test pending (1) 09:01:08 INFO - (xpcshell/head.js) | test run_next_test 0 pending (2) 09:01:08 INFO - (xpcshell/head.js) | test MAIN run_test finished (2) 09:01:08 INFO - running event loop 09:01:08 INFO - browser/components/migration/tests/unit/test_Edge_db_migration.js | Starting 09:01:08 INFO - (xpcshell/head.js) | test pending (2) 09:01:08 INFO - TEST-PASS | browser/components/migration/tests/unit/test_Edge_db_migration.js | - Should recognize table we just created - true == true 09:01:08 INFO - (xpcshell/head.js) | test run_next_test 0 finished (2) 09:01:08 INFO - PID 2144 | ************************* 09:01:08 INFO - PID 2144 | A coding exception was thrown and uncaught in a Task. 09:01:08 INFO - PID 2144 | Full message: TypeError: dbFile is null 09:01:08 INFO - PID 2144 | Full stack: dbLocked@resource://app/modules/ESEDBReader.jsm:590:5 09:01:08 INFO - PID 2144 | EdgeBookmarksMigrator.prototype._migrateBookmarks<@resource://app/components/EdgeProfileMigrator.js:256:15 09:01:08 INFO - PID 2144 | migrate@resource://app/components/EdgeProfileMigrator.js:246:5 09:01:08 INFO - PID 2144 | migrateResult<@C:/slave/test/build/tests/xpcshell/tests/browser/components/migration/tests/unit/test_Edge_db_migration.js:410:52 09:01:08 INFO - PID 2144 | @C:/slave/test/build/tests/xpcshell/tests/browser/components/migration/tests/unit/test_Edge_db_migration.js:410:29 09:01:08 INFO - PID 2144 | TaskImpl_run@resource://gre/modules/Task.jsm:319:42 09:01:08 INFO - PID 2144 | TaskImpl@resource://gre/modules/Task.jsm:277:3 09:01:08 INFO - PID 2144 | asyncFunction@resource://gre/modules/Task.jsm:252:14 09:01:08 INFO - PID 2144 | Task_spawn@resource://gre/modules/Task.jsm:166:12 09:01:08 INFO - PID 2144 | _run_next_test@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:1554:9 09:01:08 INFO - PID 2144 | run@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:703:9 09:01:08 INFO - PID 2144 | _do_main@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:211:5 09:01:08 INFO - PID 2144 | _execute_test@C:\\slave\\test\\build\\tests\\xpcshell\\head.js:546:5 09:01:08 INFO - PID 2144 | @-e:1:1 09:01:08 INFO - PID 2144 | ************************* 09:01:08 WARNING - TEST-UNEXPECTED-FAIL | browser/components/migration/tests/unit/test_Edge_db_migration.js | - Migration should succeed - false == true 09:01:08 INFO - C:/slave/test/build/tests/xpcshell/tests/browser/components/migration/tests/unit/test_Edge_db_migration.js:null:416 09:01:08 INFO - _run_next_test@C:\slave\test\build\tests\xpcshell\head.js:1554:9 09:01:08 INFO - run@C:\slave\test\build\tests\xpcshell\head.js:703:9 09:01:08 INFO - _do_main@C:\slave\test\build\tests\xpcshell\head.js:211:5 09:01:08 INFO - _execute_test@C:\slave\test\build\tests\xpcshell\head.js:546:5 09:01:08 INFO - @-e:1:1 09:01:08 INFO - exiting test
Flags: needinfo?(gijskruitbosch+bugs)
Pushed by gijskruitbosch@gmail.com: https://hg.mozilla.org/integration/autoland/rev/1e63a826e79c fix hangs when trying to import bookmarks from Edge, r=dao
Flags: needinfo?(gijskruitbosch+bugs)
Status: ASSIGNED → RESOLVED
Closed: 8 years ago
Resolution: --- → FIXED
Target Milestone: --- → Firefox 55
Comment on attachment 8850120 [details] Bug 1349632 - fix hangs when trying to import bookmarks from Edge, Approval Request Comment [Feature/Bug causing the regression]: bookmarks/reading list migration from MS Edge [User impact if declined]: really long (10 or 20 second) hangs when trying to import from Edge while it's running [Is this code covered by automated tests?]: Yes! [Has the fix been verified in Nightly?]: not yet [Needs manual test from QE? If yes, steps to reproduce]: I don't think it needs extra verification beyond checking migration from Edge still works both when it's running and when it isn't. There's automated tests that verify it's not completely busted, so this can be pretty light-touch. [List of other uplifts needed for the feature/fix]: none that I'm aware of. [Is the change risky?]: no [Why is the change risky/not risky?]: it's a relatively straightforward change in an area of code that already had unit tests. [String changes made/needed]: nope
Attachment #8850120 - Flags: approval-mozilla-beta?
Attachment #8850120 - Flags: approval-mozilla-aurora?
Comment on attachment 8850120 [details] Bug 1349632 - fix hangs when trying to import bookmarks from Edge, Fix a hang issue while importing bookmarks from Edge. Aurora54+ & Beta53+.
Attachment #8850120 - Flags: approval-mozilla-beta?
Attachment #8850120 - Flags: approval-mozilla-beta+
Attachment #8850120 - Flags: approval-mozilla-aurora?
Attachment #8850120 - Flags: approval-mozilla-aurora+
has problems to apply to beta: grafting 407786:3e1b6f069e48 "Bug 1349632 - fix hangs when trying to import bookmarks from Edge, r=dao a=gchang" merging browser/components/migration/EdgeProfileMigrator.js warning: conflicts while merging browser/components/migration/EdgeProfileMigrator.js! (edit, then use 'hg resolve --mark') abort: unresolved conflicts, can't continue (use 'hg resolve' and 'hg graft --continue')
Flags: needinfo?(gijskruitbosch+bugs)
(In reply to Carsten Book [:Tomcat] from comment #18) > has problems to apply to beta: > > grafting 407786:3e1b6f069e48 "Bug 1349632 - fix hangs when trying to import > bookmarks from Edge, r=dao a=gchang" > merging browser/components/migration/EdgeProfileMigrator.js > warning: conflicts while merging > browser/components/migration/EdgeProfileMigrator.js! (edit, then use 'hg > resolve --mark') > abort: unresolved conflicts, can't continue > (use 'hg resolve' and 'hg graft --continue') Sorry, can you retry after you uplift bug 1344759? I didn't realize these conflicted - I can easily adapt the patch here so it lands on beta now, but then it'll conflict with bug 1344759, which just also got a+
Flags: needinfo?(gijskruitbosch+bugs) → needinfo?(cbook)
(In reply to :Gijs from comment #19) > (In reply to Carsten Book [:Tomcat] from comment #18) > > has problems to apply to beta: > > > > grafting 407786:3e1b6f069e48 "Bug 1349632 - fix hangs when trying to import > > bookmarks from Edge, r=dao a=gchang" > > merging browser/components/migration/EdgeProfileMigrator.js > > warning: conflicts while merging > > browser/components/migration/EdgeProfileMigrator.js! (edit, then use 'hg > > resolve --mark') > > abort: unresolved conflicts, can't continue > > (use 'hg resolve' and 'hg graft --continue') > > Sorry, can you retry after you uplift bug 1344759? I didn't realize these > conflicted - I can easily adapt the patch here so it lands on beta now, but > then it'll conflict with bug 1344759, which just also got a+ Ah, I noticed you're afk - I'll just push all of these bugs myself. :-)
Flags: needinfo?(cbook)
Flags: qe-verify+
I have reproduced this issue using Firefox 54.0a2 (2017.03.22) on Win 10 x64. I can confirm this issue is fixed, I verified using Firefox 55.0a1, 54.0a2, 53.0b9 on Win 10 x64.
Status: RESOLVED → VERIFIED
Flags: qe-verify+
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Creator:
Created:
Updated:
Size: