emberjs / ember.js

Ember.js - A JavaScript framework for creating ambitious web applications
https://emberjs.com
MIT License
22.46k stars 4.21k forks source link

Component creation performance is slower in 1.13 than in 1.12 #11502

Closed GavinJoyce closed 8 years ago

GavinJoyce commented 9 years ago

The performance of the initial component render times seems to be significantly slower in Ember 1.13 than in Ember 1.12.

Ember 1.13: http://emberjs.jsbin.com/zijuye

image

Ember 1.12: http://emberjs.jsbin.com/layoso

image

Ember 1.11: http://emberjs.jsbin.com/kunaco

Ember 1.10: http://emberjs.jsbin.com/xivavi

GavinJoyce commented 9 years ago

Possibly a dupe of https://github.com/emberjs/ember.js/issues/10261 which I've just come across.

stefanpenner commented 9 years ago

i would like to see the numbers without the ember inspector open. The inspector itself does negatively affect performance as it instrumentation overhead isn't non-trivial, it is possible that merely the instrumentation has changed to favor the former. Even if not, it non-inspector #'s would provide a more accurate perspective.

rwjblue commented 9 years ago

Quick stab at removing the need for measuring with the inspector:

1.13.0 - 112.159ms 1.12.0 - 47ms


Also, please note that 1.13.0 and 1.13.1 production builds still included all deprecations (because of an issue with the build pipeline which was fixed in 1.13.2).

stefanpenner commented 9 years ago

1.13.2 drops to: 81.203ms

This may also be do to the slightly different babel transpiled output, although I hope to a lesser degree.

OrKoN commented 9 years ago

@rwjblue @stefanpenner I have found an old benchmark which compares performance of major frameworks using a todo app. The benchmark was using an old version of Ember so I migrated it to Ember 1.13.2. Surprisingly to me, Ember turns out to be 4-10 times slower. Maybe you could take a look at the app as you're experts? I hope I am doing something terribly wrong in the app or in the test.

selection_104

Git: https://github.com/OrKoN/todomvc-perf-comparison Live: http://blog.alex-rudenko.com/todomvc-perf-comparison/

stefanpenner commented 9 years ago

This test is a-bit quirky, although there are likely some issues with initial render. So please don't assume I am being dismissive of a potential problem.

Let me explain, ember makes the following assumption:

1 click producing a 100 changes, is more realistic then 100 sequential clicks each producing 1 change.

So we batch work, and do optimizations per click. The overhead for these optimizations means the 100 sequential clicks case is poor, but benefit being, the realistic scenario should benefit from the optimizations.

A quick adjustment, to instead perform the same optimization but in what i consider to be the unrealistic scenario results in:

before:

Ember : Adding100Items : Sync: 2253.7569999694824 ms
Ember : Adding100Items : Async: 32.8890000237152 ms
Ember : CompletingAllItems : Sync: 357.1809999994002 ms
Ember : CompletingAllItems : Async: 16.21599995996803 ms
Ember : DeletingItems : Sync: 1841.7600000393577 ms
Ember : DeletingItems : Async: 10.8780000009574 ms
Ember : 4512.680999992881 ms
Run 1/1 - Total : 4512.680999992881 ms

after:

Ember : Adding100Items : Sync: 534.5300000044517 ms
Ember : Adding100Items : Async: 33.12600002391264 ms
Ember : DeletingItems : Sync: 612.1939999866299 ms
Ember : DeletingItems : Async: 14.044000010471791 ms
Ember : 1193.894000025466 ms
Run 1/1 - Total : 1193.894000025466 ms

It's worth noting, this still isn't really realistic, As simulating 100 sequential clicks isn't how an app would normally delete 100 items. It's even highly unlikely that a user could issue 100 clicks at 60fps, which would result in 1600ms of idle time.

I suspect if the test was adjusted to have a single actions that added 100 and a single actions that removed 100, and another action that merely mutated 100. We would be able to see something useful.

Now thats not saying that improvements here couldn't provide some benefit, but they run the risk of focusing on the wrong things, and maybe even making the important case worse.

sandstrom commented 9 years ago

I've created a simple example app on initial rendering performance, basically a bunch of small components. Perhaps it's useful for investigations.

OrKoN commented 9 years ago

I think I get the idea but it seems that it's not quite working at the moment. Although the tests support the idea (see below). The app is faster when 100 items are inserted at once. But still slower than others.

I have modified the angular and ember apps to insert 100 items at once (with update & removal as previously):

image

only insertion of 100 items at once w/o removal and update:

image

insertion 1 by 1 w/o removal and update:

image

Then I thought that the Ember app may be slower due to ember-data and the locale storage adapter that it uses. So I changed the app to use just Ember.A. This is a batch insert of 100 items at once:

image

In my real app, I have got a problem with a dropdown. ~200 items take 600ms for initial rendering (gets worse on mobiles). So it's pretty much like this screen:

image

or with backbone included:

image

Also I want to say that most of other apps seem low-level to me and harder to understand than the Ember app. But performance is important too.

mixonic commented 9 years ago

A complete aside, but FWIW I constantly reference the benchmarks in https://github.com/eviltrout/ember-performance to understand how Ember's performance changes over time. Please contribute benchmarks to that repo, and improve what is there. A one-off repo may be helpful for this immediate discussion, but will not have a long-term impact.

That is all, thanks :-)

GavinJoyce commented 9 years ago

Thanks @mixonic, I'll make some conributions to ember-performance.

The Renders Complex List test captures the difference between 1.12.0 and 1.13.3:

image

image

marcemira commented 9 years ago

I have a huge and heavily loaded of components page... Since I switched from 1.12.1 to 1.13.3 it is now WAY slower.. T__T . Transitions with liquid-fire freezes and glitches for 2 o 3 seconds :/ - Without liquid fire, takes around the same amount of time but instead, it renders the loading template (not the case with liquid-outled for some odd reason)

stefanpenner commented 9 years ago

Ya lots of the compat layer stuff seems to be borking performance. Hopefully someone dives in

GavinJoyce commented 9 years ago

@stefanpenner do you have any pointers on where to begin looking?

stefanpenner commented 9 years ago

that question feels like a trap. Start with the profiler, grab a coffee, put on some good trance music and hang on & hope for the best.

stefanpenner commented 9 years ago

My ember-conf talk is also related

GavinJoyce commented 9 years ago

:-) thanks

stefanpenner commented 9 years ago

Rather then sleeping (now i have resorted to coffee), I did some checking and noticed a large number of small issues. Some of these issues have the potential to cause pretty hefty work amplification. Although fixing each of them will only result in a small win, we are currently in a death by a thousand papercuts scenario.

My plan is to slowly (as time permits) go through each issue in detail

Anyways the first finding, it appears far to many change related events are firing during initial render. This is obviously not needed, since initial render should have sufficient state for initial render, and not rely on change events to complete its render ( at-least in this situation)

For reference, I just added some extra debugging code to sendEvent to see what was going on. I did this since it was near the top of the profile, but on initial render it should really be nearly unused.

The resulting instrumentation output was:

// fine
@array:before: 3
@array:change: 3
@enumerable:before: 3
@enumerable:change: 3
activate: 2
arrangedContent:before: 1
arrangedContent:change: 1

// unexpected on initial render.
attrs.context:before: 2203
attrs.context:change: 2203
attrs.layoutName:before: 2203
attrs.layoutName:change: 2203
attrs.templateName:before: 2203
attrs.templateName:change: 2203
attrs:before: 2203
attrs:change: 2203

// fine
content:before: 1
content:change: 1

// unexpected
controller:before: 2201
controller:change: 2201

// expected (these are the life-cycle hooks)
didInitAttrs: 2200
didInsertElement: 2202
didReceiveAttrs: 2200
didRender: 2202

// routing
didTransition: 1

// expected
init: 2216

// strange but to low to care about
length:before: 3
length:change: 3
model:before: 1
model:change: 1

// very might unexpected
parentViewDidChange: 2201

// expected
willInsertElement: 2202
willRender: 2200

// expected
willTransition: 1

Well, apparently we have 2200 components/views, so some life-cycle events should be happening but clearly lots of these really should NOT be happening. Not only are the dispatches wasteful but potential consumers may considerably amplify the work.

Anyways, after reviewing the instrumentation two discrete problematic areas appear:

  1. parentView <-> view is invalidating on initial render – this results in parentViewDidChange, controller:before, controller:after events.
  2. this.attrs* are invalidating on initial render

parentView <-> view

Is the smaller of the two, but also the easiest to fix quickly. Based on the assumption that we render top -> bottom (which turns out to be true), there is no reason to create a child before the parent, and as such we should be able to give the parent to the child at creation. This ensures the parentView reference is part of the initial state of the childView, and costing us 0 changeEvents.

When looking at the componentCreation code, we clearly already setup the parent -> child relationship at child creation time: ...

The offending code is actually linkChild which explicitly calls set and instance.trigger. Set correctly detects that nothing changes, and doesn't emit a observer change event, but the trigger isn't ware of this, and fires regardless. Causing some of the unexpected work.

proposed fix: https://github.com/emberjs/ember.js/blob/5c6b6278b6807b55dc4d70823c9b04e182eb3609/packages/ember-views/lib/mixins/view_child_views_support.js#L124-L129 (need to fixup some things, and write tests)

The result was a marginally improved experience (sendEvent dropped by 10-15%). Clearly more to do.

Also note: the container and ownerView should not change post initial componentCreation. ownerView is a bit dubious still so i left it for now, but i also removed container set.

this.attrs invalidations

This second one is more involved, but we can also break it down into two chunks.

  1. this.attrs itself
  2. this.attrs.*

The first this.attrs is being reset during render, I believe this is largely to do with how positionalArgs are provided:

I have left an idea for discussion:

The second this.attrs.* currently always broadcasts changes: https://github.com/emberjs/ember.js/blob/master/packages/ember-views/lib/compat/attrs-proxy.js#L75-L87 Again, even if the state is the initial state.

I haven't opened a targeted issue for this one yet, but hope to after ^^

Thats all for now, ^^ will likely keep me busy for some time. During my session i did notice many other offenders, some future iteration will try to explore them further.

marcemira commented 9 years ago

:+1: :+1:

sandstrom commented 9 years ago

Awesome, your wizard eyes on this are hugely appreciated! :dizzy:

GavinJoyce commented 9 years ago

I'm seeing a small improvement in 1.13.4 (using this ember-performance PR)

image

image

image

stefanpenner commented 9 years ago

@GavinJoyce I also noticed mandatory setter was mistakenly left enabled in 1.13.x which is a mega slow down. @rwjblue has a quick fix and I suspect another release is imminent.

rwjblue commented 9 years ago

I updated the 1.13.4 builds (instead of immediately releasing a 1.13.5). The builds @gavinjoyce used in ember-performance (see PR over there) did not include the mandatory-setter mistake.

marcemira commented 9 years ago

@rwjblue thanks! :+1:

GavinJoyce commented 9 years ago

Ember 1.13.5 (pr) shows no significant change from 1.13.4:

image

Ember 1.12.0:

image

devlo commented 9 years ago

I am too seeing degrade in rendering performance in components... huge degrade between 1.12 and 1.13.4, it's so big that it's noticeable for user. I need loading spinners in 1.13.4 on content that i didn't use them before in 1.12, because waiting times are such higher. In one of you blog posts you wrote:

Initial render of component-heavy pages shows some improvement in most of our tests

while using glimmer engine. I have different components on different routes, some of them complex, some nested etc. I do not have any depreciation's in code, i am no expert either, but i am not seeing any improvement, only slower rendering times. I've checked some of big ember implementations, some of random sites where people use ember etc and in only about 10%-20% of them i could really see glimmer shine, in the rest of them current glimmer version would only degrade render performance without any benefit. Please correct me if i am wrong. It's not like everyone have use case with list of companies from stock market in which 100+ elements are updated every 500 ms...
I really love ember, i really love developing with ember and most of its concepts. While 1.12 version performance was only acceptable taking into consideration all the benefits of the framework, 1.13+ in this state is not.. As i said before i am no expert, so maybe some expert could answer my question.. is it possible that glimmer will be in future at least as fast as engine from 1.12 version ?

stefanpenner commented 9 years ago

is it possible that glimmer will be in future at least as fast as engine from 1.12 version ?

This isn't glimmer related at all. Code above the glimmer layer is causing the issues, and large due to compatibility. My comment above begins the investigation -> https://github.com/emberjs/ember.js/issues/11502#issuecomment-119667735 and the just got +1 on fixing another piece of the puzzle https://github.com/emberjs/ember.js/issues/11686

GavinJoyce

Ya, this is expected. I don't believe any performance tweaks would have landed for that release. But atleast it did not regress further.

If you have time, adding more comprehensive tests to ember-performance would be fantastic.

GavinJoyce commented 9 years ago

@stefanpenner sure, I'd be happy to do that.

stefanpenner commented 9 years ago

@stefanpenner sure, I'd be happy to do that.

We have always wanted a good thorough regression suite. That we could easily use to test for regressions, and also run on a regular basis (i think automation would be a stretch goal, but requires some dedicated hardware to reduce variability that vms introduce. I have such a machine handy if needed)

devlo commented 9 years ago

@stefanpenner Thank you for clarification and all your hard work investigating the core of this issue, i hope for the best.

peec commented 9 years ago

I'm having trouble with this as well, it takes around 351ms to load up a select menu (built on components). Ember 1.13.5. On mobile, its really really slow (tested on android / chrome )

Live test: http://jensb.home.pkj.no/paper-menu/index.html#/paper-select The related code for these menus: https://github.com/miguelcobain/ember-paper/pull/140

When the select menu has 5 items, its only 61ms. When it has 51 items it takes around 351ms.

stefanpenner commented 9 years ago

@ef4 implemented fixes for the first work amplifications I described above in #11935 which resulted in 10%-15% speedup. Not the whole story, but a good step in the right direction.

It does appear some more work amplifications still exist, i mentioned them in chat to @ef4 but will try to report in issue form sometime soon. (got family over for the next while, so i am unsure how active i will be).

After some other small adjustments it appeared another 5% or more should be considered low hanging fruit.

A quick test shows that our friend V8 is 2x-3x slower then Safari when running @sandstrom's code... This difference is partially (a non trivial portion of it is ) related to my ember-conf talk. Where V8 does very poorly, when excess shape allocations occur. It appears that the recent view layer refactoring, although much nicer then before has actually introduced some additional related issues.

I'll keep diving for long hanging fruit, as that gives us the best bang for our buck.

sandstrom commented 9 years ago

@stefanpenner I appreciate the ongoing investigations, and fruit harvest! :green_apple:

rwjblue commented 9 years ago

"Render Complex List" results for 1.13.6:

All tests against 1.12.1, 1.13.5, and 1.13.6: https://gist.github.com/rwjblue/fe7223e7d10801b37ae0

stefanpenner commented 9 years ago

another related PR (with some nice improvements) https://github.com/emberjs/ember.js/pull/11946

stefanpenner commented 9 years ago

something of interest, i have added some ghetto instrumentation to get a picture of how the new code is being utilized:

_createOwnMap: 3008
_geInherited: 25355
_getOrCreateInheritedMap: 17289
_getOrCreateInheritedMap.create: 110
_getOrCreateInheritedMap.fromParent: 5287
_getOrCreateOwnMap: 5269
inheritedCustomObject_readableChains: 2220
inheritedCustomObject_writableChains: 0
inheritedMapOfMaps_getAllDeps: 0
inheritedMapOfMaps_readableDeps: 6
inheritedMapOfMaps_writableDeps: 4404
inheritedMap_clearBindings: 0
inheritedMap_clearMixins: 0
inheritedMap_clearValues: 0
inheritedMap_clearWatching: 0
inheritedMap_peekBindings: 0
inheritedMap_peekMixins: 5405
inheritedMap_peekValues: 0
inheritedMap_peekWatching: 15367
inheritedMap_readAbleBindings: 2357
inheritedMap_readAbleMixins: 0
inheritedMap_readAbleValues: 0
inheritedMap_readAbleWatching: 0
inheritedMap_writableBindings: 0
inheritedMap_writableMixins: 188
inheritedMap_writableValues: 0
inheritedMap_writableWatching: 7410
ownCustomObject_readableChainWatchers: 7438
ownCustomObject_writableChainWatchers: 0
ownMap_reableCache: 28
ownMap_writable_Cache: 5269

the following is likely the worse offender in-terms of performance.

_getOrCreateInheritedMap.fromParent: 5287
stefanpenner commented 9 years ago

Another interesting set of data is seeing which gets are most common: I have also annotated which of these are actually descriptors.

note: i have removed those of small N.

_deprecatedFlagForBlockProvided: 2200
_template: 2200
ariaRole: 2201
classNameBindings: 2201
classNames: 2201
controller: 2100
defaultLayout: 2202
defaultTemplate: 2202
isTruthy: 801
isVisible: 4403
layout: 2202 (desc)
layoutName: 2208
length: 862
moduleNameLookupPatterns: 46
namespace: 40
parentView: 2201
templateName: 2202
_template: 2200 (desc)
[]: 801 (desc)

interestingly, most of these will be identical between gets.

the descriptor ones are most interesting, as they are typically CP that set up watchers. Again, for often something that is totally static.

stefanpenner commented 9 years ago

another interesting thing:

these are MutableDependencies for ProxyStream

"": 701
(mut i): 1600
(mut i).[]: 800
i: 800
model: 2
model.[]: 1
undefined: 6607
view: 11011
view.context: 4405
view.controller: 4405

view/view.context and view.controller are providing 0 value right now, but they are still being created. In-addition, even if they did provide value, each enumeration gets its own unique object here. These allocations do add up.

ef4 commented 9 years ago

I bet all 15400 gets of _template, defaultLayout, defaultTemplate, layout, layoutName, templateName, and template returned undefined, because those are all niche features that the vast majority of components don't use, and that I would suggest against anyone using in a new app.

stefanpenner commented 9 years ago

@ef4 yup. I have some ideas to make cp faster, but also we shouldn't use them speculatively like this

rwjblue commented 9 years ago

The gets for _template, template, templateName, and defaultTemplate should all be removed now on canary as of https://github.com/emberjs/ember.js/pull/12027.

stefanpenner commented 9 years ago

@rwjblue nice

stefanpenner commented 9 years ago

The performance of the initial component render times seems to be significantly slower in Ember 1.13 than in Ember 1.12.

just updated the jsbin, it appears the initial render performance of legacy components (as apposed to angle brackets – which perform better) is near parity again http://jsbin.com/qecubegace/edit?html,js,output

50ms on my machine on latast release 42ms on my machine for 1.12

Although we are approaching parity, going forward:

Thanks for your patiences on this, and @rwjblue / @ef4 for helping drive the patches :)

peec commented 9 years ago

This is super awesome, thanks a lot for the work going on the performance issues :+1:

stefanpenner commented 9 years ago

This is super awesome, thanks a lot for the work going on the performance issues

more to do, @sandstrom example is still not near parity, although the original jsbin is.

His example involves more nested and likely some other factors.

GavinJoyce commented 9 years ago

Complex list rendering performance continues to improve (:beers:):

image

image

image

image

rwjblue commented 9 years ago

A few more PR's to do less work on initial render:

rwjblue commented 9 years ago

Also to note: the ember-performance suite used in some of the numbers above suffers from an issue that causes all of ember-metal to be a debug build for Ember 1.13 and above. I created an issue to track that over in https://github.com/eviltrout/ember-performance/issues/49. This makes comparisons using ember-performance with Ember versions above 1.12 a bit off (since it includes Ember.deprecate, Ember.assert, etc statements).

GavinJoyce commented 9 years ago

I have a PR to update the ember-performance tests to work with 2.0 and have gathered some raw (and with a caveat) data here:

image

Spreadsheet: https://docs.google.com/spreadsheets/d/15MPfzCncD_PvM-nmfdrA-_UsUzNpAVV9pFkt3wU5rBo/edit?usp=sharing

GavinJoyce commented 9 years ago

Here are some quick numbers for the Render Complex List performance test now that https://github.com/eviltrout/ember-performance/issues/49 has been closed:

image

GavinJoyce commented 9 years ago

I've added the ability to run performance tests against multiple versions of ember and to show graphs, here are the latest numbers for the complex list benchmark:

image