package client import ( "fmt" "log" "sort" "strings" "sync" "sync/atomic" "time" ) // Performance diagnostics. // // The question an operator actually has is "why is this tunnel slow?", and // nothing here could answer it before. A stream that is not moving bytes is // blocked on exactly one of three things: // // - the flow-control window — the peer is not draining to its terminal // socket, so the bottleneck is past the tunnel (a struggling game server, a // player on a bad link); // - the shaper — the configured bandwidth cap is the binding constraint, and // raising it is the fix; // - the peer socket itself — bytes move, but slowly, which points at the path // rather than at either end. // // Those three are indistinguishable from throughput alone and call for // completely different responses, so they are counted apart. // // Cost. Both structs are nil unless statsIntervalMs is set, so the default is a // single predictable branch per event and no allocation at all. When enabled, // counters sit under locks the code already holds; only the frame counters use // atomics, because the read loop must never queue behind a send. A clock is read // only when a goroutine is about to block, never per chunk — if nothing stalls, // nothing is timed. // streamStats accumulates one stream's lifetime. Guarded by Stream.mu. type streamStats struct { opened time.Time bytesUp int64 // destination -> hub bytesDown int64 // hub -> destination windowStall time.Duration // blocked with no send credit shaperStall time.Duration // blocked on the bandwidth cap qPeak int // high-water mark of the receive queue resumes int hung time.Duration // total time parked awaiting a reattach replayBytes int64 } // connStats accumulates one worker conn's lifetime. type connStats struct { opened time.Time framesIn atomic.Int64 framesOut atomic.Int64 writeErrs atomic.Int64 // Round-trip time of the worker heartbeat. The probe already carries a // timestamp that the peer echoes and both sides currently throw away, so // this measures tunnel latency for no added cost. mu sync.Mutex rttLast time.Duration rttMin time.Duration rttMax time.Duration rttSum time.Duration rttN int64 } func (cs *connStats) observeRTT(d time.Duration) { if cs == nil || d < 0 { return // a nonce we cannot read as one of our own timestamps } cs.mu.Lock() defer cs.mu.Unlock() cs.rttLast = d if cs.rttN == 0 || d < cs.rttMin { cs.rttMin = d } if d > cs.rttMax { cs.rttMax = d } cs.rttSum += d cs.rttN++ } func (cs *connStats) rtt() (last, min, avg, max time.Duration) { cs.mu.Lock() defer cs.mu.Unlock() if cs.rttN == 0 { return 0, 0, 0, 0 } return cs.rttLast, cs.rttMin, cs.rttSum / time.Duration(cs.rttN), cs.rttMax } // stallClock times a block without charging the path that does not block: the // clock is read only once a wait is actually about to happen. type stallClock struct{ start time.Time } func (t *stallClock) begin(on bool) { if on && t.start.IsZero() { t.start = time.Now() } } func (t *stallClock) elapsed() time.Duration { if t.start.IsZero() { return 0 } return time.Since(t.start) } // statsLoop prints one aggregate line per interval. Never started when // statsIntervalMs is 0, which is the default. func (c *Client) statsLoop(stop <-chan struct{}) { ticker := time.NewTicker(time.Duration(c.cfg.StatsIntervalMs) * time.Millisecond) defer ticker.Stop() for { select { case <-stop: return case <-ticker.C: log.Print(c.StatsLine()) } } } // StatsLine renders the current pool and per-conn state as one greppable line. // Exported so tests and embedders can sample it without waiting for the ticker. func (c *Client) StatsLine() string { conns := c.pool.snapshot() var b strings.Builder fmt.Fprintf(&b, "stats conns=%d", len(conns)) live, parked := 0, 0 for _, wc := range conns { st := wc.getStream() bound := 0 if st != nil { bound = 1 live++ st.mu.Lock() if st.parked { parked++ } st.mu.Unlock() } fmt.Fprintf(&b, " | conn%d bound=%d", wc.id, bound) if cs := wc.stats; cs != nil { _, mn, avg, mx := cs.rtt() fmt.Fprintf(&b, " frames=%d/%d rtt=%s/%s/%s", cs.framesIn.Load(), cs.framesOut.Load(), round(mn), round(avg), round(mx)) if n := cs.writeErrs.Load(); n > 0 { fmt.Fprintf(&b, " writeErrs=%d", n) } } } fmt.Fprintf(&b, " | tunnels=%d parked=%d", live, parked) return b.String() } // logSummary reports a stream's lifetime as it closes. This is the artifact that // answers a specific complaint after the fact, once the periodic line has // scrolled away. func (s *Stream) logSummary() { s.mu.Lock() st := s.stats if st == nil { s.mu.Unlock() return } line := fmt.Sprintf("stream closed after %s: up=%s down=%s stalled(window=%s shaper=%s) qPeak=%s", round(time.Since(st.opened)), bytesHuman(st.bytesUp), bytesHuman(st.bytesDown), round(st.windowStall), round(st.shaperStall), bytesHuman(int64(st.qPeak))) if st.resumes > 0 { line += fmt.Sprintf(" resumes=%d hung=%s replayed=%s", st.resumes, round(st.hung), bytesHuman(st.replayBytes)) } s.mu.Unlock() log.Print(line) } func (p *WorkerPool) snapshot() []*WorkerConn { p.mu.Lock() conns := make([]*WorkerConn, 0, len(p.conns)) for wc := range p.conns { conns = append(conns, wc) } p.mu.Unlock() sort.Slice(conns, func(i, j int) bool { return conns[i].id < conns[j].id }) return conns } // round trims a duration to something readable in a log line. func round(d time.Duration) time.Duration { switch { case d <= 0: return 0 case d < time.Millisecond: return d.Round(time.Microsecond) case d < time.Second: return d.Round(time.Millisecond) default: return d.Round(10 * time.Millisecond) } } func bytesHuman(n int64) string { const unit = 1024 if n < unit { return fmt.Sprintf("%dB", n) } div, exp := int64(unit), 0 for v := n / unit; v >= unit; v /= unit { div *= unit exp++ } return fmt.Sprintf("%.1f%ciB", float64(n)/float64(div), "KMGT"[exp]) }