Phoenix / Curl Response Times

Phoenix Forum Questions / Help
1

So I have a simple http api endpoint: just a “hello” json text served on my local machine by Phoenix 1.4 and notice something interesting. In debug mode I can see that when I make the call the Phoenix console logs [info] Sent 200 in 206µs. However the actual response time from curl is something like ~16-26ms. Why the nearly 100x difference in time? API call completely stays local and does not go over the network.

2 Likes
2

  1. since you are in debug/iex - the code isn’t loaded - so always test twice to load the code in the first run…

  2. some OS’s does weird stuff with dns lookups - so make sure to test against 127.0.0.1

3

Also how do you measure the 16 to 26 ms?

1 Like
4

Using 127.0.0.1 doesn’t change the response time. The code is loaded as this measurement is from the 3-5th run. As for how I’m measuring I’m using curl’s time to first byte via a curl format file: TTFB: %{time_starttransfer} Here is a sample run, {"status": "online"} is the response of the call:

{"status":"online"} 

    time_namelookup:  0.001012
       time_connect:  0.001801
    time_appconnect:  0.000000
   time_pretransfer:  0.001830
      time_redirect:  0.000000
 time_starttransfer:  0.025648
                    ----------
         time_total:  0.025667

Running on Mac OS X Catalina 10.15.2.

Update: 12.19.2019, So it seems if I build the app using MIX_ENV=prod mix phx.server response times for the same api call go down to 1-2ms which is much more reasonable. It’s still 10x away from what the console says when response times are in the microsecond range but its better. The offending line responsible for the much better response times is the setting code_reloader: true in prod.exs to false.

I’m not sure why the code_reloader option has to add latency to every single request even after the code is no longer changing but those were my observations.

5

Try moving

  plug Plug.Telemetry, event_prefix: [:phoenix, :endpoint]

to the top of MyApp.Endpoint file. (previously it was Plug.Logger.) I believe that the thing timing the request is not wrapped around the code reloader. This makes sense because the code reloader is not going to run in production, so you wouldn’t really care about the measurement locally.

This causes Phoenix logs to go from 140us to 6ms in my local test. The ttfb is about 11ms, and there’s probably TCP connect overhead in there. You could probably use Keep-Alive connections to get curl and Phoenix to agree with each other.

3 Likes
6

Thanks! Yes moving that line to the top does cause the response time reported in the console to be more realistic when code_reloader: true. I just did a measure against Go (using Gin) serving the same kind of response and when code_reloader: false the results are pretty good. Golang serves the responses in the 20-60 us range vs Phoenix in the 100-300us but due to the rest of the http connection overheads it still ends up being ~ 1ms total time which is the same as Phoenix, so all good.

1 Like
7

Because it has to check whether the code has changed.

As far as the times reported, remember that timing is happening in Phoenix. In general there’s also a similar amount of time in Cowboy handling the connection and inbound request before it gets to Phoenix, and again after Phoenix is done. Then there’s the setup of the connection that happens from the curl side before Cowboy…

8

Makes sense…

9

can you post a bit more info about your curl data measurement trick? this sounds very useful. There’s good docs on the curl manpage, so no need to regurgitate it, but I’m interested to hear how you use it, what fields you’ve found useful to track, and if you track that data over time / between runs.

1 Like