impl connection recovery
This commit is contained in:
iceBear67
+223
@@ -0,0 +1,223 @@
|
||||
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 mux 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 — and it is the best signal
|
||||
// available for head-of-line blocking, where one stream's backlog delays
|
||||
// every other stream sharing the connection.
|
||||
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 {
|
||||
wc.mu.Lock()
|
||||
streams := make([]*Stream, 0, len(wc.streams))
|
||||
for _, s := range wc.streams {
|
||||
streams = append(streams, s)
|
||||
}
|
||||
wc.mu.Unlock()
|
||||
live += len(streams)
|
||||
for _, s := range streams {
|
||||
s.mu.Lock()
|
||||
if s.parked {
|
||||
parked++
|
||||
}
|
||||
s.mu.Unlock()
|
||||
}
|
||||
|
||||
fmt.Fprintf(&b, " | conn%d streams=%d", wc.id, len(streams))
|
||||
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, " | streams=%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 := append([]*WorkerConn(nil), p.conns...)
|
||||
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])
|
||||
}
|
||||
Reference in New Issue
Block a user