Closed Bug 70156 Opened 24 years ago Closed 14 years ago

Some dhtml animations run slowly in mozilla

Categories

(Core :: DOM: CSS Object Model, defect, P2)

defect

Tracking

()

RESOLVED WORKSFORME
Future

People

(Reporter: jrgmorrison, Assigned: jesup)

References

(Depends on 1 open bug, )

Details

(4 keywords, Whiteboard: [Hixie-P1])

Attachments

(7 files)

The dhtml animation (which is very nice!) at the URL
   http://www.html-online.de/niko.temp/time/time.html
runs fairly slowly in mozilla, and pegs the cpu when it is "idle". 

The original, not-working-in-mozilla version was at 
   http://12.13.171.162/time/time.htm)

This was originally noted in a post to n.p.m.seamonkey asking how to
modify it to work in mozilla with the w3c dom. After I made the needed
changes (basically to use the event's .screenX/Y property, and
retrieving nodes with .getElementById), it was noted that the
animation ran much slower in mozilla than in Nav4 or IE (with their
respective document.layers and document.all collections).

There are really two parts to this bug (and perhaps I should have
filed separate bugs, but...): 

(1) when the mouse is moved to a new location, and the animation is in process
    (the clock elements are flowing to the new mouse location), when I
    broke in the debugger, it was mainly style resolution and layout
    reflow code that was in action (no typical stack, just lots of layout 
    and style system in action). 

(2) after you have triggered the animation, and the animation has "caught
    up" with the mouse, there is still a prolonged period when the 
    the CPU is at 100%, as if it is still trying to deal with a backlog of 
    timeouts. I broke in the debugger with an optimized build,
    and the most common stack was like the one below, with the pivotal
    function being 'SetCSS2PropertiesProperty'

nsDocument::AttributeChanged(nsDocument * const 0x02da9e50, nsIContent * 
0x02e8ef18, int 0, nsIAtom * 0x00c0c820, int 0) line 1682 + 47 bytes
nsDOMCSSAttributeDeclaration::ParseDeclaration(nsDOMCSSAttributeDeclaration * 
const 0x02da9ee0, const basic_nsAReadableString<unsigned short> & {...}, int 1, 
int 0) line 338 + 22 bytes
nsDOMCSSDeclaration::SetProperty(nsDOMCSSDeclaration * const 0x02ea3df8, const 
basic_nsAReadableString<unsigned short> & {...}, const 
basic_nsAReadableString<unsigned short> & {...}, const 
basic_nsAReadableString<unsigned short> & {...}) line 247 + 22 bytes
nsDOMCSSDeclaration::SetTop(nsDOMCSSDeclaration * const 0x02ea3df8, const 
basic_nsAReadableString<unsigned short> & {...}) line 1599 + 44 bytes
SetCSS2PropertiesProperty(JSContext * 0x02c748e8, JSObject * 0x02e95a80, long 
-223, long * 0x0012f900) line 3055 + 19 bytes
js_SetProperty(JSContext * 0x02de4490, JSObject * 0x00000005, long 13801632, 
long * 0x0012f900) line 2419 + 109 bytes
js_Interpret(JSContext * 0x02c748e8, long * 0x0012fa8c) line 2518
js_Execute(JSContext * 0x00000000, JSObject * 0x02ccd3e0, JSScript * 
0x02ccd3e0, JSStackFrame * 0x00000000, unsigned int 0, long * 0x0012fa8c) line 
958
JS_EvaluateUCScriptForPrincipals(JSContext * 0x02c748e8, JSObject * 0x02ccd3e0, 
JSPrincipals * 0x02d858f0, const unsigned short * 0x0012faf8, unsigned int 6, 
const char * 0x02eadbe0, unsigned int 143, long * 0x0012fa8c) line 3221 + 17 
bytes
nsJSContext::EvaluateString(nsJSContext * const 0x00000000, const 
basic_nsAReadableString<unsigned short> & {...}, void * 0x02ccd3e0, 
nsIPrincipal * 0x0012faf8, const char * 0x02eadbe0, unsigned int 143, const 
char * 0x002a11e0 `string', basic_nsAWritableString<unsigned short> & {...}, 
int * 0x0012fc6c) line 609 + 57 bytes
GlobalWindowImpl::RunTimeout(GlobalWindowImpl * const 0x02da9ee0, nsTimeoutImpl 
* 0x02d6191c) line 3927
nsGlobalWindow_RunTimeout(nsITimer * 0x041b6e28, void * 0x02eadb70) line 4201 + 
14 bytes
nsTimer::Fire(nsTimer * const 0x02da9ee0) line 194 + 6 bytes
nsTimerManager::FireNextReadyTimer(nsTimerManager * const 0x00c20b50, unsigned 
int 0) line 117
FireTimeout(HWND__ * 0x00000000, unsigned int 275, unsigned int 31549, unsigned 
long 267251187) line 88 + 12 bytes
USER32! 77e13eb0()
USER32! 77e14092()
USER32! 77e192da()
nsAppShellService::Run(nsAppShellService * const 0x00b5ff30) line 408
main1(int 1, char * * 0x00372ba8, nsISupports * 0x00372bc8) line 978 + 9 bytes
main(int 1, char * * 0x00372ba8) line 1270 + 25 bytes
WinMain(HINSTANCE__ * 0x00400000, HINSTANCE__ * 0x00400000, char * 0x00132c81, 
HINSTANCE__ * 0x00400000) line 1288 + 21 bytes
MOZILLA! WinMainCRTStartup + 308 bytes
KERNEL32! 77e87903()
->perf keyword
Keywords: perf
dveditz wrote in news://news.mozilla.org/3A9ABF17.5901F753%40netscape.com

"I did a quantify run on this in winembed, timing the actions between the
clock starting at one position, moving the mouse across the window, and
stopping quantify when the clock was reformed at the new position. On my
machine in Communicator this takes about 1.5 seconds; in winEmbed and
Mozilla this takes 6 or 7 seconds.

At the highest level, 60% of the time was spent in 71 reflow events,
36% was spent in the 71 times the timeout function fired (mostly
property setting that triggered style stuff), and 4% in 35 calls to
paint the window (of which half is our rendering code, and half is the
OS calls to do the actual painting).

- 4% of time (190msec) was spent in 35 calls to nsWindow::WindowProc,
  essentially in painting of the screen

  - Down several layers the bulk of that (172msec) is eventually spent in
    nsViewManager2::Refresh

    - 74% (128msec) spent in 35 calls to nsViewManager2::RenderViews

    - 25% (43msec) spent in 35 calls to 
                   nsRenderingContextWin::CopyOffScreenBits

- 37% of time (1755 msec) spent in 71 calls to FireTimeout, of which
  most was spent in 69 script executions. Those 69 js_interpret calls
  generated 1696 js_SetProperty calls, which in turn called
  SetCSS2PropertiesProperty 1530 times (1600 msec).

  - 9% of that (145msec) spent in 1530 calls to
    nsJSUtils::nsConvertJSValToString--more time than in RenderViews!

  - 88% (1412msec) total spent in 765 calls each to nsDOMCSSDeclaration
    methods SetLeft and SetTop, which each call SetProperty. Nearly all
    of this time is spent in nsDOMCSSAttributeDeclaration::ParseDeclaration

    - 10% (146msec) in 1530 calls to CSSParserImpl::ParseAndAppendDeclaration
      about half of which comes down to an equal number of
      nsCSSScanner::ParseNumber calls. Most of that time is spent in
      nsString::ToFloat, but there are an astounding 26,804 calls to
      nsCString::AppendWithConversion

    - 86% (1203msec) in 1530 calls to nsDocument::AttributeChanged, the 
      bulk of which (1021msec) eventually ends up in NS_NewStyleContext.

      A large part of the time spent here is eventually down in 1399 calls
      to nsDeviceContextWin::CheckFontExistence (708msec) where we actually
      query the OS (GetDC, EnumFontFamiliesA, ReleaseDC) each time.

      We need to guard against people who install fonts hundreds of times
      a second? For those not following the math, this is a little over
      14% of the total time spent checking things that aren't going to change

- 59% of the total time (2850msec) spent in 71 calls to md_EventReceiverProc,
  which turns out to be ReflowEvent::HandleEvent (we lose 58msec getting
  down to that level, though).

  This got fairly confusing to follow because the totals didn't add up
  (due to cycles or recursion), but at the bottom 30% of the total time,
  1525msec, was spent in **11,681** calls to the Win API InvalidateRect.

Other than some of the hot-spots noted above, in this 5 second or so
run other notable function calls were
   47,055 calls to "new" (260msec -- 5%)
   43,911 calls to "delete" (254msec --5%)
  113,173 calls each to PR_Lock and PR_Unlock (160msec together -- 3%)
  127,855 calls to ftol (88msec)
   13,386 calls to malloc (58msec)
   12,357 calls to free (56msec)
  508,872 calls to AccumulateCRC (43msec)
   82,411 calls to memcpy (43msec)
   46,344 calls to memset (34msec)

That's an insane number of function calls to move 22 objects
on the screen 35 times."
The reason this animation is slow seems to be exactly the same as what's
described in bug 64516, duping.

*** This bug has been marked as a duplicate of 64516 ***
Status: NEW → RESOLVED
Closed: 24 years ago
Resolution: --- → DUPLICATE
I'm reopening -- this example is slow in part due to the same 
SetCSS2PropertiesProperty stuff described in bug 64516, but it mostly shows a 
completely separate problem.  In bug 64514 SetCSS2PropertiesProperty and 
children accounts for 74% of the time; here it's only about 30%.

ReflowEvent::HandleEvent is nearly nothing in bug 64516, here it accounts for 
more than half the time. InvalidateRect doesn't even show in bug 64516, here 
that one call accounts for 30% of the time. The weird font enum stuff doesn't 
take much time in bug 64516, here we call GetDC and EnumFontFamiliesA thousands 
of times.

The outward appearance (slow DHTML) may be the same, but the time appears to be 
spent in entirely different places.
Status: RESOLVED → REOPENED
Depends on: 64516
Resolution: DUPLICATE → ---
I still think the biggest problem here is exectly the same as in bug 64516,
looking at this in quantify I do see the EnumFontFamiliesA function being called
thousands of times (same for GetDC n' friends), but that's due to the same
problem, excessive style re-reolution. The numbers in the clock in the animation
have a style rule that changes the font that the numbers are shown with and that
results in the style system calling EnumFontFamiliesA a bunch of times...

Either way, this is not a DOM problem, IMO it's to a great deal the same problem
as bug 64516 describes, or if that's not true, then the it's a layout reflow
problem, both those problems belong with attinasi AFAIK, so he'll get to be the
next proud owner of this bug. Reassigning.
Assignee: jst → attinasi
Status: REOPENED → NEW
I'll check it out. It does smell like bug 64516, even thought the stacks and 
profiels are different, because it has to do with making a lot of rapid changes 
to an elements style data, and that causes lots of style resolution/reflow and 
that is too slow. Anyway, I'll dig in and see what I can learn.

BTW: that is one cool clock!
Status: NEW → ASSIGNED
So one reason for the reflow code shows up more in this profile than in the
other one is that in this bug everything is triggerd from a mouse move, and for
every mouse move on this page we call FlushPendingNotifications() on the pres
shell and that causes all the reflow to be done there and then in stead of later
when there's more time to do it...

And yes, the clock is awesome :-)
The major difference here is the 1400 calls to the sequence 
GetDC-EnumFontFamiliesA-ReleaseDC which eat up a large chunk of time -- we 
should be caching that data.

jst-- The mouse was moved exactly once. The mouse was moved off-screen before 
the timing was started, and I poked it just over the edge to start the 
clock travelling to the new position and immediately moved it out of the window 
again. There were zero calls to FlushPendingNotifications(), or any function 
with "flush" or "notification" in the function name other than 3 calls to 
js_FlushPropertyCache.
spam: cc'ing me
dveditz, bug 64516 is the reason we do all those
GetDC-EnumFontFamiliesA-ReleaseDC calls.
How so? bug 64516 doesn't even show EnumFontFamiliesA in the attached quantify 
trace, and GetDC is only called a reasonable 7 times. I'm sure the style stuff 
is affecting the sheer number of calls, but why do we need to *ever* call more 
than once? Installing fonts is rare, we should be caching that information.
Bug 64516 doesn't show EnumFontFamiliesA since there are no style rules in that
testcase that contain font info. Sure, maybe it should be cached...
Blocks: 21762
Slow on my linux build from yesterday too. All/All. Nominating for 0.9.2.
Keywords: mozilla0.9.2
OS: Windows 2000 → All
Hardware: PC → All
*** Bug 66881 has been marked as a duplicate of this bug. ***
For the suggested caching idea, maybe it might be possible to leverage on the 
nsIDeviceContext::mFontCache. mFontCache stores basically an array of 
nsIFontMetrics, and a nsIFontMetrics provides a hook from where to peek at the 
global list of all installed fonts, and this list 'is' (or 'will be') 
automatically kept up-to-date if new fonts are installed (see bug 69117).

The global list of installed fonts is needed for the Prefs -> Fonts dialog
anyway (it is also needed for other tricks in the font sub-system). So 
leveraging on that list for CheckFontExistence() might be faster without 
introducing too much overhead.
Updating target and priority.
Priority: -- → P2
Summary: a dhtml animation which runs slowly in mozilla → Some dhtml animations run slowly in mozilla
Target Milestone: --- → mozilla1.0
*** Bug 76299 has been marked as a duplicate of this bug. ***
Whiteboard: [Hixie-P2]
Copying keyword and status spammage from duplicate bug. See also:
   http://timeless.student.umd.edu/mozilla/css/
Severity: normal → major
URL http://timeless.student.umd.edu cannot be found - guess it went away?
*** Bug 83852 has been marked as a duplicate of this bug. ***
Bug 91956 covers part of this; some of the Font Cache stuff (if this used the
font cache).  Someone should retest/quantify this testcase!
*** Bug 95072 has been marked as a duplicate of this bug. ***
I have experimented with the script and found indeed that Mozilla continues to
use considerable amounts of CPU after the display has caught up with the mouse.

This got me thinking about whether the style settings were being changed too
often.  I added the following test before resetting the left & top values:

if (Math.abs(parseInt(oDivs[i][0].left) -(oDivs[i][1] + oDivs[i][3]))>=1 ||
Math.abs(parseInt(oDivs[i][0].top)-(oDivs[i][2] + oDivs[i][4]))>=1) {
      oDivs[i][0].left = oDivs[i][1] + oDivs[i][3];
      oDivs[i][0].top =  oDivs[i][2] + oDivs[i][4];
}

This caused the CPU (post catching up) to collapse by 80%.

In this particular dhtml animation left/top are given lots of fractional value
that eventually converge to integer values.

Does the fact that the CPU rate collapses after the introduction of this simple
test on whether the change in value is significant suggest that adding that sort
of test before "changing" the value would improve overall performance of the DHTML?
I stole an URL from one of the newsgroups that demonstrates this rather
dramatically. The site is her:
http://www.dynamic-core.net/widgetx/

And a direct link to one example is:
http://www.dynamic-core.net/widgetx/examples/vectorsine.htm

It uses 256 different layers to simulate a 3D rotating sine wave structure.
*** Bug 78103 has been marked as a duplicate of this bug. ***
Grey,

demos from http://www.dynamic-core.net/widgetx/ are being addressed in bug 98828
I think.
comparing this with msie and mozilla is tough :-/
http://www.dynamicdrive.com/dynamicindex3/leaves.htm
http://www.world-direct.com/mozilla/moz_sliding.htm
just click on the top-navigation to start the animation.

msie, opera and ns4.x do very fine at this!
cc'ed me.
Target Milestone: mozilla1.0 → mozilla0.9.9
The original URL doesn't do anything for me anymore, running build 2001112308 on
linux.

It used to 'work'
The animation stopped working with build of Sept. 09, from a checkin by dbaron
for handling doctypes and strict vs. quirks mode.

  <!DOCTYPE HTML PUBLIC "-//W3C//DTD HTML 4.01 Transitional//EN"
      "http://www.w3.org/TR/1999/REC-html401-19991224/loose.dtd">

That document has the above doctype, which is triggering strict mode (should 
it, dbaron? hixie? Comments in bug 55264 suggest that that is intended).

Given strict mode, then units are required for lengths, e.g., 'top:10px' vs. 
'top:10'. This diff "fixes" the animation:

@@ -41,8 +42,8 @@
        for (i=0; i<iDivs; i++) {
                oDivs[i][1] = oDivs[i][1] * 0.5 + x * 0.5;
                oDivs[i][2] = oDivs[i][2] * 0.5 + y * 0.5;
-               oDivs[i][0].left = oDivs[i][1] + oDivs[i][3];
-               oDivs[i][0].top =  oDivs[i][2] + oDivs[i][4];
+               oDivs[i][0].left = oDivs[i][1] + oDivs[i][3] + 'px';
+               oDivs[i][0].top =  oDivs[i][2] + oDivs[i][4] + 'px';
                x = oDivs[i][1];
                y = oDivs[i][2];
        }

[plus one other place where inline style sez 'top:135' for div id='yo0' 
(although that doesn't break the animation).]
Sorry. Didn't intend to remove original URL. 

And, that's still just a gorgeous animation :-]
> That document has the above doctype, which is triggering strict mode (should 
> it, dbaron? hixie? Comments in bug 55264 suggest that that is intended).

Bug 42525 shows even more clearly that it was intended.  Furthermore, before my
checkin that DOCTYPE declaration would have triggered strict mode if the word
"loose" had appeared within the first 25 characters of the system identifier,
rather than at 48 as it does.  That's why I always argued with rickg that his
method of parsing doctypes was wrong...
Heh. Nice scroll test (er, well aside from the time).

[We may be in danger of overloading this bug with examples that, while still 
dhtml, have different root causes. But since attinasi widened my initial 
summary from 'a' to 'some', then I'll let him decide if he wants separate bugs
for these examples].
Is it just me or did the animated clock stop working in mozilla?
Hello. Hello? Is this thing on?
  http://bugzilla.mozilla.org/show_bug.cgi?id=70156#c33
Ah, heh, yeah :-) I was playing around with a local copy of the old testcase...
sorry, i graduated so my .edu dns entry expired.
*** Bug 120417 has been marked as a duplicate of this bug. ***
Blocks: 100951
Whiteboard: [Hixie-P2] → [Hixie-P1]
Seems this has also an impact on bug 107746.
Keywords: nsbeta1, top100
*** Bug 107746 has been marked as a duplicate of this bug. ***
perf --> 1.0
Target Milestone: mozilla0.9.9 → mozilla1.0
Moving to Moz1.1. Engineers are overloaded with higher priority bugs.
Target Milestone: mozilla1.0 → mozilla1.1
Marking nsbeta1-
Keywords: nsbeta1nsbeta1-
top100, topperf, severity: major ... this seems to have a great impact on 
DHTML in general - shouldn't this be tried to fix for 1.0 ?
How can this bug be targeted to 1.1 when bug 21762 is targeted to 0.9.9?
Keywords: mozilla1.0+
Keywords: mozilla1.0
sorry my computer is having firewall issues, same testcases are now temporarily hosted by dcran.
This contains the profiles for the 4 testcases attached to this bug, created
using the "Profile" feature of venkman.
I tweaked the fishcam dhtml script to be a bit more pathological, it now has 12
animated objects with alpha blended pngs, see
<http://www.hacksrus.com/~ginda/animator/circles.html>.
reinstating original URL for version of time is on the move, which works in 
Nav4x: http://www.html-online.de/niko.temp/time/time.html  (why was this 
changed in the first place?).

A version adjusted to work in mozilla is
  http://bugzilla.mozilla.org/attachment.cgi?id=59020&action=view
Whiteboard: [Hixie-P1] → [Hixie-P1] http://DEATHSTARII.imperialnetwork.org:8080/70156/
This works quite well under the reflow tree branch (bug 129115).
Depends on: 129115
Keywords: mozilla1.0+mozilla1.0-
The dhtml performance is getting better :)

But it's still very slow compared to IE.

(Using 2002050508 / Win 2000)

One slow example:
http://www.formula-one.nu/dhtml/fish/fish2.htm

If you block the images from loading it's much faster.
Also with the lastest build (with patch for bug 129115) things are quite the 
same.
Depends on: 75121
Using trunk build 2002052308 on win-xp,1.1ghz,512RAM this little and simple 
animation (ticker text) is bringing my system nearly down. 100% CPU usage and 
a very sluggish responding Mozilla.
http://www.frantschach.com
Taking bug, at least for the time being.
Assignee: attinasi → rjesup
Status: ASSIGNED → NEW
I've read through a few of these dhtml performance bugs and done some testing
myself (some results in http://bugzilla.mozilla.org/show_bug.cgi?id=117436#c30
and http://bugzilla.mozilla.org/show_bug.cgi?id=117061#c70). In conclusion, for
me it looks like all the symptoms finally lead to two problems:

1. painting is too slow (for example resizing images all the time)
2. we paint too much (static pieces)

There seems to be also some weird stuff going on with painting that is affected
by changes in display mode on at least one system of mine (see the first comment
above).
Exaclty - testing with trunk build 2002062808 on win-xp pro,1.1ghz,512ram the 
testcase at
http://www.formula-one.nu/dhtml/fish/fish2.htm
is very choppy at 32bit but running great in 16bit color depth, if I change 
the color mode and don't restart Mozilla. If I restart Mozilla then the 
testcase is same slow in 16bit mode.

That's the same Ere reported in bug 117436 comment #30
Jprofs are needed with latest trunk (perhaps with and without images blocked?)
Status: NEW → ASSIGNED
Depends on: 164421
Blocks: 164421
No longer depends on: 164421
the "fish testcase" is now located at
http://www.world-direct.com/mozilla/dhtml/fish2.htm

seems we still have no clue what is going wrong here. cc'ing a few people.
Keywords: perfmozilla1.2, nsbeta1
Basing on Comment #65 - WFM. Mozilla 2002121008. Mozilla is smoother and faster
than IE here.
With build 2002121204, Windows 2000 this is still extremly slow. 
Just check out the URL attach to this bug, results: 

 - Mozilla 29 seconds (+ CPU going up to 100%)
 - IE 3.5 seconds!
Right, this one is still very slow. But testcase from Comment #65 works now.
Depends on: 186465
adt: nsbeta1-
Keywords: nsbeta1nsbeta1-
Keywords: 4xp, mozilla1.2, nsbeta1-
Whiteboard: [Hixie-P1] http://DEATHSTARII.imperialnetwork.org:8080/70156/ → [Hixie-P1]
bug@annevankesteren.nl, is this truly no longer 4xp?
Yes. Since NN 4.x doesn't have market share anymore the keyword has been deprecated.
With latest Firefox 3beta5pre the URL gives around 3.888, and with IE7 - 4.0x but we still get CPU up to 40-50% while IE7 keeps it at 0% during this test
Target Milestone: mozilla1.1alpha → Future
QA Contact: ian → general
Build ID:
Mozilla/5.0 (Windows; U; Windows NT 5.1; en-US; rv:1.9.3a1pre) Gecko/20091113 Minefield/3.7a1pre

Testcase faster in Firefox than IE. CPU usage 15.
The issue in description 0 is no longer visible. 

Testcase is faster in Firefox than Chrome and IE. Marking this as WFM.

I believe that it would be better to open a new bug for a  specific issue instead of having a bug description that applies to "some" "slow" "animations".
Status: ASSIGNED → RESOLVED
Closed: 24 years ago14 years ago
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.

Attachment

General

Created:
Updated:
Size: