redapricot/client/stats.go

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])
}