feature: flightrecorder to enable Go trace

Signed-off-by: Sandor Szücs <sandor.szuecs@zalando.de>

go.mod

@@ -164,7 +164,7 @@ require (
  go.opentelemetry.io/proto/otlp v1.0.0 // indirect
  go.uber.org/atomic v1.9.0 // indirect
  go.uber.org/automaxprocs v1.5.3 // indirect
- golang.org/x/exp v0.0.0-20230905200255-921286631fa9 // indirect
+ golang.org/x/exp v0.0.0-20240314144324-c7f7c6466f7f // indirect
  golang.org/x/mod v0.16.0 // indirect
  golang.org/x/sys v0.18.0 // indirect
  golang.org/x/text v0.14.0 // indirect

go.sum

@@ -488,6 +488,8 @@ golang.org/x/exp v0.0.0-20190306152737-a1d7652674e8/go.mod h1:CJ0aWSM057203Lf6IL
 golang.org/x/exp v0.0.0-20191030013958-a1ab85dbe136/go.mod h1:JXzH8nQsPlswgeRAPE3MuO9GYsAcnJvJ4vnMwN/5qkY=
 golang.org/x/exp v0.0.0-20230905200255-921286631fa9 h1:GoHiUyI/Tp2nVkLI2mCxVkOjsbSXD66ic0XW0js0R9g=
 golang.org/x/exp v0.0.0-20230905200255-921286631fa9/go.mod h1:S2oDrQGGwySpoQPVqRShND87VCbxmc6bL1Yd2oYrm6k=
+golang.org/x/exp v0.0.0-20240314144324-c7f7c6466f7f h1:3CW0unweImhOzd5FmYuRsD4Y4oQFKZIjAnKbjV4WIrw=
+golang.org/x/exp v0.0.0-20240314144324-c7f7c6466f7f/go.mod h1:CxmFvTBINI24O/j8iY7H1xHzx2i4OsyguNBmN/uPtqc=
 golang.org/x/image v0.0.0-20180708004352-c73c2afc3b81/go.mod h1:ux5Hcp/YLpHSI86hEcLt0YII63i6oz57MZXIpbrjZUs=
 golang.org/x/image v0.0.0-20190227222117-0694c2d4d067/go.mod h1:kZ7UVZpmo3dzQBMxlp+ypCbDeSB+sBbTgSJuh5dn5js=
 golang.org/x/image v0.0.0-20190802002840-cff245a6509b/go.mod h1:FeLwcggjj3mMvU+oOTbSwawSJRM1uh48EjtB4UJZlP0=

proxy/proxy.go

@@ -18,9 +18,11 @@ import (
  "runtime"
  "strconv"
  "strings"
+ "sync"
  "time"
  "unicode/utf8"
 
+ "golang.org/x/exp/trace"
  "golang.org/x/time/rate"
 
  ot "github.com/opentracing/opentracing-go"
@@ -410,6 +412,9 @@ type Proxy struct {
  clientTLS *tls.Config
  hostname string
  onPanicSometimes rate.Sometimes
+ flightRecorder *trace.FlightRecorder
+ traceOnce sync.Once
+ tooLong time.Duration
 }
 
 // proxyError is used to wrap errors during proxying and to indicate
@@ -796,6 +801,15 @@ func WithParams(p Params) *Proxy {
  endpointRegistry: p.EndpointRegistry,
  }
  }
+ // TODO(sszuecs): expose an option to start it
+ fr := trace.NewFlightRecorder()
+ //fr.SetPeriod(d)
+ //fr.SetSize(bytes int)
+ err := fr.Start()
+ if err != nil {
+ println("Failed to start FlightRecorder:", err.Error())
+ }
+
  return &Proxy{
  routing: p.Routing,
  registry: p.EndpointRegistry,
@@ -824,6 +838,32 @@ func WithParams(p Params) *Proxy {
  clientTLS: tr.TLSClientConfig,
  hostname: hostname,
  onPanicSometimes: rate.Sometimes{First: 3, Interval: 1 * time.Minute},
+ flightRecorder: fr,
+ traceOnce: sync.Once{},
+ tooLong: 250 * time.Millisecond,
+ }
+}
+
+func (p *Proxy) writeTraceIfTooSlow(ctx *context) {
+ p.log.Infof("write trace if too slow: %s > %s", time.Since(ctx.startServe), p.tooLong)
+ if time.Since(ctx.startServe) > p.tooLong {
+ p.log.Info("too slow")
+ // Do it only once for simplicitly, but you can take more than one.
+ p.traceOnce.Do(func() {
+ p.log.Info("write trace because we were too slow")
+ // Grab the snapshot.
+ var b bytes.Buffer
+ _, err := p.flightRecorder.WriteTo(&b)
+ if err != nil {
+ p.log.Errorf("Failed to write flightrecorder data: %v", err)
+ return
+ }
+ // Write it to a file.
+ if err := os.WriteFile("trace.out", b.Bytes(), 0o755); err != nil {
+ p.log.Errorf("Failed to write trace.out: %v", err)
+ return
+ }
+ })
  }
 }
 
@@ -969,6 +1009,8 @@ func (p *Proxy) makeBackendRequest(ctx *context, requestContext stdlibcontext.Co
  ctx.proxySpan.LogKV("http_roundtrip", StartEvent)
  req = injectClientTrace(req, ctx.proxySpan)
 
+ p.writeTraceIfTooSlow(ctx)
+
  response, err := roundTripper.RoundTrip(req)
  if endpointMetrics != nil {
  endpointMetrics.IncRequests(routing.IncRequestsOptions{FailedRoundTrip: err != nil})
@@ -1586,6 +1628,7 @@ func (p *Proxy) ServeHTTP(w http.ResponseWriter, r *http.Request) {
 func (p *Proxy) Close() error {
  close(p.quit)
  p.registry.Close()
+ p.flightRecorder.Stop()
  return nil
 }