SSE collapsing -- is duration available in the logs?

General
1

I’ve read the blog post on SSE request collapsing a few times but one thing I’d like to know is what the logs look like when an SSE request has been collapsed.

In particular we’d like to know how many connections times how long those connections are connected to the SSE stream. Would the %T field in a log include the total connection time for an SSE stream?

Thank you

1 Like
2

Hi @jkebinger,

I’m the author of that blog and happy to help.

Request collapsing works by creating a cache entry for a request as soon as we start fetching it from the backend, and that allows subsequent requests to, essentially, get a cache hit, even though the thing in the cache is not (yet) a complete object.

So on the backend side, you’ll see only the misses, but vcl_log will run for every request, and %T (which maps to the time.elapsed.sec VCL variable) will reflect the time we spent streaming the response to that client.

Example:

  • 00:00 Request 1 is received, is a miss, starts a backend fetch and creates an entry in cache. The server responds after 2 seconds, streams for 30 seconds, and then ends the response. vcl_log records a time of 32 seconds for this request.
  • 00:01 Request 2 arrives. There’s a marker in cache but no object has been created yet. We join the waiting list for the object, and eventually get the same response over the same period as request 1. vcl_log will record a time of 31 seconds.
  • 00:12 Request 3 arrives. There’s an object in cache which is fresh, and incomplete. We are sent the current contents of the cached object (everything that was received on the stream in the prior 10 seconds) and then we receive everything from that point onwards in real time. vcl_log will record a time of 20 seconds.
  • 00:45 Request 4 arrives. The object in cache expired at the moment the stream ended, so we have a miss and create another backend fetch.

In this example, arguably you have delivered 30 seconds-worth of streaming content to 3 users, so the total ‘consumed stream time’ is 90 seconds, but the clients only spent a collective 83 seconds connected, because when you join an existing stream after it starts you get the buffered content instantly.

Overall take-away is that summing the value of time.elapsed.sec in vcl_log will give you a good understanding of how long clients have spent connected to SSE streams served from your Fastly service.

1 Like
3

That’s terrific, thank you so much for clarifying!

1 Like