stutter/lag on protovis force-directed layout demo




JavaScript Engine
8 years ago
4 years ago


(Reporter: shaver, Unassigned)


(Blocks: 1 bug, {perf})

Windows 7

Firefox Tracking Flags

(Not tracked)



when dragging the main node around in the demo, the graph updating is much stutter on my 4-core Win 7 desktop.  Chrome is smooth, though both seem to be saturating a core.  Firefox keeps that core pegged for several seconds after I finish dragging, though.

tried a JM tbox build from today and today's m-c nightly, same visually as well as in terms of CPU "hangover".  Not set up to profile on this box, and I'm not sure we have symbols in the server for JM tbox builds anyway!
Blocks: 579390
OK.  I did a profile of TM and a profile of JM+tracing.  The latter is somewhat faster, looks like, but still slower than Chrome.  Going to focus on the JM profile for the moment (because for TM 25% of the time is in js_Interpret, so...)

For JM, the story seems to be that 49% of total time is spent in libmozjs doing the main script execution (so somewhere between when JS_CallFunctionValue is called for the timeout or event handler and when we reenter libgklayout).  The rest seems to be:

17% painting.  The lion's share of this is nsSVGPathGeometryFrame::Render.  I
    wonder how this does with d2d; I'm profiling on Mac, obviously.
 2% event dispatch for the various mouse moves I was doing.
 3% under some minor DOM stuff.
24% under the nsIDOMElement_SetAttribute quickstub, breaking down as:
  1% AttributeWillChange
  2% constructing the nsAString from the JSString (good old JS_ValueToString;
     with TM we really benefit from traceable natives here!)
  4% parsing path attributes
  1% nsAttrValue munging
 12% nsIFrame invalidation (InvalidateWithFlags up the tree)
  2% nsSVGPathGeometryFrame::UpdateCoveredRegion
  1% FindFilterInvalidation

Total gklayout time is about 46%.  We have some plans for improving the invalidation end of things there; not sure about painting.

Now for the time under JS_CallFunctionValue.  Percentages that follow are percentages of the time under JS_CallFunctionValue with all the libgklayout stuff it calls into removed, so the "js engine" part of the situation.  You can get whole-testcase percentages by dividing by 2 or so, since the sum of the stuff below is about 49% of total.

Things that take the most time in themeselves (not under; all these are self percentages):

24% in JaegerShot or jit-generated symbol-less code.
 7% in js_Interpret (called via MonitorTracePoint or RunTracer or
 4% malloc
 2% realloc
 2% free (from the background thread, mostly)
 5% in JSScope::searchTable
 4% in js_LookupPropertyWithFlags
 3% in js_dtostr
 3% in InlineGetProp
 2% in js_fun_apply
Looking at a top/down profile, there's the usual nesting of fun_apply and fun_call withing each other.  Some RunTracer stuff around, with MonitorTracePoint ending up calling apply.  

Some things that jump out at me; these percentages are NOT exclusive of the ones above:

* stubs::Add is somewhere north of 11% of the total jseng time.  This is about
  1/6 js_ConcatStrings and the rest js_NumberToStringWithBase (js_dtostr is
  about half the total Add time, and js_NewStringCopyZ is about a third).

* stubs::GetElem is about 4% of the total jseng time.  A third of this is in
  GetElem itself (or maybe jit code that I blamed to it?  Not sure; plus some
  of this is ebp munging; I need to update to a build with -fomit-frame-
  pointer), another third under js_LookupPropertyWithFlags.  Getting Values off
  sp and into locals seems to take 5-6 mov instructions each.  :(

* stubs::GetProp is about 8% of the total jseng time.  Lots of InlineGetProp
  (or jit code it calls?  1/3 of the time here).  
  1/5 js_LookupPropertyWithFlags, 1/12 in GetProp stub itself.  1/6 propcache
  fills and tests.  1/10 js_NativeGet.  Are we missing PICs here?

* stubs::SetElem is about 5% of total jseng time.  1/3 self time (maybe
  including jit code), 1/3 js_LookupPropertyWithFlags, 1/3 in
  js_SetPropertyHelper.  Again, are we missing PICs?

* stubs::CallProp is about 3% of jseng time.  Again, self, lookups, propcache.

* various minor stuff (stubs::Name, stubs::Arguments, stubs::Callwhatever).
  Under 2% each, most under 1%.

I wonder how much of the stutter shaver sees is painting-related, not js-related....
When I run this benchmark I see an inordinate amount of GCs in the error console, all clocking in at around 10ms.
FWIW, this site has a bunch of demos. I found this bug via the n-body demo, which is also noticeably faster in Chrome vs Firefox.

Comment 4

5 years ago
The demo is not working on Nightly 27, but it's working on Firefox 25 Beta 11.
Guilherme, do you still see this not working in a nightly?
Flags: needinfo?(guijoselito)

Comment 6

4 years ago
Something fixed the problem for me. Working perfectly and very fast!
Last Resolved: 4 years ago
Flags: needinfo?(guijoselito)
Resolution: --- → WORKSFORME
You need to log in before you can comment on or make changes to this bug.