Can't understand the performance of various steps of making a request.

[tobz]

Sorry, I realize this is a little weird, but bare with me here.

I'm using HTTPotion to make requests to external resources and time how long it takes. As a simple start, I'm marking the time before I actually call HTTPotion.get, and then capturing the time when I receive %HTTPotion.AsyncHeaders{}, the first %HTTPotion.AsyncChunk{}, and finally, %HTTPotion.AsyncEnd{}.

Now, this works, and everything happens in the expected order. If I measure the time between start and end, the time looks right. What doesn't look right, however, is the time I measure of when the headers arrive.

Here's some data for grabbing the SSH keys I have set up for Github:

%{check_id: "test check",
  check_options: %{check_url: "https://github.com/tobz.keys"},
  results: %{body_end: 1471278282867, body_start: 1471278282867,
    headers_at: 1471278282630, started_at: 1471278282629}}

These times are the system time in milliseconds, so going in chronological order:

T+0: request fired off T+1ms: headers arrived/are ready T+238ms: first response body chunk arrives/is ready T+238ms: response marked complete/ended

As you can see, the headers arrive uncharacteristically fast, while the response body comes in at a believable time after the request is sent. Even if we consider that the connection is already established, and all we're doing is picking up an open connection and putting the request through, 1ms is still an unreasonable response time to already have the headers back.

If I measure the system time in microseconds, things get even stranger, and the time from starting the request to getting the headers drops to an incredibly low ~80uS, which, if my math is right, would suggest GitHub has a direct fiber optic connection to my house that is under 25km long. :)

I suspect something simple is responsible here for the incongruence, but I just can't seem to figure it out. :(

[valpackett]

That's some very nice performance :D

Well, HTTPotion simply translates ibrowse's async messages into Elixir-friendly ones. Try using ibrowse directly. If the weirdness persists, ask the ibrowse developers.

[valpackett]

Any progress on this? Have you tried doing this with ibrowse?

[tobz]

Haven't tried doing this with ibrowse, no. Have been busy + on holiday.

I think my plan is ultimately to switch to using Hackney directly because it has the concept of metrics already and the author seemed receptive to a PR that would expose them on a per-request basis, and it lets me get much closer to the actual connection phase and so on.

I'll close this out.