1package telemetry23import (4 "log/slog"5 "maps"6 "runtime/metrics"7 "slices"8 "sync"9 "time"10)1112// Frames come 60 a second, too many to log one by one at Info, so they13// are summarized once a second with the gauges: a "frames" event with14// counts, percentiles and the live heap.1516// window is how often the summary is written.17const window = time.Second1819// maxSamples bounds the durations kept per window.20const maxSamples = 40962122type frameStats struct {23 mu sync.Mutex24 since time.Time25 render []time.Duration // View and everything the frame took26 keys []time.Duration // from a key press to its frame27 gauges map[string]int6428}2930var frames = frameStats{gauges: map[string]int64{}}3132func (f *frameStats) reset(now time.Time) {33 f.mu.Lock()34 defer f.mu.Unlock()35 f.since, f.render, f.keys = now, f.render[:0], f.keys[:0]36}3738// Frame records a frame that took render to draw. key is how long ago39// the key press it answers happened, or 0 when it answers none.40func Frame(render, key time.Duration) {41 if !on.Load() {42 return43 }44 now := time.Now()45 f := &frames46 f.mu.Lock()47 if len(f.render) < maxSamples {48 f.render = append(f.render, render)49 }50 if key > 0 && len(f.keys) < maxSamples {51 f.keys = append(f.keys, key)52 }53 due := now.Sub(f.since) >= window54 var rs, ks []time.Duration55 var gauges map[string]int6456 since := f.since57 if due {58 rs, ks, gauges = slices.Clone(f.render), slices.Clone(f.keys), maps.Clone(f.gauges)59 f.since, f.render, f.keys = now, f.render[:0], f.keys[:0]60 }61 f.mu.Unlock()62 if due {63 summarize(since, now, rs, ks, gauges)64 }65 Debug("frame", render, slog.Float64("key_ms", ms(key)))66}6768// Set records a gauge, such as the number of cells or JEV questions69// waiting, reported with the next frame summary.70func Set(name string, v int64) {71 if !on.Load() {72 return73 }74 frames.mu.Lock()75 frames.gauges[name] = v76 frames.mu.Unlock()77}7879// summarize logs the frames drawn from since to now, and hands them to80// OTLP as metrics when it is on.81func summarize(since, now time.Time, render, keys []time.Duration, gauges map[string]int64) {82 r, k, heap := statsOf(render), statsOf(keys), heapBytes()83 attrs := []slog.Attr{84 slog.Int("frames", r.count),85 slog.Float64("render_p50_ms", r.p50),86 slog.Float64("render_p95_ms", r.p95),87 slog.Float64("render_max_ms", r.pmax),88 slog.Int("keys", k.count),89 slog.Float64("key_p50_ms", k.p50),90 slog.Float64("key_p95_ms", k.p95),91 slog.Float64("key_max_ms", k.pmax),92 slog.Int64("heap_bytes", heap),93 }94 for _, k := range slices.Sorted(maps.Keys(gauges)) {95 attrs = append(attrs, slog.Int64(k, gauges[k]))96 }97 emit(slog.LevelInfo, "frames", window, attrs, spanIDs{})98 if _, e := current(); e != nil && e.urls.metrics != "" {99 e.window(frameWindow{start: since, end: now, render: r, key: k, heap: heap, gauges: gauges})100 }101}102103func statsOf(ds []time.Duration) stats {104 s := stats{count: len(ds), p50: ms(percentile(ds, 50)), p95: ms(percentile(ds, 95)), pmax: ms(percentile(ds, 100))}105 for _, d := range ds {106 s.sum += ms(d)107 }108 return s109}110111// percentile is the p-th percentile of ds (nearest rank), 0 when empty.112func percentile(ds []time.Duration, p int) time.Duration {113 if len(ds) == 0 {114 return 0115 }116 slices.Sort(ds)117 i := (len(ds)*p + 99) / 100118 return ds[max(i-1, 0)]119}120121// heapBytes is the heap held by live and not yet swept objects, read122// without stopping the world as runtime.ReadMemStats would.123func heapBytes() int64 {124 s := []metrics.Sample{{Name: "/memory/classes/heap/objects:bytes"}}125 metrics.Read(s)126 if s[0].Value.Kind() != metrics.KindUint64 {127 return 0128 }129 return int64(s[0].Value.Uint64())130}