135305 - Should throttle rate of status string updates for performance

Status: RESOLVED EXPIRED

(SeaMonkey :: UI Design, defect)

Description

[Simon Fraser [no longer active]]

JS code that does something like:

    for (i = 0; i < 1000; i ++)
    {
        window.status = i;
    }

is very slow in Mozilla, because we redraw the status string every time through
the loop. 4.x (and probably IE) redraw the status string on a timer, which can
save lots of udpates.

Comment 1

[Simon Fraser [no longer active]]

Attachment: Testcase: times 1000 status updates

Comment 2

[Simon Fraser [no longer active]]

With the attached test case, here are some results:

IE 5.x, OS X:          91ms (only draws the final status)
Moz debug, OS X:    10595ms (draws every status)
NS 4.x, OS 9:       ~4000ms (draws every state, fails to correctly execute test)

Comment 3

[Simon Fraser [no longer active]]

Attachment: Hokey, non-functonal patch

Patch that makes setJSStatus() use setTimeout(), like onStatusChange() does.

This patch reduces the test time to about 4000ms, but doesn't produce the
desired effect (periodic status updates), because the setTimeout doesn't run
until the end of the test. What is does show is that we take about 4 seconds
for the test, even when no UI is being udpated (but with lots of trips from C++
to JS and back).

Comment 4

[Simon Fraser [no longer active]]

It turns out that synchronous status updates were done for bug 97227, where 
(http://bugzilla.mozilla.org/show_bug.cgi?id=97227#c19) rpotts says:

"There may be performance issues if a particular javascript starts spamming
status messages... this should be addressed if it turns out to be a real 
problem..." 

Turning off synchronous display in nsContentTreeOwner::SetStatus() causes the
test time to be about 5 seconds, but again no visible updates happen until after 
the test is over.

Comment 5

[Robert Kaiser]

is this somehow connected to bug 129115 ?

Comment 6

[David Baron :dbaron: (⌚️UTC-5, no longer working on Mozilla)]

No.

Comment 7

[Robert Kaiser]

Also no connection to bug 117061?

Comment 8

[Christian :Biesinger (don't email me, ping me on IRC)]

No.

Comment 9

[Chris Casciano]

Simon, my OSX results differ sleightly with your test case.

OS 10.1.3/g4-400 powerbook/1gb ram/0.9.9:

Test took 12136ms

BUT, I had the rainbow 'wait' cursor from the time the input button was pressed
until the test was done, and only the "999" state was displayed in the status
bar. Same results seen on 2 occations (closing and relaunching browser).

Comment 10

[Simon Fraser [no longer active]]

For a *single* setting of 'window.status', the following are functions that take 
> 1% of the time:

Function name                                   Call count  Total       Total       
Exclusive   Exclusive
                                                            time (ms)   %           
Time        %
nsStyleContext::GetStyleData                    2897        5.147       8.11        
3.299       5.20
nsBoxFrame::PaintChild                          952         22.993      36.24       
2.091       3.30
nsBoxFrame::GetFrame                            2929        1.960       3.09        
1.960       3.09
nsRuleNode::GetStyleData                        1528        1.847       2.91        
1.847       2.91
nsRenderingContextMac::CopyOffScreenBits        8           1.885       2.97        
1.754       2.76
nsCOMPtr_base::~nsCOMPtr_base                   1461        2.887       4.55        
1.227       1.93
nsFrame::GetView const                          1062        1.471       2.32        
1.174       1.85
nsRect::IntersectRect                           1085        1.141       1.80        
1.141       1.80
nsRenderingContextMac::FillRect                 86          1.361       2.14        
0.933       1.47
nsBox::GetNextBox                               1177        0.850       1.34        
0.850       1.34
nsBox::GetBounds                                1007        1.457       2.30        
0.800       1.26
nsCOMPtr_base::begin_assignment()               1077        0.790       1.25        
0.787       1.24
nsBoxFrame::PaintChildren                       111         23.200      36.56       
0.750       1.18
nsRenderingContextMac::SetupPortState()         220         0.732       1.15        
0.732       1.15
nsRenderingContextMac::SelectDrawingSurface     62          1.232       1.94        
0.713       1.12
nsImageMac::AllocateGWorld                      2           0.655       1.03        
0.655       1.03

Comment 11

[Simon Fraser [no longer active]]

Icky wrapping. Clearer data, again for a *single* 'window.status = i' line:

Function name                                  Call count   % of time (F)
-------------------------------------------------------------------------
nsStyleContext::GetStyleData                    2897        5.20
nsBoxFrame::PaintChild                          952         3.30
nsBoxFrame::GetFrame                            2929        3.09
nsRuleNode::GetStyleData                        1528        2.91
nsRenderingContextMac::CopyOffScreenBits        8           2.76
nsCOMPtr_base::~nsCOMPtr_base                   1461        1.93
nsFrame::GetView const                          1062        1.85
nsRect::IntersectRect                           1085        1.80
nsRenderingContextMac::FillRect                 86          1.47
nsBox::GetNextBox                               1177        1.34
nsBox::GetBounds                                1007        1.26
nsCOMPtr_base::begin_assignment()               1077        1.24
nsBoxFrame::PaintChildren                       111         1.18
nsRenderingContextMac::SetupPortState()         220         1.15
nsRenderingContextMac::SelectDrawingSurface     62          1.12
nsImageMac::AllocateGWorld                      2           1.03

Comment 12

[Wevah (Nate Weaver)]

Verifying Chris Casciano's comment:

PowerBook G4/500 MHz/512 MB RAM/OS X 10.1.3/Moz 0.9.9

I also get the spinning rainbow cursor until the loop is finished, leaving only
'999' in the status bar.

The test took me 8074 ms.

Comment 13

[Simon Fraser [no longer active]]

You folks are correct in stating that, on Mac OS X, the status text is not
updated until the end; this is because windows are double-buffered on Mac OS X.
Note also that the test will take much longer if focus is in the URL bar when
yhou click the button. In that case, we redraw the url bar and the button on
every status bar update.

Comment 14

[Simon Fraser [no longer active]]

Pre-sabbatical bug triage.

Comment 15

[Simon Fraser [no longer active]]

Update: Mozilla 1.3 takes ~3900ms, IE 5 takes 69ms to run the test. Still an issue.

Comment 16

[Kevin McCluskey (gone)]

Now that the fix for bug 129844 has landed I get the following results on WINXP.

2003041609 build on WinXP 750Mhz AMD  
  (2233 ms)

IE 6.0 on same machine                
  (2163ms)

Comment 17

[José Jeria]

My results on Win 2000:
2003051108: 3555
IE 6      : 381

Comment 18

[Markus Hübner]

wow - doing the testcase at http://bugzilla.mozilla.org/attachment.cgi?
id=77557&action=view I see a considerable better result of Mozilla rather than 
MSIE 6 SP2 :)

MSIE6 SP2: 2264ms
2003063008: 1241ms

Though if we can still improve that - I'd go with it :>
[jose, can you rerun the test for confirmation too]

Comment 19

[Markus Hübner]

Can we close this, or are there any remaining things to work on?

Comment 20

[José Jeria]

My results on Windows XP (AMD XP 1.6 Ghz, 758 RAM, ATI Radeon 9700):
20030926:  861
IE 6    :  190

Comment 21

[R.K.Aa.]

teseting on Linux and a current trunk CVS build, Gtk2, P4 1.8 GHz:

Test in attachment 77557 [details] takes 4869 ms. with Mozilla.
With Opera: 15 ms.

Which makes Opera approximately 325 times faster...

Comment 22

[Robert Kaiser]

MASS-CHANGE:
This bug report is registered in the SeaMonkey product, but has been without a comment since the inception of the SeaMonkey project. This means that it was logged against the old Mozilla suite and we cannot determine that it's still valid for the current SeaMonkey suite. Because of this, we are setting it to an UNCONFIRMED state.

If you can confirm that this report still applies to current SeaMonkey 2.x nightly builds, please set it back to the NEW state along with a comment on how you reproduced it on what Build ID, or if it's an enhancement request, why it's still worth implementing and in what way.
If you can confirm that the report doesn't apply to current SeaMonkey 2.x nightly builds, please set it to the appropriate RESOLVED state (WORKSFORME, INVALID, WONTFIX, or similar).
If no action happens within the next few months, we move this bug report to an EXPIRED state.

Query tag for this change: mass-UNCONFIRM-20090614

Comment 23

[Robert Kaiser]

MASS-CHANGE:
This bug report is registered in the SeaMonkey product, but still has no comment since the inception of the SeaMonkey project 5 years ago.

Because of this, we're resolving the bug as EXPIRED.

If you still can reproduce the bug on SeaMonkey 2 or otherwise think it's still valid, please REOPEN it and if it is a platform or toolkit issue, move it to the according component.

Query tag for this change: EXPIRED-20100420