Skip to content
New issue

Have a question about this project? Sign up for a free GitHub account to open an issue and contact its maintainers and the community.

By clicking “Sign up for GitHub”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? Sign in to your account

feat(s2n-quic-dc): emit top-level stream events #2394

Merged
merged 1 commit into from
Dec 3, 2024

Conversation

camshaft
Copy link
Contributor

@camshaft camshaft commented Dec 3, 2024

Description of changes:

This change adds several stream events for s2n-quic-dc streams. This can provide better insight into what is happening to streams both in aggregate and individually.

Testing:

You can see the events showing up in the tracing logs for the tests:

$ cargo test -p s2n-quic-dc stream::send::tests::tcp::current_thread::write_10k::send_limited::shutdown_test -- --nocapture

running 1 test
2024-12-03T18:36:54.585999Z DEBUG s2n_quic_dc: path_secret_map_initialized: capacity=16
2024-12-03T18:36:54.590528Z DEBUG server:s2n_quic_dc: path_secret_map_initialized: capacity=16
2024-12-03T18:36:54.595035Z DEBUG server:s2n_quic_dc: acceptor_tcp_started: id=0 local_address=127.0.0.1:54249 backlog=16
expected=10000
2024-12-03T18:36:54.595274Z DEBUG server:s2n_quic_dc: acceptor_tcp_fresh_batch_completed: enqueued=0 dropped=0 errored=0
2024-12-03T18:36:54.595307Z DEBUG server:s2n_quic_dc: acceptor_tcp_loop_iteration_completed: pending_streams=0 slots_idle=16 slot_utilization=0.0 processing_duration=39µs max_sojourn_time=5s
2024-12-03T18:36:54.595639Z DEBUG s2n_quic_dc: path_secret_map_entry_inserted: peer_address=127.0.0.1:54249 credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68]
2024-12-03T18:36:54.595673Z DEBUG s2n_quic_dc: path_secret_map_entry_ready: peer_address=127.0.0.1:54249 credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68]
2024-12-03T18:36:54.595714Z DEBUG server:s2n_quic_dc: path_secret_map_entry_inserted: peer_address=127.0.0.1:1337 credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68]
2024-12-03T18:36:54.595737Z DEBUG server:s2n_quic_dc: path_secret_map_entry_ready: peer_address=127.0.0.1:1337 credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68]
2024-12-03T18:36:54.595774Z DEBUG s2n_quic_dc: path_secret_map_address_cache_accessed: peer_address=127.0.0.1:54249 hit=false
2024-12-03T18:36:54.595851Z DEBUG server:s2n_quic_dc: acceptor_tcp_fresh_enqueued: remote_address=127.0.0.1:57196
2024-12-03T18:36:54.595887Z DEBUG server:s2n_quic_dc: acceptor_tcp_fresh_batch_completed: enqueued=1 dropped=0 errored=0
2024-12-03T18:36:54.595949Z DEBUG server:s2n_quic_dc: acceptor_tcp_loop_iteration_completed: pending_streams=1 slots_idle=15 slot_utilization=6.25 processing_duration=116µs max_sojourn_time=5s
2024-12-03T18:36:54.596160Z DEBUG application:s2n_quic_dc:conn: stream_write_socket_flushed: provided_len=46 committed_len=46 processing_duration=26µs id=0
2024-12-03T18:36:54.596196Z DEBUG application:s2n_quic_dc:conn: stream_write_flushed: provided_len=0 committed_len=0 is_fin=false processing_duration=121µs id=0
2024-12-03T18:36:54.596343Z DEBUG application:s2n_quic_dc:conn: stream_write_socket_flushed: provided_len=10382 committed_len=10382 processing_duration=21µs id=0
2024-12-03T18:36:54.596377Z DEBUG application:s2n_quic_dc:conn: stream_write_flushed: provided_len=10000 committed_len=10000 is_fin=false processing_duration=134µs id=0
2024-12-03T18:36:54.596448Z DEBUG server:s2n_quic_dc: acceptor_tcp_fresh_batch_completed: enqueued=0 dropped=0 errored=0
2024-12-03T18:36:54.596504Z DEBUG server:s2n_quic_dc: acceptor_tcp_packet_received: remote_address=127.0.0.1:57196 credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68] stream_id=3 payload_len=0 is_fin=false is_fin_known=false sojourn_time=614µs
2024-12-03T18:36:54.596538Z DEBUG server:s2n_quic_dc: path_secret_map_id_cache_accessed: credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68] hit=true
2024-12-03T18:36:54.596616Z DEBUG server:s2n_quic_dc: acceptor_tcp_stream_enqueued: remote_address=127.0.0.1:57196 credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68] stream_id=3 sojourn_time=614µs blocked_count=1
2024-12-03T18:36:54.596655Z DEBUG server:s2n_quic_dc: acceptor_tcp_loop_iteration_completed: pending_streams=0 slots_idle=16 slot_utilization=0.0 processing_duration=208µs max_sojourn_time=1s
2024-12-03T18:36:54.596710Z DEBUG server:s2n_quic_dc: acceptor_stream_dequeued: remote_address=127.0.0.1:57196 credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68] stream_id=3 sojourn_time=260µs
2024-12-03T18:36:54.596875Z DEBUG server:s2n_quic_dc: key_accepted: credential_id=[13, 28, 95, 231, 182, 183, 190, 129, 215, 175, 84, 248, 202, 249, 135, 68] key_id=0 gap=1 forward_shift=0
2024-12-03T18:36:54.597018Z DEBUG server:s2n_quic_dc:conn: stream_read_flushed: capacity=131072 committed_len=10000 processing_duration=182µs id=0
2024-12-03T18:36:54.597058Z DEBUG server:s2n_quic_dc:conn: stream_read_socket_blocked: capacity=65536 processing_duration=6µs id=0
2024-12-03T18:36:54.597087Z DEBUG server:s2n_quic_dc:conn: stream_read_blocked: capacity=131072 processing_duration=38µs id=0
2024-12-03T18:36:54.599253Z DEBUG application:s2n_quic_dc:conn: stream_write_socket_flushed: provided_len=49 committed_len=49 processing_duration=18µs id=0
2024-12-03T18:36:54.599301Z DEBUG application:s2n_quic_dc:conn: stream_write_shutdown: buffer_len=0 background=false id=0
2024-12-03T18:36:54.599338Z DEBUG application:s2n_quic_dc:conn: stream_read_socket_blocked: capacity=65536 processing_duration=4µs id=0
2024-12-03T18:36:54.599365Z DEBUG application:s2n_quic_dc:conn: stream_read_shutdown: background=true id=0
2024-12-03T18:36:54.599388Z DEBUG application: s2n_quic_dc::stream::recv::application: spawning task to read server's response
2024-12-03T18:36:54.599478Z DEBUG application:s2n_quic_dc:conn: stream_read_socket_blocked: capacity=65536 processing_duration=14µs id=0
2024-12-03T18:36:54.599534Z DEBUG server:s2n_quic_dc:conn: stream_read_socket_flushed: capacity=65536 committed_len=49 processing_duration=6µs id=0
2024-12-03T18:36:54.599654Z DEBUG server:s2n_quic_dc:conn: stream_read_flushed: capacity=131072 committed_len=0 processing_duration=133µs id=0
2024-12-03T18:36:54.599732Z DEBUG server:s2n_quic_dc:conn: stream_read_shutdown: background=false id=0
2024-12-03T18:36:54.599828Z DEBUG server:s2n_quic_dc:conn: stream_write_socket_flushed: provided_len=47 committed_len=47 processing_duration=21µs id=0
2024-12-03T18:36:54.599856Z DEBUG server:s2n_quic_dc:conn: stream_write_shutdown: buffer_len=0 background=false id=0
2024-12-03T18:36:54.599991Z DEBUG application:s2n_quic_dc:conn: stream_read_socket_flushed: capacity=65536 committed_len=47 processing_duration=10µs id=0
2024-12-03T18:36:54.600050Z DEBUG server:tcp: s2n_quic_dc::stream::server::tokio::tcp: acceptor task has been dropped
2024-12-03T18:36:54.600167Z DEBUG server:s2n_quic_dc: path_secret_map_uninitialized: capacity=16 entries=1 lifetime=9.78ms
2024-12-03T18:36:54.600167Z DEBUG s2n_quic_dc: path_secret_map_uninitialized: capacity=16 entries=1 lifetime=14.436ms
test stream::send::tests::tcp::current_thread::write_10k::send_limited::shutdown_test ... ok

By submitting this pull request, I confirm that my contribution is made under the terms of the Apache 2.0 license.

@camshaft camshaft force-pushed the camshaft/dc-stream-events branch 5 times, most recently from e3337a5 to 2384171 Compare December 3, 2024 18:34
@camshaft camshaft changed the title feat(s2n-quic-dc): emit basic stream events feat(s2n-quic-dc): emit top-level stream events Dec 3, 2024
@camshaft camshaft marked this pull request as ready for review December 3, 2024 18:39
/// The amount of time it took to process the write request
///
/// Note that this includes both any syscall and encryption overhead
#[measure("processing_duration", Duration)]
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

I guess this is OK for now, but I wonder if we should have a duration_per_byte or something like that, to make it easier to actually make sense of what this means.

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

yeah that could be an interesting metric to have. i can add that as a follow-up

dc/s2n-quic-dc/events/connection.rs Outdated Show resolved Hide resolved
#[event("stream:read_socket_flushed")]
pub struct StreamReadSocketFlushed {
/// The number of bytes that the stream tried to read from the socket
#[measure("capacity", Bytes)]
Copy link
Collaborator

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

This buffer is always an internal buffer IIRC, right? Do we expect meaningful size differences on that?

Copy link
Contributor Author

Choose a reason for hiding this comment

The reason will be displayed to describe this comment to others. Learn more.

Yeah it's always an internal buffer. I was curious to see if we were ever needing to read more for stream sockets to complete a packet, in which case this buffer would be undersized.

Mark-Simulacrum
Mark-Simulacrum previously approved these changes Dec 3, 2024
@camshaft camshaft force-pushed the camshaft/dc-stream-events branch from ca4038b to fc51fd1 Compare December 3, 2024 19:15
@camshaft camshaft merged commit 0dfeff7 into main Dec 3, 2024
129 of 130 checks passed
@camshaft camshaft deleted the camshaft/dc-stream-events branch December 3, 2024 19:58
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
Labels
None yet
Projects
None yet
Development

Successfully merging this pull request may close these issues.

2 participants