Enable Fastboot with USE_FASTBOOT environment variable set to 1 #1900

kzys · 2019-11-15T05:41:17Z

This PR enables Fastboot on /policies like before, but only if USE_FASTBOOT is defined.

rust-highfive · 2019-11-15T05:41:28Z

(rust_highfive has picked a reviewer for you, use r? to override)

jtgeibel

Looks great to me overall! I'm pushing it to my Heroku instance now, and just have the 1 comment below.

config/nginx.conf.erb

USE_FASTBOOT environment variable is used to enable Fastboot. The number of workers configurable through WEB_CONCURRENCY. https://devcenter.heroku.com/articles/node-memory-use#running-multiple-processes

kzys · 2019-11-15T06:57:02Z

Travis seems having a bad day.

script/start-web.sh

carols10cents · 2019-11-15T14:49:44Z

I have this deployed to staging right now with USE_FASTBOOT=TRUE, /policies is working fine!

I don't see any difference in the logs really, am I supposed to? Here's what I see in the logs for a request to /policies:

2019-11-15T14:39:48.323842+00:00 heroku[router]: at=info method=GET path="/policies" host=staging-crates-io.herokuapp.com request_id=e99bc704-d296-4755-a20e-e27de1ab3143 fwd="71.112.158.75,70.132.60.136" dyno=web.1 connect=0ms service=16ms status=200 bytes=2333 protocol=https
2019-11-15T14:39:48.320751+00:00 app[web.1]: at=info method=GET path="/policies" request_id=e99bc704-d296-4755-a20e-e27de1ab3143 fwd="70.132.60.136" service=0ms status=200 user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.97 Safari/537.36"
2019-11-15T14:39:48.324643+00:00 app[web.1]: measure#nginx.service=0.014 request_id=e99bc704-d296-4755-a20e-e27de1ab3143
2019-11-15T14:39:48.629354+00:00 heroku[router]: at=info method=GET path="/cargo-835dd6a18132048a52ac569f2615b59d.png" host=staging-crates-io.herokuapp.com request_id=7130b9fa-b2ec-4506-b347-012d30e67e1d fwd="71.112.158.75,70.132.60.134" dyno=web.1 connect=0ms service=5ms status=200 bytes=60779 protocol=https
2019-11-15T14:39:48.625404+00:00 app[web.1]: at=info method=GET path="/cargo-835dd6a18132048a52ac569f2615b59d.png" request_id=7130b9fa-b2ec-4506-b347-012d30e67e1d fwd="70.132.60.134" service=0ms status=200 user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.97 Safari/537.36"
2019-11-15T14:39:48.629663+00:00 app[web.1]: measure#nginx.service=0.006 request_id=7130b9fa-b2ec-4506-b347-012d30e67e1d

And here's what I see in the logs for a request to /category_slugs:

2019-11-15T14:39:13.606528+00:00 heroku[router]: at=info method=GET path="/category_slugs" host=staging-crates-io.herokuapp.com request_id=cbe927ce-c63c-4d8a-ae86-97a795b8a719 fwd="71.112.158.75,70.132.60.156" dyno=web.1 connect=0ms service=8ms status=200 bytes=2333 protocol=https
2019-11-15T14:39:13.603467+00:00 app[web.1]: at=info method=GET path="/category_slugs" request_id=cbe927ce-c63c-4d8a-ae86-97a795b8a719 fwd="70.132.60.156" service=0ms status=200 user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.97 Safari/537.36"
2019-11-15T14:39:13.605816+00:00 app[web.1]: measure#nginx.service=0.005 request_id=cbe927ce-c63c-4d8a-ae86-97a795b8a719
2019-11-15T14:39:13.742656+00:00 app[web.1]: at=info method=GET path="/api/v1/category_slugs" request_id=7f31c9af-ee51-453d-84d3-1f9a4b7313b8 fwd="70.132.60.131" service=4ms status=200 user_agent="Mozilla/5.0 (Macintosh; Intel Mac OS X 10_15_1) AppleWebKit/537.36 (KHTML, like Gecko) Chrome/78.0.3904.97 Safari/537.36"
2019-11-15T14:39:13.749201+00:00 app[web.1]: measure#nginx.service=0.014 request_id=7f31c9af-ee51-453d-84d3-1f9a4b7313b8
2019-11-15T14:39:13.749153+00:00 heroku[router]: at=info method=GET path="/api/v1/category_slugs" host=staging-crates-io.herokuapp.com request_id=7f31c9af-ee51-453d-84d3-1f9a4b7313b8 fwd="71.112.158.75,70.132.60.131" dyno=web.1 connect=3ms service=16ms status=200 bytes=4003 protocol=https

I'm not seeing the memory issues reported in #1827; in fact, the memory usage is lower after deploying this (previously staging had 77856b0 on it). I made sure to request /policies repeatedly, and I'm not seeing any memory usage growth. It's hanging out at 32MB:

kzys · 2019-11-15T17:08:06Z

Thanks @carols10cents. Have you deployed something else on staging-crates-io.herokuapp.com? https://staging-crates-io.herokuapp.com/policies doesn't seem to have Fastboot.

Regarding logs, you should at least have logs from https://github.com/ember-fastboot/fastboot-express-middleware/blob/3febb1dbc11b4b95e2125c6866de2498e9d4d08c/src/index.js#L91, which I couldn't find a way to disable that from fastboot-app-server.

carols10cents · 2019-11-15T19:01:56Z

I have not... it's still at 6e373b6. I set USE_FASTBOOT to true and just confirmed that it's still set, is that not right?

How can you tell if a page uses fastboot or not?

carols10cents · 2019-11-15T19:05:43Z

script/ember.sh

+
+export FASTBOOT_DISABLED
+
+if [ "${USE_FASTBOOT:-0}" = '1' ]; then


oh oops it needs to be 1 here? let me try that

ember.sh is only used from npm run, but start-web.sh is doing the same check. Yes. It has to be 1

carols10cents · 2019-11-15T19:06:25Z

config/nginx.conf.erb

@@ -64,6 +64,13 @@ http {
 			proxy_pass http://app_server;
 		}

+		<% if ENV['USE_FASTBOOT'] %>


i saw this line and thought it just needed to be set.

jtgeibel · 2019-11-15T19:17:06Z

I've pushed a commit to my staging area that allows me to experimentally enable FastBoot for all front-end paths (via USE_FASTBOOT=staging-experimental). This should make it easier to test things going forward. We could include it in this PR, or I can wait and open a separate PR for this.

Branch pr/1900-experimental: https://github.com/jtgeibel/crates.io/tree/pr/1900-experimental
Diff: jtgeibel@4c33f00

carols10cents · 2019-11-15T19:17:50Z

OK now I am seeing this in the logs for a request to /policies:

2019-11-15T19:16:39.834591+00:00 heroku[router]: at=info method=GET path="/policies" host=staging-crates-io.herokuapp.com request_id=12a23729-d07c-442e-953d-fac4fdbe1187 fwd="71.112.158.75" dyno=web.1 connect=1ms service=416ms status=200 bytes=5826 protocol=https
2019-11-15T19:16:39.826593+00:00 app[web.1]: 2019-11-15T19:16:39.826Z 200 OK /policies
2019-11-15T19:16:39.835736+00:00 app[web.1]: measure#nginx.service=0.410 request_id=12a23729-d07c-442e-953d-fac4fdbe1187

jtgeibel · 2019-11-15T19:28:32Z

Regarding the log format, my only suggestions would be to see if we can remove the extra timestamp from line 2, replacing it with "FastBoot:". It would also be nice to log the request_id on that line.

2019-11-15T19:16:39.826593+00:00 app[web.1]: FastBoot: 200 OK /policies request_id=12a23729-d07c-442e-953d-fac4fdbe1187

carols10cents · 2019-11-15T20:33:22Z

Ok I am seeing higher memory usage now, but not outrageously so. There was a jump from 37MB to 57MB when the dynos were done restarting after I fixed the env var value, and it fluctuated as high as 86MB, but I made a point to reload /policies a whole bunch and I didn't see any resulting change in memory usage. Here's the metrics graph:

sgrif · 2019-11-15T22:46:07Z

I'm seeing 500s for that page on staging

sgrif · 2019-11-15T22:51:07Z

Scratch that, was able to successfully access from another domain. I did a quick stress test sending 1k requests to /policies. Memory usage did increase for a bit, but topped out at ~30MB total which seems fine. Response times were slower than I'd like but staging isn't representative of production for that.

kzys · 2019-11-15T23:23:24Z

@jtgeibel Regarding the log message, changing that is hard because we cannot configure the logger through fastboot-app-server. I would like to send a PR for one of the Fastboot packages but it may take time.

Adding a new log to indicate Fastboot access is much easier. I can do that probably in this PR if you want to.

jtgeibel · 2019-11-15T23:36:10Z

@kzys I think the log format is fine for now, especially for this single endpoint. There was already a related todo item on #1811 and I've linked to the comment above from there. I think we'll want to eventually add the request_id to the output before adding too many more endpoints, but since that requires upstream changes I don't think that needs to block this particular PR.

I've assigned #1811 to you, in the hopes that it will enable you to edit that issue. If not, I'll try to keep it synced with our progress as things land (I believe I've addressed your other comments in that thread).

carols10cents · 2019-11-18T16:00:09Z

Sounds like we're all good with this. I'm going to merge now, but not deploy til Wednesday when we're sure the cloudfront changes have gone well.

@bors r+

bors · 2019-11-18T16:00:11Z

📌 Commit 6e373b6 has been approved by carols10cents

bors · 2019-11-18T16:00:19Z

⌛ Testing commit 6e373b6 with merge 2efe33d...

Enable Fastboot with USE_FASTBOOT environment variable set to 1 This PR enables Fastboot on `/policies` like before, but only if USE_FASTBOOT is defined.

bors · 2019-11-18T16:15:39Z

☀️ Test successful - checks-travis
Approved by: carols10cents
Pushing 2efe33d to master...

rust-highfive assigned carols10cents Nov 15, 2019

rust-highfive added the S-waiting-on-review label Nov 15, 2019

kzys force-pushed the use-fastboot branch 2 times, most recently from 1b98fd1 to 6e49e86 Compare November 15, 2019 06:03

jtgeibel reviewed Nov 15, 2019

View reviewed changes

config/nginx.conf.erb Show resolved Hide resolved

kzys force-pushed the use-fastboot branch from 6e49e86 to ec79e30 Compare November 15, 2019 06:38

kzys added 2 commits November 14, 2019 22:40

Enable Fastboot and run its Node server from Procfile

3c12897

USE_FASTBOOT environment variable is used to enable Fastboot. The number of workers configurable through WEB_CONCURRENCY. https://devcenter.heroku.com/articles/node-memory-use#running-multiple-processes

Fix /crates/$crate_id

9ced6ef

kzys force-pushed the use-fastboot branch from ec79e30 to 9ced6ef Compare November 15, 2019 06:40

kzys commented Nov 15, 2019

View reviewed changes

script/start-web.sh Show resolved Hide resolved

kzys added 2 commits November 14, 2019 23:07

"wait -n" needs bash

2bdf7ae

Fix eslint

6e373b6

kzys mentioned this pull request Nov 15, 2019

Tracking issue for Ember FastBoot #1811

Closed

19 tasks

carols10cents reviewed Nov 15, 2019

View reviewed changes

carols10cents changed the title ~~Enable Fastboot with USE_FASTBOOT environment variable~~ Enable Fastboot with USE_FASTBOOT environment variable set to 1 Nov 15, 2019

bors added a commit that referenced this pull request Nov 18, 2019

Auto merge of #1900 - kzys:use-fastboot, r=carols10cents

2efe33d

Enable Fastboot with USE_FASTBOOT environment variable set to 1 This PR enables Fastboot on `/policies` like before, but only if USE_FASTBOOT is defined.

bors merged commit 6e373b6 into rust-lang:master Nov 18, 2019

carols10cents mentioned this pull request Dec 2, 2019

Crate name / search term should be in the page title #1930

Closed

Provide feedback

Saved searches

Use saved searches to filter your results more quickly

Enable Fastboot with USE_FASTBOOT environment variable set to 1 #1900

Enable Fastboot with USE_FASTBOOT environment variable set to 1 #1900

kzys commented Nov 15, 2019 •

edited

Loading

rust-highfive commented Nov 15, 2019

jtgeibel left a comment

kzys commented Nov 15, 2019

carols10cents commented Nov 15, 2019 •

edited

Loading

kzys commented Nov 15, 2019

carols10cents commented Nov 15, 2019

carols10cents Nov 15, 2019

kzys Nov 15, 2019

carols10cents Nov 15, 2019

jtgeibel commented Nov 15, 2019

carols10cents commented Nov 15, 2019

jtgeibel commented Nov 15, 2019

carols10cents commented Nov 15, 2019

sgrif commented Nov 15, 2019

sgrif commented Nov 15, 2019

kzys commented Nov 15, 2019

jtgeibel commented Nov 15, 2019

carols10cents commented Nov 18, 2019

bors commented Nov 18, 2019

bors commented Nov 18, 2019

bors commented Nov 18, 2019


		export FASTBOOT_DISABLED

		if [ "${USE_FASTBOOT:-0}" = '1' ]; then

Enable Fastboot with USE_FASTBOOT environment variable set to 1 #1900

Enable Fastboot with USE_FASTBOOT environment variable set to 1 #1900

Conversation

kzys commented Nov 15, 2019 • edited Loading

rust-highfive commented Nov 15, 2019

jtgeibel left a comment

Choose a reason for hiding this comment

kzys commented Nov 15, 2019

carols10cents commented Nov 15, 2019 • edited Loading

kzys commented Nov 15, 2019

carols10cents commented Nov 15, 2019

carols10cents Nov 15, 2019

Choose a reason for hiding this comment

kzys Nov 15, 2019

Choose a reason for hiding this comment

carols10cents Nov 15, 2019

Choose a reason for hiding this comment

jtgeibel commented Nov 15, 2019

carols10cents commented Nov 15, 2019

jtgeibel commented Nov 15, 2019

carols10cents commented Nov 15, 2019

sgrif commented Nov 15, 2019

sgrif commented Nov 15, 2019

kzys commented Nov 15, 2019

jtgeibel commented Nov 15, 2019

carols10cents commented Nov 18, 2019

bors commented Nov 18, 2019

bors commented Nov 18, 2019

bors commented Nov 18, 2019

kzys commented Nov 15, 2019 •

edited

Loading

carols10cents commented Nov 15, 2019 •

edited

Loading