Instrumentation Features

tisba commented 6 years ago

Hi there.

I'm currently taking a look at different Erlang/Elixir HTTP client libraries. One particular aspect, despite a good degree of control of the client, I'm also interested in getting metrics and instrumentation out of the client.

I was wondering if and how gun does offer metrics per request or connection. Is there something like https://blog.golang.org/http-tracing or alike? I'm particular interested in information like:

was the connection re-used?
how long did it take to make the TCP and TLS handshake?
how long did it take to write the request, including payload to the socket (sending the request)?
how long did it take before the server has send the first result? (time to first byte)
how long did it take to fully read the response?

I tried to follow the implementation, but wasn't able to figure out if this information is provided somewhere.

essen commented 6 years ago

It isn't. Would be good to have but maybe for version 2.

essen commented 5 years ago

It could help to have a full list of events expected to be provided.

tisba commented 5 years ago

Like I said, I think https://blog.golang.org/http-tracing is a good foundation that could be use for inspiration. The technical documentation can be found here https://golang.org/pkg/net/http/httptrace/#ClientTrace.

If we talk about tracing from an events perspective, my list would be:

DNS start
DNS finish
Connection start
Connection established
TLS start
TLS done
Request sent
First Response Byte received
Response read

If connection pooling is used there might be specific events for the request of a connection and one for when a connection was returned by the pool.

For the Golang net/http/httptrace package you can hook into these events and derive timing information that you require. This can get a bit tricky as several event callbacks can get called multiple times and concurrently, for features like happy eyeballing (IPv4/IPv6), HTTP2 upgrades, HTTP 100 responses, …

essen commented 5 years ago

Alright thanks. Afraid DNS start/finish isn't possible at this time but that might be interesting to do later. It'll be counted between connection start/established meanwhile. The rest should be fine.

essen commented 5 years ago

Very rough direction I'm going for this:

-module(gun_event).

%% init.

-type init_event() :: #{
    owner := Owner,
    transport := OriginTransport,
    origin_scheme := OriginScheme,
    origin_host := Host,
    origin_port := Port,
    opts := Opts
}.

-callback init(init_event(), State) → State.

%% connect_start/connect_end.

-type connect_event() :: #{
    host := Host,
    port := Port,
    transport := Transport:name(),
    transport_opts := TransOpts,
    connect_timeout := ConnectTimeout,
    %% OK.
    socket ⇒ Socket,
    protocol ⇒ Protocol:name(),
    %% Error.
    error ⇒ Reason
}.

-callback connect_start(connect_event(), State) → State.
-callback connect_end(connect_event(), State) → State.

Basically a callback module with a state defined via Gun options, that has a callback per event type with the event details as first argument and state as second argument/return value. The event details vary depending on the event type and result of the operation, for example on connect success the event also contains the socket and protocol to be used and on connect failure the error reason is provided instead.

Thoughts?

essen commented 5 years ago

There will also be a tls_handshake_start/_end callback but at first it will only be for CONNECT to TLS origins. For the original TCP connection the code will have to be modified to first connect via plain TCP and then perform the handshake so that'll be done later, possibly at the same time as separating DNS calls.

essen commented 5 years ago

Here's the full list of events I'm willing to add:

init (Gun process init)
domain_lookup_start (DNS lookup)
domain_lookup_end (DNS lookup success/failure)
connect_start (TCP connection start)
connect_end (TCP connection established/failed)
tls_handshake_start
tls_handshake_end (success/failure)
stream_start (when the user does a request or when the server pushes a resource)
stream_end (when the request/response are complete or the stream is canceled either by server or user)
request_start
request_headers (only called if we send the headers and stream the body, otherwise request_end directly)
request_end
response_start (call it once per inform + one for the response)
response_inform (1xx responses)
response_headers
response_end
push_promise_start (first PUSH_PROMISE frame, same as push_promise_end if no CONTINUATION)
push_promise_end (followed by a response)
ws_frame_read_start (we received bytes while waiting for the next frame)
ws_frame_read_header (we read the frame's header)
ws_frame_read_end (we read the frame's body)
ws_frame_write_start (before calling send)
ws_frame_write_end (after calling send)
terminate

/cc @deadtrickster

essen commented 5 years ago

Yesterday I've noticed I missed origin_changed, transport_changed, protocol_changed and disconnected events.

deadtrickster commented 5 years ago

Hi, please read this: https://github.com/census-instrumentation/opencensus-specs/blob/master/trace/HTTP.md. Would be cool if gun/cowboy provide needed entrypoints.

essen commented 5 years ago

I read it twice and am still not sure what it's saying exactly, but the events above seem to cover the data that it's talking about so I guess it's fine?

essen commented 5 years ago

Started work on this with 3 initial events, more to come. cfd702a

essen commented 5 years ago

I've added disconnect and terminate events.

essen commented 5 years ago

Now has request and response events. It should start to be useful: https://github.com/ninenines/gun/blob/master/src/gun_event.erl

essen commented 5 years ago

Added more events. Here's what's left: https://github.com/ninenines/gun/blob/master/src/gun_event.erl#L160

essen commented 5 years ago

And more: https://github.com/ninenines/gun/blob/master/src/gun_event.erl#L210

Still to do the domain lookup/TLS handshake separate from the current "connect does everything" step we currently have. But that requires reworking the connection and that's a fair bit of work. Still, must be done for 2.0.

The next two are related to CONNECT so probably wouldn't be missed if it was only added later. And then push promise/cancel related events that are probably rare as well. Might just be left for a future release.

essen commented 5 years ago

https://github.com/ninenines/gun/commit/516933f9dd2722329b3886c495d5242308958fe1 splits connect into domain lookup, connect and tls_handshake events.

tisba commented 5 years ago

Sorry for the noise, but it's great to see that you are working on this topic! 💕

essen commented 5 years ago

I think it's about done, the rest is more edge cases, so please do look and provide feedback.

essen commented 5 years ago

Added push_promise/cancel events. Only CONNECT related events missing now. Also need to check that HTTP/1.0 responses with no content-length do get a response_end event (they probably don't right now).

essen commented 5 years ago

I've pushed with the missing events added, minus CONNECT TLS over TLS handshake events. Need to rework things a little for that one.

essen commented 5 years ago

All done! https://github.com/ninenines/gun/blob/master/src/gun_event.erl

Please open new tickets with feedback, thanks!

ninenines / gun

Instrumentation Features #151