From 0ab2ab241208ca6363143af3a9c649e2e2ba3fab Mon Sep 17 00:00:00 2001 From: Tommaso Barbugli Date: Tue, 29 Sep 2026 12:15:27 +0200 Subject: [PATCH 1/4] Report connection setup timing per call Call.ConnectionTiming and Call.OnConnectionTiming expose when the coordinator join, the SFU websocket and join, and each peer connection's signaling, ICE, DTLS and first RTP happened, so callers can print where connection setup time goes. Co-Authored-By: Claude Opus 5.5 (1M context) --- call.go | 17 +++++ connection_timing.go | 125 +++++++++++++++++++++++++++++++ connection_timing_test.go | 78 +++++++++++++++++++ interceptor/first_packet.go | 68 +++++++++++++++++ interceptor/first_packet_test.go | 91 ++++++++++++++++++++++ pc/pc.go | 52 ++++++++++++- pc/timing_test.go | 70 +++++++++++++++++ publisher.go | 9 +++ signal/client.go | 13 ++++ subscriber.go | 10 +++ 10 files changed, 530 insertions(+), 3 deletions(-) create mode 100644 connection_timing.go create mode 100644 connection_timing_test.go create mode 100644 interceptor/first_packet.go create mode 100644 interceptor/first_packet_test.go create mode 100644 pc/timing_test.go diff --git a/call.go b/call.go index 5d9b27e..237a277 100644 --- a/call.go +++ b/call.go @@ -274,6 +274,8 @@ type Call struct { joinOptions []JoinOption coordinatorState atomic.Pointer[CallState] + // timing records the first join's steps; see ConnectionTiming. + timing connectionTimer GetCred GetCredentialsFunc cred atomic.Pointer[models.Credentials] @@ -400,10 +402,12 @@ func (c *Call) joinCoordinator(ctx context.Context, options joinOptions) error { return nil } + c.timing.update(func(t *ConnectionTiming) { stamp(&t.CoordinatorStarted, time.Now()) }) result, getCred, err := c.cc.joinCoordinator(ctx, c.Type, c.Id, options.coordinatorRequest()) if err != nil { return xerr.Wrap(err) } + c.timing.update(func(t *ConnectionTiming) { stamp(&t.CoordinatorDone, time.Now()) }) c.GetCred = getCred cred := result.Credentials @@ -804,6 +808,12 @@ func (c *Call) Join(ctx context.Context, opts ...JoinOption) (*sfu_events.JoinRe for _, o := range opts { o(&options) } + if options.reconnectDetails.GetStrategy() == sfu_models.WebsocketReconnectStrategy_WEBSOCKET_RECONNECT_STRATEGY_UNSPECIFIED { + c.timing.update(func(t *ConnectionTiming) { stamp(&t.JoinStarted, time.Now()) }) + } else { + // Reconnects re-enter Join; the timing describes the first join only. + c.timing.seal() + } if err := c.joinCoordinator(ctx, options); err != nil { return nil, err @@ -895,6 +905,12 @@ func (c *Call) Join(ctx context.Context, opts ...JoinOption) (*sfu_events.JoinRe return nil, xerr.Wrap(err) } } + joinedAt := time.Now() + dialedAt := c.Client().DialedAt() + c.timing.update(func(t *ConnectionTiming) { + stamp(&t.SFUConnected, dialedAt) + stamp(&t.SFUJoined, joinedAt) + }) c.store.Store(NewParticipantStore(c, resp.CallState)) c.applyJoinResponse(resp) @@ -1148,6 +1164,7 @@ func (c *Call) RawHandler(event *sfu_events.SfuEvent) { // REJOIN or a Leave performs, and this runs on the signalling read loop, so a // panic here would take the process down with it. func (c *Call) OnSubscriberOffer(offer *sfu_events.SfuEvent_SubscriberOffer) { + c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.Offer, time.Now()) }) sub := c.subscriberPeer() if sub == nil { c.logger.Warn("dropping subscriber offer: no subscriber peer connection") diff --git a/connection_timing.go b/connection_timing.go new file mode 100644 index 0000000..f574b35 --- /dev/null +++ b/connection_timing.go @@ -0,0 +1,125 @@ +package rtc + +import ( + "sync" + "time" + + "github.com/GetStream/getstream-go-webrtc/pc" +) + +// ConnectionTiming is when each step of joining a call happened, so a caller can see +// where the time to media goes. A zero time is a step that has not happened (yet). +// +// It describes the first join only. A reconnect or migration builds new peer connections +// but leaves these alone: what a caller wants from them is how long the call took to come +// up, not how long the last repair took. +type ConnectionTiming struct { + // JoinStarted is when Join was first called. + JoinStarted time.Time + // CoordinatorStarted and CoordinatorDone bracket the coordinator's join-call request, + // which returns the SFU to connect to and the token for it. + CoordinatorStarted time.Time + CoordinatorDone time.Time + // SFUConnected is when the websocket to the SFU finished opening. + SFUConnected time.Time + // SFUJoined is when the SFU answered the join request. + SFUJoined time.Time + // Publisher and Subscriber are each peer connection's path from signaling to media. + Publisher PeerTiming + Subscriber PeerTiming +} + +// PeerTiming is one peer connection's path from signaling to media. +type PeerTiming struct { + // Offer is when the offer existed: created locally for the publisher, received from + // the SFU for the subscriber. + Offer time.Time + // SignalSent and SignalDone bracket the request that carries the local description to + // the SFU: SetPublisher, which returns the answer, or SendAnswer. + SignalSent time.Time + SignalDone time.Time + // ICEChecking and ICEConnected are the ICE agent's first transitions. + ICEChecking time.Time + ICEConnected time.Time + // DTLSConnected is when the DTLS handshake finished. + DTLSConnected time.Time + // Connected is when the peer connection reported connected. + Connected time.Time + // FirstRTP is the first media packet: sent for the publisher, received for the + // subscriber. It waits for there to be media, so it is not purely connection time. + FirstRTP time.Time +} + +// connectionTimer records ConnectionTiming as the steps happen. +type connectionTimer struct { + mu sync.Mutex + timing ConnectionTiming + sealed bool + handler func(ConnectionTiming) +} + +// update applies fn and hands the result to the handler if anything changed. Once sealed, +// nothing changes any more. +func (r *connectionTimer) update(fn func(*ConnectionTiming)) { + r.mu.Lock() + if r.sealed { + r.mu.Unlock() + return + } + before := r.timing + fn(&r.timing) + changed := before != r.timing + snapshot, handler := r.timing, r.handler + r.mu.Unlock() + + if changed && handler != nil { + handler(snapshot) + } +} + +// seal stops recording, so a reconnect does not write into the first join's timing. +func (r *connectionTimer) seal() { + r.mu.Lock() + defer r.mu.Unlock() + r.sealed = true +} + +func (r *connectionTimer) snapshot() ConnectionTiming { + r.mu.Lock() + defer r.mu.Unlock() + return r.timing +} + +func (r *connectionTimer) setHandler(handler func(ConnectionTiming)) { + r.mu.Lock() + defer r.mu.Unlock() + r.handler = handler +} + +// stamp records at in *field unless the step was already recorded. +func stamp(field *time.Time, at time.Time) { + if field.IsZero() && !at.IsZero() { + *field = at + } +} + +// stampTransport copies a transport's connection steps into a peer's timing. +func stampTransport(peer *PeerTiming, t pc.Timing) { + stamp(&peer.ICEChecking, t.ICEChecking) + stamp(&peer.ICEConnected, t.ICEConnected) + stamp(&peer.DTLSConnected, t.DTLSConnected) + stamp(&peer.Connected, t.Connected) +} + +// ConnectionTiming returns when each step of the call's first join happened. +func (c *Call) ConnectionTiming() ConnectionTiming { + return c.timing.snapshot() +} + +// OnConnectionTiming sets a handler that receives the call's ConnectionTiming each time a +// step of the first join is recorded. Set it before Join to see every step. It runs on +// whichever goroutine recorded the step, including pion callbacks and the packet path, +// so it must not block. +func (c *Call) OnConnectionTiming(handler func(ConnectionTiming)) { + c.timing.setHandler(handler) +} diff --git a/connection_timing_test.go b/connection_timing_test.go new file mode 100644 index 0000000..4de9983 --- /dev/null +++ b/connection_timing_test.go @@ -0,0 +1,78 @@ +package rtc + +import ( + "context" + "testing" + "time" + + sfu_events "github.com/GetStream/protocol/protobuf/video/sfu/event" + "github.com/stretchr/testify/require" + + "github.com/GetStream/getstream-go-webrtc/internal/testutil" +) + +// TestJoinRecordsTheCoordinatorAndSFUSteps runs the real Join against a fake SFU and +// checks the join steps are recorded in the order they happen. +func TestJoinRecordsTheCoordinatorAndSFUSteps(t *testing.T) { + t.Parallel() + + sfu := testutil.NewFakeSFU() + defer sfu.Close() + + reports := make(chan ConnectionTiming, 64) + call := newFakeSFUCall(t, sfu, "sfu-fake") + call.onceConnect.Do(func() {}) + call.OnConnectionTiming(func(timing ConnectionTiming) { + select { + case reports <- timing: + default: + } + }) + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + _, err := call.Join(ctx) + require.NoError(t, err) + t.Cleanup(func() { _ = call.Leave("test over") }) + + timing := call.ConnectionTiming() + require.False(t, timing.JoinStarted.IsZero()) + require.False(t, timing.SFUConnected.Before(timing.JoinStarted)) + require.False(t, timing.SFUJoined.Before(timing.SFUConnected), "the SFU answers after the websocket is open") + require.NotEmpty(t, reports, "the handler saw the steps") +} + +// TestReconnectDoesNotOverwriteTheFirstJoin keeps the first join's timing when Join runs +// again for a reconnect. +func TestReconnectDoesNotOverwriteTheFirstJoin(t *testing.T) { + t.Parallel() + + sfu := testutil.NewFakeSFU() + defer sfu.Close() + + call, _ := joinFakeSFU(t, sfu) + first := call.ConnectionTiming() + + ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) + defer cancel() + _, err := call.Join(ctx, withReconnectDetails(&sfu_events.ReconnectDetails{ + Strategy: strategyRejoin, + PreviousSessionId: call.SessionID.Load(), + })) + require.NoError(t, err) + + require.Equal(t, first, call.ConnectionTiming()) +} + +func TestConnectionTimerStampsOnlyTheFirstTime(t *testing.T) { + t.Parallel() + + var timer connectionTimer + calls := 0 + timer.setHandler(func(ConnectionTiming) { calls++ }) + first := time.Now() + timer.update(func(ct *ConnectionTiming) { stamp(&ct.JoinStarted, first) }) + timer.update(func(ct *ConnectionTiming) { stamp(&ct.JoinStarted, first.Add(time.Second)) }) + + require.Equal(t, first, timer.snapshot().JoinStarted) + require.Equal(t, 1, calls, "an update that changes nothing is not reported") +} diff --git a/interceptor/first_packet.go b/interceptor/first_packet.go new file mode 100644 index 0000000..5296e0c --- /dev/null +++ b/interceptor/first_packet.go @@ -0,0 +1,68 @@ +package interceptor + +import ( + "sync/atomic" + "time" + + "github.com/pion/interceptor" + "github.com/pion/rtp" +) + +// FirstPacketFactory reports when a peer connection sends its first RTP packet and when +// it receives its first one. After that it costs one atomic load per packet. +type FirstPacketFactory struct { + onFirstWrite func(time.Time) + onFirstRead func(time.Time) +} + +// NewFirstPacketFactory returns a factory whose interceptors call onFirstWrite after the +// first RTP packet is sent and onFirstRead after the first one is read. A write pion drops +// because the transport is not ready yet does not count as sent. Either may be +// nil. The callbacks run on the packet path and must not block. +func NewFirstPacketFactory(onFirstWrite, onFirstRead func(time.Time)) *FirstPacketFactory { + return &FirstPacketFactory{onFirstWrite: onFirstWrite, onFirstRead: onFirstRead} +} + +// NewInterceptor implements interceptor.Factory. +func (f *FirstPacketFactory) NewInterceptor(string) (interceptor.Interceptor, error) { + return &firstPacket{onFirstWrite: f.onFirstWrite, onFirstRead: f.onFirstRead}, nil +} + +type firstPacket struct { + interceptor.NoOp + + onFirstWrite func(time.Time) + onFirstRead func(time.Time) + wrote atomic.Bool + read atomic.Bool +} + +// BindLocalStream reports the first packet written on any outgoing stream. +func (i *firstPacket) BindLocalStream(_ *interceptor.StreamInfo, writer interceptor.RTPWriter) interceptor.RTPWriter { + if i.onFirstWrite == nil { + return writer + } + return interceptor.RTPWriterFunc(func(header *rtp.Header, payload []byte, attributes interceptor.Attributes) (int, error) { + n, err := writer.Write(header, payload, attributes) + // Before DTLS finishes pion accepts packets and drops them, reporting zero bytes + // written, so only a write that sent something counts. + if err == nil && n > 0 && !i.wrote.Load() && i.wrote.CompareAndSwap(false, true) { + i.onFirstWrite(time.Now()) + } + return n, err + }) +} + +// BindRemoteStream reports the first packet read on any incoming stream. +func (i *firstPacket) BindRemoteStream(_ *interceptor.StreamInfo, reader interceptor.RTPReader) interceptor.RTPReader { + if i.onFirstRead == nil { + return reader + } + return interceptor.RTPReaderFunc(func(b []byte, attributes interceptor.Attributes) (int, interceptor.Attributes, error) { + n, attrs, err := reader.Read(b, attributes) + if err == nil && !i.read.Load() && i.read.CompareAndSwap(false, true) { + i.onFirstRead(time.Now()) + } + return n, attrs, err + }) +} diff --git a/interceptor/first_packet_test.go b/interceptor/first_packet_test.go new file mode 100644 index 0000000..2446fa8 --- /dev/null +++ b/interceptor/first_packet_test.go @@ -0,0 +1,91 @@ +package interceptor + +import ( + "sync/atomic" + "testing" + "time" + + "github.com/pion/interceptor" + "github.com/pion/rtp" + "github.com/stretchr/testify/require" +) + +func TestFirstPacketReportsTheFirstWriteAndReadOnce(t *testing.T) { + var writes, reads atomic.Int32 + var wroteAt atomic.Int64 + factory := NewFirstPacketFactory(func(at time.Time) { + writes.Add(1) + wroteAt.Store(at.UnixNano()) + }, func(time.Time) { reads.Add(1) }) + built, err := factory.NewInterceptor("") + require.NoError(t, err) + + writer := built.BindLocalStream(&interceptor.StreamInfo{}, interceptor.RTPWriterFunc( + func(_ *rtp.Header, payload []byte, _ interceptor.Attributes) (int, error) { return len(payload), nil })) + reader := built.BindRemoteStream(&interceptor.StreamInfo{}, interceptor.RTPReaderFunc( + func(b []byte, a interceptor.Attributes) (int, interceptor.Attributes, error) { return len(b), a, nil })) + + before := time.Now() + for range 3 { + _, err := writer.Write(&rtp.Header{}, []byte{1}, nil) + require.NoError(t, err) + _, _, err = reader.Read(make([]byte, 4), nil) + require.NoError(t, err) + } + + require.Equal(t, int32(1), writes.Load(), "only the first write is reported") + require.Equal(t, int32(1), reads.Load(), "only the first read is reported") + require.False(t, time.Unix(0, wroteAt.Load()).Before(before)) +} + +func TestFirstPacketLeavesStreamsAloneWithoutACallback(t *testing.T) { + built, err := NewFirstPacketFactory(nil, nil).NewInterceptor("") + require.NoError(t, err) + + writer := interceptor.RTPWriterFunc(func(*rtp.Header, []byte, interceptor.Attributes) (int, error) { return 7, nil }) + n, err := built.BindLocalStream(&interceptor.StreamInfo{}, writer).Write(&rtp.Header{}, nil, nil) + require.NoError(t, err) + require.Equal(t, 7, n) +} + +func TestFirstPacketDoesNotReportAFailedWrite(t *testing.T) { + var writes atomic.Int32 + built, err := NewFirstPacketFactory(func(time.Time) { writes.Add(1) }, nil).NewInterceptor("") + require.NoError(t, err) + + failing := interceptor.RTPWriterFunc(func(*rtp.Header, []byte, interceptor.Attributes) (int, error) { + return 0, errWriteFailed + }) + _, err = built.BindLocalStream(&interceptor.StreamInfo{}, failing).Write(&rtp.Header{}, nil, nil) + require.ErrorIs(t, err, errWriteFailed) + require.Zero(t, writes.Load()) +} + +func TestFirstPacketDoesNotReportAPacketDroppedBeforeTheTransportIsReady(t *testing.T) { + var writes atomic.Int32 + built, err := NewFirstPacketFactory(func(time.Time) { writes.Add(1) }, nil).NewInterceptor("") + require.NoError(t, err) + ready := false + writer := built.BindLocalStream(&interceptor.StreamInfo{}, interceptor.RTPWriterFunc( + func(_ *rtp.Header, payload []byte, _ interceptor.Attributes) (int, error) { + if !ready { + return 0, nil + } + return len(payload), nil + })) + + _, err = writer.Write(&rtp.Header{}, []byte{1}, nil) + require.NoError(t, err) + require.Zero(t, writes.Load(), "pion drops packets before DTLS finishes and reports zero bytes") + + ready = true + _, err = writer.Write(&rtp.Header{}, []byte{1}, nil) + require.NoError(t, err) + require.Equal(t, int32(1), writes.Load()) +} + +var errWriteFailed = &writeError{} + +type writeError struct{} + +func (*writeError) Error() string { return "write failed" } diff --git a/pc/pc.go b/pc/pc.go index f679838..3715cbe 100644 --- a/pc/pc.go +++ b/pc/pc.go @@ -74,8 +74,10 @@ type Transport struct { connectTimer *time.Timer iceStartedAt time.Time iceConnectedAt time.Time - connectedAt time.Time - lastPCState webrtc.PeerConnectionState + // dtlsConnectedAt is when the DTLS handshake finished for the first time. + dtlsConnectedAt time.Time + connectedAt time.Time + lastPCState webrtc.PeerConnectionState // lastICEState and lastDTLSState skip the Closed transition that Close // causes, so a snapshot taken afterwards still shows where the connection // stalled. @@ -118,6 +120,23 @@ type TransportParams struct { IsOfferer bool PeerConfig timeouts *transportTimeouts + // OnTimingChange, when set, receives a snapshot each time the transport reaches a + // new connection step. It runs on a pion callback goroutine and must not block. + OnTimingChange func(Timing) +} + +// Timing is when a transport first reached each step of connecting. A zero time is a +// step it has not reached. ICE restarts do not move these: they describe how the +// transport came up in the first place. +type Timing struct { + // ICEChecking is when ICE started checking candidate pairs. + ICEChecking time.Time + // ICEConnected is when ICE found a working pair. + ICEConnected time.Time + // DTLSConnected is when the DTLS handshake finished on top of ICE. + DTLSConnected time.Time + // Connected is when the peer connection reported connected. + Connected time.Time } type PeerConfig struct { @@ -241,7 +260,10 @@ func (p TransportParams) iceTimeouts() (disconnected, failed, keepalive time.Dur func (t *Transport) bindCallbacks() { h := t.Params.Handler if dtls := dtlsTransportOf(t.PC); dtls != nil { - dtls.OnStateChange(t.onDTLSStateChange) + dtls.OnStateChange(func(state webrtc.DTLSTransportState) { + t.onDTLSStateChange(state) + t.notifyTiming() + }) } t.PC.OnICEGatheringStateChange(func(state webrtc.ICEGatheringState) { t.Params.Logger.Debugw("ice gathering state change", "state", state.String()) @@ -260,10 +282,12 @@ func (t *Transport) bindCallbacks() { }) t.PC.OnICEConnectionStateChange(func(state webrtc.ICEConnectionState) { t.onICEStateChange(state) + t.notifyTiming() h.OnICEConnectionStateChange(state) }) t.PC.OnConnectionStateChange(func(state webrtc.PeerConnectionState) { t.onPCStateChange(state) + t.notifyTiming() h.OnConnectionStateChange(state) }) t.PC.OnTrack(h.OnTrack) @@ -793,6 +817,9 @@ func (t *Transport) onDTLSStateChange(state webrtc.DTLSTransportState) { if state != webrtc.DTLSTransportStateClosed { t.lastDTLSState = state } + if state == webrtc.DTLSTransportStateConnected && t.dtlsConnectedAt.IsZero() { + t.dtlsConnectedAt = time.Now() + } t.mu.Unlock() var sinceICEConnected time.Duration @@ -805,6 +832,25 @@ func (t *Transport) onDTLSStateChange(state webrtc.DTLSTransportState) { ) } +// Timing returns when the transport first reached each connection step. +func (t *Transport) Timing() Timing { + t.mu.Lock() + defer t.mu.Unlock() + return Timing{ + ICEChecking: t.iceStartedAt, + ICEConnected: t.iceConnectedAt, + DTLSConnected: t.dtlsConnectedAt, + Connected: t.connectedAt, + } +} + +// notifyTiming hands the current timing to OnTimingChange, if one is set. +func (t *Transport) notifyTiming() { + if t.Params.OnTimingChange != nil { + t.Params.OnTimingChange(t.Timing()) + } +} + // connectionInfo snapshots the transport for a failure report. Duration is // the time spent in the failing phase: DTLS once ICE has connected, ICE // before that. diff --git a/pc/timing_test.go b/pc/timing_test.go new file mode 100644 index 0000000..2cb7114 --- /dev/null +++ b/pc/timing_test.go @@ -0,0 +1,70 @@ +package pc + +import ( + "sync" + "testing" + "time" + + "github.com/pion/webrtc/v4" + "github.com/stretchr/testify/require" + + "github.com/GetStream/getstream-go-webrtc/logger" + "github.com/GetStream/protocol/protobuf/video/sfu/models" +) + +// TestTimingRecordsEachConnectionStepInOrder connects a transport to a real pion peer and +// checks that every step is recorded, in the order it happens, and reported through +// OnTimingChange. +func TestTimingRecordsEachConnectionStepInOrder(t *testing.T) { + var mu sync.Mutex + var reported []Timing + st := newPCTestWithTransportParams(t, TransportParams{ + Transport: models.PeerType_PEER_TYPE_SUBSCRIBER, + Logger: logger.Noop{}, + IsOfferer: true, + PeerConfig: newPCTestPeerConfig(t), + OnTimingChange: func(timing Timing) { + mu.Lock() + reported = append(reported, timing) + mu.Unlock() + }, + }) + require.Equal(t, Timing{}, st.tr.Timing(), "nothing has happened before negotiation") + + remote := newRemotePeer(t, st.tr) + st.handler.onICECandidateSender = remote.ICECandidateSender + st.tr.Negotiate(true) + st.tr.HandleRemoteDescription(remote.Answer(st.waitForOffer())) + st.waitForPCState(webrtc.PeerConnectionStateConnected, 2*time.Second) + + timing := st.tr.Timing() + require.False(t, timing.ICEChecking.IsZero()) + require.False(t, timing.ICEConnected.Before(timing.ICEChecking)) + require.False(t, timing.DTLSConnected.Before(timing.ICEConnected), "DTLS runs on top of ICE") + require.False(t, timing.Connected.Before(timing.DTLSConnected)) + + require.Eventually(t, func() bool { + mu.Lock() + defer mu.Unlock() + return len(reported) > 0 && reported[len(reported)-1] == timing + }, time.Second, 10*time.Millisecond, "the last report is the final timing") +} + +// TestTimingIsNotMovedByLaterStateChanges keeps the first connection's timing when the +// transport goes through the same states again, as it does on an ICE restart. +func TestTimingIsNotMovedByLaterStateChanges(t *testing.T) { + st := newPCTest(t) + remote := newRemotePeer(t, st.tr) + st.handler.onICECandidateSender = remote.ICECandidateSender + st.tr.Negotiate(true) + st.tr.HandleRemoteDescription(remote.Answer(st.waitForOffer())) + st.waitForPCState(webrtc.PeerConnectionStateConnected, 2*time.Second) + first := st.tr.Timing() + + st.tr.onICEStateChange(webrtc.ICEConnectionStateChecking) + st.tr.onICEStateChange(webrtc.ICEConnectionStateConnected) + st.tr.onDTLSStateChange(webrtc.DTLSTransportStateConnected) + st.tr.onPCStateChange(webrtc.PeerConnectionStateConnected) + + require.Equal(t, first, st.tr.Timing()) +} diff --git a/publisher.go b/publisher.go index 296a065..33c417f 100644 --- a/publisher.go +++ b/publisher.go @@ -95,6 +95,9 @@ func newPublisher(c *Call, peerConfig pc.PeerConfig) (*publisher, error) { // Add RTX prober interceptor to send probe packets that help the SFU // discover RTX SSRC mappings via header extensions (mid, rsid) peerConfig.Registry.Add(sdkinterceptor.NewRTXProberFactory()) + peerConfig.Registry.Add(sdkinterceptor.NewFirstPacketFactory(func(at time.Time) { + c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.FirstRTP, at) }) + }, nil)) cred := c.cred.Load() if peerConfig.Config.ICEServers == nil { @@ -115,6 +118,9 @@ func newPublisher(c *Call, peerConfig pc.PeerConfig) (*publisher, error) { Handler: pub, IsOfferer: true, Transport: sfu_models.PeerType_PEER_TYPE_PUBLISHER_UNSPECIFIED, + OnTimingChange: func(timing pc.Timing) { + c.timing.update(func(t *ConnectionTiming) { stampTransport(&t.Publisher, timing) }) + }, }) pub.Transport = peerc @@ -262,6 +268,7 @@ func (p *publisher) OnTrack(t *webrtc.TrackRemote, _ *webrtc.RTPReceiver) { } func (p *publisher) OnOffer(sd webrtc.SessionDescription, negotiationID uint32) error { + p.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.Offer, time.Now()) }) ctx, cancel := context.WithTimeout(context.Background(), time.Second*3) defer cancel() @@ -277,10 +284,12 @@ func (p *publisher) OnOffer(sd webrtc.SessionDescription, negotiationID uint32) SessionId: p.c.SessionID.Load(), Tracks: tracks, } + p.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.SignalSent, time.Now()) }) resp, err := p.c.Client().SetPublisher(ctx, req) if err != nil { return err } + p.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.SignalDone, time.Now()) }) if sfuErr := resp.GetError(); sfuErr != nil { // Return a NegotiationError with SFU error details (code, message) return pc.NewNegotiationError("SetPublisher failed", nil, sfuErr) diff --git a/signal/client.go b/signal/client.go index 58f3c16..92a50ed 100644 --- a/signal/client.go +++ b/signal/client.go @@ -105,6 +105,8 @@ type Client struct { lastHealthCheckNanos atomic.Int64 conn atomic.Pointer[websocket.Connection[sfu_events.SfuEvent, sfu_events.SfuRequest]] cred atomic.Pointer[models.Credentials] + // dialedAtNanos is when the last websocket to the SFU finished opening. + dialedAtNanos atomic.Int64 disconnected atomic.Bool // detached stops events from reaching the Handler while still recording them @@ -231,12 +233,23 @@ func (c *Client) SetCredentials(cred models.Credentials) { c.setRPC(c.getSignalRPCClient(cred)) } +// DialedAt is when the last websocket to the SFU finished opening, or the zero time if +// none has. +func (c *Client) DialedAt() time.Time { + nanos := c.dialedAtNanos.Load() + if nanos == 0 { + return time.Time{} + } + return time.Unix(0, nanos) +} + func (c *Client) Connect(ctx context.Context, joinRequest *sfu_events.JoinRequest) (*sfu_events.JoinResponse, error) { endpoint := c.cred.Load().Server.WsEndpoint wsConn, _, _, err := ws.DefaultDialer.Dial(ctx, endpoint) if err != nil { return nil, err } + c.dialedAtNanos.Store(time.Now().UnixNano()) c.Tracing.Load().Emit(rtcstats.SignalWSOpenEvent, map[string]any{ "url": endpoint, }) diff --git a/subscriber.go b/subscriber.go index d6a81ef..7a26935 100644 --- a/subscriber.go +++ b/subscriber.go @@ -19,6 +19,7 @@ import ( "github.com/thesyncim/skipset" "github.com/valyala/bytebufferpool" + sdkinterceptor "github.com/GetStream/getstream-go-webrtc/interceptor" "github.com/GetStream/getstream-go-webrtc/logger" "github.com/GetStream/getstream-go-webrtc/pc" "github.com/GetStream/getstream-go-webrtc/rtcstats" @@ -123,6 +124,10 @@ func newSubscriber(c *Call, s Subscriber, peerConfig pc.PeerConfig, beforeSendAn c.logger.Warnf("external RTCP is enabled, RTCP reports will not be sent by the SDK") } + peerConfig.Registry.Add(sdkinterceptor.NewFirstPacketFactory(nil, func(at time.Time) { + c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.FirstRTP, at) }) + })) + sub.Tracing.Load().Emit(rtcstats.PeerCreateEvent, peerConfig.Config) peerc, err := pc.NewPCTransport(pc.TransportParams{ @@ -131,6 +136,9 @@ func newSubscriber(c *Call, s Subscriber, peerConfig pc.PeerConfig, beforeSendAn Handler: sub, IsOfferer: false, Transport: sfu_models.PeerType_PEER_TYPE_SUBSCRIBER, + OnTimingChange: func(timing pc.Timing) { + c.timing.update(func(t *ConnectionTiming) { stampTransport(&t.Subscriber, timing) }) + }, }) sub.c = c sub.Transport = peerc @@ -275,10 +283,12 @@ func (s *subscriber) OnAnswer(sd webrtc.SessionDescription, negotiationId uint32 return xerr.Wrap(err) } } + s.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.SignalSent, time.Now()) }) answer, err := s.c.Client().SendAnswer(context.Background(), req) if err != nil { return xerr.Wrap(err) } + s.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.SignalDone, time.Now()) }) if err := answer.GetError(); err != nil { return errors.New(err.Message) } From a8fe97288f116605090b5d41fa927a3a360ace39 Mon Sep 17 00:00:00 2001 From: Tommaso Barbugli Date: Wed, 30 Sep 2026 16:10:10 +0200 Subject: [PATCH 2/4] feat(netdelay): simulate a network round-trip time on local connections Delays every write and read by rtt/2 in order, and a TCP connect by one rtt, on stream conns, packet conns and a pion transport.Net for ICE. For tests and benches only. --- internal/netdelay/netdelay.go | 343 +++++++++++++++++++++++++++++ internal/netdelay/netdelay_test.go | 169 ++++++++++++++ internal/netdelay/packet.go | 185 ++++++++++++++++ 3 files changed, 697 insertions(+) create mode 100644 internal/netdelay/netdelay.go create mode 100644 internal/netdelay/netdelay_test.go create mode 100644 internal/netdelay/packet.go diff --git a/internal/netdelay/netdelay.go b/internal/netdelay/netdelay.go new file mode 100644 index 0000000..3ca82d5 --- /dev/null +++ b/internal/netdelay/netdelay.go @@ -0,0 +1,343 @@ +// Package netdelay makes a local connection behave like one across a network with a given +// round-trip time: every write is held for half the RTT before it is sent and every read +// is held for half the RTT after it arrived, and a TCP connect takes one RTT. Only this +// side of a connection is wrapped, so a request and its response together pay one RTT. +// Packets are never reordered within a connection. +// +// It is for tests and benches only. +package netdelay + +import ( + "context" + "net" + "net/http" + "net/http/httptrace" + "os" + "runtime" + "sync" + "time" + + "github.com/pion/transport/v4/deadline" +) + +// DialFunc opens a network connection, like net.Dialer.DialContext. +type DialFunc = func(ctx context.Context, network, addr string) (net.Conn, error) + +// Dialer wraps base, a nil base being a plain net.Dialer, so its connections are delayed +// by rtt. It reports the whole delayed connect to the context's httptrace.ClientTrace; base +// does not see that trace, or it would report the undelayed one. +func Dialer(rtt time.Duration, base DialFunc) DialFunc { + if base == nil { + base = (&net.Dialer{Timeout: 30 * time.Second, KeepAlive: 30 * time.Second}).DialContext + } + return func(ctx context.Context, network, addr string) (net.Conn, error) { + trace := httptrace.ContextClientTrace(ctx) + if trace != nil && trace.ConnectStart != nil { + trace.ConnectStart(network, addr) + } + conn, err := dial(ctx, rtt, base, network, addr) + if trace != nil && trace.ConnectDone != nil { + trace.ConnectDone(network, addr, err) + } + return conn, err + } +} + +func dial(ctx context.Context, rtt time.Duration, base DialFunc, network, addr string) (net.Conn, error) { + untraced, cancel := context.WithCancel(context.Background()) + defer cancel() + stop := context.AfterFunc(ctx, cancel) + defer stop() + conn, err := base(untraced, network, addr) + if err != nil { + if ctx.Err() != nil { + return nil, ctx.Err() + } + return nil, err + } + if isTCP(network) { + // The SYN out and the SYN-ACK back. + t := time.NewTimer(rtt) + select { + case <-t.C: + case <-ctx.Done(): + t.Stop() + _ = conn.Close() + return nil, ctx.Err() + } + } + return NewConn(conn, rtt), nil +} + +// HTTPTransport is http.DefaultTransport with its connections delayed by rtt. +func HTTPTransport(rtt time.Duration) *http.Transport { + tr := http.DefaultTransport.(*http.Transport).Clone() + tr.DialContext = Dialer(rtt, nil) + return tr +} + +func isTCP(network string) bool { + switch network { + case "tcp", "tcp4", "tcp6": + return true + } + return false +} + +// packet is one write or read held until due. +type packet struct { + b []byte + addr net.Addr + due time.Time + err error +} + +// queueSize bounds the packets held in each direction; a full queue blocks the writer or +// the socket reader, like a full socket buffer. +const queueSize = 1024 + +// delayer holds the two queues of one connection. +type delayer struct { + half time.Duration + + out chan packet + in chan packet + closed chan struct{} + once sync.Once + + readDeadline *deadline.Deadline + writeDeadline *deadline.Deadline + + // rmu serializes readers; head is the packet being handed out. + rmu sync.Mutex + head *packet + + errMu sync.Mutex + writeErr error +} + +func newDelayer(rtt time.Duration) *delayer { + return &delayer{ + half: rtt / 2, + out: make(chan packet, queueSize), + in: make(chan packet, queueSize), + closed: make(chan struct{}), + readDeadline: deadline.New(), + writeDeadline: deadline.New(), + } +} + +// enqueueWrite holds a copy of b for half the RTT. +func (d *delayer) enqueueWrite(b []byte, addr net.Addr) (int, error) { + if err := d.lastWriteErr(); err != nil { + return 0, err + } + select { + case <-d.writeDeadline.Done(): + return 0, os.ErrDeadlineExceeded + default: + } + p := packet{b: append([]byte(nil), b...), addr: addr, due: time.Now().Add(d.half)} + select { + case d.out <- p: + return len(b), nil + case <-d.closed: + return 0, net.ErrClosed + case <-d.writeDeadline.Done(): + return 0, os.ErrDeadlineExceeded + } +} + +// writeLoop sends each held write when it is due, in order. After Close it still sends +// what was already written, then calls closeConn. +func (d *delayer) writeLoop(send func(packet) error, closeConn func()) { + defer closeConn() + for { + select { + case p := <-d.out: + sleepUntil(p.due) + if err := send(p); err != nil { + d.setWriteErr(err) + return + } + case <-d.closed: + for { + select { + case p := <-d.out: + sleepUntil(p.due) + if send(p) != nil { + return + } + default: + return + } + } + } + } +} + +// readLoop reads from the socket until it fails, stamping each read with when it is due. +func (d *delayer) readLoop(recv func([]byte) (int, net.Addr, error), bufSize int) { + buf := make([]byte, bufSize) + for { + n, addr, err := recv(buf) + due := time.Now().Add(d.half) + if n > 0 { + select { + case d.in <- packet{b: append([]byte(nil), buf[:n]...), addr: addr, due: due}: + case <-d.closed: + return + } + } + if err != nil { + select { + case d.in <- packet{err: err, due: due}: + case <-d.closed: + } + return + } + } +} + +// next waits for the next read to be due. With whole set, the packet is handed out in +// one piece (datagrams); otherwise the caller consumes head and clears it when empty. +func (d *delayer) next() (*packet, error) { + if d.head == nil { + select { + case p := <-d.in: + d.head = &p + case <-d.readDeadline.Done(): + return nil, os.ErrDeadlineExceeded + case <-d.closed: + return nil, net.ErrClosed + } + } + if wait := time.Until(d.head.due) - spin; wait > 0 { + t := time.NewTimer(wait) + select { + case <-t.C: + case <-d.readDeadline.Done(): + t.Stop() + return nil, os.ErrDeadlineExceeded + case <-d.closed: + t.Stop() + return nil, net.ErrClosed + } + } + spinUntil(d.head.due) + if d.head.err != nil { + return nil, d.head.err + } + return d.head, nil +} + +func (d *delayer) close() bool { + first := false + d.once.Do(func() { + first = true + close(d.closed) + }) + return first +} + +func (d *delayer) setDeadline(t time.Time) { + d.readDeadline.Set(t) + d.writeDeadline.Set(t) +} + +func (d *delayer) setWriteErr(err error) { + d.errMu.Lock() + defer d.errMu.Unlock() + if d.writeErr == nil { + d.writeErr = err + } +} + +func (d *delayer) lastWriteErr() error { + d.errMu.Lock() + defer d.errMu.Unlock() + return d.writeErr +} + +// spin is how early a sleep ends so the rest of the wait can be spun off: timers +// overshoot by a millisecond or two, macOS's especially, and every delayed packet would +// otherwise add that to the RTT. +const spin = 2 * time.Millisecond + +func sleepUntil(t time.Time) { + if wait := time.Until(t) - spin; wait > 0 { + time.Sleep(wait) + } + spinUntil(t) +} + +func spinUntil(t time.Time) { + for time.Now().Before(t) { + runtime.Gosched() + } +} + +// Conn is a stream connection with delayed reads and writes. +type Conn struct { + net.Conn + d *delayer +} + +// NewConn wraps conn so it behaves as if it crossed a network with round-trip time rtt. +func NewConn(conn net.Conn, rtt time.Duration) *Conn { + c := &Conn{Conn: conn, d: newDelayer(rtt)} + go c.d.writeLoop(func(p packet) error { + _, err := conn.Write(p.b) + return err + }, func() { _ = conn.Close() }) + go c.d.readLoop(func(b []byte) (int, net.Addr, error) { + n, err := conn.Read(b) + return n, nil, err + }, 32<<10) + return c +} + +// Read returns data at least half an RTT after it arrived. +func (c *Conn) Read(b []byte) (int, error) { + c.d.rmu.Lock() + defer c.d.rmu.Unlock() + p, err := c.d.next() + if err != nil { + return 0, err + } + n := copy(b, p.b) + p.b = p.b[n:] + if len(p.b) == 0 { + c.d.head = nil + } + return n, nil +} + +// Write holds b for half an RTT, then sends it. It returns at once. +func (c *Conn) Write(b []byte) (int, error) { + return c.d.enqueueWrite(b, nil) +} + +// Close stops reads at once; writes already made are still sent, then the connection +// closes. +func (c *Conn) Close() error { + if !c.d.close() { + return net.ErrClosed + } + return nil +} + +func (c *Conn) SetDeadline(t time.Time) error { + c.d.setDeadline(t) + return nil +} + +func (c *Conn) SetReadDeadline(t time.Time) error { + c.d.readDeadline.Set(t) + return nil +} + +func (c *Conn) SetWriteDeadline(t time.Time) error { + c.d.writeDeadline.Set(t) + return nil +} diff --git a/internal/netdelay/netdelay_test.go b/internal/netdelay/netdelay_test.go new file mode 100644 index 0000000..bcb5973 --- /dev/null +++ b/internal/netdelay/netdelay_test.go @@ -0,0 +1,169 @@ +package netdelay + +import ( + "context" + "encoding/binary" + "io" + "net" + "os" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +const testRTT = 100 * time.Millisecond + +// requireRTT checks a measured round trip is testRTT within 5%. +func requireRTT(t *testing.T, got time.Duration, what string) { + t.Helper() + require.InDelta(t, float64(testRTT), float64(got), float64(testRTT)*0.05, + "%s took %v, want %v ± 5%%", what, got, testRTT) +} + +func tcpEchoServer(t *testing.T) string { + t.Helper() + ln, err := net.Listen("tcp", "127.0.0.1:0") + require.NoError(t, err) + t.Cleanup(func() { _ = ln.Close() }) + go func() { + for { + conn, err := ln.Accept() + if err != nil { + return + } + go func() { + defer conn.Close() + _, _ = io.Copy(conn, conn) + }() + } + }() + return ln.Addr().String() +} + +func TestTCPConnectAndEchoTakeOneRTTEach(t *testing.T) { + t.Parallel() + addr := tcpEchoServer(t) + + start := time.Now() + conn, err := Dialer(testRTT, nil)(context.Background(), "tcp", addr) + require.NoError(t, err) + defer conn.Close() + requireRTT(t, time.Since(start), "connect") + + for i := range 3 { + start = time.Now() + _, err = conn.Write([]byte("ping")) + require.NoError(t, err) + buf := make([]byte, 4) + _, err = io.ReadFull(conn, buf) + require.NoError(t, err) + requireRTT(t, time.Since(start), "echo") + require.Equal(t, "ping", string(buf), "round %d", i) + } +} + +func TestTCPKeepsOrderAcrossManyWrites(t *testing.T) { + t.Parallel() + conn, err := Dialer(testRTT, nil)(context.Background(), "tcp", tcpEchoServer(t)) + require.NoError(t, err) + defer conn.Close() + + const n = 500 + go func() { + for i := range n { + var b [4]byte + binary.BigEndian.PutUint32(b[:], uint32(i)) + _, _ = conn.Write(b[:]) + } + }() + for i := range n { + var b [4]byte + _, err := io.ReadFull(conn, b[:]) + require.NoError(t, err) + require.Equal(t, uint32(i), binary.BigEndian.Uint32(b[:])) + } +} + +func TestReadDeadlineInterruptsAHeldRead(t *testing.T) { + t.Parallel() + conn, err := Dialer(testRTT, nil)(context.Background(), "tcp", tcpEchoServer(t)) + require.NoError(t, err) + defer conn.Close() + + require.NoError(t, conn.SetReadDeadline(time.Now().Add(10*time.Millisecond))) + _, err = conn.Read(make([]byte, 1)) + require.ErrorIs(t, err, os.ErrDeadlineExceeded) + var netErr net.Error + require.ErrorAs(t, err, &netErr) + require.True(t, netErr.Timeout()) + + // The data sent before the deadline is not lost by it. + require.NoError(t, conn.SetReadDeadline(time.Time{})) + _, err = conn.Write([]byte("x")) + require.NoError(t, err) + b := make([]byte, 1) + _, err = io.ReadFull(conn, b) + require.NoError(t, err) + require.Equal(t, "x", string(b)) +} + +func TestUDPEchoTakesOneRTT(t *testing.T) { + t.Parallel() + server, err := net.ListenPacket("udp", "127.0.0.1:0") + require.NoError(t, err) + defer server.Close() + go func() { + buf := make([]byte, 1500) + for { + n, addr, err := server.ReadFrom(buf) + if err != nil { + return + } + _, _ = server.WriteTo(buf[:n], addr) + } + }() + + n, err := NewNet(testRTT) + require.NoError(t, err) + client, err := n.ListenUDP("udp4", &net.UDPAddr{IP: net.IPv4(127, 0, 0, 1)}) + require.NoError(t, err) + defer client.Close() + + for i := range 3 { + start := time.Now() + _, err = client.WriteTo([]byte{byte(i)}, server.LocalAddr()) + require.NoError(t, err) + buf := make([]byte, 1500) + got, from, err := client.ReadFrom(buf) + require.NoError(t, err) + requireRTT(t, time.Since(start), "udp echo") + require.Equal(t, []byte{byte(i)}, buf[:got]) + require.Equal(t, server.LocalAddr().String(), from.String()) + } +} + +func TestUDPKeepsOrder(t *testing.T) { + t.Parallel() + server, err := net.ListenPacket("udp", "127.0.0.1:0") + require.NoError(t, err) + defer server.Close() + + client, err := net.ListenPacket("udp", "127.0.0.1:0") + require.NoError(t, err) + delayed := NewPacketConn(client, testRTT) + defer delayed.Close() + + const n = 200 + for i := range n { + _, err := delayed.WriteTo([]byte{byte(i)}, server.LocalAddr()) + require.NoError(t, err) + } + buf := make([]byte, 16) + for i := range n { + require.NoError(t, server.SetReadDeadline(time.Now().Add(5*time.Second))) + got, _, err := server.ReadFrom(buf) + require.NoError(t, err) + require.Equal(t, []byte{byte(i)}, buf[:got]) + } +} diff --git a/internal/netdelay/packet.go b/internal/netdelay/packet.go new file mode 100644 index 0000000..a2340bd --- /dev/null +++ b/internal/netdelay/packet.go @@ -0,0 +1,185 @@ +package netdelay + +import ( + "errors" + "net" + "time" + + "github.com/pion/transport/v4" + "github.com/pion/transport/v4/stdnet" +) + +// PacketConn is a datagram socket with delayed reads and writes. +type PacketConn struct { + conn net.PacketConn + d *delayer +} + +// NewPacketConn wraps conn so it behaves as if it crossed a network with round-trip time +// rtt. +func NewPacketConn(conn net.PacketConn, rtt time.Duration) *PacketConn { + c := &PacketConn{conn: conn, d: newDelayer(rtt)} + connected, _ := conn.(interface{ Write([]byte) (int, error) }) + go c.d.writeLoop(func(p packet) error { + var err error + if p.addr == nil && connected != nil { + _, err = connected.Write(p.b) + } else { + _, err = conn.WriteTo(p.b, p.addr) + } + // A datagram that cannot be sent is lost, like on a network; only a closed socket + // ends the loop. + if errors.Is(err, net.ErrClosed) { + return err + } + return nil + }, func() { _ = conn.Close() }) + go c.d.readLoop(conn.ReadFrom, 64<<10) + return c +} + +// ReadFrom returns a datagram at least half an RTT after it arrived. A datagram longer +// than p is truncated. +func (c *PacketConn) ReadFrom(p []byte) (int, net.Addr, error) { + c.d.rmu.Lock() + defer c.d.rmu.Unlock() + pkt, err := c.d.next() + if err != nil { + return 0, nil, err + } + c.d.head = nil + return copy(p, pkt.b), pkt.addr, nil +} + +// WriteTo holds p for half an RTT, then sends it. It returns at once. +func (c *PacketConn) WriteTo(p []byte, addr net.Addr) (int, error) { + return c.d.enqueueWrite(p, addr) +} + +// Close stops reads at once; datagrams already written are still sent. +func (c *PacketConn) Close() error { + if !c.d.close() { + return net.ErrClosed + } + return nil +} + +func (c *PacketConn) LocalAddr() net.Addr { return c.conn.LocalAddr() } + +func (c *PacketConn) SetDeadline(t time.Time) error { + c.d.setDeadline(t) + return nil +} + +func (c *PacketConn) SetReadDeadline(t time.Time) error { + c.d.readDeadline.Set(t) + return nil +} + +func (c *PacketConn) SetWriteDeadline(t time.Time) error { + c.d.writeDeadline.Set(t) + return nil +} + +// UDPConn is a PacketConn over a pion transport.UDPConn, for ICE. +type UDPConn struct { + *PacketConn + udp transport.UDPConn +} + +var _ transport.UDPConn = (*UDPConn)(nil) + +// NewUDPConn wraps conn so it behaves as if it crossed a network with round-trip time rtt. +func NewUDPConn(conn transport.UDPConn, rtt time.Duration) *UDPConn { + return &UDPConn{PacketConn: NewPacketConn(conn, rtt), udp: conn} +} + +func (c *UDPConn) RemoteAddr() net.Addr { return c.udp.RemoteAddr() } +func (c *UDPConn) SetReadBuffer(bytes int) error { return c.udp.SetReadBuffer(bytes) } +func (c *UDPConn) SetWriteBuffer(bytes int) error { return c.udp.SetWriteBuffer(bytes) } + +func (c *UDPConn) Read(b []byte) (int, error) { + n, _, err := c.ReadFrom(b) + return n, err +} + +func (c *UDPConn) ReadFromUDP(b []byte) (int, *net.UDPAddr, error) { + n, addr, err := c.ReadFrom(b) + udpAddr, _ := addr.(*net.UDPAddr) + return n, udpAddr, err +} + +// ReadMsgUDP drops the out-of-band data. +func (c *UDPConn) ReadMsgUDP(b, _ []byte) (n, oobn, flags int, addr *net.UDPAddr, err error) { + n, addr, err = c.ReadFromUDP(b) + return n, 0, 0, addr, err +} + +func (c *UDPConn) Write(b []byte) (int, error) { + return c.d.enqueueWrite(b, nil) +} + +func (c *UDPConn) WriteToUDP(b []byte, addr *net.UDPAddr) (int, error) { + return c.WriteTo(b, addr) +} + +// WriteMsgUDP drops the out-of-band data. +func (c *UDPConn) WriteMsgUDP(b, _ []byte, addr *net.UDPAddr) (n, oobn int, err error) { + if addr == nil { + n, err = c.Write(b) + } else { + n, err = c.WriteTo(b, addr) + } + return n, 0, err +} + +// Net is the host network for pion with every UDP socket and dialed connection delayed. +// TCP listeners are not wrapped: the SDK gathers UDP candidates only. +type Net struct { + transport.Net + rtt time.Duration +} + +// NewNet returns the host network with its sockets delayed by rtt. +func NewNet(rtt time.Duration) (*Net, error) { + std, err := stdnet.NewNet() + if err != nil { + return nil, err + } + return &Net{Net: std, rtt: rtt}, nil +} + +func (n *Net) ListenUDP(network string, laddr *net.UDPAddr) (transport.UDPConn, error) { + conn, err := n.Net.ListenUDP(network, laddr) + if err != nil { + return nil, err + } + return NewUDPConn(conn, n.rtt), nil +} + +func (n *Net) ListenPacket(network, address string) (net.PacketConn, error) { + conn, err := n.Net.ListenPacket(network, address) + if err != nil { + return nil, err + } + return NewPacketConn(conn, n.rtt), nil +} + +func (n *Net) DialUDP(network string, laddr, raddr *net.UDPAddr) (transport.UDPConn, error) { + conn, err := n.Net.DialUDP(network, laddr, raddr) + if err != nil { + return nil, err + } + return NewUDPConn(conn, n.rtt), nil +} + +func (n *Net) Dial(network, address string) (net.Conn, error) { + conn, err := n.Net.Dial(network, address) + if err != nil { + return nil, err + } + if isTCP(network) { + time.Sleep(n.rtt) + } + return NewConn(conn, n.rtt), nil +} From 3e4a695acea0618424ad80f248e7ab22e1a3054b Mon Sep 17 00:00:00 2001 From: Tommaso Barbugli Date: Wed, 30 Sep 2026 16:10:10 +0200 Subject: [PATCH 3/4] feat(wsdial): dial websockets through a replaceable, httptrace-aware dialer Reports TLS, request and first-byte times to the context's httptrace.ClientTrace, and leaves DNS and connect to the dial function, as net/http does. --- internal/wsdial/wsdial.go | 84 +++++++++++++++++++++++++++++++++++++++ 1 file changed, 84 insertions(+) create mode 100644 internal/wsdial/wsdial.go diff --git a/internal/wsdial/wsdial.go b/internal/wsdial/wsdial.go new file mode 100644 index 0000000..c9a0506 --- /dev/null +++ b/internal/wsdial/wsdial.go @@ -0,0 +1,84 @@ +// Package wsdial opens client websockets the way net/http opens connections: through a +// replaceable dial function, and reporting DNS, TCP, TLS, request and first-byte times +// to the net/http/httptrace.ClientTrace in the context. +package wsdial + +import ( + "context" + "crypto/tls" + "net" + "net/http/httptrace" + "sync/atomic" + + "github.com/gobwas/ws" +) + +// DialFunc opens a network connection, like net.Dialer.DialContext. +type DialFunc = func(ctx context.Context, network, addr string) (net.Conn, error) + +// Dial opens a websocket to urlstr. A nil dial uses a plain net.Dialer; a nil tlsConfig +// the system roots. Like net/http, it leaves reporting DNS and connect times to dial. +func Dial(ctx context.Context, urlstr string, dial DialFunc, tlsConfig *tls.Config) (net.Conn, error) { + if dial == nil { + dial = (&net.Dialer{}).DialContext + } + trace := httptrace.ContextClientTrace(ctx) + if trace == nil { + trace = &httptrace.ClientTrace{} + } + d := ws.Dialer{ + // The dial function reports DNS and connect to the trace, as it does for net/http. + NetDial: dial, + TLSClient: func(conn net.Conn, hostname string) net.Conn { + cfg := &tls.Config{} + if tlsConfig != nil { + cfg = tlsConfig.Clone() + } + if cfg.ServerName == "" { + cfg.ServerName = hostname + } + tc := tls.Client(conn, cfg) + if trace.TLSHandshakeStart != nil { + trace.TLSHandshakeStart() + } + // A failed handshake is reported again by the upgrade's first write. + err := tc.HandshakeContext(ctx) + if trace.TLSHandshakeDone != nil { + trace.TLSHandshakeDone(tc.ConnectionState(), err) + } + return tc + }, + WrapConn: func(conn net.Conn) net.Conn { + if trace.GotConn != nil { + trace.GotConn(httptrace.GotConnInfo{Conn: conn}) + } + return &tracedConn{Conn: conn, trace: trace} + }, + } + conn, _, _, err := d.Dial(ctx, urlstr) + return conn, err +} + +// tracedConn reports the upgrade request's write and the response's first byte. +type tracedConn struct { + net.Conn + trace *httptrace.ClientTrace + wrote atomic.Bool + read atomic.Bool +} + +func (c *tracedConn) Write(b []byte) (int, error) { + n, err := c.Conn.Write(b) + if !c.wrote.Load() && c.wrote.CompareAndSwap(false, true) && c.trace.WroteRequest != nil { + c.trace.WroteRequest(httptrace.WroteRequestInfo{Err: err}) + } + return n, err +} + +func (c *tracedConn) Read(b []byte) (int, error) { + n, err := c.Conn.Read(b) + if n > 0 && !c.read.Load() && c.read.CompareAndSwap(false, true) && c.trace.GotFirstResponseByte != nil { + c.trace.GotFirstResponseByte() + } + return n, err +} From e7cac97b29af22fd892631727ea189e80f3cc5bb Mon Sep 17 00:00:00 2001 From: Tommaso Barbugli Date: Wed, 30 Sep 2026 16:10:10 +0200 Subject: [PATCH 4/4] feat: record the first join as a latency DAG Replaces ConnectionTiming with jointrace: each step of the join is a span with its dependencies, kind (net, local, timer) and peer, so the trace shows which branches run in parallel and which chain is critical. - Call.JoinTrace and Call.OnJoinTrace, fired when media flows both ways or after JoinTraceTimeout. - httptrace detail (DNS, TCP, TLS, request, first byte) for the coordinator REST call, the coordinator and SFU websockets and the SFU RPCs; Server-Timing when the server sends it. - RTT per peer from the TCP connect and the ICE selected pair; every network span is also expressed in round trips of its peer. - Trace.String draws the DAG with the critical path marked; the trace marshals to a JSON report. - WithNetworkDelay, for tests and benches: every connection the client opens, UDP included, behaves as if it crossed a network with that RTT. - signal.WithDialContext and signal.WithTLSConfig; testutil.WithTLS. --- README.md | 15 ++ call.go | 73 +++++-- client.go | 93 +++++++- connection_timing.go | 125 ----------- connection_timing_test.go | 78 ------- coordinator/client.go | 20 +- coordinator/websocket.go | 5 +- go.mod | 2 +- internal/readmecheck/readmecheck.go | 7 + internal/testutil/fakesfu.go | 28 ++- join_trace.go | 231 ++++++++++++++++++++ join_trace_test.go | 260 ++++++++++++++++++++++ jointrace/httptrace.go | 223 +++++++++++++++++++ jointrace/httptrace_test.go | 114 ++++++++++ jointrace/recorder.go | 167 ++++++++++++++ jointrace/render.go | 146 +++++++++++++ jointrace/span.go | 102 +++++++++ jointrace/testdata/today_join.golden | 27 +++ jointrace/trace.go | 316 +++++++++++++++++++++++++++ jointrace/trace_test.go | 180 +++++++++++++++ pc/pc.go | 55 ++++- pc/timing_test.go | 5 + publisher.go | 49 +++-- signal/client.go | 37 +++- subscriber.go | 37 +++- 25 files changed, 2126 insertions(+), 269 deletions(-) delete mode 100644 connection_timing.go delete mode 100644 connection_timing_test.go create mode 100644 join_trace.go create mode 100644 join_trace_test.go create mode 100644 jointrace/httptrace.go create mode 100644 jointrace/httptrace_test.go create mode 100644 jointrace/recorder.go create mode 100644 jointrace/render.go create mode 100644 jointrace/span.go create mode 100644 jointrace/testdata/today_join.golden create mode 100644 jointrace/trace.go create mode 100644 jointrace/trace_test.go diff --git a/README.md b/README.md index 5c78402..785d186 100644 --- a/README.md +++ b/README.md @@ -104,6 +104,21 @@ if _, err := call.AddTrack(track.TrackInfo(), track); err != nil { return writer.Write(audio.FromInt16(samples, 24000, 1)) ``` +## Join latency + +A call records how its first join went: every network step, timer and local step, what it +waited for, and each step in round trips to its peer. `String()` draws it as a DAG with +the critical path marked; it marshals to JSON. + +```go +call.OnJoinTrace(func(trace jointrace.Trace) { + log.Print(trace) // or json.Marshal(trace) +}) +``` + +It fires once media flows both ways, or after `rtc.JoinTraceTimeout`. `call.JoinTrace()` +returns what has been recorded so far. + ## Examples ```bash diff --git a/call.go b/call.go index 237a277..3419f7e 100644 --- a/call.go +++ b/call.go @@ -28,8 +28,10 @@ import ( "github.com/GetStream/getstream-go-webrtc/coordinator/models" "github.com/GetStream/getstream-go-webrtc/event" "github.com/GetStream/getstream-go-webrtc/internal/atomicx" + "github.com/GetStream/getstream-go-webrtc/internal/netdelay" "github.com/GetStream/getstream-go-webrtc/internal/ratelimit" "github.com/GetStream/getstream-go-webrtc/internal/xerr" + "github.com/GetStream/getstream-go-webrtc/jointrace" "github.com/GetStream/getstream-go-webrtc/logger" "github.com/GetStream/getstream-go-webrtc/pc" "github.com/GetStream/getstream-go-webrtc/rtcstats" @@ -274,8 +276,8 @@ type Call struct { joinOptions []JoinOption coordinatorState atomic.Pointer[CallState] - // timing records the first join's steps; see ConnectionTiming. - timing connectionTimer + // trace records the first join's steps; see JoinTrace. + trace joinTracer GetCred GetCredentialsFunc cred atomic.Pointer[models.Credentials] @@ -384,6 +386,7 @@ func newCall(cc *Client, callType, callID string) *Call { } c.runReconnect = c.reconnect c.fastReconnectViable = c.canFastReconnect + c.trace.udpRTT = c.selectedPairRTT c.callCtx, c.callCancel = context.WithCancel(context.Background()) c.connState.Store(CallConnectionStateConnecting) c.nextReconnectStrategy = sfu_models.WebsocketReconnectStrategy_WEBSOCKET_RECONNECT_STRATEGY_REJOIN @@ -402,12 +405,10 @@ func (c *Call) joinCoordinator(ctx context.Context, options joinOptions) error { return nil } - c.timing.update(func(t *ConnectionTiming) { stamp(&t.CoordinatorStarted, time.Now()) }) - result, getCred, err := c.cc.joinCoordinator(ctx, c.Type, c.Id, options.coordinatorRequest()) + result, getCred, err := c.cc.joinCoordinator(ctx, c.Type, c.Id, options.coordinatorRequest(), c.trace.recorder()) if err != nil { return xerr.Wrap(err) } - c.timing.update(func(t *ConnectionTiming) { stamp(&t.CoordinatorDone, time.Now()) }) c.GetCred = getCred cred := result.Credentials @@ -808,11 +809,10 @@ func (c *Call) Join(ctx context.Context, opts ...JoinOption) (*sfu_events.JoinRe for _, o := range opts { o(&options) } - if options.reconnectDetails.GetStrategy() == sfu_models.WebsocketReconnectStrategy_WEBSOCKET_RECONNECT_STRATEGY_UNSPECIFIED { - c.timing.update(func(t *ConnectionTiming) { stamp(&t.JoinStarted, time.Now()) }) - } else { - // Reconnects re-enter Join; the timing describes the first join only. - c.timing.seal() + reconnecting := options.reconnectDetails.GetStrategy() != sfu_models.WebsocketReconnectStrategy_WEBSOCKET_RECONNECT_STRATEGY_UNSPECIFIED + rec := c.trace.begin(time.Now(), reconnecting) + if !reconnecting { + c.cc.claimConnectTrace(rec) } if err := c.joinCoordinator(ctx, options); err != nil { @@ -889,12 +889,18 @@ func (c *Call) Join(ctx context.Context, opts ...JoinOption) (*sfu_events.JoinRe c.Client().Tracing.Store(c.Tracing.Load()) } + pcsStart := time.Now() if err := c.initPubAndSub(options); err != nil { return nil, xerr.Wrap(err) } + rec.Add(jointrace.Span{ + Name: jointrace.PCsCreate, After: afterFirst(rec, jointrace.CoordJoin), + Start: pcsStart, End: time.Now(), Kind: jointrace.KindLocal, Peer: jointrace.PeerLocal, + }) var resp *sfu_events.JoinResponse - resp, err = c.Client().Connect(ctx, req) + dialStart := time.Now() + resp, err = c.Client().Connect(jointrace.WithStep(ctx, rec, jointrace.SFUWSDial, jointrace.PeerSFU), req) if err != nil { // If ReconnectStrategy is still not specified here, it means the first join failed and we did not start the retry mechanism. // We need to start it now, in the other case, we just need to return the error @@ -907,10 +913,17 @@ func (c *Call) Join(ctx context.Context, opts ...JoinOption) (*sfu_events.JoinRe } joinedAt := time.Now() dialedAt := c.Client().DialedAt() - c.timing.update(func(t *ConnectionTiming) { - stamp(&t.SFUConnected, dialedAt) - stamp(&t.SFUJoined, joinedAt) + rec.Add(jointrace.Span{ + Name: jointrace.SFUWSDial, After: afterFirst(rec, jointrace.PCsCreate), + Start: dialStart, End: dialedAt, Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, }) + rec.Add(jointrace.Span{ + Name: jointrace.SFUJoin, After: []string{jointrace.SFUWSDial}, + Start: dialedAt, End: joinedAt, Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, + }) + if !reconnecting { + c.trace.markJoined() + } c.store.Store(NewParticipantStore(c, resp.CallState)) c.applyJoinResponse(resp) @@ -1005,6 +1018,16 @@ func (c *Call) initPubAndSub(options joinOptions) error { c.sentSubscriptions = nil c.subscribedTracksMu.Unlock() + if c.cc.networkDelay > 0 { + for _, conf := range []*pc.PeerConfig{&options.subscriberPeerConfig, &options.publisherPeerConfig} { + delayed, err := netdelay.NewNet(c.cc.networkDelay) + if err != nil { + return xerr.Wrap(err) + } + conf.SettingEngine.SetNet(delayed) + } + } + sub, err := newSubscriber(c, options.subscriber, options.subscriberPeerConfig, options.beforeSubscriberSendAnswer) if err != nil { return xerr.Wrap(err) @@ -1061,6 +1084,9 @@ func (c *Call) signalOptions() []signal.Option { if c.statsEnabled() { opts = append(opts, signal.WithTracing()) } + if c.cc.networkDelay > 0 { + opts = append(opts, signal.WithDialContext(netdelay.Dialer(c.cc.networkDelay, nil))) + } return opts } @@ -1137,7 +1163,7 @@ func (c *Call) RefreshState(ctx context.Context) error { return xerr.Error("call has not been joined") } - result, _, err := c.cc.joinCoordinator(ctx, c.Type, c.Id, *state.JoinCallRequest) + result, _, err := c.cc.joinCoordinator(ctx, c.Type, c.Id, *state.JoinCallRequest, nil) if err != nil { return xerr.Wrap(err) } @@ -1164,7 +1190,7 @@ func (c *Call) RawHandler(event *sfu_events.SfuEvent) { // REJOIN or a Leave performs, and this runs on the signalling read loop, so a // panic here would take the process down with it. func (c *Call) OnSubscriberOffer(offer *sfu_events.SfuEvent_SubscriberOffer) { - c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.Offer, time.Now()) }) + c.subscriberOffer(time.Now()) sub := c.subscriberPeer() if sub == nil { c.logger.Warn("dropping subscriber offer: no subscriber peer connection") @@ -1275,13 +1301,20 @@ func (c *Call) SubscribeToTracks(ctx context.Context, trackDetails ...*signal_rp // Callers that have to reach the SFU regardless -- a reconnect restoring state // onto a session that knows nothing about it -- go through here. func (c *Call) sendSubscriptions(ctx context.Context, trackDetails []*signal_rpc.TrackSubscriptionDetails) error { - resp, err := c.Client().UpdateSubscriptions(ctx, &signal_rpc.UpdateSubscriptionsRequest{ - SessionId: c.SessionID.Load(), - Tracks: trackDetails, - }) + rec := c.trace.recorder() + start := time.Now() + resp, err := c.Client().UpdateSubscriptions(jointrace.WithStep(ctx, rec, jointrace.SubSubscribe, jointrace.PeerSFU), + &signal_rpc.UpdateSubscriptionsRequest{ + SessionId: c.SessionID.Load(), + Tracks: trackDetails, + }) if err != nil { return xerr.Wrap(err) } + rec.Add(jointrace.Span{ + Name: jointrace.SubSubscribe, After: []string{jointrace.SFUJoin}, + Start: start, End: time.Now(), Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, + }) if err := resp.GetError(); err != nil { return xerr.Wrap(fmt.Errorf("SubscribeToTracks error: %s", err.String())) diff --git a/client.go b/client.go index 03ee206..af701e5 100644 --- a/client.go +++ b/client.go @@ -2,6 +2,7 @@ package rtc import ( "context" + "net/http" "sync" "sync/atomic" "time" @@ -14,7 +15,9 @@ import ( "github.com/GetStream/getstream-go-webrtc/coordinator" "github.com/GetStream/getstream-go-webrtc/coordinator/models" "github.com/GetStream/getstream-go-webrtc/internal/atomicx" + "github.com/GetStream/getstream-go-webrtc/internal/netdelay" "github.com/GetStream/getstream-go-webrtc/internal/xerr" + "github.com/GetStream/getstream-go-webrtc/jointrace" "github.com/GetStream/getstream-go-webrtc/logger" "github.com/GetStream/getstream-go-webrtc/rtcstats" ) @@ -58,6 +61,23 @@ type options struct { // user is who NewRTCClient connects as. NewClient takes its user as an // argument instead. user User + + // networkDelay is the round-trip time WithNetworkDelay adds to every connection. + networkDelay time.Duration +} + +// WithNetworkDelay makes every connection the client opens behave as if it crossed a +// network with round-trip time rtt: the coordinator REST and websocket connections, the +// SFU websocket and RPCs, the location hint, and the peer connections' UDP sockets. Each +// packet is held rtt/2 when sent and rtt/2 when received, in order, and a TCP connect +// takes one rtt. It lets a test or bench against a local stack measure round trips as +// if the stack were remote. +// +// For tests and benches only. +func WithNetworkDelay(rtt time.Duration) Option { + return func(o *options) { + o.networkDelay = rtt + } } type Option func(*options) @@ -285,6 +305,25 @@ type Client struct { OwnUser atomic.Pointer[models.OwnUserResponse] Tracing atomic.Pointer[rtcstats.TraceBuffer] muStats sync.RWMutex + + // connectTrace holds the coordinator websocket's spans from NewClient. The first + // call to join claims them: later joins find the websocket already open. + connectTrace *jointrace.Recorder + connectClaimed atomic.Bool +} + +// claimConnectTrace copies the client's own connection spans into the first join's trace. +func (c *Client) claimConnectTrace(rec *jointrace.Recorder) { + if rec == nil || c.connectTrace == nil || !c.connectClaimed.CompareAndSwap(false, true) { + return + } + t := c.connectTrace.Trace() + for _, s := range t.Spans { + rec.Add(s) + } + for peer, rtt := range t.RTT { + rec.SetRTT(peer, rtt) + } } func defaultClientOptions() options { @@ -449,6 +488,9 @@ func newClient(apiKey string, user User, token TokenProvider, o options) (*Clien if !c.withCoordinatorWS { coordOptions = append(coordOptions, coordinator.WithoutWebsocket()) } + if o.networkDelay > 0 { + coordOptions = append(coordOptions, coordinator.WithDialContext(netdelay.Dialer(o.networkDelay, nil))) + } cc, err := coordinator.NewClient(apiKey, userID, coordinator.StaticTokenProvider(tok), coordinator.NoopHandler{}, coordOptions...) @@ -470,10 +512,27 @@ func newClient(apiKey string, user User, token TokenProvider, o options) (*Clien Token: tok, } c.Tracing.Load().Emit(rtcstats.CoordinatorWSConnectEvent, auth) - resp, err := connectWsWithRetries(ctx, cc, &auth) + rec := jointrace.NewRecorder(time.Now()) + dialCtx := jointrace.WithStep(ctx, rec, jointrace.CoordWSDial, jointrace.PeerCoordinator) + start := time.Now() + resp, err := connectWsWithRetries(dialCtx, cc, &auth) if err != nil { return nil, err } + // The upgrade response is the first byte back; the auth exchange follows it. + upgraded := jointrace.FirstByte(dialCtx) + if upgraded.IsZero() { + upgraded = start + } + rec.Add(jointrace.Span{ + Name: jointrace.CoordWSDial, Start: start, End: upgraded, + Kind: jointrace.KindNet, Peer: jointrace.PeerCoordinator, + }) + rec.Add(jointrace.Span{ + Name: jointrace.CoordWSAuth, After: []string{jointrace.CoordWSDial}, Start: upgraded, End: time.Now(), + Kind: jointrace.KindNet, Peer: jointrace.PeerCoordinator, + }) + c.connectTrace = rec c.Tracing.Load().Emit(rtcstats.CoordinatorWSConnectedEvent, resp) c.ConnectionID.Store(resp.ConnectionID) c.OwnUser.Store(&resp.Me) @@ -484,7 +543,13 @@ func newClient(apiKey string, user User, token TokenProvider, o options) (*Clien c.CoordinatorClientInterface = cc c.token.Store(tok) if o.detectLocation { - c.locationDiscovery = NewCloudFrontDiscovery(o.locationHintURL, 3, locationHTTPClient, c.logger) + httpClient := locationHTTPClient + if o.networkDelay > 0 { + tr := locationHTTPClient.Transport.(*http.Transport).Clone() + tr.DialContext = netdelay.Dialer(o.networkDelay, tr.DialContext) + httpClient = &http.Client{Transport: tr, Timeout: locationHTTPClient.Timeout + 3*o.networkDelay} + } + c.locationDiscovery = NewCloudFrontDiscovery(o.locationHintURL, 3, httpClient, c.logger) } return c, nil } @@ -554,10 +619,15 @@ func (c *Client) AddVideoSourceStatsProviders(providers ...VideoSourceStatsProvi c.videoSourceStatsProviders = append(c.videoSourceStatsProviders, providers...) } -func (c *Client) detectLocationCached(ctx context.Context) string { +func (c *Client) detectLocationCached(ctx context.Context, rec *jointrace.Recorder) string { if c.locationCache.Load() == "" { c.logger.Info("Join call request without location, discovering location...") - loc := c.locationDiscovery.Discover(ctx) + start := time.Now() + loc := c.locationDiscovery.Discover(jointrace.WithStep(ctx, rec, jointrace.LocationHint, jointrace.PeerCloudFront)) + rec.Add(jointrace.Span{ + Name: jointrace.LocationHint, After: afterFirst(rec, jointrace.CoordWSAuth), + Start: start, End: time.Now(), Kind: jointrace.KindNet, Peer: jointrace.PeerCloudFront, + }) c.locationCache.Store(loc) c.logger.Infof("%q location discovered", loc) } @@ -653,16 +723,27 @@ func (c *Client) joinCoordinator( ctx context.Context, callType, id string, joinCallRequest models.JoinCallRequest, + rec *jointrace.Recorder, ) (*models.JoinCallResponse, GetCredentialsFunc, error) { if joinCallRequest.Location == "" && c.detectLocation { - joinCallRequest.Location = c.detectLocationCached(ctx) + joinCallRequest.Location = c.detectLocationCached(ctx, rec) } c.Tracing.Load().Emit(rtcstats.CoordinatorConnectEvent, joinCallRequest) - result, err := c.connectWithRetries(ctx, callType, id, joinCallRequest) + start := time.Now() + joinCtx := jointrace.WithStep(ctx, rec, jointrace.CoordJoin, jointrace.PeerCoordinator) + result, err := c.connectWithRetries(joinCtx, callType, id, joinCallRequest) if err != nil { return nil, nil, err } + note := "" + if jointrace.Reused(joinCtx) { + note = "reused connection" + } + rec.Add(jointrace.Span{ + Name: jointrace.CoordJoin, After: afterFirst(rec, jointrace.LocationHint, jointrace.CoordWSAuth), + Start: start, End: time.Now(), Kind: jointrace.KindNet, Peer: jointrace.PeerCoordinator, Note: note, + }) c.Tracing.Load().Emit(rtcstats.CoordinatorConnectedEvent, result) getCred := func(forceReload bool, excludeSFUID string) (models.Credentials, error) { diff --git a/connection_timing.go b/connection_timing.go deleted file mode 100644 index f574b35..0000000 --- a/connection_timing.go +++ /dev/null @@ -1,125 +0,0 @@ -package rtc - -import ( - "sync" - "time" - - "github.com/GetStream/getstream-go-webrtc/pc" -) - -// ConnectionTiming is when each step of joining a call happened, so a caller can see -// where the time to media goes. A zero time is a step that has not happened (yet). -// -// It describes the first join only. A reconnect or migration builds new peer connections -// but leaves these alone: what a caller wants from them is how long the call took to come -// up, not how long the last repair took. -type ConnectionTiming struct { - // JoinStarted is when Join was first called. - JoinStarted time.Time - // CoordinatorStarted and CoordinatorDone bracket the coordinator's join-call request, - // which returns the SFU to connect to and the token for it. - CoordinatorStarted time.Time - CoordinatorDone time.Time - // SFUConnected is when the websocket to the SFU finished opening. - SFUConnected time.Time - // SFUJoined is when the SFU answered the join request. - SFUJoined time.Time - // Publisher and Subscriber are each peer connection's path from signaling to media. - Publisher PeerTiming - Subscriber PeerTiming -} - -// PeerTiming is one peer connection's path from signaling to media. -type PeerTiming struct { - // Offer is when the offer existed: created locally for the publisher, received from - // the SFU for the subscriber. - Offer time.Time - // SignalSent and SignalDone bracket the request that carries the local description to - // the SFU: SetPublisher, which returns the answer, or SendAnswer. - SignalSent time.Time - SignalDone time.Time - // ICEChecking and ICEConnected are the ICE agent's first transitions. - ICEChecking time.Time - ICEConnected time.Time - // DTLSConnected is when the DTLS handshake finished. - DTLSConnected time.Time - // Connected is when the peer connection reported connected. - Connected time.Time - // FirstRTP is the first media packet: sent for the publisher, received for the - // subscriber. It waits for there to be media, so it is not purely connection time. - FirstRTP time.Time -} - -// connectionTimer records ConnectionTiming as the steps happen. -type connectionTimer struct { - mu sync.Mutex - timing ConnectionTiming - sealed bool - handler func(ConnectionTiming) -} - -// update applies fn and hands the result to the handler if anything changed. Once sealed, -// nothing changes any more. -func (r *connectionTimer) update(fn func(*ConnectionTiming)) { - r.mu.Lock() - if r.sealed { - r.mu.Unlock() - return - } - before := r.timing - fn(&r.timing) - changed := before != r.timing - snapshot, handler := r.timing, r.handler - r.mu.Unlock() - - if changed && handler != nil { - handler(snapshot) - } -} - -// seal stops recording, so a reconnect does not write into the first join's timing. -func (r *connectionTimer) seal() { - r.mu.Lock() - defer r.mu.Unlock() - r.sealed = true -} - -func (r *connectionTimer) snapshot() ConnectionTiming { - r.mu.Lock() - defer r.mu.Unlock() - return r.timing -} - -func (r *connectionTimer) setHandler(handler func(ConnectionTiming)) { - r.mu.Lock() - defer r.mu.Unlock() - r.handler = handler -} - -// stamp records at in *field unless the step was already recorded. -func stamp(field *time.Time, at time.Time) { - if field.IsZero() && !at.IsZero() { - *field = at - } -} - -// stampTransport copies a transport's connection steps into a peer's timing. -func stampTransport(peer *PeerTiming, t pc.Timing) { - stamp(&peer.ICEChecking, t.ICEChecking) - stamp(&peer.ICEConnected, t.ICEConnected) - stamp(&peer.DTLSConnected, t.DTLSConnected) - stamp(&peer.Connected, t.Connected) -} - -// ConnectionTiming returns when each step of the call's first join happened. -func (c *Call) ConnectionTiming() ConnectionTiming { - return c.timing.snapshot() -} - -// OnConnectionTiming sets a handler that receives the call's ConnectionTiming each time a -// step of the first join is recorded. Set it before Join to see every step. It runs on -// whichever goroutine recorded the step, including pion callbacks and the packet path, -// so it must not block. -func (c *Call) OnConnectionTiming(handler func(ConnectionTiming)) { - c.timing.setHandler(handler) -} diff --git a/connection_timing_test.go b/connection_timing_test.go deleted file mode 100644 index 4de9983..0000000 --- a/connection_timing_test.go +++ /dev/null @@ -1,78 +0,0 @@ -package rtc - -import ( - "context" - "testing" - "time" - - sfu_events "github.com/GetStream/protocol/protobuf/video/sfu/event" - "github.com/stretchr/testify/require" - - "github.com/GetStream/getstream-go-webrtc/internal/testutil" -) - -// TestJoinRecordsTheCoordinatorAndSFUSteps runs the real Join against a fake SFU and -// checks the join steps are recorded in the order they happen. -func TestJoinRecordsTheCoordinatorAndSFUSteps(t *testing.T) { - t.Parallel() - - sfu := testutil.NewFakeSFU() - defer sfu.Close() - - reports := make(chan ConnectionTiming, 64) - call := newFakeSFUCall(t, sfu, "sfu-fake") - call.onceConnect.Do(func() {}) - call.OnConnectionTiming(func(timing ConnectionTiming) { - select { - case reports <- timing: - default: - } - }) - ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) - defer cancel() - _, err := call.Join(ctx) - require.NoError(t, err) - t.Cleanup(func() { _ = call.Leave("test over") }) - - timing := call.ConnectionTiming() - require.False(t, timing.JoinStarted.IsZero()) - require.False(t, timing.SFUConnected.Before(timing.JoinStarted)) - require.False(t, timing.SFUJoined.Before(timing.SFUConnected), "the SFU answers after the websocket is open") - require.NotEmpty(t, reports, "the handler saw the steps") -} - -// TestReconnectDoesNotOverwriteTheFirstJoin keeps the first join's timing when Join runs -// again for a reconnect. -func TestReconnectDoesNotOverwriteTheFirstJoin(t *testing.T) { - t.Parallel() - - sfu := testutil.NewFakeSFU() - defer sfu.Close() - - call, _ := joinFakeSFU(t, sfu) - first := call.ConnectionTiming() - - ctx, cancel := context.WithTimeout(context.Background(), 10*time.Second) - defer cancel() - _, err := call.Join(ctx, withReconnectDetails(&sfu_events.ReconnectDetails{ - Strategy: strategyRejoin, - PreviousSessionId: call.SessionID.Load(), - })) - require.NoError(t, err) - - require.Equal(t, first, call.ConnectionTiming()) -} - -func TestConnectionTimerStampsOnlyTheFirstTime(t *testing.T) { - t.Parallel() - - var timer connectionTimer - calls := 0 - timer.setHandler(func(ConnectionTiming) { calls++ }) - first := time.Now() - timer.update(func(ct *ConnectionTiming) { stamp(&ct.JoinStarted, first) }) - timer.update(func(ct *ConnectionTiming) { stamp(&ct.JoinStarted, first.Add(time.Second)) }) - - require.Equal(t, first, timer.snapshot().JoinStarted) - require.Equal(t, 1, calls, "an update that changes nothing is not reported") -} diff --git a/coordinator/client.go b/coordinator/client.go index 48bf0ab..0a0200f 100644 --- a/coordinator/client.go +++ b/coordinator/client.go @@ -9,6 +9,7 @@ import ( "encoding/json" "fmt" "io" + "net" "net/http" "net/url" "reflect" @@ -21,6 +22,7 @@ import ( "github.com/GetStream/getstream-go-webrtc/event" "github.com/GetStream/getstream-go-webrtc/internal/rtretry" "github.com/GetStream/getstream-go-webrtc/internal/xerr" + "github.com/GetStream/getstream-go-webrtc/jointrace" "github.com/GetStream/getstream-go-webrtc/logger" ) @@ -43,6 +45,7 @@ type options struct { versionHeader string logger logger.ILogger enableWs bool + dial func(ctx context.Context, network, addr string) (net.Conn, error) } var defaultOptions = options{ @@ -81,6 +84,14 @@ func WithWsURL(wsURL string) Option { } } +// WithDialContext opens the REST and websocket connections through dial instead of a +// plain net.Dialer. +func WithDialContext(dial func(ctx context.Context, network, addr string) (net.Conn, error)) Option { + return func(o *options) { + o.dial = dial + } +} + // WithLogger sets the logger. Without it the client logs nothing. func WithLogger(l logger.ILogger) Option { return func(o *options) { @@ -164,9 +175,15 @@ func NewClient(apiKey, userID string, tokenProvider TokenProvider, handler Handl c.wsclient = newWsClient(u.String(), c) } + var transport http.RoundTripper = http.DefaultTransport + if o.dial != nil { + tr := http.DefaultTransport.(*http.Transport).Clone() + tr.DialContext = o.dial + transport = tr + } c.httpClient = &http.Client{ Timeout: 5 * time.Second, - Transport: rtretry.NewRoundTripperRetryer(http.DefaultTransport), + Transport: rtretry.NewRoundTripperRetryer(transport), } return c, nil } @@ -243,6 +260,7 @@ func (c *Client) makeRequest(ctx context.Context, method, path string, pathParam return xerr.Wrapf(err, "%s %s", method, path) } defer resp.Body.Close() + jointrace.ServerTiming(ctx, resp.Header.Get("Server-Timing")) if resp.StatusCode/100 != 2 { body, _ := io.ReadAll(resp.Body) diff --git a/coordinator/websocket.go b/coordinator/websocket.go index 60faacc..d097505 100644 --- a/coordinator/websocket.go +++ b/coordinator/websocket.go @@ -9,9 +9,8 @@ import ( "sync/atomic" "time" - "github.com/gobwas/ws" - "github.com/GetStream/getstream-go-webrtc/coordinator/models" + "github.com/GetStream/getstream-go-webrtc/internal/wsdial" "github.com/GetStream/getstream-go-webrtc/internal/xerr" "github.com/GetStream/getstream-go-webrtc/websocket" ) @@ -108,7 +107,7 @@ func (wsc *wsclient) Connect(ctx context.Context, joinRequest *models.WSAuthMess return nil, xerr.Error("ws client is nil") } - wsConn, _, _, err := ws.DefaultDialer.Dial(ctx, wsc.url) + wsConn, err := wsdial.Dial(ctx, wsc.url, wsc.c.dial, nil) if err != nil { return nil, xerr.Wrapf(err, "dial %s", wsc.url) } diff --git a/go.mod b/go.mod index b057770..7a3b485 100644 --- a/go.mod +++ b/go.mod @@ -17,6 +17,7 @@ require ( github.com/pion/rtcp v1.2.17 github.com/pion/rtp v1.10.5 github.com/pion/sdp/v3 v3.0.19 + github.com/pion/transport/v4 v4.1.0 github.com/pion/webrtc/v4 v4.2.20 github.com/sirupsen/logrus v1.9.3 github.com/stretchr/testify v1.12.1 @@ -37,7 +38,6 @@ require ( github.com/pion/sctp v1.11.1 // indirect github.com/pion/srtp/v3 v3.0.13 // indirect github.com/pion/stun/v4 v4.0.0 // indirect - github.com/pion/transport/v4 v4.1.0 // indirect github.com/pion/turn/v5 v5.1.0 // indirect github.com/wlynxg/anet v0.0.5 // indirect go.yaml.in/yaml/v3 v3.0.5 // indirect diff --git a/internal/readmecheck/readmecheck.go b/internal/readmecheck/readmecheck.go index 843efa1..7f4c965 100644 --- a/internal/readmecheck/readmecheck.go +++ b/internal/readmecheck/readmecheck.go @@ -16,6 +16,7 @@ import ( "github.com/GetStream/getstream-go-webrtc/audio" "github.com/GetStream/getstream-go-webrtc/audio/opus" audiortc "github.com/GetStream/getstream-go-webrtc/audio/rtc" + "github.com/GetStream/getstream-go-webrtc/jointrace" ) var stt struct{ Send func([]byte) } @@ -88,3 +89,9 @@ func sendAudio(call *rtc.Call, samples []int16) error { } return writer.Write(audio.FromInt16(samples, 24000, 1)) } + +func joinLatency(call *rtc.Call) { + call.OnJoinTrace(func(trace jointrace.Trace) { + log.Print(trace) // or json.Marshal(trace) + }) +} diff --git a/internal/testutil/fakesfu.go b/internal/testutil/fakesfu.go index f92fb4b..b072f85 100644 --- a/internal/testutil/fakesfu.go +++ b/internal/testutil/fakesfu.go @@ -2,6 +2,8 @@ package testutil import ( "context" + "crypto/tls" + "crypto/x509" "net/http" "net/http/httptest" "strings" @@ -57,6 +59,7 @@ type FakeSFU struct { connected chan struct{} once sync.Once + tls bool } // FakeSFUOption configures a FakeSFU. Options are applied before the server @@ -80,6 +83,13 @@ func WithJoinHandler(handler func(*sfu_events.JoinRequest) *sfu_events.SfuEvent) } } +// WithTLS serves the websocket and the RPCs over TLS, with a certificate TLSConfig trusts. +func WithTLS() FakeSFUOption { + return func(f *FakeSFU) { + f.tls = true + } +} + // WithSignalRPC overrides the twirp signalling RPC answers. func WithSignalRPC(rpc SignalRPC) FakeSFUOption { return func(f *FakeSFU) { @@ -125,13 +135,27 @@ func NewFakeSFU(opts ...FakeSFUOption) *FakeSFU { mux.HandleFunc(wsPath, f.serve) mux.Handle("/", f.recordAuthorization(sfu_signal_rpc.NewSignalServerServer( &signalRPCService{f: f}, twirp.WithServerPathPrefix("")))) - f.srv = httptest.NewServer(mux) + f.srv = httptest.NewUnstartedServer(mux) + if f.tls { + f.srv.StartTLS() + } else { + f.srv.Start() + } return f } +// TLSConfig trusts the certificate of a fake started WithTLS. +func (f *FakeSFU) TLSConfig() *tls.Config { + pool := x509.NewCertPool() + if cert := f.srv.Certificate(); cert != nil { + pool.AddCert(cert) + } + return &tls.Config{RootCAs: pool} +} + const wsPath = "/ws" -// WsEndpoint is the ws:// URL a signal client dials. +// WsEndpoint is the ws:// (wss:// WithTLS) URL a signal client dials. func (f *FakeSFU) WsEndpoint() string { return "ws" + strings.TrimPrefix(f.srv.URL, "http") + wsPath } diff --git a/join_trace.go b/join_trace.go new file mode 100644 index 0000000..02055f8 --- /dev/null +++ b/join_trace.go @@ -0,0 +1,231 @@ +package rtc + +import ( + "sync" + "time" + + "github.com/GetStream/getstream-go-webrtc/jointrace" + "github.com/GetStream/getstream-go-webrtc/pc" +) + +// JoinTraceTimeout is how long after Join the OnJoinTrace handler is called at the latest, +// with whatever was recorded, when media has not started flowing both ways by then. +const JoinTraceTimeout = 10 * time.Second + +// joinTracer records the spans of a call's first join. A reconnect or migration builds +// new peer connections but leaves the trace alone: it describes how the call came up, +// not how the last repair went. +type joinTracer struct { + mu sync.Mutex + rec *jointrace.Recorder + joined bool + fired bool + timer *time.Timer + handler func(jointrace.Trace) + + // Moments the spans are built from that are not spans of their own. + pubSignalSent time.Time + subOfferAt time.Time + + // udpRTT samples the media path's RTT from the peer connections. + udpRTT func() time.Duration +} + +// begin starts the trace at the first Join and returns its recorder. It returns nil for +// a Join that re-enters to repair a call that had already joined. +func (j *joinTracer) begin(now time.Time, reconnect bool) *jointrace.Recorder { + j.mu.Lock() + defer j.mu.Unlock() + if j.rec == nil { + j.rec = jointrace.NewRecorder(now) + j.timer = time.AfterFunc(JoinTraceTimeout, j.fire) + return j.rec + } + if reconnect && j.joined { + j.rec.Seal() + return nil + } + return j.rec +} + +// recorder is the trace's recorder, nil before the first Join. Recording into it is a +// no-op once it is sealed. +func (j *joinTracer) recorder() *jointrace.Recorder { + j.mu.Lock() + defer j.mu.Unlock() + return j.rec +} + +func (j *joinTracer) markJoined() { + j.mu.Lock() + defer j.mu.Unlock() + j.joined = true +} + +func (j *joinTracer) snapshot() jointrace.Trace { + j.mu.Lock() + rec, sample := j.rec, j.udpRTT + j.mu.Unlock() + if sample != nil { + rec.SetRTT(jointrace.PeerUDP, sample()) + } + return rec.Trace() +} + +// done hands the trace to the handler once media flows both ways. +func (j *joinTracer) done() { + rec := j.recorder() + if rec.Has(jointrace.PubRTP) && rec.Has(jointrace.SubRTP) { + j.fire() + } +} + +func (j *joinTracer) fire() { + j.mu.Lock() + if j.fired || j.rec == nil { + j.mu.Unlock() + return + } + j.fired = true + if j.timer != nil { + j.timer.Stop() + } + handler := j.handler + j.mu.Unlock() + if handler != nil { + // Off the packet path: the snapshot asks ICE for the pair's RTT. + go func() { handler(j.snapshot()) }() + } +} + +// JoinTrace returns what has been recorded of the call's first join so far. +func (c *Call) JoinTrace() jointrace.Trace { + return c.trace.snapshot() +} + +// OnJoinTrace sets a handler called once with the first join's trace: when media flows +// both ways (the first RTP packet sent and the first received), or JoinTraceTimeout +// after Join otherwise. Set it before Join. It runs on its own goroutine. +func (c *Call) OnJoinTrace(handler func(jointrace.Trace)) { + c.trace.mu.Lock() + defer c.trace.mu.Unlock() + c.trace.handler = handler +} + +// peerSpans records the spans a transport's timing completes. +func (c *Call) peerSpans(publisher bool, t pc.Timing) { + rec := c.trace.recorder() + if rec == nil { + return + } + if publisher { + rec.Add(jointrace.Span{ + Name: jointrace.PubDebounce, After: []string{jointrace.SFUJoin}, + Start: t.NegotiationRequested, End: t.OfferStarted, + Kind: jointrace.KindTimer, Peer: jointrace.PeerLocal, + }) + c.trace.mu.Lock() + sent := c.trace.pubSignalSent + c.trace.mu.Unlock() + rec.Add(jointrace.Span{ + Name: jointrace.PubSFUCandidates, After: []string{jointrace.PubSetPublisher}, + Start: sent, End: t.FirstRemoteCandidate, + Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, + Note: "offer sent to first SFU candidate", + }) + rec.Add(jointrace.Span{ + Name: jointrace.PubICE, After: []string{jointrace.PubSetPublisher, jointrace.PubSFUCandidates}, + Start: t.ICEChecking, End: t.ICEConnected, + Kind: jointrace.KindNet, Peer: jointrace.PeerUDP, + }) + rec.Add(jointrace.Span{ + Name: jointrace.PubDTLS, After: []string{jointrace.PubICE}, + Start: t.ICEConnected, End: t.DTLSConnected, + Kind: jointrace.KindNet, Peer: jointrace.PeerUDP, + }) + return + } + rec.Add(jointrace.Span{ + Name: jointrace.SubICE, After: []string{jointrace.SubSendAnswer}, + Start: t.ICEChecking, End: t.ICEConnected, + Kind: jointrace.KindNet, Peer: jointrace.PeerUDP, + }) + rec.Add(jointrace.Span{ + Name: jointrace.SubDTLS, After: []string{jointrace.SubICE}, + Start: t.ICEConnected, End: t.DTLSConnected, + Kind: jointrace.KindNet, Peer: jointrace.PeerUDP, + }) +} + +// firstRTP records the first RTP packet sent by the publisher or received by the +// subscriber. +func (c *Call) firstRTP(publisher bool, dtlsConnected, at time.Time) { + rec := c.trace.recorder() + name, after := jointrace.SubRTP, jointrace.SubDTLS + if publisher { + name, after = jointrace.PubRTP, jointrace.PubDTLS + } + start := dtlsConnected + if start.IsZero() || start.After(at) { + start = at + } + rec.Add(jointrace.Span{ + Name: name, After: []string{after}, Start: start, End: at, + Kind: jointrace.KindNet, Peer: jointrace.PeerUDP, + }) + c.trace.done() +} + +// subscriberOffer records the SFU's side of the subscriber offer: the wait between the +// SFU join and the offer arriving. The client sees only the arrival, so the split into +// the SFU's wait and the half round trip in flight is inferred from RTT_s. +func (c *Call) subscriberOffer(at time.Time) { + rec := c.trace.recorder() + c.trace.mu.Lock() + if c.trace.subOfferAt.IsZero() { + c.trace.subOfferAt = at + } + c.trace.mu.Unlock() + joined, ok := rec.Get(jointrace.SFUJoin) + if !ok || rec.Has(jointrace.SubOffer) { + return + } + sent := at.Add(-rec.RTT(jointrace.PeerSFU) / 2) + if sent.Before(joined.End) { + sent = joined.End + } + rec.Add(jointrace.Span{ + Name: jointrace.SubDebounce, After: []string{jointrace.SFUJoin}, + Start: joined.End, End: sent, Kind: jointrace.KindTimer, Peer: jointrace.PeerSFU, + Note: "SFU-side wait (debounce or publisher gate), inferred", + }) + rec.Add(jointrace.Span{ + Name: jointrace.SubOffer, After: []string{jointrace.SubDebounce}, + Start: sent, End: at, Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, + Note: "RTT_s/2 in flight, inferred", + }) +} + +// selectedPairRTT is the RTT ICE measured on the publisher's selected pair, or the +// subscriber's. +func (c *Call) selectedPairRTT() time.Duration { + if pub := c.publisherPeer(); pub != nil && pub.Transport != nil { + if rtt := pub.SelectedPairRTT(); rtt > 0 { + return rtt + } + } + if sub := c.subscriberPeer(); sub != nil && sub.Transport != nil { + return sub.SelectedPairRTT() + } + return 0 +} + +// afterFirst returns the first of names that was recorded, as a dependency list. +func afterFirst(rec *jointrace.Recorder, names ...string) []string { + for _, name := range names { + if rec.Has(name) { + return []string{name} + } + } + return nil +} diff --git a/join_trace_test.go b/join_trace_test.go new file mode 100644 index 0000000..7bbf70b --- /dev/null +++ b/join_trace_test.go @@ -0,0 +1,260 @@ +package rtc + +import ( + "context" + "sync/atomic" + "testing" + "time" + + sfu_events "github.com/GetStream/protocol/protobuf/video/sfu/event" + sfu_models "github.com/GetStream/protocol/protobuf/video/sfu/models" + "github.com/GetStream/protocol/protobuf/video/sfu/signal_rpc" + "github.com/pion/webrtc/v4" + "github.com/stretchr/testify/require" + + "github.com/GetStream/getstream-go-webrtc/coordinator/models" + "github.com/GetStream/getstream-go-webrtc/internal/testutil" + "github.com/GetStream/getstream-go-webrtc/jointrace" + "github.com/GetStream/getstream-go-webrtc/signal" +) + +// mediaSFU is a fake SFU with a real peer connection per client peer: it answers the +// publisher, offers alice's audio to the subscriber, and routes trickled candidates. +type mediaSFU struct { + fake *testutil.FakeSFU + pub, sub *sfuWebRTCPeer + aliceAudio *webrtc.TrackLocalStaticSample +} + +func newMediaSFU(t *testing.T, opts ...testutil.FakeSFUOption) *mediaSFU { + t.Helper() + + m := &mediaSFU{} + var pub, sub atomic.Pointer[sfuWebRTCPeer] + opts = append([]testutil.FakeSFUOption{ + testutil.WithJoinResponse(&sfu_events.JoinResponse{ + CallState: &sfu_models.CallState{ + Participants: []*sfu_models.Participant{ + {UserId: "alice", SessionId: "session-a", TrackLookupPrefix: "prefix-a"}, + }, + ParticipantCount: &sfu_models.ParticipantCount{Total: 2}, + }, + }), + testutil.WithSignalRPC(testutil.SignalRPC{ + SetPublisher: func(_ context.Context, req *signal_rpc.SetPublisherRequest) (*signal_rpc.SetPublisherResponse, error) { + answer, err := pub.Load().Answer(req.GetSdp()) + if err != nil { + return nil, err + } + return &signal_rpc.SetPublisherResponse{Sdp: answer}, nil + }, + SendAnswer: func(_ context.Context, req *signal_rpc.SendAnswerRequest) (*signal_rpc.SendAnswerResponse, error) { + if err := sub.Load().AcceptAnswer(req.GetSdp()); err != nil { + return nil, err + } + return &signal_rpc.SendAnswerResponse{}, nil + }, + IceTrickle: func(_ context.Context, trickle *sfu_models.ICETrickle) (*signal_rpc.ICETrickleResponse, error) { + peer := pub.Load() + if trickle.GetPeerType() == sfu_models.PeerType_PEER_TYPE_SUBSCRIBER { + peer = sub.Load() + } + if err := peer.AddRemoteCandidate(trickle.GetIceCandidate()); err != nil { + return nil, err + } + return &signal_rpc.ICETrickleResponse{}, nil + }, + UpdateSubscriptions: func(context.Context, *signal_rpc.UpdateSubscriptionsRequest) (*signal_rpc.UpdateSubscriptionsResponse, error) { + return &signal_rpc.UpdateSubscriptionsResponse{}, nil + }, + }), + }, opts...) + m.fake = testutil.NewFakeSFU(opts...) + t.Cleanup(m.fake.Close) + + m.pub = newSFUWebRTCPeer(t, m.fake, sfu_models.PeerType_PEER_TYPE_PUBLISHER_UNSPECIFIED) + m.sub = newSFUWebRTCPeer(t, m.fake, sfu_models.PeerType_PEER_TYPE_SUBSCRIBER) + pub.Store(m.pub) + sub.Store(m.sub) + + var err error + m.aliceAudio, err = webrtc.NewTrackLocalStaticSample( + webrtc.RTPCodecCapability{MimeType: webrtc.MimeTypeOpus}, "audio", "prefix-a:TRACK_TYPE_AUDIO") + require.NoError(t, err) + _, err = m.sub.PC.AddTrack(m.aliceAudio) + require.NoError(t, err) + return m +} + +// newTracedCall is newFakeSFUCall with client options, and signal options for the SFU. +func newTracedCall(t *testing.T, sfu *testutil.FakeSFU, clientOpts []Option, signalOpts ...signal.Option) *Call { + t.Helper() + + const userID = "fake-sfu-user" + token, err := testutil.GenerateToken("test-api-key", "test-api-secret", userID, time.Hour) + require.NoError(t, err) + + clientOpts = append([]Option{WithoutCoordinatorWS(), WithoutLocationDiscovery()}, clientOpts...) + client, err := NewClient(token.APIKey, User{ID: userID}, StaticToken(token.Token), clientOpts...) + require.NoError(t, err) + + cred := fakeSFUCredentials(sfu, "sfu-fake", token.Token) + call := newCall(client, testutil.DefaultCallType, "fake-sfu-call-id") + call.GetCred = func(bool, string) (models.Credentials, error) { return cred, nil } + call.getPeer().client.Store(signal.NewClient(cred, call, append(call.signalOptions(), signalOpts...)...)) + call.SetCredentials(cred) + call.onceConnect.Do(func() {}) + t.Cleanup(func() { call.callCancel() }) + return call +} + +// joinWithMedia runs a whole join the way an agent does: Join, publish a track and +// subscribe to alice's, and waits for media both ways. It returns the trace handed to +// OnJoinTrace and when Join was called. +func joinWithMedia(t *testing.T, m *mediaSFU, call *Call) (jointrace.Trace, time.Time) { + t.Helper() + + traces := make(chan jointrace.Trace, 1) + call.OnJoinTrace(func(tr jointrace.Trace) { traces <- tr }) + + ctx, cancel := context.WithCancel(context.Background()) + t.Cleanup(cancel) + + joinCalled := time.Now() + _, err := call.Join(ctx, + WithOnTrack(SubscriberFunc(func(OnTrackReceived) {})), + WithPublisherPeerConfiguration(loopbackPeerConfig()), + WithSubscriberPeerConfiguration(loopbackPeerConfig())) + require.NoError(t, err) + t.Cleanup(func() { _ = call.Leave("test over") }) + + audio, err := webrtc.NewTrackLocalStaticSample( + webrtc.RTPCodecCapability{MimeType: webrtc.MimeTypeOpus}, "audio", "prefix:TRACK_TYPE_AUDIO") + require.NoError(t, err) + _, err = call.AddTrack(&sfu_models.TrackInfo{ + TrackId: "published-audio", + TrackType: sfu_models.TrackType_TRACK_TYPE_AUDIO, + }, audio) + require.NoError(t, err) + go writeSamplesUntilDone(ctx, audio) + + require.NoError(t, call.SubscribeToTracks(ctx, &signal_rpc.TrackSubscriptionDetails{ + UserId: "alice", SessionId: "session-a", TrackType: sfu_models.TrackType_TRACK_TYPE_AUDIO, + })) + offer, err := m.sub.Offer() + require.NoError(t, err) + require.NoError(t, m.fake.Send(&sfu_events.SfuEvent{ + EventPayload: &sfu_events.SfuEvent_SubscriberOffer{ + SubscriberOffer: &sfu_events.SubscriberOffer{Sdp: offer, NegotiationId: 1}, + }, + }, iceTimeout)) + go writeSamplesUntilDone(ctx, m.aliceAudio) + + select { + case tr := <-traces: + return tr, joinCalled + case <-time.After(iceTimeout): + t.Fatalf("OnJoinTrace never fired; recorded so far:\n%s", call.JoinTrace()) + return jointrace.Trace{}, time.Time{} + } +} + +// TestJoinTraceRecordsTheLegacyJoin joins with media both ways and checks the trace has +// every step of today's join the fake exercises (all but the coordinator's), each after +// what it depends on, and that its critical path accounts for the whole join. +func TestJoinTraceRecordsTheLegacyJoin(t *testing.T) { + t.Parallel() + + m := newMediaSFU(t) + call := newTracedCall(t, m.fake, nil) + trace, joinCalled := joinWithMedia(t, m, call) + t.Logf("\n%s", trace) + + for _, name := range []string{ + jointrace.PCsCreate, jointrace.SFUWSDial, jointrace.SFUJoin, + jointrace.PubDebounce, jointrace.PubOffer, jointrace.PubSetPublisher, + jointrace.PubSFUCandidates, jointrace.PubTrickleOut, jointrace.PubICE, jointrace.PubDTLS, jointrace.PubRTP, + jointrace.SubSubscribe, jointrace.SubDebounce, jointrace.SubOffer, jointrace.SubSendAnswer, + jointrace.SubICE, jointrace.SubDTLS, jointrace.SubRTP, + jointrace.SFUWSDial + jointrace.DetailTCP, jointrace.SFUWSDial + jointrace.DetailFirstByte, + } { + _, ok := trace.Span(name) + require.True(t, ok, "no %s span", name) + } + + for _, s := range trace.Spans { + require.False(t, s.End.Before(s.Start), s.Name) + require.False(t, s.Start.Before(trace.Origin), s.Name) + for _, dep := range s.After { + d, ok := trace.Span(dep) + if !ok { + continue + } + require.False(t, s.End.Before(d.Start), "%s ends before %s, which it depends on, starts", s.Name, dep) + } + } + require.Positive(t, trace.RTT[jointrace.PeerSFU], "the SFU websocket's TCP connect") + require.Positive(t, trace.RTT[jointrace.PeerUDP], "the ICE pair's RTT") + + path := trace.CriticalPath() + require.Equal(t, []string{jointrace.PCsCreate, jointrace.SFUWSDial, jointrace.SFUJoin}, + path.Names()[:3]) + last := path.Steps[len(path.Steps)-1].Span + require.Contains(t, jointrace.Terminals, last.Name) + measured := last.End.Sub(joinCalled) + require.InDelta(t, float64(measured), float64(path.Total), float64(5*time.Millisecond), + "the critical path (%s, %s waiting) accounts for Join to the last first RTP (%s)", + path.Total, path.Wait, measured) + + require.GreaterOrEqual(t, len(call.JoinTrace().Spans), len(trace.Spans), + "JoinTrace returns what OnJoinTrace got, and anything recorded since") +} + +// TestJoinTraceWithNetworkDelay joins over a simulated 100 ms network: every step is +// then a whole number of round trips, which is what the trace has to show. +func TestJoinTraceWithNetworkDelay(t *testing.T) { + t.Parallel() + + const rtt = 100 * time.Millisecond + m := newMediaSFU(t, testutil.WithTLS()) + call := newTracedCall(t, m.fake, []Option{WithNetworkDelay(rtt)}, signal.WithTLSConfig(m.fake.TLSConfig())) + trace, _ := joinWithMedia(t, m, call) + t.Logf("\n%s", trace) + + within := func(name string, want float64, got time.Duration) { + t.Helper() + exact := time.Duration(want * float64(rtt)) + require.InDelta(t, float64(exact), float64(got), float64(exact)/10, + "%s: want %.1f RTT (%s), got %s", name, want, exact, got) + } + span := func(name string) jointrace.Span { + t.Helper() + s, ok := trace.Span(name) + require.True(t, ok, "no %s span", name) + return s + } + + within("RTT sfu", 1, trace.RTT[jointrace.PeerSFU]) + within("RTT udp", 1, trace.RTT[jointrace.PeerUDP]) + // TCP, TLS 1.3, then the websocket upgrade. + within(jointrace.SFUWSDial, 3, span(jointrace.SFUWSDial).Duration()) + within(jointrace.SFUJoin, 1, span(jointrace.SFUJoin).Duration()) + for _, suffix := range []string{jointrace.DetailTCP, jointrace.DetailTLS, jointrace.DetailFirstByte} { + within(jointrace.SFUWSDial+suffix, 1, span(jointrace.SFUWSDial+suffix).Duration()) + } +} + +func TestJoinTraceIgnoresRepairsAfterTheFirstJoin(t *testing.T) { + t.Parallel() + + var j joinTracer + first := j.begin(time.Now(), false) + require.NotNil(t, first) + require.Same(t, first, j.begin(time.Now(), true), "a retry of the first join still records") + + j.markJoined() + require.Nil(t, j.begin(time.Now(), true), "a reconnect after the join does not") + first.Add(jointrace.Span{Name: jointrace.SFUJoin, Start: time.Now(), End: time.Now()}) + require.False(t, first.Has(jointrace.SFUJoin), "and the trace is sealed") + j.timer.Stop() +} diff --git a/jointrace/httptrace.go b/jointrace/httptrace.go new file mode 100644 index 0000000..44af3a7 --- /dev/null +++ b/jointrace/httptrace.go @@ -0,0 +1,223 @@ +package jointrace + +import ( + "context" + "crypto/tls" + "net/http/httptrace" + "strconv" + "strings" + "sync" + "time" +) + +type stepKey struct{} + +// step is the network step a context's requests are part of. +type step struct { + rec *Recorder + name string + peer Peer + + mu sync.Mutex + dnsStart time.Time + connStart time.Time + tlsStart time.Time + connReady time.Time + wroteAt time.Time + firstByte time.Time + reused bool +} + +// WithStep returns a context whose HTTP requests and websocket dials record their DNS, +// TCP, TLS, request and first-byte times as detail spans of the step called name, and +// whose fresh TCP connections give rec a round-trip time to peer. +func WithStep(ctx context.Context, rec *Recorder, name string, peer Peer) context.Context { + if rec == nil { + return ctx + } + s := &step{rec: rec, name: name, peer: peer} + ctx = context.WithValue(ctx, stepKey{}, s) + return httptrace.WithClientTrace(ctx, s.clientTrace()) +} + +// Reused reports whether the step's request went out on a connection that was already +// open, so it paid no TCP or TLS round trips. +func Reused(ctx context.Context) bool { + s, _ := ctx.Value(stepKey{}).(*step) + if s == nil { + return false + } + s.mu.Lock() + defer s.mu.Unlock() + return s.reused +} + +// FirstByte is when the step's first response byte arrived, or zero. +func FirstByte(ctx context.Context) time.Time { + s, _ := ctx.Value(stepKey{}).(*step) + if s == nil { + return time.Time{} + } + s.mu.Lock() + defer s.mu.Unlock() + return s.firstByte +} + +func (s *step) detail(suffix string, start, end time.Time, kind Kind, note string) { + s.rec.Add(Span{ + Name: s.name + suffix, Parent: s.name, Start: start, End: end, + Kind: kind, Peer: s.peer, Note: note, + }) +} + +func (s *step) clientTrace() *httptrace.ClientTrace { + return &httptrace.ClientTrace{ + DNSStart: func(httptrace.DNSStartInfo) { + s.mu.Lock() + s.dnsStart = time.Now() + s.mu.Unlock() + }, + DNSDone: func(httptrace.DNSDoneInfo) { + s.mu.Lock() + start := s.dnsStart + s.mu.Unlock() + s.detail(DetailDNS, start, time.Now(), KindNet, "") + }, + ConnectStart: func(string, string) { + s.mu.Lock() + if s.connStart.IsZero() { + s.connStart = time.Now() + } + s.mu.Unlock() + }, + ConnectDone: func(_, _ string, err error) { + if err != nil { + return + } + now := time.Now() + s.mu.Lock() + start, abandoned := s.connStart, !s.connReady.IsZero() + s.mu.Unlock() + s.rec.SetRTT(s.peer, now.Sub(start)) + // net/http finishes a dial it no longer needs when an idle connection freed up + // first; the request did not wait for it. + if !abandoned { + s.detail(DetailTCP, start, now, KindNet, "") + } + }, + TLSHandshakeStart: func() { + s.mu.Lock() + s.tlsStart = time.Now() + s.mu.Unlock() + }, + TLSHandshakeDone: func(state tls.ConnectionState, err error) { + if err != nil { + return + } + s.mu.Lock() + start, abandoned := s.tlsStart, !s.connReady.IsZero() + s.mu.Unlock() + if abandoned { + return + } + note := "" + if state.DidResume { + note = "resumed" + } + s.detail(DetailTLS, start, time.Now(), KindNet, note) + }, + GotConn: func(info httptrace.GotConnInfo) { + s.mu.Lock() + if s.connReady.IsZero() { + s.connReady = time.Now() + s.reused = info.Reused + } + s.mu.Unlock() + }, + WroteRequest: func(info httptrace.WroteRequestInfo) { + if info.Err != nil { + return + } + now := time.Now() + s.mu.Lock() + start := s.connReady + if s.wroteAt.IsZero() { + s.wroteAt = now + } + reused := s.reused + s.mu.Unlock() + note := "" + if reused { + note = "reused connection" + } + s.detail(DetailRequest, start, now, KindLocal, note) + }, + GotFirstResponseByte: func() { + now := time.Now() + s.mu.Lock() + start := s.wroteAt + if s.firstByte.IsZero() { + s.firstByte = now + } + s.mu.Unlock() + s.detail(DetailFirstByte, start, now, KindNet, "") + }, + } +} + +// ServerTiming records the server's own time for the context's step from a +// Server-Timing response header, as a detail span centred in the wait for the first +// byte. It uses the "total" metric when the header has one, otherwise the longest. +func ServerTiming(ctx context.Context, header string) { + s, _ := ctx.Value(stepKey{}).(*step) + if s == nil || header == "" { + return + } + dur, ok := parseServerTiming(header) + if !ok { + return + } + s.mu.Lock() + wrote, first := s.wroteAt, s.firstByte + s.mu.Unlock() + if wrote.IsZero() || first.IsZero() { + return + } + wait := first.Sub(wrote) + if dur > wait { + dur = wait + } + start := wrote.Add((wait - dur) / 2) + s.detail(DetailServer, start, start.Add(dur), KindLocal, "server-timing") +} + +func parseServerTiming(header string) (time.Duration, bool) { + var longest, total time.Duration + haveTotal, found := false, false + for _, metric := range strings.Split(header, ",") { + fields := strings.Split(metric, ";") + name := strings.TrimSpace(fields[0]) + for _, param := range fields[1:] { + key, value, ok := strings.Cut(strings.TrimSpace(param), "=") + if !ok || !strings.EqualFold(key, "dur") { + continue + } + v, err := strconv.ParseFloat(strings.Trim(value, `"`), 64) + if err != nil || v < 0 { + continue + } + d := time.Duration(v * float64(time.Millisecond)) + found = true + if strings.EqualFold(name, "total") { + total, haveTotal = d, true + } + if d > longest { + longest = d + } + } + } + if haveTotal { + return total, true + } + return longest, found +} diff --git a/jointrace/httptrace_test.go b/jointrace/httptrace_test.go new file mode 100644 index 0000000..dae71a7 --- /dev/null +++ b/jointrace/httptrace_test.go @@ -0,0 +1,114 @@ +package jointrace_test + +import ( + "context" + "crypto/sha1" + "encoding/base64" + "net/http" + "net/http/httptest" + "testing" + "time" + + "github.com/stretchr/testify/require" + + "github.com/GetStream/getstream-go-webrtc/internal/netdelay" + "github.com/GetStream/getstream-go-webrtc/internal/wsdial" + "github.com/GetStream/getstream-go-webrtc/jointrace" +) + +const rtt = 100 * time.Millisecond + +// cpu is what a TLS handshake adds to its round trips, generous for the race detector. +const cpu = 15 * time.Millisecond + +// requireRTTs checks got is want round trips: within 5% under, and 10% plus local work over. +func requireRTTs(t *testing.T, want float64, got, local time.Duration) { + t.Helper() + exact := time.Duration(want * float64(rtt)) + require.GreaterOrEqual(t, got, exact-rtt/20, "want %.1f RTT, got %s", want, got) + require.LessOrEqual(t, got, exact+rtt/10+local, "want %.1f RTT, got %s", want, got) +} + +func TestWithStepRecordsTheRequestPhases(t *testing.T) { + t.Parallel() + + srv := httptest.NewTLSServer(http.HandlerFunc(func(w http.ResponseWriter, _ *http.Request) { + w.Header().Set("Server-Timing", "db;dur=3, total;dur=12.5") + time.Sleep(20 * time.Millisecond) + })) + defer srv.Close() + + tr := srv.Client().Transport.(*http.Transport).Clone() + tr.DialContext = netdelay.Dialer(rtt, nil) + client := &http.Client{Transport: tr} + + rec := jointrace.NewRecorder(time.Now()) + ctx := jointrace.WithStep(context.Background(), rec, jointrace.CoordJoin, jointrace.PeerCoordinator) + req, err := http.NewRequestWithContext(ctx, http.MethodPost, srv.URL, nil) + require.NoError(t, err) + resp, err := client.Do(req) + require.NoError(t, err) + jointrace.ServerTiming(ctx, resp.Header.Get("Server-Timing")) + require.NoError(t, resp.Body.Close()) + + trace := rec.Trace() + tcp, ok := trace.Span(jointrace.CoordJoin + jointrace.DetailTCP) + require.True(t, ok) + requireRTTs(t, 1, tcp.Duration(), 0) + require.Equal(t, jointrace.CoordJoin, tcp.Parent) + requireRTTs(t, 1, trace.RTT[jointrace.PeerCoordinator], 0) + + tlsSpan, ok := trace.Span(jointrace.CoordJoin + jointrace.DetailTLS) + require.True(t, ok) + requireRTTs(t, 1, tlsSpan.Duration(), cpu) // TLS 1.3 + + first, ok := trace.Span(jointrace.CoordJoin + jointrace.DetailFirstByte) + require.True(t, ok) + require.InDelta(t, float64(rtt+20*time.Millisecond), float64(first.Duration()), float64(rtt/10)) + require.False(t, jointrace.FirstByte(ctx).IsZero()) + require.False(t, jointrace.Reused(ctx)) + + server, ok := trace.Span(jointrace.CoordJoin + jointrace.DetailServer) + require.True(t, ok) + require.Equal(t, 12500*time.Microsecond, server.Duration(), "the total metric wins") + require.False(t, server.Start.Before(first.Start)) + require.False(t, server.End.After(first.End)) +} + +func TestWebsocketDialIsTraced(t *testing.T) { + t.Parallel() + + srv := httptest.NewTLSServer(http.HandlerFunc(func(w http.ResponseWriter, r *http.Request) { + // A bare websocket handshake answer; the dial needs nothing more. + w.Header().Set("Upgrade", "websocket") + w.Header().Set("Connection", "Upgrade") + w.Header().Set("Sec-WebSocket-Accept", accept(r.Header.Get("Sec-WebSocket-Key"))) + w.WriteHeader(http.StatusSwitchingProtocols) + })) + defer srv.Close() + + rec := jointrace.NewRecorder(time.Now()) + ctx := jointrace.WithStep(context.Background(), rec, jointrace.SFUWSDial, jointrace.PeerSFU) + cfg := srv.Client().Transport.(*http.Transport).TLSClientConfig + start := time.Now() + conn, err := wsdial.Dial(ctx, "wss"+srv.URL[len("https"):], netdelay.Dialer(rtt, nil), cfg) + require.NoError(t, err) + elapsed := time.Since(start) + require.NoError(t, conn.Close()) + + requireRTTs(t, 3, elapsed, cpu) + trace := rec.Trace() + for _, suffix := range []string{jointrace.DetailTCP, jointrace.DetailTLS, jointrace.DetailFirstByte} { + s, ok := trace.Span(jointrace.SFUWSDial + suffix) + require.True(t, ok, suffix) + requireRTTs(t, 1, s.Duration(), cpu) + } + _, ok := trace.Span(jointrace.SFUWSDial + jointrace.DetailRequest) + require.True(t, ok) + requireRTTs(t, 1, trace.RTT[jointrace.PeerSFU], 0) +} + +func accept(key string) string { + sum := sha1.Sum([]byte(key + "258EAFA5-E914-47DA-95CA-C5AB0DC85B11")) + return base64.StdEncoding.EncodeToString(sum[:]) +} diff --git a/jointrace/recorder.go b/jointrace/recorder.go new file mode 100644 index 0000000..9645c20 --- /dev/null +++ b/jointrace/recorder.go @@ -0,0 +1,167 @@ +package jointrace + +import ( + "sort" + "sync" + "time" +) + +// Recorder collects the spans of one join. It is safe for concurrent use, and every +// method is a no-op on a nil Recorder, so instrumented code need not check. +// +// The first recording of a span wins: a retry or a later renegotiation does not move a +// step that already happened. Seal stops all recording. +type Recorder struct { + mu sync.Mutex + origin time.Time + spans map[string]*Span + order []string + rtt map[Peer]time.Duration + sealed bool +} + +// NewRecorder returns a recorder whose trace starts at origin, the moment the join began. +func NewRecorder(origin time.Time) *Recorder { + return &Recorder{ + origin: origin, + spans: make(map[string]*Span, 48), + rtt: make(map[Peer]time.Duration, 4), + } +} + +// Add records a span unless one with the same name exists. A span with a zero Start or +// End is ignored. +func (r *Recorder) Add(s Span) { + if r == nil || s.Start.IsZero() || s.End.IsZero() { + return + } + r.mu.Lock() + defer r.mu.Unlock() + r.addLocked(s) +} + +func (r *Recorder) addLocked(s Span) { + if r.sealed { + return + } + if _, ok := r.spans[s.Name]; ok { + return + } + if s.End.Before(s.Start) { + s.End = s.Start + } + r.spans[s.Name] = &s + r.order = append(r.order, s.Name) +} + +// Extend records s, or, if a span of that name exists, moves its end to s.End when that +// is later. It is for steps made of several operations, such as a series of trickled +// candidates. +func (r *Recorder) Extend(s Span) { + if r == nil || s.Start.IsZero() || s.End.IsZero() { + return + } + r.mu.Lock() + defer r.mu.Unlock() + if r.sealed { + return + } + if existing, ok := r.spans[s.Name]; ok { + if s.End.After(existing.End) { + existing.End = s.End + } + return + } + r.addLocked(s) +} + +// Has reports whether a span of that name was recorded. +func (r *Recorder) Has(name string) bool { + if r == nil { + return false + } + r.mu.Lock() + defer r.mu.Unlock() + _, ok := r.spans[name] + return ok +} + +// Get returns the span of that name. +func (r *Recorder) Get(name string) (Span, bool) { + if r == nil { + return Span{}, false + } + r.mu.Lock() + defer r.mu.Unlock() + s, ok := r.spans[name] + if !ok { + return Span{}, false + } + return *s, true +} + +// SetRTT records a round-trip time to peer, unless one is already known. +func (r *Recorder) SetRTT(peer Peer, rtt time.Duration) { + if r == nil || rtt <= 0 { + return + } + r.mu.Lock() + defer r.mu.Unlock() + if r.sealed { + return + } + if _, ok := r.rtt[peer]; !ok { + r.rtt[peer] = rtt + } +} + +// RTT is the round-trip time recorded for peer, or zero. +func (r *Recorder) RTT(peer Peer) time.Duration { + if r == nil { + return 0 + } + r.mu.Lock() + defer r.mu.Unlock() + return r.rtt[peer] +} + +// Seal stops recording: everything after is ignored. +func (r *Recorder) Seal() { + if r == nil { + return + } + r.mu.Lock() + defer r.mu.Unlock() + r.sealed = true +} + +// Trace returns what has been recorded so far, spans ordered by start. +func (r *Recorder) Trace() Trace { + if r == nil { + return Trace{} + } + r.mu.Lock() + t := Trace{ + JoinAt: r.origin, + Spans: make([]Span, 0, len(r.order)), + RTT: make(map[Peer]time.Duration, len(r.rtt)), + } + for _, name := range r.order { + s := *r.spans[name] + s.After = append([]string(nil), s.After...) + t.Spans = append(t.Spans, s) + } + for p, d := range r.rtt { + t.RTT[p] = d + } + r.mu.Unlock() + + sort.SliceStable(t.Spans, func(i, j int) bool { return t.Spans[i].Start.Before(t.Spans[j].Start) }) + t.Origin = t.JoinAt + for _, s := range t.Spans { + if t.Origin.IsZero() || s.Start.Before(t.Origin) { + t.Origin = s.Start + } + } + return t +} diff --git a/jointrace/render.go b/jointrace/render.go new file mode 100644 index 0000000..ea0c97f --- /dev/null +++ b/jointrace/render.go @@ -0,0 +1,146 @@ +package jointrace + +import ( + "fmt" + "sort" + "strings" + "time" +) + +const timelineWidth = 40 + +// String draws the trace: one row per step in start order, what it waited for, when it +// started and how long it took, in ms and in round trips of its peer, and a timeline +// that shows which steps ran in parallel. Critical-path steps are marked with "*" and +// drawn with "="; detail spans sit under their step. The critical path and the times to +// media follow. +func (t Trace) String() string { + var b strings.Builder + if len(t.Spans) == 0 { + return "join trace: no steps recorded\n" + } + path := t.CriticalPath() + critical := make(map[string]bool, len(path.Steps)) + for _, s := range path.Steps { + critical[s.Span.Name] = true + } + + fmt.Fprintf(&b, "join DAG (%s)\n", t.rttSummary()) + end := t.Origin + for _, s := range t.Spans { + if s.End.After(end) { + end = s.End + } + } + scale := end.Sub(t.Origin) + + children := make(map[string][]Span) + for _, s := range t.Spans { + if s.Parent != "" { + children[s.Parent] = append(children[s.Parent], s) + } + } + fmt.Fprintf(&b, " %-22s %-36s %7s %8s %6s %s\n", "step", "after", "start", "ms", "RTT", "timeline") + for _, s := range t.Spans { + if s.Parent != "" { + continue + } + mark := " " + if critical[s.Name] { + mark = "*" + } + after := strings.Join(s.After, ",") + if after == "" { + after = "-" + } + fmt.Fprintf(&b, "%s %-22s %-36s %7.1f %8.1f %6s %s%s\n", mark, s.Name, after, + msf(s.Start.Sub(t.Origin)), msf(s.Duration()), t.rttCell(s), + t.bar(s, scale, critical[s.Name]), noteSuffix(s.Note)) + kids := children[s.Name] + sort.SliceStable(kids, func(i, j int) bool { return kids[i].Start.Before(kids[j].Start) }) + for _, c := range kids { + name := " " + strings.TrimPrefix(c.Name, s.Name) + fmt.Fprintf(&b, " %-22s %-36s %7.1f %8.1f %6s %s%s\n", name, "", + msf(c.Start.Sub(t.Origin)), msf(c.Duration()), t.rttCell(c), + t.bar(c, scale, false), noteSuffix(c.Note)) + } + } + + if len(path.Steps) > 0 { + fmt.Fprintf(&b, "critical path: %s\n", strings.Join(path.Names(), " > ")) + fmt.Fprintf(&b, " %.1f ms = %.2f RTT (%.1f ms network) + %.1f ms timers + %.1f ms local; %.1f ms unaccounted waiting\n", + msf(path.Total), path.RTTs, msf(path.Net), msf(path.Timers), msf(path.Local), msf(path.Wait)) + } + if d, ok := t.PublishToMedia(); ok { + fmt.Fprintf(&b, "publish to media: %.1f ms from Join (first RTP sent + RTT/2)\n", msf(d)) + } + if d, ok := t.SubscribeToMedia(); ok { + fmt.Fprintf(&b, "subscribe to media: %.1f ms from Join\n", msf(d)) + } + return b.String() +} + +func (t Trace) rttSummary() string { + if len(t.RTT) == 0 { + return "no RTT measured" + } + peers := make([]string, 0, len(t.RTT)) + for p := range t.RTT { + peers = append(peers, string(p)) + } + sort.Strings(peers) + parts := make([]string, 0, len(peers)) + for _, p := range peers { + parts = append(parts, fmt.Sprintf("RTT %s %.1f ms", p, msf(t.RTT[Peer(p)]))) + } + return strings.Join(parts, ", ") +} + +func (t Trace) rttCell(s Span) string { + if s.Kind != KindNet { + return string(s.Kind) + } + if t.RTTOf(s.Peer) <= 0 { + return "?" + } + return fmt.Sprintf("%.2f", t.RTTs(s.Peer, s.Duration())) +} + +func (t Trace) bar(s Span, scale time.Duration, critical bool) string { + cells := []byte(strings.Repeat(" ", timelineWidth)) + if scale > 0 { + from := int(float64(s.Start.Sub(t.Origin)) / float64(scale) * timelineWidth) + to := int(float64(s.End.Sub(t.Origin))/float64(scale)*timelineWidth + 0.5) + from = clamp(from, 0, timelineWidth-1) + to = clamp(to, from+1, timelineWidth) + fill := byte('-') + if critical { + fill = '=' + } + for i := from; i < to; i++ { + cells[i] = fill + } + } + return "|" + string(cells) + "|" +} + +func noteSuffix(note string) string { + if note == "" { + return "" + } + return " " + note +} + +func clamp(v, lo, hi int) int { + if v < lo { + return lo + } + if v > hi { + return hi + } + return v +} + +func msf(d time.Duration) float64 { + return float64(d) / float64(time.Millisecond) +} diff --git a/jointrace/span.go b/jointrace/span.go new file mode 100644 index 0000000..3d177a5 --- /dev/null +++ b/jointrace/span.go @@ -0,0 +1,102 @@ +// Package jointrace records where the time goes when a client joins a call: one span per +// step of the join, each with the steps it waited for, so the critical path through the +// join and its cost in network round trips can be read off. +// +// Node names follow the join DAG the SDK is measured against (the "3RTT" project's +// research/join-dag.md), so bench output and that document line up. +package jointrace + +import "time" + +// Kind is what a span spends its time on. +type Kind string + +const ( + // KindNet is time waiting for the network: a request and its response. + KindNet Kind = "net" + // KindLocal is CPU work on this machine: SDP, key generation, peer connection setup. + KindLocal Kind = "local" + // KindTimer is time spent waiting on a timer, such as a negotiation debounce. + KindTimer Kind = "timer" +) + +// Peer is who a network span talks to. Its round trips are counted in that peer's RTT. +type Peer string + +const ( + PeerCoordinator Peer = "coordinator" + PeerSFU Peer = "sfu" + PeerCloudFront Peer = "cloudfront" + // PeerUDP is the media path to the SFU: ICE, DTLS and RTP. + PeerUDP Peer = "udp" + PeerLocal Peer = "local" +) + +// The steps of a join as the SDK performs it today (legacy path). +const ( + CoordWSDial = "coord.ws.dial" + CoordWSAuth = "coord.ws.auth" + LocationHint = "location.hint" + CoordJoin = "coord.join" + PCsCreate = "pcs.create" + SFUWSDial = "sfu.ws.dial" + SFUJoin = "sfu.join" + PubDebounce = "pub.debounce" + PubOffer = "pub.offer" + PubSetPublisher = "pub.setpublisher" + PubSFUCandidates = "pub.sfu.candidates" + PubTrickleOut = "pub.trickle.out" + PubICE = "pub.ice" + PubDTLS = "pub.dtls" + PubRTP = "pub.rtp" + SubSubscribe = "sub.subscribe" + SubGate = "sub.gate" + SubDebounce = "sub.debounce" + SubOffer = "sub.offer" + SubSendAnswer = "sub.sendanswer" + SubICE = "sub.ice" + SubDTLS = "sub.dtls" + SubRTP = "sub.rtp" +) + +// The steps of the fast join path. +const ( + CoordFastJoin = "coord.fastjoin" + SFUFastJoin = "sfu.fastjoin" + SFUWS = "sfu.ws" + SubAnswer = "sub.answer" + PubICEDTLS = "pub.ice+dtls" + SubICEDTLS = "sub.ice+dtls" +) + +// Suffixes of the detail spans a network step is split into. A detail span is named +// after its parent, "coord.join.tcp" for example, and has Parent set. +const ( + DetailDNS = ".dns" + DetailTCP = ".tcp" + DetailTLS = ".tls" + DetailRequest = ".request" + DetailFirstByte = ".first_byte" + DetailServer = ".server" +) + +// Span is one step of a join. +type Span struct { + Name string + // After lists the steps this one waited for. + After []string + // Parent is set on detail spans: the network step they are part of. Detail spans are + // not part of the dependency graph. + Parent string + Start time.Time + End time.Time + Kind Kind + Peer Peer + // Note says anything unusual about how the span was measured. + Note string +} + +// Duration is how long the span took. +func (s Span) Duration() time.Duration { + return s.End.Sub(s.Start) +} diff --git a/jointrace/testdata/today_join.golden b/jointrace/testdata/today_join.golden new file mode 100644 index 0000000..2a32881 --- /dev/null +++ b/jointrace/testdata/today_join.golden @@ -0,0 +1,27 @@ +join DAG (RTT coordinator 100.0 ms, RTT sfu 100.0 ms, RTT udp 100.0 ms) + step after start ms RTT timeline +* coord.join - 0.0 400.0 4.00 |============= | + .tcp 0.0 100.0 1.00 |--- | + .tls 100.0 200.0 2.00 | ------- | + .first_byte 300.0 100.0 1.00 | ---- | + .server 340.0 20.0 local | - | server-timing +* pcs.create coord.join 400.0 2.0 local | = | +* sfu.ws.dial pcs.create 402.0 300.0 3.00 | ========== | +* sfu.join sfu.ws.dial 702.0 100.0 1.00 | ==== | + pub.debounce sfu.join 802.0 0.5 timer | - | +* sub.debounce sfu.join 802.0 148.0 timer | ===== | + pub.offer pub.debounce 802.5 2.5 local | - | + pub.setpublisher pub.offer 805.0 100.0 1.00 | ---- | + pub.sfu.candidates pub.setpublisher 805.0 55.0 0.55 | -- | + pub.ice pub.setpublisher,pub.sfu.candidates 906.0 100.0 1.00 | ---- | +* sub.offer sub.debounce 950.0 50.0 0.50 | == | +* sub.sendanswer sub.offer 1000.0 103.0 1.03 | ==== | +* sub.ice sub.sendanswer 1003.0 100.0 1.00 | ==== | + pub.dtls pub.ice 1006.0 100.0 1.00 | ---- | +* sub.dtls sub.ice 1103.0 100.0 1.00 | === | + pub.rtp pub.dtls 1106.0 4.0 local | - | +* sub.rtp sub.dtls 1203.0 22.0 local | =| +critical path: coord.join > pcs.create > sfu.ws.dial > sfu.join > sub.debounce > sub.offer > sub.sendanswer > sub.ice > sub.dtls > sub.rtp + 1225.0 ms = 10.53 RTT (1053.0 ms network) + 148.0 ms timers + 24.0 ms local; 0.0 ms unaccounted waiting +publish to media: 1160.0 ms from Join (first RTP sent + RTT/2) +subscribe to media: 1225.0 ms from Join diff --git a/jointrace/trace.go b/jointrace/trace.go new file mode 100644 index 0000000..71007c9 --- /dev/null +++ b/jointrace/trace.go @@ -0,0 +1,316 @@ +package jointrace + +import ( + "encoding/json" + "time" +) + +// Trace is the recorded join. +type Trace struct { + // JoinAt is when Call.Join was called. + JoinAt time.Time + // Origin is when the first recorded step started: JoinAt, or earlier when the trace + // includes the client's own connection to the coordinator. + Origin time.Time + // Spans are ordered by start. + Spans []Span + // RTT is the measured round-trip time to each peer. + RTT map[Peer]time.Duration +} + +// Span returns the span of that name. +func (t Trace) Span(name string) (Span, bool) { + for _, s := range t.Spans { + if s.Name == name { + return s, true + } + } + return Span{}, false +} + +// RTTOf is the round-trip time spans to peer are counted in. The media path falls back to +// the SFU's signalling RTT when ICE has not measured one. +func (t Trace) RTTOf(peer Peer) time.Duration { + if d := t.RTT[peer]; d > 0 { + return d + } + if peer == PeerUDP { + return t.RTT[PeerSFU] + } + return 0 +} + +// RTTs is d in round trips to peer, or zero when that RTT is unknown. +func (t Trace) RTTs(peer Peer, d time.Duration) float64 { + rtt := t.RTTOf(peer) + if rtt <= 0 { + return 0 + } + return float64(d) / float64(rtt) +} + +// Step is one span on a path and what it adds to the path's length. +type Step struct { + Span Span + // Wait is the time between the previous step ending and this one starting: nothing on + // the path accounts for it. + Wait time.Duration + // Cost is how much this step adds to the path: its duration, less any part that + // overlaps the previous step. + Cost time.Duration + // RTTs is Cost in round trips of the span's peer; zero for local work and timers. + RTTs float64 +} + +// Path is a dependency chain through the trace. +type Path struct { + Steps []Step + // Total is the sum of the steps' costs; Wait the sum of the gaps between them. Total + // plus Wait is the time from the trace's origin to the last step's end. + Total time.Duration + Wait time.Duration + // RTTs is the network part of Total in round trips; Timers and Local the rest. + RTTs float64 + Net time.Duration + Timers time.Duration + Local time.Duration +} + +// Names lists the path's steps. +func (p Path) Names() []string { + names := make([]string, len(p.Steps)) + for i, s := range p.Steps { + names[i] = s.Span.Name + } + return names +} + +// Terminals are the steps a join is finished at: media flowing both ways. +var Terminals = []string{PubRTP, SubRTP} + +// CriticalPath is the path to whichever terminal step finished last, or, when none was +// reached, to the step that finished last. +func (t Trace) CriticalPath() Path { + var last *Span + for _, name := range Terminals { + if s, ok := t.Span(name); ok && (last == nil || s.End.After(last.End)) { + last = &s + } + } + if last == nil { + for i := range t.Spans { + s := t.Spans[i] + if s.Parent == "" && (last == nil || s.End.After(last.End)) { + last = &s + } + } + } + if last == nil { + return Path{} + } + return t.PathTo(last.Name) +} + +// PathTo walks back from the named step, at each step following the dependency that +// finished last: the one it was actually waiting for. +func (t Trace) PathTo(name string) Path { + byName := make(map[string]Span, len(t.Spans)) + for _, s := range t.Spans { + if s.Parent == "" { + byName[s.Name] = s + } + } + cur, ok := byName[name] + if !ok { + return Path{} + } + var chain []Span + seen := map[string]bool{} + for { + chain = append(chain, cur) + seen[cur.Name] = true + var pred *Span + for _, dep := range cur.After { + s, ok := byName[dep] + if !ok || seen[dep] { + continue + } + if pred == nil || s.End.After(pred.End) { + pred = &s + } + } + if pred == nil { + break + } + cur = *pred + } + + var p Path + prevEnd := t.Origin + for i := len(chain) - 1; i >= 0; i-- { + s := chain[i] + step := Step{Span: s} + begin := s.Start + if gap := s.Start.Sub(prevEnd); gap > 0 { + step.Wait = gap + } else { + begin = prevEnd + } + if s.End.After(begin) { + step.Cost = s.End.Sub(begin) + } + switch s.Kind { + case KindNet: + step.RTTs = t.RTTs(s.Peer, step.Cost) + p.Net += step.Cost + case KindTimer: + p.Timers += step.Cost + default: + p.Local += step.Cost + } + p.Steps = append(p.Steps, step) + p.Total += step.Cost + p.Wait += step.Wait + p.RTTs += step.RTTs + if s.End.After(prevEnd) { + prevEnd = s.End + } + } + return p +} + +// PublishToMedia is from Join to the first RTP packet reaching the SFU: the first one +// sent, plus half an RTT in flight. +func (t Trace) PublishToMedia() (time.Duration, bool) { + s, ok := t.Span(PubRTP) + if !ok || t.JoinAt.IsZero() { + return 0, false + } + return s.End.Sub(t.JoinAt) + t.RTTOf(PeerUDP)/2, true +} + +// SubscribeToMedia is from Join to the first RTP packet received from the SFU. +func (t Trace) SubscribeToMedia() (time.Duration, bool) { + s, ok := t.Span(SubRTP) + if !ok || t.JoinAt.IsZero() { + return 0, false + } + return s.End.Sub(t.JoinAt), true +} + +// Report is the JSON form of a Trace, for benches and the agent. Times are milliseconds +// from Origin. +type Report struct { + // Origin is the trace's origin as Unix milliseconds. + OriginUnixMs float64 `json:"origin_unix_ms"` + // JoinAtMs is when Join was called, relative to the origin. + JoinAtMs float64 `json:"join_at_ms"` + // RTTMs is the measured RTT per peer. + RTTMs map[Peer]float64 `json:"rtt_ms"` + Spans []ReportSpan `json:"spans"` + // CriticalPath names the steps of the critical path, in order. + CriticalPath []string `json:"critical_path"` + CriticalMs float64 `json:"critical_ms"` + CriticalRTTs float64 `json:"critical_rtts"` + CriticalNetMs float64 `json:"critical_net_ms"` + CriticalTimeMs float64 `json:"critical_timer_ms"` + CriticalLocal float64 `json:"critical_local_ms"` + CriticalWaitMs float64 `json:"critical_wait_ms"` + // PublishToMediaMs and SubscribeToMediaMs are from Join; absent when not reached. + PublishToMediaMs *float64 `json:"publish_to_media_ms,omitempty"` + SubscribeToMediaMs *float64 `json:"subscribe_to_media_ms,omitempty"` +} + +// ReportSpan is one span of a Report. +type ReportSpan struct { + Name string `json:"name"` + After []string `json:"after,omitempty"` + Parent string `json:"parent,omitempty"` + Kind Kind `json:"kind"` + Peer Peer `json:"peer"` + StartMs float64 `json:"start_ms"` + EndMs float64 `json:"end_ms"` + Ms float64 `json:"ms"` + RTTs float64 `json:"rtts"` + Critical bool `json:"critical,omitempty"` + // CostMs and WaitMs are set on critical spans: what the span adds to the critical + // path and the unexplained wait before it. + CostMs float64 `json:"cost_ms,omitempty"` + WaitMs float64 `json:"wait_ms,omitempty"` + Note string `json:"note,omitempty"` +} + +// Report builds the JSON form of the trace. +func (t Trace) Report() Report { + path := t.CriticalPath() + critical := make(map[string]Step, len(path.Steps)) + for _, s := range path.Steps { + critical[s.Span.Name] = s + } + r := Report{ + OriginUnixMs: float64(t.Origin.UnixNano()) / 1e6, + JoinAtMs: ms(t.JoinAt.Sub(t.Origin)), + RTTMs: make(map[Peer]float64, len(t.RTT)), + Spans: make([]ReportSpan, 0, len(t.Spans)), + CriticalPath: path.Names(), + CriticalMs: ms(path.Total), + CriticalRTTs: round2(path.RTTs), + CriticalNetMs: ms(path.Net), + CriticalTimeMs: ms(path.Timers), + CriticalLocal: ms(path.Local), + CriticalWaitMs: ms(path.Wait), + } + if t.Origin.IsZero() { + r.OriginUnixMs, r.JoinAtMs = 0, 0 + } + for p, d := range t.RTT { + r.RTTMs[p] = ms(d) + } + for _, s := range t.Spans { + rs := ReportSpan{ + Name: s.Name, + After: s.After, + Parent: s.Parent, + Kind: s.Kind, + Peer: s.Peer, + StartMs: ms(s.Start.Sub(t.Origin)), + EndMs: ms(s.End.Sub(t.Origin)), + Ms: ms(s.Duration()), + Note: s.Note, + } + if s.Kind == KindNet { + rs.RTTs = round2(t.RTTs(s.Peer, s.Duration())) + } + if step, ok := critical[s.Name]; ok && s.Parent == "" { + rs.Critical = true + rs.CostMs = ms(step.Cost) + rs.WaitMs = ms(step.Wait) + } + r.Spans = append(r.Spans, rs) + } + if d, ok := t.PublishToMedia(); ok { + v := ms(d) + r.PublishToMediaMs = &v + } + if d, ok := t.SubscribeToMedia(); ok { + v := ms(d) + r.SubscribeToMediaMs = &v + } + return r +} + +// MarshalJSON encodes the trace as its Report. +func (t Trace) MarshalJSON() ([]byte, error) { + return json.Marshal(t.Report()) +} + +func ms(d time.Duration) float64 { + return round2(float64(d) / float64(time.Millisecond)) +} + +func round2(v float64) float64 { + if v < 0 { + return -round2(-v) + } + return float64(int64(v*100+0.5)) / 100 +} diff --git a/jointrace/trace_test.go b/jointrace/trace_test.go new file mode 100644 index 0000000..8d99f4f --- /dev/null +++ b/jointrace/trace_test.go @@ -0,0 +1,180 @@ +package jointrace + +import ( + "encoding/json" + "flag" + "os" + "path/filepath" + "testing" + "time" + + "github.com/stretchr/testify/require" +) + +var update = flag.Bool("update", false, "rewrite the golden files") + +var t0 = time.Date(2026, 9, 30, 12, 0, 0, 0, time.UTC) + +func at(ms float64) time.Time { + return t0.Add(time.Duration(ms * float64(time.Millisecond))) +} + +// todayJoin is a legacy join at 100 ms to every peer, laid out the way the SDK records +// it: two branches, publish and subscribe, run in parallel after sfu.join. +func todayJoin() Trace { + rec := NewRecorder(t0) + rec.SetRTT(PeerCoordinator, 100*time.Millisecond) + rec.SetRTT(PeerSFU, 100*time.Millisecond) + rec.SetRTT(PeerUDP, 100*time.Millisecond) + add := func(name string, after []string, from, to float64, kind Kind, peer Peer) { + rec.Add(Span{Name: name, After: after, Start: at(from), End: at(to), Kind: kind, Peer: peer}) + } + add(CoordJoin, nil, 0, 400, KindNet, PeerCoordinator) + rec.Add(Span{Name: CoordJoin + DetailTCP, Parent: CoordJoin, Start: at(0), End: at(100), Kind: KindNet, Peer: PeerCoordinator}) + rec.Add(Span{Name: CoordJoin + DetailTLS, Parent: CoordJoin, Start: at(100), End: at(300), Kind: KindNet, Peer: PeerCoordinator}) + rec.Add(Span{Name: CoordJoin + DetailFirstByte, Parent: CoordJoin, Start: at(300), End: at(400), Kind: KindNet, Peer: PeerCoordinator}) + rec.Add(Span{Name: CoordJoin + DetailServer, Parent: CoordJoin, Start: at(340), End: at(360), Kind: KindLocal, Peer: PeerCoordinator, Note: "server-timing"}) + add(PCsCreate, []string{CoordJoin}, 400, 402, KindLocal, PeerLocal) + add(SFUWSDial, []string{PCsCreate}, 402, 702, KindNet, PeerSFU) + add(SFUJoin, []string{SFUWSDial}, 702, 802, KindNet, PeerSFU) + add(PubDebounce, []string{SFUJoin}, 802, 802.5, KindTimer, PeerLocal) + add(PubOffer, []string{PubDebounce}, 802.5, 805, KindLocal, PeerLocal) + add(PubSetPublisher, []string{PubOffer}, 805, 905, KindNet, PeerSFU) + add(PubSFUCandidates, []string{PubSetPublisher}, 805, 860, KindNet, PeerSFU) + add(PubICE, []string{PubSetPublisher, PubSFUCandidates}, 906, 1006, KindNet, PeerUDP) + add(PubDTLS, []string{PubICE}, 1006, 1106, KindNet, PeerUDP) + add(PubRTP, []string{PubDTLS}, 1106, 1110, KindLocal, PeerLocal) + add(SubDebounce, []string{SFUJoin}, 802, 950, KindTimer, PeerSFU) + add(SubOffer, []string{SubDebounce}, 950, 1000, KindNet, PeerSFU) + add(SubSendAnswer, []string{SubOffer}, 1000, 1103, KindNet, PeerSFU) + add(SubICE, []string{SubSendAnswer}, 1003, 1103, KindNet, PeerUDP) + add(SubDTLS, []string{SubICE}, 1103, 1203, KindNet, PeerUDP) + add(SubRTP, []string{SubDTLS}, 1203, 1225, KindLocal, PeerLocal) + tr := rec.Trace() + tr.JoinAt = t0 + return tr +} + +func TestCriticalPathFollowsTheLatestDependency(t *testing.T) { + path := todayJoin().CriticalPath() + + require.Equal(t, []string{ + CoordJoin, PCsCreate, SFUWSDial, SFUJoin, + SubDebounce, SubOffer, SubSendAnswer, SubICE, SubDTLS, SubRTP, + }, path.Names(), "sub.rtp ends last, and each step waits for the dependency that ended last") + require.Equal(t, 1225*time.Millisecond, path.Total+path.Wait, + "the path's cost and waits add up to the time to its end") + require.Zero(t, path.Wait) + require.Equal(t, 148*time.Millisecond, path.Timers) + require.Equal(t, 24*time.Millisecond, path.Local) + // sub.ice runs entirely inside sub.sendanswer, so it adds nothing. + require.InDelta(t, 4+3+1+0.5+1.03+0+1, path.RTTs, 0.01) + require.Zero(t, path.Steps[7].Cost) +} + +func TestPathCountsGapsAsWait(t *testing.T) { + rec := NewRecorder(t0) + rec.Add(Span{Name: SFUWSDial, Start: at(0), End: at(100), Kind: KindNet, Peer: PeerSFU}) + rec.Add(Span{Name: SFUJoin, After: []string{SFUWSDial}, Start: at(130), End: at(230), Kind: KindNet, Peer: PeerSFU}) + path := rec.Trace().PathTo(SFUJoin) + + require.Equal(t, 200*time.Millisecond, path.Total) + require.Equal(t, 30*time.Millisecond, path.Wait) + require.Zero(t, path.RTTs, "no RTT measured, so no round trips") +} + +func TestPathIgnoresMissingDependencies(t *testing.T) { + rec := NewRecorder(t0) + rec.Add(Span{Name: SubSendAnswer, After: []string{SubOffer}, Start: at(10), End: at(20), Kind: KindNet, Peer: PeerSFU}) + path := rec.Trace().CriticalPath() + + require.Equal(t, []string{SubSendAnswer}, path.Names()) + require.Equal(t, 10*time.Millisecond, path.Wait) +} + +func TestRecorderKeepsTheFirstRecording(t *testing.T) { + rec := NewRecorder(t0) + rec.Add(Span{Name: SFUJoin, Start: at(0), End: at(10)}) + rec.Add(Span{Name: SFUJoin, Start: at(50), End: at(60)}) + rec.Add(Span{Name: SFUWSDial, Start: at(5), End: at(1)}) + rec.Add(Span{Name: PubDTLS, End: at(1)}) + rec.SetRTT(PeerSFU, 10*time.Millisecond) + rec.SetRTT(PeerSFU, 90*time.Millisecond) + rec.Seal() + rec.Add(Span{Name: SubRTP, Start: at(0), End: at(1)}) + + tr := rec.Trace() + require.Len(t, tr.Spans, 2) + join, _ := tr.Span(SFUJoin) + require.Equal(t, at(10), join.End) + dial, _ := tr.Span(SFUWSDial) + require.Equal(t, dial.Start, dial.End, "an end before the start is clamped") + require.Equal(t, 10*time.Millisecond, tr.RTT[PeerSFU]) + + var nilRec *Recorder + nilRec.Add(Span{Name: SFUJoin, Start: at(0), End: at(1)}) + require.Empty(t, nilRec.Trace().Spans) +} + +func TestReportRoundTripsAsJSON(t *testing.T) { + tr := todayJoin() + raw, err := json.Marshal(tr) + require.NoError(t, err) + + var r Report + require.NoError(t, json.Unmarshal(raw, &r)) + require.Len(t, r.Spans, len(tr.Spans)) + require.Equal(t, tr.CriticalPath().Names(), r.CriticalPath) + require.InDelta(t, 1225, r.CriticalMs, 0.01) + require.InDelta(t, 100, r.RTTMs[PeerSFU], 0.01) + require.NotNil(t, r.PublishToMediaMs) + require.InDelta(t, 1160, *r.PublishToMediaMs, 0.01, "first RTP sent plus RTT/2") + require.NotNil(t, r.SubscribeToMediaMs) + require.InDelta(t, 1225, *r.SubscribeToMediaMs, 0.01) + + for _, s := range r.Spans { + if s.Name == SFUWSDial { + require.True(t, s.Critical) + require.InDelta(t, 3, s.RTTs, 0.01) + } + if s.Name == PubSetPublisher { + require.False(t, s.Critical) + } + } +} + +func TestRenderGolden(t *testing.T) { + got := todayJoin().String() + golden := filepath.Join("testdata", "today_join.golden") + if *update { + require.NoError(t, os.MkdirAll("testdata", 0o755)) + require.NoError(t, os.WriteFile(golden, []byte(got), 0o644)) + } + want, err := os.ReadFile(golden) + require.NoError(t, err, "run go test ./jointrace -update to create it") + require.Equal(t, string(want), got) +} + +func TestRenderEmpty(t *testing.T) { + require.Equal(t, "join trace: no steps recorded\n", Trace{}.String()) +} + +// A join records a few dozen spans; collecting them must not be what makes it slow. +func TestRecordingIsCheap(t *testing.T) { + const joins = 200 + start := time.Now() + for range joins { + tr := todayJoin() + _ = tr.CriticalPath() + _, _ = json.Marshal(tr) + } + perJoin := time.Since(start) / joins + t.Logf("recording, critical path and JSON: %s per join", perJoin) + require.Less(t, perJoin, time.Millisecond) +} + +func BenchmarkRecordJoin(b *testing.B) { + for b.Loop() { + _ = todayJoin().CriticalPath() + } +} diff --git a/pc/pc.go b/pc/pc.go index 5cf47d8..2e8c1de 100644 --- a/pc/pc.go +++ b/pc/pc.go @@ -83,7 +83,12 @@ type Transport struct { // dtlsConnectedAt is when the DTLS handshake finished for the first time. dtlsConnectedAt time.Time connectedAt time.Time - lastPCState webrtc.PeerConnectionState + // negotiationRequestedAt, offerStartedAt and firstRemoteCandidateAt are the first + // Negotiate call, the first offer being created and the first trickled candidate. + negotiationRequestedAt time.Time + offerStartedAt time.Time + firstRemoteCandidateAt time.Time + lastPCState webrtc.PeerConnectionState // lastICEState and lastDTLSState skip the Closed transition that Close // causes, so a snapshot taken afterwards still shows where the connection // stalled. @@ -135,6 +140,12 @@ type TransportParams struct { // step it has not reached. ICE restarts do not move these: they describe how the // transport came up in the first place. type Timing struct { + // NegotiationRequested is the first Negotiate call; OfferStarted is when the first + // offer began to be created, after the debounce. + NegotiationRequested time.Time + OfferStarted time.Time + // FirstRemoteCandidate is when the first candidate trickled by the SFU arrived. + FirstRemoteCandidate time.Time // ICEChecking is when ICE started checking candidate pairs. ICEChecking time.Time // ICEConnected is when ICE found a working pair. @@ -349,6 +360,9 @@ func (t *Transport) Negotiate(force bool) { if t.closed { return } + if t.negotiationRequestedAt.IsZero() { + t.negotiationRequestedAt = time.Now() + } if force { stopTimer(&t.negotiateTimer) t.enqueueLocked("send offer", t.sendOffer) @@ -404,6 +418,15 @@ func (t *Transport) HandleRemoteDescriptionWithNegotiationID(sd webrtc.SessionDe // AddICECandidate adds a candidate trickled by the SFU. func (t *Transport) AddICECandidate(candidate webrtc.ICECandidateInit) { + t.mu.Lock() + first := t.firstRemoteCandidateAt.IsZero() + if first { + t.firstRemoteCandidateAt = time.Now() + } + t.mu.Unlock() + if first { + t.notifyTiming() + } t.enqueue("remote ice candidate", func() error { t.addRemoteCandidate(candidate) return nil @@ -552,6 +575,11 @@ func (t *Transport) offer(iceRestart bool) error { iceRestart = true } + t.mu.Lock() + if t.offerStartedAt.IsZero() { + t.offerStartedAt = time.Now() + } + t.mu.Unlock() offer, err := t.PC.CreateOffer(&webrtc.OfferOptions{ICERestart: iceRestart}) if err != nil { return xerr.Wrapf(err, "create offer failed") @@ -882,11 +910,28 @@ func (t *Transport) Timing() Timing { t.mu.Lock() defer t.mu.Unlock() return Timing{ - ICEChecking: t.iceStartedAt, - ICEConnected: t.iceConnectedAt, - DTLSConnected: t.dtlsConnectedAt, - Connected: t.connectedAt, + NegotiationRequested: t.negotiationRequestedAt, + OfferStarted: t.offerStartedAt, + FirstRemoteCandidate: t.firstRemoteCandidateAt, + ICEChecking: t.iceStartedAt, + ICEConnected: t.iceConnectedAt, + DTLSConnected: t.dtlsConnectedAt, + Connected: t.connectedAt, + } +} + +// SelectedPairRTT is the round-trip time ICE measured on the selected candidate pair, or +// zero before it has one. +func (t *Transport) SelectedPairRTT() time.Duration { + dtls := dtlsTransportOf(t.PC) + if dtls == nil || dtls.ICETransport() == nil { + return 0 + } + stats, ok := dtls.ICETransport().GetSelectedCandidatePairStats() + if !ok || stats.CurrentRoundTripTime <= 0 { + return 0 } + return time.Duration(stats.CurrentRoundTripTime * float64(time.Second)) } // notifyTiming hands the current timing to OnTimingChange, if one is set. diff --git a/pc/timing_test.go b/pc/timing_test.go index 2cb7114..a2a6b61 100644 --- a/pc/timing_test.go +++ b/pc/timing_test.go @@ -38,7 +38,12 @@ func TestTimingRecordsEachConnectionStepInOrder(t *testing.T) { st.waitForPCState(webrtc.PeerConnectionStateConnected, 2*time.Second) timing := st.tr.Timing() + require.False(t, timing.NegotiationRequested.IsZero()) + require.False(t, timing.OfferStarted.Before(timing.NegotiationRequested), "the offer waits for the debounce") + require.False(t, timing.FirstRemoteCandidate.IsZero(), "the remote peer trickles its candidates") require.False(t, timing.ICEChecking.IsZero()) + require.False(t, timing.ICEChecking.Before(timing.OfferStarted)) + require.Positive(t, st.tr.SelectedPairRTT(), "ICE has measured the selected pair") require.False(t, timing.ICEConnected.Before(timing.ICEChecking)) require.False(t, timing.DTLSConnected.Before(timing.ICEConnected), "DTLS runs on top of ICE") require.False(t, timing.Connected.Before(timing.DTLSConnected)) diff --git a/publisher.go b/publisher.go index 33c417f..5300f15 100644 --- a/publisher.go +++ b/publisher.go @@ -21,6 +21,7 @@ import ( sdkinterceptor "github.com/GetStream/getstream-go-webrtc/interceptor" "github.com/GetStream/getstream-go-webrtc/internal/nack" + "github.com/GetStream/getstream-go-webrtc/jointrace" "github.com/GetStream/getstream-go-webrtc/logger" "github.com/GetStream/getstream-go-webrtc/pc" "github.com/GetStream/getstream-go-webrtc/rtcstats" @@ -96,7 +97,11 @@ func newPublisher(c *Call, peerConfig pc.PeerConfig) (*publisher, error) { // discover RTX SSRC mappings via header extensions (mid, rsid) peerConfig.Registry.Add(sdkinterceptor.NewRTXProberFactory()) peerConfig.Registry.Add(sdkinterceptor.NewFirstPacketFactory(func(at time.Time) { - c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.FirstRTP, at) }) + var dtls time.Time + if pub.Transport != nil { + dtls = pub.Timing().DTLSConnected + } + c.firstRTP(true, dtls, at) }, nil)) cred := c.cred.Load() @@ -113,14 +118,12 @@ func newPublisher(c *Call, peerConfig pc.PeerConfig) (*publisher, error) { pub.Tracing.Load().Emit(rtcstats.PeerCreateEvent, peerConfig.Config) peerc, err := pc.NewPCTransport(pc.TransportParams{ - Logger: pub.logger, - PeerConfig: peerConfig, - Handler: pub, - IsOfferer: true, - Transport: sfu_models.PeerType_PEER_TYPE_PUBLISHER_UNSPECIFIED, - OnTimingChange: func(timing pc.Timing) { - c.timing.update(func(t *ConnectionTiming) { stampTransport(&t.Publisher, timing) }) - }, + Logger: pub.logger, + PeerConfig: peerConfig, + Handler: pub, + IsOfferer: true, + Transport: sfu_models.PeerType_PEER_TYPE_PUBLISHER_UNSPECIFIED, + OnTimingChange: func(timing pc.Timing) { c.peerSpans(true, timing) }, }) pub.Transport = peerc @@ -217,6 +220,7 @@ func (p *publisher) OnICECandidateSender(c *webrtc.ICECandidate, target sfu_mode if err != nil { return xerr.Wrap(err) } + start := time.Now() _, err = p.c.Client().IceTrickle(ctx, &sfu_models.ICETrickle{ PeerType: p.Params.Transport, IceCandidate: string(b), @@ -225,6 +229,11 @@ func (p *publisher) OnICECandidateSender(c *webrtc.ICECandidate, target sfu_mode if err != nil { return xerr.Wrap(err) } + p.c.trace.recorder().Extend(jointrace.Span{ + Name: jointrace.PubTrickleOut, After: []string{jointrace.PubOffer}, + Start: start, End: time.Now(), Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, + Note: "not needed by the ICE-lite SFU", + }) return nil } @@ -268,7 +277,11 @@ func (p *publisher) OnTrack(t *webrtc.TrackRemote, _ *webrtc.RTPReceiver) { } func (p *publisher) OnOffer(sd webrtc.SessionDescription, negotiationID uint32) error { - p.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.Offer, time.Now()) }) + rec := p.c.trace.recorder() + rec.Add(jointrace.Span{ + Name: jointrace.PubOffer, After: []string{jointrace.PubDebounce}, + Start: p.Timing().OfferStarted, End: time.Now(), Kind: jointrace.KindLocal, Peer: jointrace.PeerLocal, + }) ctx, cancel := context.WithTimeout(context.Background(), time.Second*3) defer cancel() @@ -284,12 +297,22 @@ func (p *publisher) OnOffer(sd webrtc.SessionDescription, negotiationID uint32) SessionId: p.c.SessionID.Load(), Tracks: tracks, } - p.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.SignalSent, time.Now()) }) - resp, err := p.c.Client().SetPublisher(ctx, req) + sent := time.Now() + p.c.trace.mu.Lock() + if p.c.trace.pubSignalSent.IsZero() { + p.c.trace.pubSignalSent = sent + } + p.c.trace.mu.Unlock() + resp, err := p.c.Client().SetPublisher(jointrace.WithStep(ctx, rec, jointrace.PubSetPublisher, jointrace.PeerSFU), req) if err != nil { return err } - p.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Publisher.SignalDone, time.Now()) }) + rec.Add(jointrace.Span{ + Name: jointrace.PubSetPublisher, After: []string{jointrace.PubOffer}, + Start: sent, End: time.Now(), Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, + }) + // A candidate may have arrived while the RPC was in flight. + p.c.peerSpans(true, p.Timing()) if sfuErr := resp.GetError(); sfuErr != nil { // Return a NegotiationError with SFU error details (code, message) return pc.NewNegotiationError("SetPublisher failed", nil, sfuErr) diff --git a/signal/client.go b/signal/client.go index 92a50ed..8831a78 100644 --- a/signal/client.go +++ b/signal/client.go @@ -2,18 +2,20 @@ package signal import ( "context" + "crypto/tls" "errors" "fmt" + "net" "net/http" "runtime/debug" "sync/atomic" "time" + "github.com/GetStream/getstream-go-webrtc/internal/wsdial" "github.com/GetStream/getstream-go-webrtc/internal/xerr" sfu_events "github.com/GetStream/protocol/protobuf/video/sfu/event" sfu_models "github.com/GetStream/protocol/protobuf/video/sfu/models" sfu_signal_rpc "github.com/GetStream/protocol/protobuf/video/sfu/signal_rpc" - "github.com/gobwas/ws" "github.com/twitchtv/twirp" "github.com/GetStream/getstream-go-webrtc/coordinator/models" @@ -49,6 +51,26 @@ type options struct { healthCheckInterval time.Duration healthCheckTimeout time.Duration readTimeout time.Duration + + dial func(ctx context.Context, network, addr string) (net.Conn, error) + tlsConfig *tls.Config + transport http.RoundTripper +} + +// WithTLSConfig sets the TLS configuration of the websocket and the RPC connections, so a +// test can trust its own certificate. +func WithTLSConfig(cfg *tls.Config) Option { + return func(o *options) { + o.tlsConfig = cfg + } +} + +// WithDialContext opens the websocket and the RPC connections through dial instead of a +// plain net.Dialer. +func WithDialContext(dial func(ctx context.Context, network, addr string) (net.Conn, error)) Option { + return func(o *options) { + o.dial = dial + } } func WithLogger(l logger.ILogger) Option { @@ -196,6 +218,15 @@ func NewClient(cred models.Credentials, handler Handler, opts ...Option) *Client if o.logger == nil { o.logger = logger.Noop{} } + o.transport = http.DefaultTransport + if o.dial != nil || o.tlsConfig != nil { + tr := http.DefaultTransport.(*http.Transport).Clone() + if o.dial != nil { + tr.DialContext = o.dial + } + tr.TLSClientConfig = o.tlsConfig + o.transport = tr + } client := &Client{ options: o, signalEventStore: event.NewStore(func(e *sfu_events.SfuEvent) any { @@ -220,7 +251,7 @@ func (c *Client) getSignalRPCClient(cred models.Credentials) sfu_signal_rpc.Sign cred.Server.URL, &http.Client{ Timeout: 5 * time.Second, - Transport: rtretry.NewRoundTripperRetryer(http.DefaultTransport), + Transport: rtretry.NewRoundTripperRetryer(c.transport), }, twirp.WithClientPathPrefix(""), twirp.WithClientInterceptors(twirpAuthInterceptor(cred.Token)), @@ -245,7 +276,7 @@ func (c *Client) DialedAt() time.Time { func (c *Client) Connect(ctx context.Context, joinRequest *sfu_events.JoinRequest) (*sfu_events.JoinResponse, error) { endpoint := c.cred.Load().Server.WsEndpoint - wsConn, _, _, err := ws.DefaultDialer.Dial(ctx, endpoint) + wsConn, err := wsdial.Dial(ctx, endpoint, c.dial, c.tlsConfig) if err != nil { return nil, err } diff --git a/subscriber.go b/subscriber.go index 7a26935..72dc38d 100644 --- a/subscriber.go +++ b/subscriber.go @@ -20,6 +20,7 @@ import ( "github.com/valyala/bytebufferpool" sdkinterceptor "github.com/GetStream/getstream-go-webrtc/interceptor" + "github.com/GetStream/getstream-go-webrtc/jointrace" "github.com/GetStream/getstream-go-webrtc/logger" "github.com/GetStream/getstream-go-webrtc/pc" "github.com/GetStream/getstream-go-webrtc/rtcstats" @@ -125,20 +126,22 @@ func newSubscriber(c *Call, s Subscriber, peerConfig pc.PeerConfig, beforeSendAn } peerConfig.Registry.Add(sdkinterceptor.NewFirstPacketFactory(nil, func(at time.Time) { - c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.FirstRTP, at) }) + var dtls time.Time + if sub.Transport != nil { + dtls = sub.Timing().DTLSConnected + } + c.firstRTP(false, dtls, at) })) sub.Tracing.Load().Emit(rtcstats.PeerCreateEvent, peerConfig.Config) peerc, err := pc.NewPCTransport(pc.TransportParams{ - Logger: sub.logger, - PeerConfig: peerConfig, - Handler: sub, - IsOfferer: false, - Transport: sfu_models.PeerType_PEER_TYPE_SUBSCRIBER, - OnTimingChange: func(timing pc.Timing) { - c.timing.update(func(t *ConnectionTiming) { stampTransport(&t.Subscriber, timing) }) - }, + Logger: sub.logger, + PeerConfig: peerConfig, + Handler: sub, + IsOfferer: false, + Transport: sfu_models.PeerType_PEER_TYPE_SUBSCRIBER, + OnTimingChange: func(timing pc.Timing) { c.peerSpans(false, timing) }, }) sub.c = c sub.Transport = peerc @@ -283,12 +286,22 @@ func (s *subscriber) OnAnswer(sd webrtc.SessionDescription, negotiationId uint32 return xerr.Wrap(err) } } - s.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.SignalSent, time.Now()) }) - answer, err := s.c.Client().SendAnswer(context.Background(), req) + rec := s.c.trace.recorder() + answer, err := s.c.Client().SendAnswer( + jointrace.WithStep(context.Background(), rec, jointrace.SubSendAnswer, jointrace.PeerSFU), req) if err != nil { return xerr.Wrap(err) } - s.c.timing.update(func(t *ConnectionTiming) { stamp(&t.Subscriber.SignalDone, time.Now()) }) + s.c.trace.mu.Lock() + offerAt := s.c.trace.subOfferAt + s.c.trace.mu.Unlock() + rec.Add(jointrace.Span{ + Name: jointrace.SubSendAnswer, After: []string{jointrace.SubOffer}, + Start: offerAt, End: time.Now(), Kind: jointrace.KindNet, Peer: jointrace.PeerSFU, + Note: "includes creating the answer", + }) + // ICE may have finished while the RPC was in flight. + s.c.peerSpans(false, s.Timing()) if err := answer.GetError(); err != nil { return errors.New(err.Message) }