`make serve` takes too long to start

VERIFIED FIXED in 2014-11-04

Status

Marketplace
Code Quality
P2
normal
VERIFIED FIXED
3 years ago
3 years ago

People

(Reporter: cvan, Assigned: ngoke)

Tracking

2014-11-04
x86
Mac OS X
Points:
---

Details

(Whiteboard: [repoman])

(Reporter)

Description

3 years ago
% time make serve
[12:27:27] Using gulpfile /opt/fireplace_/gulpfile.js
[12:27:27] Starting 'watch'...
[12:27:27] Finished 'watch' after 93 ms
[12:27:27] Starting 'css_compile'...
[12:27:27] Starting 'templates_build'...
[12:27:29] Finished 'css_compile' after 2.49 s
[12:27:29] Finished 'templates_build' after 2.49 s
[12:27:29] Starting 'serve'...
[12:27:29] Webserver started at http://localhost:8675
[12:27:29] Finished 'serve' after 14 ms
[12:27:29] Starting 'default'...
[12:27:29] Finished 'default' after 12 μs
^Cmake: *** [serve] Error 130

make serve  3.75s user 0.25s system 74% cpu 5.393 total

vs.

% time damper
Commonplace version does not match: 0.4.22 does not match 0.3.13
Server running at http://0.0.0.0:8675
Recompiling templates...
Commonplace v0.3.13
Watching 37 `styl` files.
Watching 57 `html` files.
^Cdamper  0.54s user 0.05s system 114% cpu 0.516 total
(Assignee)

Comment 1

3 years ago
Could probably speed this up by not compiling CSS beforehand (damper doesn't seem to do it).
Assignee: nobody → kngo
(Assignee)

Comment 2

3 years ago
https://github.com/mozilla/marketplace-gulp/commit/2b728a6609d7d55643e521301ed1fb67051639b2

Only compile CSS if no styl.css is found. Makes it pretty instant (takes like a 100ms to check for the compiled CSS though).
Status: NEW → RESOLVED
Last Resolved: 3 years ago
Resolution: --- → FIXED
(Reporter)

Comment 3

3 years ago
(In reply to Kevin Ngo [:ngoke] from comment #1)
> Could probably speed this up by not compiling CSS beforehand (damper doesn't
> seem to do it).

No, damper did compile CSS beforehand. Which is super helpful, especially when you switch branches or for first-time Fireplace users.
(Reporter)

Comment 4

3 years ago
Even after clearing all `.styl.css` files, Damper always compiled CSS beforehand. There just wasn't any console output (only file changes were logged: `> navbar.styl changed.`).

> % damper
> Commonplace version does not match: 0.4.22 does not match 0.3.13
> Server running at http://0.0.0.0:8675
> Recompiling templates...
> Commonplace v0.3.13
> Watching 37 `styl` files.
> Watching 57 `html` files.
> > /opt/fireplace_/src/media/css/account.styl recompiled after 195 ms.
> > /opt/fireplace_/src/media/css/buttons.styl recompiled after 301 ms.
> > /opt/fireplace_/src/media/css/categories.styl recompiled after 357 ms.
> > /opt/fireplace_/src/media/css/app-list.styl recompiled after 406 ms.
> > /opt/fireplace_/src/media/css/category-icons.styl recompiled after 475 ms.
> > /opt/fireplace_/src/media/css/category-dropdown-desktop.styl recompiled after 527 ms.
> > /opt/fireplace_/src/media/css/collections.styl recompiled after 587 ms.
> > /opt/fireplace_/src/media/css/compat-filtering.styl recompiled after 640 ms.
> > /opt/fireplace_/src/media/css/detail-content-ratings.styl recompiled after 687 ms.
> > /opt/fireplace_/src/media/css/detail.styl recompiled after 764 ms.
> > /opt/fireplace_/src/media/css/error-screens.styl recompiled after 812 ms.
> > /opt/fireplace_/src/media/css/feed.styl recompiled after 928 ms.
> > /opt/fireplace_/src/media/css/feedback.styl recompiled after 972 ms.
> > /opt/fireplace_/src/media/css/form-modal.styl recompiled after 1015 ms.
> > /opt/fireplace_/src/media/css/forms.styl recompiled after 1074 ms.
> > /opt/fireplace_/src/media/css/header.styl recompiled after 1169 ms.
> > /opt/fireplace_/src/media/css/infobox.styl recompiled after 1216 ms.
> > /opt/fireplace_/src/media/css/lib.styl recompiled after 1253 ms.
> > /opt/fireplace_/src/media/css/lightbox.styl recompiled after 1302 ms.
> > /opt/fireplace_/src/media/css/listing.styl recompiled after 1389 ms.
> > /opt/fireplace_/src/media/css/menu.styl recompiled after 1410 ms.
> > /opt/fireplace_/src/media/css/modal.styl recompiled after 1465 ms.
> > /opt/fireplace_/src/media/css/navbar.styl recompiled after 1521 ms.
> > /opt/fireplace_/src/media/css/nominate.styl recompiled after 1574 ms.
> > /opt/fireplace_/src/media/css/notification.styl recompiled after 1618 ms.
> > /opt/fireplace_/src/media/css/paginator.styl recompiled after 1660 ms.
> > /opt/fireplace_/src/media/css/pretty-select.styl recompiled after 1706 ms.
> > /opt/fireplace_/src/media/css/promo-grid.styl recompiled after 1765 ms.
> > /opt/fireplace_/src/media/css/purchase.styl recompiled after 1833 ms.
> > /opt/fireplace_/src/media/css/ratings.styl recompiled after 1897 ms.
> > /opt/fireplace_/src/media/css/reset.styl recompiled after 1927 ms.
> > /opt/fireplace_/src/media/css/search.styl recompiled after 1967 ms.
> > /opt/fireplace_/src/media/css/site-banner.styl recompiled after 2015 ms.
> > /opt/fireplace_/src/media/css/site.styl recompiled after 2100 ms.
> > /opt/fireplace_/src/media/css/splash.styl recompiled after 2171 ms.
> > /opt/fireplace_/src/media/css/tiles.styl recompiled after 2226 ms.
> > /opt/fireplace_/src/media/css/typography.styl recompiled after 2279 ms.

So, that's a regression if we now aren't doing that anymore.

I just pulled and things appear to be ~1 second faster with your changes, but it's still slow:

> % time make serve
> [13:58:47] Using gulpfile /opt/fireplace_/gulpfile.js
> [13:58:47] Starting 'watch'...
> [13:58:47] Finished 'watch' after 90 ms
> [13:58:47] Starting 'css_compile'...
> [13:58:47] Starting 'templates_build'...
> [13:58:49] Finished 'templates_build' after 2.44 s
> [13:58:49] Finished 'css_compile' after 2.45 s
> [13:58:49] Starting 'serve'...
> [13:58:49] Webserver started at http://localhost:8675
> [13:58:49] Finished 'serve' after 9.1 ms
> [13:58:49] Starting 'default'...
> [13:58:49] Finished 'default' after 8.61 μs
> ^Cmake: *** [serve] Error 130
> 
> make serve  3.69s user 0.22s system 89% cpu 4.364 total
Status: RESOLVED → REOPENED
Resolution: FIXED → ---
(Reporter)

Comment 5

3 years ago
So when I cleared my `.styl.css`, it appears to have taken only `0.01 s` longer (not sure how accurate these console timings are).

When you run `make serve`, you'll notice the bottleneck is the template compilation:

> [14:06:21] Starting 'templates_build'...

So, how come those are taking so long?

Anyway, here's the rest of the output:

> % time make serve
> [14:06:21] Using gulpfile /opt/fireplace_/gulpfile.js
> [14:06:21] Starting 'watch'...
> [14:06:21] Finished 'watch' after 88 ms
> [14:06:21] Starting 'css_compile'...
> [14:06:21] Starting 'templates_build'...
> [14:06:24] Finished 'templates_build' after 2.41 s
> [14:06:24] Finished 'css_compile' after 2.42 s
> [14:06:24] Starting 'serve'...
> [14:06:24] Webserver started at http://localhost:8675
> [14:06:24] Finished 'serve' after 8.92 ms
> [14:06:24] Starting 'default'...
> [14:06:24] Finished 'default' after 8.11 μs
> ^Cmake: *** [serve] Error 130
> 
> make serve  3.65s user 0.25s system 73% cpu 5.329 total
> 
> % find . -name '*.styl.css' -delete
> 
> % time make serve
> [14:06:35] Using gulpfile /opt/fireplace_/gulpfile.js
> [14:06:35] Starting 'watch'...
> [14:06:35] Finished 'watch' after 70 ms
> [14:06:35] Starting 'css_compile'...
> [14:06:35] Starting 'templates_build'...
> [14:06:38] Finished 'templates_build' after 2.42 s
> [14:06:38] Finished 'css_compile' after 2.43 s
> [14:06:38] Starting 'serve'...
> [14:06:38] Webserver started at http://localhost:8675
> [14:06:38] Finished 'serve' after 9.34 ms
> [14:06:38] Starting 'default'...
> [14:06:38] Finished 'default' after 7.92 μs
> ^Cmake: *** [serve] Error 130
> 
> make serve  3.65s user 0.23s system 86% cpu 4.457 total
(Assignee)

Comment 6

3 years ago
Speeding up the CSS compilation will speed up the server start-up time. I've reverted it back to recompile-every-time for now.

Unfortunately, I don't think we can every reach 200ms simply due to the time it takes to load the plugins. I'm aiming for 2.5s with faster CSS compilation. Sorry, that sucks, but 2.5s isn't forever and we don't restart the server often (I'll fix the Stylus error bug).

I'll also work to speed up the watcher by only recompiling CSS files that are modified.
Status: REOPENED → RESOLVED
Last Resolved: 3 years ago3 years ago
Resolution: --- → DUPLICATE
Duplicate of bug: 1091421
(Reporter)

Comment 7

3 years ago
These are clearly two separate issues. Can you please not make this a dupe?

If you don't want to fix the startup issue, then WONTFIX it (although that would make me and other devs sad). But, the template compilation is what is making the `make serve` boot-up time so slow. And bug 1091421 is about Stylus compilation being slow. Two different things.

Try developing locally lately; maybe I'm slow, but it's uncomfortably slower than Damper was. Even when the Stylus error bug gets fixed, checking out other branches, etc. taking 4.5-6 seconds every time is a long time. I would've thought a Node server would be faster to boot; for measure, it takes 6 sec to start up a Django server. I would've thought it'd be much faster. On projects of mine (work and personal), using `gulp-serve` as a local dev server plus a bunch of gulp plugins to do CSS minification/concatenation + jshinting + browserify compilation + minification, the startup time is 2.1-4.3 sec.
(Assignee)

Comment 8

3 years ago
Here's the breakdown:

Plugin loading takes ~900ms.
Templates take ~230ms.
CSS takes ~2s.

Template compilation is not what's taking long. It's the CSS mainly.

Plugin loading takes a while too, but that's hard to avoid. I read gulp-util has a huge dependency tree, so I can look at getting rid of that and see the improvements.
(Reporter)

Comment 9

3 years ago
(In reply to Kevin Ngo [:ngoke] from comment #8)
> Template compilation is not what's taking long. It's the CSS mainly.

My apologies, you're right. Sorry for thinking you were misunderstanding.

So, it turns out it was just misleading logging. I commented out `css_compile` in the `serve` gulp task.

`make serve` stalls at these lines the longest:

> [15:17:31] Starting 'css_compile'...
> [15:17:31] Starting 'templates_build'...

And then ~2.45 seconds later, you see this:

> [15:17:33] Finished 'templates_build' after 2.45 s

You would think that since CSS is the bottleneck, it would say this:

> [15:17:33] Finished 'css_compile' after 4.9 s

––

I temporarily disabled the Stylus compilation in the `css_compile` task:

>     // .pipe(stylus())

And `make serve`'s startup time suddenyl became 2.160 s!! Amazing!

I'll let us continue the discussion/work in bug 1091421.

We should probably file a separate bug to fix the logging/timing in the logs.

And sorry again :)
(Assignee)

Comment 10

3 years ago
Yeah, I don't know what's up with that. Maybe since they're both dependency tasks of `serve`, they're bunched together. I'll take a look at the CSS, and it'll probably end up with me making a small Stylus plugin.
(Assignee)

Comment 11

3 years ago
So I'm wagering that Damper actually takes the same amount of time to compile the CSS. It was just perceivably faster because it started the webserver immediately, and did the CSS compilation in the background.

I'm reopening this because I can introduce the same functionality to not have the webserver wait on the CSS, but still run the CSS in the background.
Status: RESOLVED → REOPENED
Resolution: DUPLICATE → ---
(Assignee)

Comment 12

3 years ago
https://github.com/mozilla/marketplace-gulp/commit/6afc95372834b1a3923c9d99db72f0676ecb8a24

Okay, this was totally my fault. I accidentally made nearly every task run in series/sync when Gulp would usually run everything concurrently. Thanks for the catch.
Status: REOPENED → RESOLVED
Last Resolved: 3 years ago3 years ago
Priority: -- → P2
Resolution: --- → FIXED
(Assignee)

Comment 13

3 years ago
It starts up pretty instantly for me (1.3s). Most of that time is Node requires.
(Assignee)

Updated

3 years ago
Whiteboard: [repoman]
(Reporter)

Comment 14

3 years ago
Much, much faster… 3 times faster. Impressive. Thanks, Kevin!

––

1. Verified that `.styl.css` files get compiled when `.styl.css` files do NOT exist.
2. Verified that `.styl.css` files get compiled when `.styl.css` files do exist.
3. Verified that `make serve` starts in a reasonable amount of time (1.727 sec). Previously, `make serve` started in 5.393 sec. For measure, damper starts up in 0.516 sec - so a bit slower but definitely manageable (faster than Django's ~6.00-sec startup time).

> % time make serve                                                                                                                  /opt/fireplace_ (master)
> [21:26:20] Using gulpfile /opt/fireplace_/gulpfile.js
> [21:26:20] Starting 'watch'...
> [21:26:20] Finished 'watch' after 116 ms
> [21:26:20] Starting 'templates_build'...
> [21:26:20] Finished 'templates_build' after 3.64 ms
> [21:26:20] Starting 'webserver'...
> [21:26:20] Webserver started at http://localhost:8675
> [21:26:20] Finished 'webserver' after 4.61 ms
> [21:26:20] Starting 'css_compile'...
> [21:26:20] Finished 'css_compile' after 2.03 ms
> [21:26:20] Starting 'serve'...
> [21:26:20] Finished 'serve' after 9.11 μs
> [21:26:20] Starting 'default'...
> [21:26:20] Finished 'default' after 8.56 μs
> ^Cmake: *** [serve] Error 130
> 
> make serve  1.65s user 0.16s system 105% cpu 1.727 total
Status: RESOLVED → VERIFIED
(Reporter)

Updated

3 years ago
Target Milestone: --- → 2014-11-04
You need to log in before you can comment on or make changes to this bug.