Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

sluggish startup times #6009

Closed
stefanpenner opened this issue Jun 21, 2016 · 14 comments
Closed

sluggish startup times #6009

stefanpenner opened this issue Jun 21, 2016 · 14 comments
Labels

Comments

@stefanpenner
Copy link
Contributor

 ~ ember v                                                                                                    (878ms)
WARNING: Addon[ember-try]'s commands took: 194ms to load, see: http://some-link.com/help
ember-cli: 2.7.0-beta.3-log-slow-command-loads-61749d551d
node: 6.2.2
os: darwin x64


Start time: (2016-06-21 06:51:29 UTC) [treshold=1%]
 #  module                                               time  %
 1  graceful-fs (src/ember-c...eful-fs/graceful-fs.js)   11ms  ▇ 1%
 2  glob (src/ember-cli/node_modules/glob/glob.js)       17ms  ▇ 2%
 3  rimraf (src/ember-cli/no...dules/rimraf/rimraf.js)   18ms  ▇ 2%
 4  ./remove (src/ember-cli/...ra/lib/remove/index.js)   19ms  ▇ 2%
 5  fs-extra (src/ember-cli/.../fs-extra/lib/index.js)   61ms  ▇▇▇ 6%
 6  ./_Hash (src/ember-cli/n...odules/lodash/_Hash.js)   12ms  ▇ 1%
 7  ./_mapCacheClear (src/em...dash/_mapCacheClear.js)   13ms  ▇ 1%
 8  ./_MapCache (src/ember-c...es/lodash/_MapCache.js)   20ms  ▇ 2%
 9  ./_stackSet (src/ember-c...es/lodash/_stackSet.js)   20ms  ▇ 2%
10  ./_Stack (src/ember-cli/...dules/lodash/_Stack.js)   28ms  ▇▇ 3%
11  ./_equalObjects (src/emb...odash/_equalObjects.js)   11ms  ▇ 1%
12  ./_baseIsEqualDeep (src/...sh/_baseIsEqualDeep.js)   30ms  ▇▇ 3%
13  ./_baseIsEqual (src/embe...lodash/_baseIsEqual.js)   30ms  ▇▇ 3%
14  ./_baseIsMatch (src/embe...lodash/_baseIsMatch.js)   59ms  ▇▇▇ 5%
15  ./_baseMatches (src/embe...lodash/_baseMatches.js)   61ms  ▇▇▇ 6%
16  ./_baseIteratee (src/emb...odash/_baseIteratee.js)   72ms  ▇▇▇▇ 7%
17  ./_createFind (src/ember.../lodash/_createFind.js)   72ms  ▇▇▇▇ 7%
18  lodash/find (src/ember-c...modules/lodash/find.js)   77ms  ▇▇▇▇ 7%
19  ./_baseClone (src/ember-...s/lodash/_baseClone.js)   15ms  ▇ 1%
20  ./_baseMergeDeep (src/em...dash/_baseMergeDeep.js)   22ms  ▇▇ 2%
21  ./_baseMerge (src/ember-...s/lodash/_baseMerge.js)   25ms  ▇▇ 2%
22  lodash/merge (src/ember-...odules/lodash/merge.js)   25ms  ▇▇ 2%
23  ../models/addon-discover...els/addon-discovery.js)   12ms  ▇ 1%
24  ../models/command (src/e.../lib/models/command.js)   36ms  ▇▇ 3%
25  ../models/project (src/e.../lib/models/project.js)  264ms  ▇▇▇▇▇▇▇▇▇▇▇▇▇ 25%
26  diff (src/ember-cli/node...ules/diff/lib/index.js)   14ms  ▇ 1%
27  ./edit-file-diff (src/em...dels/edit-file-diff.js)   23ms  ▇▇ 2%
28  ./file-info (src/ember-c...ib/models/file-info.js)   33ms  ▇▇ 3%
29  inflection (src/ember-cl...tion/lib/inflection.js)   11ms  ▇ 1%
30  ../models/blueprint (src...ib/models/blueprint.js)   69ms  ▇▇▇▇ 6%
31  ../utilities/merge-bluep...e-blueprint-options.js)   70ms  ▇▇▇▇ 7%
32  ./new (src/ember-cli/lib/commands/new.js)            72ms  ▇▇▇▇ 7%
33  /Users/stefanepenner/src.../lib/commands/addon.js)   73ms  ▇▇▇▇ 7%
34  /Users/stefanepenner/src.../lib/commands/serve.js)   11ms  ▇ 1%
35  ../models/builder (src/e.../lib/models/builder.js)   16ms  ▇ 1%
36  /Users/stefanepenner/src...i/lib/commands/test.js)   17ms  ▇ 2%
37  /Users/stefanepenner/src...cli/lib/tasks/serve.js)   15ms  ▇ 1%
38  ../lib/cli (src/ember-cli/lib/cli/index.js)         437ms  ▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇ 41%
39  leek (src/ember-cli/node...dules/leek/lib/leek.js)   18ms  ▇ 2%
40  lodash.merge (src/ember-.../lodash.merge/index.js)   13ms  ▇ 1%
41  yam (src/ember-cli/node_modules/yam/lib/yam.js)      16ms  ▇ 1%
42  configstore (src/ember-c...s/configstore/index.js)   13ms  ▇ 1%
43  ./baseMergeDeep (src/emb...ernal/baseMergeDeep.js)   17ms  ▇ 2%
44  ../internal/baseMerge (s.../internal/baseMerge.js)   21ms  ▇ 2%
45  lodash/object/merge (src...lodash/object/merge.js)   24ms  ▇▇ 2%
46  ./lib/style-plugin (src/...ry/lib/style-plugin.js)   34ms  ▇▇ 3%
47  ./ (src/ember-cli/node_m...cess-registry/index.js)   38ms  ▇▇ 4%
48  ember-cli-preprocess-reg...istry/preprocessors.js)   38ms  ▇▇ 4%
49  broccoli-funnel (src/emb...occoli-funnel/index.js)   12ms  ▇ 1%
50  ../models/addon (src/emb...li/lib/models/addon.js)   54ms  ▇▇▇ 5%
51  lodash/array (src/ember-...odules/lodash/array.js)   58ms  ▇▇▇ 5%
52  node-fetch (src/ember-cl...es/node-fetch/index.js)   24ms  ▇▇ 2%
53  ./fetch-ember-versions-f...ersions-from-github.js)   25ms  ▇▇ 2%
54  ./get-ember-versions (sr.../get-ember-versions.js)   83ms  ▇▇▇▇ 8%
55  ember-try-config (src/em...io-config-for-ember.js)   85ms  ▇▇▇▇ 8%
56  ../utils/config (src/emb...ry/lib/utils/config.js)   87ms  ▇▇▇▇ 8%
57  lodash (src/ember-cli/no...odules/lodash/index.js)   45ms  ▇▇▇ 4%
58  ./utils (src/ember-cli/n...li-table2/src/utils.js)   53ms  ▇▇▇ 5%
59  ./src/table (src/ember-c...li-table2/src/table.js)   59ms  ▇▇▇ 5%
60  cli-table2 (src/ember-cl...es/cli-table2/index.js)   59ms  ▇▇▇ 5%
61  ./../utils/result-summar...tils/result-summary.js)   60ms  ▇▇▇ 6%
62  fs-extra (src/ember-cli/.../fs-extra/lib/index.js)   26ms  ▇▇ 2%
63  ../dependency-manager-ad...ager-adapters/bower.js)   30ms  ▇▇ 3%
64  ./../utils/dependency-ma...ger-adapter-factory.js)   32ms  ▇▇ 3%
65  ../tasks/try-each (src/e.../lib/tasks/try-each.js)   99ms  ▇▇▇▇▇ 9%
66  ./try (src/ember-cli/nod...ry/lib/commands/try.js)  187ms  ▇▇▇▇▇▇▇▇▇ 17%
67  ./lib/commands (src/embe.../lib/commands/index.js)  194ms  ▇▇▇▇▇▇▇▇▇ 18%
68  ./pubsuffix (src/ember-c...ookie/lib/pubsuffix.js)   20ms  ▇ 2%
69  tough-cookie (src/ember-...h-cookie/lib/cookie.js)   28ms  ▇▇ 3%
70  ./lib/cookies (src/ember...request/lib/cookies.js)   28ms  ▇▇ 3%
71  bl (src/ember-cli/node_modules/bl/bl.js)             12ms  ▇ 1%
72  hawk (src/ember-cli/node...ules/hawk/lib/index.js)   15ms  ▇ 1%
73  ./formats/auto (src/embe...pk/lib/formats/auto.js)   11ms  ▇ 1%
74  ./private-key (src/ember...hpk/lib/private-key.js)   24ms  ▇▇ 2%
75  ./utils (src/ember-cli/n...les/sshpk/lib/utils.js)   27ms  ▇▇ 3%
76  ./fingerprint (src/ember...hpk/lib/fingerprint.js)   29ms  ▇▇ 3%
77  ./key (src/ember-cli/nod...dules/sshpk/lib/key.js)   36ms  ▇▇ 3%
78  sshpk (src/ember-cli/nod...les/sshpk/lib/index.js)   37ms  ▇▇ 3%
79  ./utils (src/ember-cli/n...signature/lib/utils.js)   39ms  ▇▇ 4%
80  ./parser (src/ember-cli/...ignature/lib/parser.js)   42ms  ▇▇ 4%
81  http-signature (src/embe...signature/lib/index.js)   51ms  ▇▇▇ 5%
82  mime-types (src/ember-cl...es/mime-types/index.js)   14ms  ▇ 1%
83  ./runner (src/ember-cli/...alidator/lib/runner.js)   17ms  ▇ 2%
84  har-validator (src/ember...validator/lib/index.js)   18ms  ▇ 2%
85  ./lib/har (src/ember-cli...les/request/lib/har.js)   18ms  ▇ 2%
86  ./request (src/ember-cli...les/request/request.js)  141ms  ▇▇▇▇▇▇▇ 13%
87  request (src/ember-cli/n...dules/request/index.js)  172ms  ▇▇▇▇▇▇▇▇ 16%
Total require(): 2211
Total time: 1.1s

using: https://www.npmjs.com/package/time-require

@stefanpenner
Copy link
Contributor Author

stefanpenner commented Jun 21, 2016

to biggest offenders are

@rwjblue
Copy link
Member

rwjblue commented Jun 21, 2016

ember-try was updated in ember-cli/ember-try#75, and that was released in v0.2.3.

@stefanpenner
Copy link
Contributor Author

request (likely from leek) 87 request (src/ember-cli/n...dules/request/index.js) 172ms ▇▇▇▇▇▇▇▇ 16% cc @twokul twokul/leek#31

this was seems to not show up all the time..

@stefanpenner
Copy link
Contributor Author

stefanpenner commented Jun 21, 2016

updated:

ember-cli: 2.7.0-beta.4-master-5c83db55a7
node: 5.10.1
os: darwin x64


Start time: (2016-06-21 16:27:40 UTC) [treshold=1%]
 #  module                                                         time  %
 1  chalk (src/ember-cli/node_mod...node_modules/chalk/index.js)    4ms  ▇ 1%
 2  rsvp (src/ember-cli/node_modules/rsvp/dist/rsvp.js)             4ms  ▇ 1%
 3  ../ext/promise (src/ember-cli/lib/ext/promise.js)               4ms  ▇ 1%
 4  graceful-fs (src/ember-cli/no.../graceful-fs/graceful-fs.js)    5ms  ▇ 1%
 5  ./copy (src/ember-cli/node_mo...s/fs-extra/lib/copy/copy.js)    4ms  ▇ 1%
 6  ./copy (src/ember-cli/node_mo.../fs-extra/lib/copy/index.js)    5ms  ▇ 1%
 7  glob (src/ember-cli/node_modules/glob/glob.js)                  7ms  ▇▇ 2%
 8  rimraf (src/ember-cli/node_modules/rimraf/rimraf.js)            8ms  ▇▇ 2%
 9  ./remove (src/ember-cli/node_...s-extra/lib/remove/index.js)    9ms  ▇▇ 2%
10  fs-extra (src/ember-cli/node_modules/fs-extra/lib/index.js)    31ms  ▇▇▇▇▇▇ 9%
11  ./_Hash (src/ember-cli/node_modules/lodash/_Hash.js)            4ms  ▇ 1%
12  ./_mapCacheClear (src/ember-c...es/lodash/_mapCacheClear.js)    4ms  ▇ 1%
13  ./_MapCache (src/ember-cli/node_modules/lodash/_MapCache.js)    5ms  ▇ 1%
14  ./_stackSet (src/ember-cli/node_modules/lodash/_stackSet.js)    6ms  ▇▇ 2%
15  ./_Stack (src/ember-cli/node_modules/lodash/_Stack.js)          8ms  ▇▇ 2%
16  ./_indexKeys (src/ember-cli/n...odules/lodash/_indexKeys.js)    4ms  ▇ 1%
17  ./keys (src/ember-cli/node_modules/lodash/keys.js)              4ms  ▇ 1%
18  ./_equalObjects (src/ember-cl...les/lodash/_equalObjects.js)    5ms  ▇ 1%
19  ./_baseIsEqualDeep (src/ember.../lodash/_baseIsEqualDeep.js)   11ms  ▇▇ 3%
20  ./_baseIsEqual (src/ember-cli...ules/lodash/_baseIsEqual.js)   11ms  ▇▇ 3%
21  ./_baseIsMatch (src/ember-cli...ules/lodash/_baseIsMatch.js)   19ms  ▇▇▇▇ 5%
22  ./_baseMatches (src/ember-cli...ules/lodash/_baseMatches.js)   20ms  ▇▇▇▇ 6%
23  ./_baseIteratee (src/ember-cl...les/lodash/_baseIteratee.js)   24ms  ▇▇▇▇▇ 7%
24  ./_createFind (src/ember-cli/...dules/lodash/_createFind.js)   25ms  ▇▇▇▇▇ 7%
25  lodash/find (src/ember-cli/node_modules/lodash/find.js)        27ms  ▇▇▇▇▇ 7%
26  ./_baseClone (src/ember-cli/n...odules/lodash/_baseClone.js)    5ms  ▇ 1%
27  ./_baseMergeDeep (src/ember-c...es/lodash/_baseMergeDeep.js)    8ms  ▇▇ 2%
28  ./_baseMerge (src/ember-cli/n...odules/lodash/_baseMerge.js)    8ms  ▇▇ 2%
29  lodash/merge (src/ember-cli/node_modules/lodash/merge.js)       9ms  ▇▇ 2%
30  chalk (src/ember-cli/node_modules/chalk/index.js)               4ms  ▇ 1%
31  ./deprecation (src/ember-cli/...e-object/lib/deprecation.js)    4ms  ▇ 1%
32  ./lib/assign-properties (src/...ct/lib/assign-properties.js)    4ms  ▇ 1%
33  core-object (src/ember-cli/no.../core-object/core-object.js)    5ms  ▇ 1%
34  ../models/addon-discovery (sr...b/models/addon-discovery.js)    6ms  ▇▇ 2%
35  nopt (src/ember-cli/node_modules/nopt/lib/nopt.js)              4ms  ▇ 1%
36  lodash/union (src/ember-cli/node_modules/lodash/union.js)       4ms  ▇ 1%
37  ../models/watcher (src/ember-cli/lib/models/watcher.js)         4ms  ▇ 1%
38  ../models/command (src/ember-cli/lib/models/command.js)        17ms  ▇▇▇ 5%
39  ../ui (src/ember-cli/lib/ui/index.js)                           4ms  ▇ 1%
40  npm-package-arg (src/ember-cl...ules/npm-package-arg/npa.js)    5ms  ▇ 1%
41  ../utilities/get-package-base...es/get-package-base-name.js)    5ms  ▇ 1%
42  ../models/project (src/ember-cli/lib/models/project.js)       114ms  ▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇ 31%
43  diff (src/ember-cli/node_modules/diff/lib/index.js)             6ms  ▇▇ 2%
44  quick-temp (src/ember-cli/node_modules/quick-temp/index.js)     4ms  ▇ 1%
45  ./edit-file-diff (src/ember-c...ib/models/edit-file-diff.js)   10ms  ▇▇ 3%
46  ./file-info (src/ember-cli/lib/models/file-info.js)            15ms  ▇▇▇ 4%
47  ../models/blueprint (src/ember-cli/lib/models/blueprint.js)    27ms  ▇▇▇▇▇ 7%
48  ../utilities/merge-blueprint-.../merge-blueprint-options.js)   28ms  ▇▇▇▇▇ 8%
49  ./new (src/ember-cli/lib/commands/new.js)                      29ms  ▇▇▇▇▇ 8%
50  /Users/stefanpenner/src/ember...r-cli/lib/commands/addon.js)   29ms  ▇▇▇▇▇ 8%
51  portfinder (src/ember-cli/nod...ortfinder/lib/portfinder.js)    4ms  ▇ 1%
52  /Users/stefanpenner/src/ember...r-cli/lib/commands/serve.js)    4ms  ▇ 1%
53  tree-sync (src/ember-cli/node_modules/tree-sync/index.js)       4ms  ▇ 1%
54  ../models/builder (src/ember-cli/lib/models/builder.js)         7ms  ▇▇ 2%
55  /Users/stefanpenner/src/ember...er-cli/lib/commands/test.js)    7ms  ▇▇ 2%
56  /Users/stefanpenner/src/ember...mber-cli/lib/tasks/serve.js)    4ms  ▇ 1%
57  ../lib/cli (src/ember-cli/lib/cli/index.js)                   193ms  ▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇▇ 53%
58  lodash.keys (src/ember-cli/no...odules/lodash.keys/index.js)    4ms  ▇ 1%
59  lodash._baseassign (src/ember...lodash._baseassign/index.js)    5ms  ▇ 1%
60  lodash.assign (src/ember-cli/...ules/lodash.assign/index.js)    7ms  ▇▇ 2%
61  leek (src/ember-cli/node_modules/leek/lib/leek.js)             11ms  ▇▇ 3%
62  lodash.merge (src/ember-cli/n...dules/lodash.merge/index.js)    5ms  ▇ 1%
63  yam (src/ember-cli/node_modules/yam/lib/yam.js)                 7ms  ▇▇ 2%
64  configstore (src/ember-cli/no...odules/configstore/index.js)    5ms  ▇ 1%
65  ./baseMergeDeep (src/ember-cl...h/internal/baseMergeDeep.js)    7ms  ▇▇ 2%
66  ../internal/baseMerge (src/em...odash/internal/baseMerge.js)    7ms  ▇▇ 2%
67  lodash/object/merge (src/embe...ules/lodash/object/merge.js)   10ms  ▇▇ 3%
68  broccoli-merge-trees (src/emb...occoli-merge-trees/index.js)    4ms  ▇ 1%
69  ./lib/style-plugin (src/ember...egistry/lib/style-plugin.js)   15ms  ▇▇▇ 4%
70  ./ (src/ember-cli/node_module...reprocess-registry/index.js)   16ms  ▇▇▇ 4%
71  ember-cli-preprocess-registry...s-registry/preprocessors.js)   16ms  ▇▇▇ 4%
72  broccoli-funnel (src/ember-cl...es/broccoli-funnel/index.js)    7ms  ▇▇ 2%
73  ../models/addon (src/ember-cli/lib/models/addon.js)            25ms  ▇▇▇▇▇ 7%
74  ./try (src/ember-cli/node_mod...ber-try/lib/commands/try.js)    5ms  ▇ 1%
75  ./lib/commands (src/ember-cli...r-try/lib/commands/index.js)    7ms  ▇▇ 2%

  • dig into 42 ../models/project (src/ember-cli/lib/models/project.js) 114ms some more, see what we can squeeze out

@Turbo87
Copy link
Member

Turbo87 commented Jul 13, 2016

@stefanpenner if we require the dependencies on demand how will this work with ES6 modules if we would switch at some point? My understanding is that import statements must be at the top level, correct?

@nathanhammond
Copy link
Contributor

@Turbo87 Hopefully node fixes its slow module import time by the time that happens? Otherwise this will troll large projects tremendously.

@stefanpenner
Copy link
Contributor Author

@stefanpenner if we require the dependencies on demand how will this work with ES6 modules if we would switch at some point? My understanding is that import statements must be at the top level, correct?

There will be a way to also require lazily/on-demand, it has not yet been fleshed out though.

@twokul
Copy link
Contributor

twokul commented Jul 13, 2016

we could load some of the other deps lazily:

but something tells me this might not be the right avenue

@stefanpenner
Copy link
Contributor Author

stefanpenner commented Jul 13, 2016

but something tells me this might not be the right avenue

i think its fine for us to be mindful about require ordering and timing to ensuring it is pay as you go when possible. We should drive it based on identifying slow points and addressing them.

homu added a commit that referenced this issue Jul 14, 2016
Makes sure dependecies are loaded on demand

results: https://gist.github.com/twokul/54542ed6783e20bbfd2f62bd9dfb89c7

before:

```
Total require(): 1375
Total time: 1.1s
```

after:

```
Total require(): 995
Total time: 832ms
```

depends on #6071
related to #6009
@musaffa
Copy link

musaffa commented Aug 4, 2016

In my setup (ember 2.7, node 6.3.1), ember v takes 4.9s after a computer reboot and 500-600ms on the same subsequent commands after the first command has been executed. It takes significantly less time than ember s.

A signification amount of bottlenecks may also be found doing the same test with ember s. To eliminate the hypothesis of ember "has already warmed up", ember s should be the first command of ember bin executable after a fresh reboot.

@musaffa
Copy link

musaffa commented Aug 4, 2016

Flamegraph is also an interesting tool for performance instrumentation. Sam Saffron has been using flamegraph to pin point the bottlenecks of discourse rails server. He wrote a blog post about performance instrumentation and finding bottlenecks with flamegraph.

Nodejs has some implemenations of flamegraph, for example stackvis, 0x.

@stefanpenner
Copy link
Contributor Author

@musaffa yup! This issue outlines some things that should help many scenarios for you, as it goes to make sure we don't eagerly require too much. This should help.

@stefanpenner
Copy link
Contributor Author

stefanpenner commented Sep 27, 2016

We have made progress. The original issue has improved, but we will continue to reduce dependency weight which will hopefully continue to help :)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
Projects
None yet
Development

No branches or pull requests

6 participants