Homepage response time 5x slower

[rofe]

Since the last increase end of May, page response times measured on www.project-helix.io have massively degraded again around July 5th, this time shooting from ~0.6s up to ~6.4s, then settling in at ~3.3s. The following issues fall into this timeframe:

• helix-pingdom-status: Error XML is not well formatted
• helix-pipeline: default pipeline should include
  s
• helix-experimental-dispatch: Strain mount path got lost during refactoring; strain url path is not respected anymore; requests to selector resources fail; if static and content repo are identical, don't fetch twice; only serve 404.html for *.html requests
• helix-cli: Remove local helix-static; allow custom dispatch version, changing log level does not work anymore

Also, I'm wondering why there is such a variance in the response time given that the site should always be cached...

cc @davidnuescheler

[trieloff]

It looks like it isn't cached - or not cached consistently.

[trieloff]

When it's cached, x-timer: S1562612780.493742,VS0,VE7 says that Varnish takes 7ms to run.

[rofe]

uncached...

vs cached?

In the latter case, the wait for the html is down from 3.1s to 13ms, but the wait for all content images is still 900+ms each, and even the helix_logo.png (4.6KB) takes 800ms to load.

[rofe]

Having pragma and cache-control set to no-cache probably doesn't help, either ;)

[ejthurgo]

Are these images running through IO?

[rofe]

@ejthurgo no, these are Pingdom screenshots

[trieloff]

@rofe the page response time reported in the initial comment does not include any of the resources that are required for the full rendering, so I'd say we are dealing with different issues here.

The page response time is back to normal now, and the only thing that affect the page response time are:

1. how long does it take Pingdom to establish a connection to Fastly
2. how well is the page cached.

Given that a request is made almost every minute and given that the response times are shorter now, I'd say it's (1).

The relatively slow image delivery you are seeing is a different issue.

[trieloff]

@ejthurgo the images do not seem to go through IO:

$ curl -v -H X-Debug:true https://www.project-helix.io/assets/browser.png
*   Trying 151.101.114.217...
* TCP_NODELAY set
* Connected to www.project-helix.io (151.101.114.217) port 443 (#0)
* ALPN, offering h2
* ALPN, offering http/1.1
* Cipher selection: ALL:!EXPORT:!EXPORT40:!EXPORT56:!aNULL:!LOW:!RC4:@STRENGTH
* successfully set certificate verify locations:
*   CAfile: /etc/ssl/cert.pem
  CApath: none
* TLSv1.2 (OUT), TLS handshake, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Server hello (2):
* TLSv1.2 (IN), TLS handshake, Certificate (11):
* TLSv1.2 (IN), TLS handshake, Server key exchange (12):
* TLSv1.2 (IN), TLS handshake, Server finished (14):
* TLSv1.2 (OUT), TLS handshake, Client key exchange (16):
* TLSv1.2 (OUT), TLS change cipher, Client hello (1):
* TLSv1.2 (OUT), TLS handshake, Finished (20):
* TLSv1.2 (IN), TLS change cipher, Client hello (1):
* TLSv1.2 (IN), TLS handshake, Finished (20):
* SSL connection using TLSv1.2 / ECDHE-RSA-AES128-GCM-SHA256
* ALPN, server accepted to use h2
* Server certificate:
*  subject: C=US; ST=California; L=San Francisco; O=Fastly, Inc.; CN=v2.shared.global.fastly.net
*  start date: Jun 27 09:55:20 2019 GMT
*  expire date: Feb 26 21:35:27 2020 GMT
*  subjectAltName: host "www.project-helix.io" matched cert's "*.project-helix.io"
*  issuer: C=BE; O=GlobalSign nv-sa; CN=GlobalSign CloudSSL CA - SHA256 - G3
*  SSL certificate verify ok.
* Using HTTP2, server supports multi-use
* Connection state changed (HTTP/2 confirmed)
* Copying HTTP/2 data in stream buffer to connection buffer after upgrade: len=0
* Using Stream ID: 1 (easy handle 0x7fac2980c600)
> GET /assets/browser.png HTTP/2
> Host: www.project-helix.io
> User-Agent: curl/7.54.0
> Accept: */*
> X-Debug:true
> 
* Connection state changed (MAX_CONCURRENT_STREAMS updated)!
< HTTP/2 200 
< access-control-allow-headers: Authorization, Origin, X-Requested-With, Content-Type, Accept, User-Agent
< access-control-allow-methods: OPTIONS, GET, DELETE, POST, PUT, HEAD, PATCH
< access-control-allow-origin: *
< cache-control: s-max-age=300
< content-type: image/png
< etag: "VOWKnwF8iCjtVl6qB36TCg=="
< perf-br-resp-out: 1562674343.232
< server: api-gateway/1.9.3.1
< x-content-type-options: nosniff
< x-frame-options: deny
< x-gw-cache: HIT
< x-openwhisk-activation-id: 067d8461efc54bfbbd8461efc53bfb0a
< x-request-id: HXRMm7OMGP0NwcbuGuYPGj6QMrJ7W2hj
< x-static: Raw/Static
< x-xss-protection: 1; mode=block
< x-backend-name: 3t7g8apsfQlFyvuHIQn9e8--F_AdobeRuntime
< x-cdn-request-id: e7bac719-5b84-494a-bff4-3b68fa4fd964
< accept-ranges: bytes
< date: Tue, 09 Jul 2019 12:12:23 GMT
< via: 1.1 varnish
< age: 0
< x-served-by: cache-hhn4067-HHN
< x-cache: MISS
< x-cache-hits: 0
< x-timer: S1562674343.138391,VS0,VE181
< vary: X-Debug,X-Strain,X-Request-Type
< strict-transport-security: max-age=31536000
< x-version: 123; src=123; cli=2.0.1; rev=online
< x-url: /assets/browser.png
< x-backend-url: /api/v1/web/helix-pages/helix-services/experimental-dispatch@v1?static.owner=adobe&static.repo=project-helix.io&static.ref=master&static.root=/htdocs&content.owner=adobe&content.repo=project-helix.io&content.ref=master&content.root=&content.package=bf8c6033dbc9a3581d5588e0e87a548be8fef7dd&content.index=index.html&path=/assets/browser.png&strain=default&params=
< x-request-type: Dispatch
< x-strain: default
< x-github-static-ref: @master
< x-fulldirname: /assets
< x-index: index.html
< x-action-root: helix-pages/bf8c6033dbc9a3581d5588e0e87a548be8fef7dd
< x-orig-url: /assets/browser.png
< x-repo-root-path: 
< x-trace: vcl_recv; hlx_recv_init; hlx_strain(resolved); hlx_block_recv; hlx_deny; hlx_allow; hlx_determine_request_type(none); hlx_type_dispatch; hlx_owner; hlx_repo; hlx_ref; hlx_root_path; hlx_index; hlx_github_static_owner; hlx_github_static_repo; hlx_github_static_ref; hlx_github_static_root(/htdocs); hlx_action_root; vcl_hash(www.project-helix.io/assets/browser.png); hlx_bereq,vcl_miss(www.project-helix.io/assets/browser.png); vcl_fetch(200: /assets/browser.png Dispatch); vcl_deliver; hlx_headers_deliver; hlx_deliver_errors; hlx_deliver_type(Dispatch); hlx_deliver_static(ok)
< content-length: 175542

[rofe]

the page response time reported in the initial comment does not include any of the resources that are required for the full rendering, so I'd say we are dealing with different issues here.

Ah, so the data shown on https://status.project-helix.io/ only shows the time to deliver the html?

The page response time is back to normal now

You're right... "normal" meaning the state between end of May and beginning of July...
Do we know why? What happened yesterday at 6:35 PM CEST?

2. how well is the page cached.

Given the pragma and cache-control headers are set to no-cache, how can it be cached?

The relatively slow image delivery you are seeing is a different issue.

OK

[kptdobe]

cache-control: s-max-age=300

It is not set to no-cache but to 5 mins.
II have played with the cache on a helix-pages service and set it to 5 mins but not the project-helix.io service... I need to double-check.

[rofe]

Ah, silly me: I was looking at the request headers in the Pingdom check :D

But actually, the cache-control value should be s-maxage=..., not s-max-age=... - maybe Fastly doesn't cache anything?

[rofe]

s-max-age=300 is set only for the images and the favicon.ico. The index.html has the correct s-maxage=604800 (pipeline default).

[kptdobe]

https://github.com/adobe/helix-static/blob/2fc1fd9f74ecde7c3a45ea8ab8a3b09a193729e8/src/index.js#L135
and
https://github.com/adobe/helix-static/blob/2fc1fd9f74ecde7c3a45ea8ab8a3b09a193729e8/src/index.js#L358

[davidnuescheler]

looking at the peak that we had in the response times ...

... and the "recovery" (to 🐌900ms) i think it would be important to understand what happened and correlate that with deployments/changes.

[tripodsan]

closing won't fix as it doesn't apply to helix 3 anymore.