Some proxied requests add 10-15s delay

[DanAndreasson]

We have a frontend which are proxying all API requests to our backend.

Web has the following static.json

{
  "root": "build/",
  "https_only": true,
  "headers": {
    "/**": {
      "Strict-Transport-Security": "max-age=7776000"
    }
  },
  "routes": {
    "/**": "index.html"
  },
  "proxies": {
    "/api/": {
      "origin": "${REACT_APP_API_PROTOCOL}://${REACT_APP_API_ENDPOINT}"
    }
  }
}

It's working well for us, but sometimes a request is super slow (10-15s) but the API is responding way faster than that.

Feb 11 12:01:38 learn2-web-production heroku[router] info at=info method=POST path="/api/graphql" host=app.gameplan.gg request_id=81c75a60-7f04-46bb-b40e-2f7eefbb1888 fwd="98.128.190.86" dyno=web.1 connect=1ms service=18518ms status=200 bytes=4330 protocol=https
Feb 11 12:01:39 learn2-api-production heroku[router] info at=info method=POST path="/graphql" host=l2-api.com request_id=81c75a60-7f04-46bb-b40e-2f7eefbb1888 fwd="98.128.190.86,54.217.40.94" dyno=web.2 connect=23ms service=159ms status=200 bytes=12475 protocol=https

From the logs above
Web service=18518ms
API service=159ms.

Any ideas?

[mars]

What kind of Heroku dyno is this running on? If it's one of the lower or free tiers, then those could be caused by other dynos (noisy/naughty neighbors) saturating resources of the host and causing latency. Such issues should disappear as dynos cycle each day, or if you heroku ps:stop each of the dynos.

[DanAndreasson]

API runs 2 Performance-M and WEB runs 1 Performance-M. It seems like the issue above was related to request queueing due to some long-running requests.

However, It seems like there's still some overhead with the proxying. Diffing 22ms between API service and WEB service. is that expected?

Feb 26 16:08:56 learn2-api-production app[web] DEBUG D, [2021-02-26T15:08:56.523253 #51] DEBUG -- : source=rack-timeout id=39601b7d-348e-453f-acef-bae55311dcb7 wait=6ms timeout=10000ms service=3ms state=active
Feb 26 16:08:56 learn2-api-production app[web] INFO I, [2021-02-26T15:08:56.686653 #51]  INFO -- : [39601b7d-348e-453f-acef-bae55311dcb7] method=POST path=/graphql format=*/* controller=GraphqlController action=execute status=200 duration=164.75 view=0.86 db=0.00 request_id=39601b7d-348e-453f-acef-bae55311dcb7  operation=GetAppData
Feb 26 16:08:56 learn2-api-production app[web] INFO I, [2021-02-26T15:08:56.689448 #51]  INFO -- : source=rack-timeout id=39601b7d-348e-453f-acef-bae55311dcb7 wait=6ms timeout=10000ms service=169ms state=completed
Feb 26 16:08:57 learn2-api-production heroku[router] info at=info method=POST path="/graphql" host=l2-api.com request_id=39601b7d-348e-453f-acef-bae55311dcb7 fwd="185.224.57.161,34.254.186.215" dyno=web.2 connect=1ms service=180ms status=200 bytes=11584 protocol=https
Feb 26 16:08:57 learn2-web-production heroku[router] info at=info method=POST path="/api/graphql" host=app.gameplan.com request_id=39601b7d-348e-453f-acef-bae55311dcb7 fwd="185.224.57.161" dyno=web.1 connect=0ms service=202ms status=200 bytes=3867 protocol=https

[mars]

Yes, proxying always adds latency overhead. That's the nature of adding hops to a network connection. 22ms additional latency for the proxied round-trip is pretty typical.

[DanAndreasson]

Thanks for the explanation 👍