588630 - When invoking TabCandy/Panorama with many open blank tabs, Firefox hangs & then pops up "Unresponsive Script" dialog

Status: VERIFIED FIXED

(Firefox Graveyard :: Panorama, defect, P2)

Description

[Daniel Holbert [:dholbert]]

STR:
 1. Hold Ctrl + T for ~20 seconds (to open many many tabs)
   --> (Note that Firefox remains pretty responsive. You can switch, reorder, & close tabs, resize browser, etc. without any delay)

 2. Invoke TabCandy (e.g. Ctrl + Space)

ACTUAL RESULTS:
Firefox becomes unresponsive for ~15 seconds, and then pops up the "Warning: Unresponsive Script" dialog.
  --> If you click "Continue", this repeats (at least once, for me)
  --> If you click "Cancel", it drops you into a Tab Candy view. (which might be in an inconsistent state, since I don't know what "Cancel" actually interrupted)

Comment 1

[Michael Yoshitaka Erlewine [:mitcho]]

I'm unable to reproduce this on recent tabcandy-central builds (where we are working on bug 578512, which introduces a number of architectural changes). Please reopen if you see this again after bug 578512 lands on nightlies.

Comment 2

[Daniel Holbert [:dholbert]]

Ok, thanks!

Comment 3

[Dietrich Ayala (:dietrich)]

Blocking+ in case this gets re-opened at some point.

Comment 4

[Daniel Holbert [:dholbert]]

Reopening per bug 578512 comment 26. (It sounds like that bug has been retargeted to be post-Firefox-4.)

Comment 5

[Michael Yoshitaka Erlewine [:mitcho]]

See also: bug 591704 for Panorama loading simply taking a long time.

Comment 6

[Daniel Holbert [:dholbert]]

For the record: on the one hand, part of me feels like this bug is hard/unlikely-to-be-fixed, simply because it just takes a nonzero amount of time for each tab to render in Panorama, and that time obviously adds up.

HOWEVER: Because Panaroma is **so easy to invoke completely by accident** due to its choice of key-combination[1], it is paramount that Panorama not hang the browser, even under huge-numbers-of-tabs situations. Otherwise, many-tab-sessions effectively become ticking time bombs, just waiting for the user to accidentally hit Ctrl+space.

[1] When editing text fields, I frequently intermix cut/copy/paste actions (involving "Ctrl") with typing (including spaces), so I often invoke Panorama's "Ctrl+space" key-combo completely by accident. (a few times per week)

Comment 7

[Ian Gilman [:iangilman]]

The actual rendering of the thumbnails doesn't happen in the initial load; this is spread out over a period of time afterward, therefore should have no effect on the initial loading time. Whatever's causing this issue is just the initial set up of the divs and data structures. Probably some profiling would be useful here to see where the hot spots are.

Comment 8

[Sean Dunn]

The other perf bug I have is bug 589076, so I'll attack both of these at the same time.

Comment 9

[Sean Dunn]

Attachment: v1 WIP

My solution was to cancel all arrangements until after the UI initialization is finished. I track a list of the groups that wanted to be arranged, and the last set of options used. At the end of UI initialization, I call these.

For ~150 tabs, this takes 1s to open, whereas without the patch it takes 5s.

This solution feels a little bolted on -- any ideas on how to better build this into the architecture?

Comment 10

[Sean Dunn]

I should also mention that I shaved a little time off of setBounds by storing elements that iQ would have searched for during each call.

Comment 11

[Ian Gilman [:iangilman]]

Comment on attachment 482299 [details] [diff] [review]
v1 WIP

Actually seems like a decent approach. It'll be even better once bug 590268 lands. 

Comments, mostly stylistic:

>+  _arrangePaused: false,
>+  _arrangePending: [],

It's not clear from the name that _arrangePending is an array; I'd use _arrangesPending or some such. 

>+  pauseArrange: function GroupItems_pauseArrange() {
>+    this._arrangePaused = true;
>+    this._arrangePending = [];
>+  },

I know it's not a risk with the current usage, but it seems like some attention should be paid to what happens if it's called when already paused. Perhaps at this point just an assert would be the way to go?

Also, why do you clear out the pending array? Seems like if for some reason there were already items in the array, we don't want to lose them. 

Also, please document these new routines in the same style as other routines (with the comment block above in the NaturalDocs style). 

>+  pushArrange: function GroupItems_pushArrange(group, options) {

I'd prefer the argument "group" to be named "groupItem" so it's clear what it is. With bug 578512 (post-ff4) we'll be introducing group objects that are more or less the "model" to the GroupItem's "view", so it will become more of an issue then, but we might as well keep it clean in the meantime.

>+    if (this._arrangePaused) { 

Maybe this should be an assert instead?

>+      let i;
>+      for (i=0; i<this._arrangePending.length; i++) {
>+        let g = this._arrangePending[i];
>+        if (g[0] === group) {
>+          break;
>+        }
>+      }
>+      if (i < this._arrangePending.length) {
>+        this._arrangePending[i] = [group, options];
>+      } else {
>+        this._arrangePending.push([group, options]);
>+      }

For code clarity, rather than pushing arrays into the array, push objects with property names. Something like so:

      let i;
      for (i=0; i<this._arrangePending.length; i++) {
        let g = this._arrangePending[i];
        if (g.groupItem === groupItem) {
          break;
        }
      }
      let arrangeInfo = {
      	groupItem: groupItem, 
      	options: options
      }; 
      if (i < this._arrangePending.length) {
        this._arrangePending[i] = arrangeInfo;
      } else {
        this._arrangePending.push(arrangeInfo);
      }

... then in resumeArrange, this is a lot clearer:

  g.groupItem.arrange(g.options);

>+    for (let i=0; i<this._arrangePending.length; i++) {
>+      let g = this._arrangePending[i];

This can also be done this way:

    this._arrangePending.forEach(function(g) {
      ... 
    });
    
I'm not actually sure which is more efficient, so I'm not advocating you change it; just mentioning it as it's a common pattern. 

f+ with those items addressed.

Comment 12

[Sean Dunn]

Attachment: v2

Incorporated your changes.

Comment 13

[Ian Gilman [:iangilman]]

Comment on attachment 483239 [details] [diff] [review]
v2

Looks great! 

Minor point: I'd like us to try to standardize on having our assert text written in terms of what should happen rather than what did or did not happen, e.g. Utils.assert(a == 2, "a should be equal to 2"). This way it's clear both when reading the code and when reading the console/log.

Comment 14

[Dietrich Ayala (:dietrich)]

Comment on attachment 483239 [details] [diff] [review]
v2

>   // ----------
>+  // Function: arrangeIsPaused
>+  // Returns whether arrange()s and are being bypassed and

nit: and are

also, why a function instead of a property?

>+  // ----------
>+  // Function: pushArrange
>+  // Push an arrange() call and its arguments onto an array
>+  // to be resolved in resumeArrange()
>+  pushArrange: function GroupItems_pushArrange(groupItem, options) {
>+    Utils.assert(this._arrangePaused, 
>+      "Attempted pushArrange() while arrange()s aren't paused"); 
>+    let i;
>+    for (i=0; i<this._arrangesPending.length; i++) {

nit: spaces before/after operators

>+  // ----------
>+  // Function: resumeArrange
>+  // Resolve bypassed and collected arrange() calls
>+  resumeArrange: function GroupItems_resumeArrange() {
>+    for (let i=0; i<this._arrangesPending.length; i++) {

ditto

>+      
>+      GroupItems.resumeArrange();
>     } catch(e) {
>       Utils.log(e);
>     }
>   },

i don't dig this whole function body being wrapped in a try block. what happens when something throws between pause and resume? is the user just borked for the rest of the session until a restart? maybe just the code between pause/resume should be wrapped in a try block?

r+ conditionally, depending on the answer to the above.

Comment 15

[Sean Dunn]

Attachment: Original v3 (already landed)

Fixed issues. Pulled GroupItems.resumeArrange() into finally{} segment.

Comment 16

[Ian Gilman [:iangilman]]

Sean, please package for check-in. Also, does it need a try run?

Comment 17

[Sean Dunn]

Try: http://hg.mozilla.org/try/pushloghtml?changeset=d53f52b66513

Comment 18

[Ian Gilman [:iangilman]]

(In reply to comment #17)
> Try: http://hg.mozilla.org/try/pushloghtml?changeset=d53f52b66513

Was the try successful?

Comment 19

[Sean Dunn]

Try was successful.

Comment 20

[Ian Gilman [:iangilman]]

(In reply to comment #19)
> Try was successful.

Excellent... I'll land it soon.

Comment 21

[Ian Gilman [:iangilman]]

http://hg.mozilla.org/mozilla-central/rev/ea41c727079b

Comment 22

[Sean Dunn]

Mathnerd314 saw the unresponsive script dialog coming up. I'm going to try to break up the initialization asynchronously.

Comment 23

[Sean Dunn]

This was on a slow XP netbook.

Comment 24

[Ian Gilman [:iangilman]]

Mathnerd314, does this happen every time? How many tabs do you have? If I post a patch with profiling hooks, could you run it? Or would you prefer a try build?

Comment 25

[Allan Gardner (:Mathnerd314)]

It happened for the 5 times I tried, so yes. I'm guessing somewhere around 600 tabs; do you want an exact count? And I'd prefer a try build; even a debug build took >2 hours on my machine.

Comment 26

[Ian Gilman [:iangilman]]

(In reply to comment #25)
> It happened for the 5 times I tried, so yes. I'm guessing somewhere around 600
> tabs; do you want an exact count? And I'd prefer a try build; even a debug
> build took >2 hours on my machine.

Yow! That's a lot of tabs. 

The try build is underway:

http://tbpl.mozilla.org/?tree=MozillaTry&rev=1563d9594017

... and should be available shortly here:

http://ftp.mozilla.org/pub/mozilla.org/firefox/tryserver-builds/?C=M;O=D

You'll need to run it from the command line; it dumps profile information. Please copy the resulting dump back here into the bug.

Thank you for your help!

Comment 27

[Ian Gilman [:iangilman]]

While this is certainly something we'd like to fix, I'm nominating it for unblocking, as 600 tabs on a slow XP notebook is an extreme case, and we haven't heard of this from anyone else since the original patch landed.

Comment 28

[Ian Gilman [:iangilman]]

Attachment: profiling code

I'm attaching the profiling code I sent to try.

Comment 29

[Ian Gilman [:iangilman]]

So, possible strategies for dealing with this issue: 

* Break the UI.init function into a series of routines that are chained together via setTimeout. If we do this, we'll need to make sure all of our event handlers are added at the end, so we don't start taking input (either from the user or from the browser) until we're all set up.

* Identify the heaviest operations and defer them until later. For instance, if setting up the thumbnails is taking most of the time, we can defer that but otherwise set everything up in one shot. If we do this, we'll have to make sure the defered item isn't used until it's set up.

Comment 30

[Mike Beltzner [:beltzner, not reading bugmail]]

Agree with comment 27 - removing as blocker.

Comment 31

[Allan Gardner (:Mathnerd314)]

After some experimenting, I found the cutoff point was somewhere between 300 and 450 tabs.

Comment 32

[Ian Gilman [:iangilman]]

Mathnerd314 got this output with 447 tabs:

PANORAMA PROFILE START: average, total - (min, max; count)
UI init = 74.00, 74 - (74, 74; 1)
TabItem DOM1 = 1.13, 504 - (0, 26; 447)
TabItem DOM2 = 1.20, 536 - (1, 17; 447)
TabItem DOM3 = 25.23, 11276 - (3, 122; 447)
TabItem DOM4 = 20.53, 9179 - (1, 142; 447)
TabItem events = 13.21, 5906 - (1, 4971; 447)
TabItem reconnect1 = 0.77, 346 - (0, 14; 447)
TabItem reconnect2 = 2.58, 1154 - (1, 35; 447)
TabItem reconnect3 = 2.69, 1202 - (1, 36; 447)
TabItem reconnect4 = 1.44, 645 - (0, 41; 447)
TabItem reconnect5 = 0.69, 310 - (0, 8; 447)
Total = 31132
PANORAMA PROFILE END

31 seconds total. 

He had to click away the "slow script" dialog once, which probably accounts for the anomolous time on "TabItems events"; we can probably remove four seconds or so.

Here's his output at 400 tabs, also with a "slow script" dialog; the long "TabItem DOM4" is probably accounted for by that.

PANORAMA PROFILE START: average, total - (min, max; count)
UI init = 56.00, 56 - (56, 56; 1)
TabItem DOM1 = 1.08, 433 - (0, 8; 400)
TabItem DOM2 = 1.21, 483 - (0, 13; 400)
TabItem DOM3 = 22.55, 9021 - (3, 112; 400)
TabItem DOM4 = 33.62, 13447 - (1, 6372; 400)
TabItem events = 1.89, 755 - (1, 17; 400)
TabItem reconnect1 = 0.84, 335 - (0, 26; 400)
TabItem reconnect2 = 2.59, 1036 - (1, 35; 400)
TabItem reconnect3 = 2.99, 1195 - (1, 132; 400)
TabItem reconnect4 = 1.29, 515 - (0, 26; 400)
TabItem reconnect5 = 0.69, 277 - (0, 15; 400)
Total = 27553
PANORAMA PROFILE END

Here's 375 tabs, with no "slow script" dialog (and no anomolous time):

PANORAMA PROFILE START: average, total - (min, max; count)
UI init = 67.00, 67 - (67, 67; 1)
TabItem DOM1 = 1.07, 401 - (0, 30; 375)
TabItem DOM2 = 1.31, 493 - (1, 45; 375)
TabItem DOM3 = 18.24, 6841 - (3, 77; 375)
TabItem DOM4 = 14.35, 5381 - (1, 101; 375)
TabItem events = 1.88, 706 - (1, 22; 375)
TabItem reconnect1 = 0.86, 322 - (0, 31; 375)
TabItem reconnect2 = 2.51, 942 - (1, 42; 375)
TabItem reconnect3 = 2.56, 960 - (1, 52; 375)
TabItem reconnect4 = 1.41, 528 - (0, 28; 375)
TabItem reconnect5 = 0.60, 226 - (0, 3; 375)
Total = 16867
PANORAMA PROFILE END

At any rate, it's clear that the slowness is just creating all of the TabItems, and that most of that DOM manipulation.

In particular, DOM3 is where we add the close box and the expander to the div (rather than creating them in the .html() statement earlier); I believe this is left over from when we had .locked.close and .locked.size to contend with. Reintegrating them into the .html() call would be an easy win.

DOM4 is where we poll the DOM for the padding values. This is the same for every TabItem, so it's pointless to do it for everyone; we should do it just for the first one, and share that across them all.

Also in DOM4, we're setting this.bounds to $div.bounds(); that's probably entirely unnecessary (leftover from a bygone era), since the div's location isn't even set up by then. That line should just go away.

While I'm making recommendations, we could probably streamline the .update() calls TabItems.init makes for every tab; instead of calling .update() and having it look through _tabsWaitingForUpdate for each one, we could just push everybody onto the list and start the heartbeat. That's just speculative optimization, though, something I noticed in the code, rather than something the profiling points to.

My recommendation is that we implement these optimizations for Fx4, which should push us well over 400 tabs, and that we engage in the bigger architectural changes post Fx4 (probably in a new bug), when we have the time to let the repercussions of the changes shake out.

Comment 33

[Michael Yoshitaka Erlewine [:mitcho]]

> In particular, DOM3 is where we add the close box and the expander to the div
> (rather than creating them in the .html() statement earlier); I believe this is
> left over from when we had .locked.close and .locked.size to contend with.
> Reintegrating them into the .html() call would be an easy win.

Moreover, the div that we create for each TabItem, pre-tab-specific info, could be put in a DOM DocumentFragment, which can be cloned for each TabItem instance. This could possibly be a great performance improvement:

http://ejohn.org/blog/dom-documentfragments/

I'd like to take a stab at a couple of these quick cleanups.

Comment 34

[Michael Yoshitaka Erlewine [:mitcho]]

(In reply to comment #32)
> At any rate, it's clear that the slowness is just creating all of the TabItems,
> and that most of that DOM manipulation.

These tasks now in bug 631747.

> While I'm making recommendations, we could probably streamline the .update()
> calls TabItems.init makes for every tab; instead of calling .update() and
> having it look through _tabsWaitingForUpdate for each one, we could just push
> everybody onto the list and start the heartbeat. That's just speculative
> optimization, though, something I noticed in the code, rather than something
> the profiling points to.

This is now bug 631748.

> we engage in the bigger
> architectural changes post Fx4 (probably in a new bug), when we have the time
> to let the repercussions of the changes shake out.

Ian, I'm not sure what specific items you had in mind for the post-fx4 items, so I didn't create any bugs for that.

Resolving this bug itself fixed. Please comment on the new followup bugs or create new followups for specific issues or tasks.

Comment 35

[Ian Gilman [:iangilman]]

(In reply to comment #34)
> Ian, I'm not sure what specific items you had in mind for the post-fx4 items,
> so I didn't create any bugs for that.

Bug 632222. Thanks for filing the other bugs!

Comment 36

[Tracy Walker [:tracy]]

verified with nightly build of minefield.