012 --log events.jsonl (or O12_LOG) records: - recalc: cells evaluated, stored and volatile, full or incremental, through sheet.OnRecalc, so the engine stays free of logging - import and export (format, bytes, rows, cells), save and open - every command, and sort, filter, find, replace and fill with sizes - JEV questions (kind, queue depth, outcome) and chart images - frames: render time and key press to frame, summarized each second BenchmarkTelemetry: an arrow key through to its frame on 8192x26 costs 1.049 ms with telemetry off and 1.042 ms on (noise); an edit adds about 0.7 us for its recalc event.
- commit
- 8124ca1acbc8f41cd13327c91754e26858c12d66
- parent
- 595dd8cec9ab097f566a9b8b04887133e4e95dd2
- author
- Dami <dami.etoile@gmail.com>
| M | cmd/ | 12 | ++++- |
| A | cmd/ | 57 | ++++++++++++++++++++++++++ |
| M | internal/ | 38 | ++++++++++++++++++ |
| M | internal/ | 4 | +- |
| A | internal/ | 38 | ++++++++++++++++++ |
| M | internal/ | 7 | +++- |
| M | internal/ | 4 | +- |
| M | internal/ | 2 | +- |
| M | internal/ | 6 | +++ |
| M | internal/ | 5 | ++ |
| M | internal/ | 4 | ++ |
| M | internal/ | 6 | +++ |
| M | internal/ | 8 | +++- |
| M | internal/ | 15 | ++++++- |
| M | internal/ | 21 | ++++++++++ |
| M | internal/ | 6 | +++ |
| M | internal/ | 15 | +++++++ |
| M | internal/ | 4 | ++ |
| M | internal/ | 65 | +++++++++++++++++++++++++++++- |
@@ -24,9 +24,15 @@ func main() {
2424 }2525 2626 func run(args []string) error {27- if len(args) > 1 {28- return errors.New("usage: 012 [file]: a " + sheet.FileExt + " sheet, or a .csv, .tsv, .xlsx, .sqlite, .parquet or .wk1 file to import")27+ tc, args, err := logFlag(args)28+ if err != nil || len(args) > 1 {29+ return errors.New("usage: 012 [--log file.jsonl] [file]: a " + sheet.FileExt + " sheet, or a .csv, .tsv, .xlsx, .sqlite, .parquet or .wk1 file to import")2930 }31+ stopTelemetry, err := startTelemetry(tc)32+ if err != nil {33+ return err34+ }35+ defer stopTelemetry()3036 // JEV functions run when an API key is set, in the environment or a3137 // .env file next to the sheet or in the current directory. The cache3238 // goes in before loading so the file's JEV cells queue their questions.@@ -79,6 +85,6 @@ func run(args []string) error {
7985 if jevClient != nil {8086 m.EnableJEV(jevClient, jevCache)8187 }82- _, err := tea.NewProgram(m).Run()88+ _, err = tea.NewProgram(m).Run()8389 return err8490 }@@ -0,0 +1,57 @@
1+package main2+3+import (4+ "errors"5+ "log/slog"6+ "runtime/debug"7+ "strings"8+9+ "github.com/FelineStateMachine/012/internal/sheet"10+ "github.com/FelineStateMachine/012/internal/telemetry"11+)12+13+// logFlag takes --log path (or --log=path) out of args. Without it the14+// log file comes from O12_LOG, and telemetry stays off when neither is15+// set.16+func logFlag(args []string) (telemetry.Config, []string, error) {17+ c := telemetry.ConfigFromEnv()18+ var rest []string19+ for i := 0; i < len(args); i++ {20+ switch a := args[i]; {21+ case a == "--log":22+ if i+1 >= len(args) {23+ return c, nil, errors.New("--log needs a file")24+ }25+ c.LogPath = args[i+1]26+ i++27+ case strings.HasPrefix(a, "--log="):28+ c.LogPath = strings.TrimPrefix(a, "--log=")29+ default:30+ rest = append(rest, a)31+ }32+ }33+ return c, rest, nil34+}35+36+// startTelemetry opens the log and reports every recalculation to it.37+func startTelemetry(c telemetry.Config) (func() error, error) {38+ if info, ok := debug.ReadBuildInfo(); ok {39+ c.Version = info.Main.Version40+ for _, s := range info.Settings {41+ if s.Key == "vcs.revision" {42+ c.Version = s.Value43+ }44+ }45+ }46+ stop, err := telemetry.Setup(c)47+ if err != nil || !telemetry.Enabled() {48+ return stop, err49+ }50+ sheet.OnRecalc = func(i sheet.RecalcInfo) {51+ telemetry.Set("cells", int64(i.Cells))52+ telemetry.Event("recalc", i.Duration,53+ slog.Bool("full", i.Full), slog.Int("evaluated", i.Evaluated), slog.Int("cells", i.Cells),54+ slog.Int("volatile", i.Volatile), slog.Bool("circular", i.Circular))55+ }56+ return stop, nil57+}@@ -9,11 +9,14 @@ import (
99 "context"1010 "errors"1111 "fmt"12+ "log/slog"13+ "os"1214 "path/filepath"1315 "strings"1416 "sync/atomic"1517 1618 "github.com/FelineStateMachine/012/internal/sheet"19+ "github.com/FelineStateMachine/012/internal/telemetry"1720 )1821 1922 // Kind is an external file format.@@ -177,6 +180,19 @@ func Import(ctx context.Context, name string, opt Options) (*Result, error) {
177180 if !ok {178181 return nil, ErrUnsupported179182 }183+ span := telemetry.Start("import", slog.String("format", k.String()))184+ r, err := importKind(ctx, name, k, opt)185+ if err != nil {186+ span.Fail(err)187+ return nil, err188+ }189+ if telemetry.Enabled() {190+ span.End(slog.Int64("bytes", fileSize(name)), slog.Int("rows", r.Rows), slog.Int("cells", r.Sheet.Len()), slog.Int("notes", len(r.Notes)))191+ }192+ return r, nil193+}194+195+func importKind(ctx context.Context, name string, k Kind, opt Options) (*Result, error) {180196 var (181197 r *Result182198 err error@@ -216,6 +232,19 @@ type ExportResult struct {
216232 217233 // Export writes a snapshot of a sheet to name in format k.218234 func Export(ctx context.Context, name string, k Kind, snap *Snapshot, opt ExportOptions) (*ExportResult, error) {235+ span := telemetry.Start("export", slog.String("format", k.String()), slog.Int("cells", len(snap.Cells)))236+ res, err := exportKind(ctx, name, k, snap, opt)237+ if err != nil {238+ span.Fail(err)239+ return nil, err240+ }241+ if telemetry.Enabled() {242+ span.End(slog.Int("rows", res.Rows), slog.Int64("bytes", fileSize(name)))243+ }244+ return res, nil245+}246+247+func exportKind(ctx context.Context, name string, k Kind, snap *Snapshot, opt ExportOptions) (*ExportResult, error) {219248 switch k {220249 case CSV, TSV:221250 return exportDelimited(name, k, snap)@@ -226,3 +255,12 @@ func Export(ctx context.Context, name string, k Kind, snap *Snapshot, opt Export
226255 }227256 return nil, fmt.Errorf("can't export %s files", k)228257 }258+259+// fileSize is the size of the file name, for telemetry; -1 if unknown.260+func fileSize(name string) int64 {261+ st, err := os.Stat(name)262+ if err != nil {263+ return -1264+ }265+ return st.Size()266+}@@ -0,0 +1,38 @@
1+package sheet2+3+import "time"4+5+// RecalcInfo describes one recalculation, for telemetry. It holds counts6+// only, never contents.7+type RecalcInfo struct {8+ Full bool // every formula, as after loading9+ Evaluated int // cells marked dirty and recomputed10+ Cells int // cells stored, including formatting-only ones11+ Volatile int // volatile formulas, recomputed every time12+ Circular bool13+ Duration time.Duration14+}15+16+// OnRecalc, when set, is called after every recalculation of any sheet.17+// The engine knows nothing of logging; cmd/012 points this at telemetry.18+// It runs on the goroutine that changed the sheet and must be cheap.19+var OnRecalc func(RecalcInfo)20+21+// recalcStart is when a recalculation began, or zero when nobody is22+// watching, so an unobserved recalculation doesn't read the clock.23+func recalcStart() time.Time {24+ if OnRecalc == nil {25+ return time.Time{}26+ }27+ return time.Now()28+}29+30+func (s *Sheet) observe(full bool, start time.Time, evaluated int) {31+ if OnRecalc == nil || start.IsZero() {32+ return33+ }34+ OnRecalc(RecalcInfo{35+ Full: full, Evaluated: evaluated, Cells: len(s.cells), Volatile: len(s.volatile),36+ Circular: s.Circular, Duration: time.Since(start),37+ })38+}@@ -361,11 +361,13 @@ func (s *Sheet) unlink(a Addr) {
361361 func (s *Sheet) RecalcAll() {362362 // Every cell is dirty, so there is nothing to propagate: tracing363363 // dependents from each cell cost O(cells x range users).364+ start := recalcStart()364365 state := make(map[Addr]int, len(s.cells))365366 for a := range s.cells {366367 state[a] = dirty367368 }368369 s.evaluate(state)370+ s.observe(true, start, len(state))369371 s.ClearHistory()370372 }371373 @@ -379,7 +381,10 @@ const (
379381 // recalc recomputes the changed cells, volatile formulas, and everything380382 // that transitively depends on them.381383 func (s *Sheet) recalc(changed []Addr) {382- s.evaluate(s.affected(changed))384+ start := recalcStart()385+ state := s.affected(changed)386+ s.evaluate(state)387+ s.observe(false, start, len(state))383388 }384389 385390 // affected marks dirty the changed cells, volatile formulas, and every@@ -2,12 +2,14 @@ package ui
22 33 import (44 "cmp"5+ "log/slog"56 "slices"67 "strings"78 89 tea "charm.land/bubbletea/v2"910 1011 "github.com/FelineStateMachine/012/internal/sheet"12+ "github.com/FelineStateMachine/012/internal/telemetry"1113 )1214 1315 // command is a user-facing action. Every action is registered once here@@ -105,6 +107,10 @@ func (m *Model) runCommand(id string) tea.Cmd {
105107 if !ok {106108 panic("unknown command " + id)107109 }110+ // Sort, filter, find, fill and the rest are all commands, so this111+ // one span times every one of them.112+ span := telemetry.Start("command", slog.String("id", id))113+ defer span.End()108114 return c.run(m)109115 }110116 @@ -1,7 +1,10 @@
11 package ui22 33 import (4+ "log/slog"5+46 "github.com/FelineStateMachine/012/internal/sheet"7+ "github.com/FelineStateMachine/012/internal/telemetry"58 )69 710 // The fill handle, as in Sheets: the bottom-right corner of the selection@@ -72,7 +75,9 @@ func (m *Model) finishFill() {
7275 if dst == src {7376 return7477 }78+ span := telemetry.Start("fill", slog.Int("cells", (dst.To.Row-dst.From.Row+1)*(dst.To.Col-dst.From.Col+1)))7579 got, err := m.sheet.FillSeries(src, dst)80+ span.Fail(err)7681 if err != nil {7782 m.fail(err.Error())7883 return@@ -1,6 +1,7 @@
11 package ui22 33 import (4+ "log/slog"45 "strconv"56 "strings"67 @@ -9,6 +10,7 @@ import (
910 "github.com/sahilm/fuzzy"1011 1112 "github.com/FelineStateMachine/012/internal/sheet"13+ "github.com/FelineStateMachine/012/internal/telemetry"1214 )1315 1416 // Filters follow Sheets' Data > Create a filter: the headers of the@@ -216,7 +218,9 @@ func (p *filterPicker) apply(m *Model) {
216218 cr.Cond = sheet.Condition{}217219 }218220 m.closeOverlay()221+ span := telemetry.Start("filter")219222 m.sheet.FilterColumn(p.col, cr)223+ span.End(slog.Int("hidden", m.sheet.HiddenRows()))220224 m.changed = true221225 if n := m.sheet.HiddenRows(); n > 0 {222226 m.note = "Filtered column " + sheet.ColName(p.col) + ": " + rowCount(n) + " hidden"@@ -1,6 +1,7 @@
11 package ui22 33 import (4+ "log/slog"45 "strconv"56 "strings"67 @@ -8,6 +9,7 @@ import (
89 "github.com/charmbracelet/x/ansi"910 1011 "github.com/FelineStateMachine/012/internal/sheet"12+ "github.com/FelineStateMachine/012/internal/telemetry"1113 )1214 1315 // Find and replace is a bar on the context line rather than a dialog, in@@ -111,7 +113,9 @@ func (f *findBar) options() sheet.FindOptions {
111113 // while typing.112114 func (f *findBar) search(m *Model) {113115 f.err, f.matches, f.index, f.cur = "", nil, nil, -1116+ span := telemetry.Start("find")114117 found, err := m.sheet.Find(f.fields[0], f.options())118+ span.End(slog.Int("matches", len(found)))115119 if err != nil {116120 f.err = "Invalid regular expression"117121 return@@ -223,7 +227,9 @@ func (f *findBar) replaceOne(m *Model) {
223227 }224228 225229 func (f *findBar) replaceAll(m *Model) {230+ span := telemetry.Start("replace")226231 n, err := m.sheet.ReplaceAll(f.fields[0], f.fields[1], f.options())232+ span.End(slog.Int("replaced", n))227233 if n > 0 {228234 m.changed = true229235 }@@ -3,6 +3,7 @@ package ui
33 import (44 "fmt"55 "image/color"6+ "log/slog"67 "os"78 "strconv"89 "strings"@@ -12,6 +13,7 @@ import (
1213 "github.com/charmbracelet/x/ansi"1314 1415 "github.com/FelineStateMachine/012/internal/chart"16+ "github.com/FelineStateMachine/012/internal/telemetry"1517 )1618 1719 // terminal is what 012 knows about the terminal it runs in, learned from@@ -165,13 +167,17 @@ func (m *Model) syncImages() tea.Cmd {
165167 continue166168 }167169 m.term.sent[id] = key170+ span := telemetry.Start("chart.image", slog.String("type", c.Type.String()), slog.Int("w", w), slog.Int("h", h))168171 g := chart.Draw(c.Type, d, w, h, o)169172 img := chart.Image(c.Type, d, w, h, o, pal)170173 if img == nil || g.Plot.Empty() {174+ span.End()171175 out.WriteString(chart.Delete(id, m.term.wrap))172176 continue173177 }174- out.WriteString(chart.Transmit(id, img, g.Plot.Dx(), g.Plot.Dy(), m.term.wrap))178+ sent := chart.Transmit(id, img, g.Plot.Dx(), g.Plot.Dy(), m.term.wrap)179+ span.End(slog.Int("bytes", len(sent)))180+ out.WriteString(sent)175181 }176182 for id := range m.term.sent {177183 if !live[id] {@@ -3,12 +3,14 @@ package ui
33 import (44 "context"55 "fmt"6+ "log/slog"67 "time"78 89 tea "charm.land/bubbletea/v2"910 1011 "github.com/FelineStateMachine/012/internal/jev"1112 "github.com/FelineStateMachine/012/internal/sheet"13+ "github.com/FelineStateMachine/012/internal/telemetry"1214 )1315 1416 // JEV functions are answered in the background: the engine queues@@ -72,7 +74,9 @@ func (m *Model) sendJEV() tea.Cmd {
7274 if m.jev == nil {7375 return nil7476 }75- inFlight, _ := m.jev.cache.Busy()77+ inFlight, queued := m.jev.cache.Busy()78+ telemetry.Set("jev_in_flight", int64(inFlight))79+ telemetry.Set("jev_queued", int64(queued))7680 calls := m.jev.cache.Take(jevParallel - inFlight)7781 cmds := make([]tea.Cmd, len(calls))7882 for i, call := range calls {@@ -80,7 +84,14 @@ func (m *Model) sendJEV() tea.Cmd {
8084 cmds[i] = func() tea.Msg {8185 ctx, cancel := context.WithTimeout(context.Background(), jevTimeout)8286 defer cancel()83- return jevAnswerMsg{call: call, answer: jev.Ask(ctx, client, call)}87+ span := telemetry.Start("jev", slog.String("kind", call.Kind), slog.Int("queued", queued))88+ answer := jev.Ask(ctx, client, call)89+ outcome := "ok"90+ if answer.Failed != "" {91+ outcome = "failed"92+ }93+ span.End(slog.String("outcome", outcome))94+ return jevAnswerMsg{call: call, answer: answer}8495 }8596 }8697 return tea.Batch(cmds...)@@ -2,6 +2,7 @@ package ui
22 33 import (44 "fmt"5+ "log/slog"56 "os"67 "path/filepath"78 "slices"@@ -13,6 +14,7 @@ import (
1314 1415 "github.com/FelineStateMachine/012/internal/fileio"1516 "github.com/FelineStateMachine/012/internal/sheet"17+ "github.com/FelineStateMachine/012/internal/telemetry"1618 )1719 1820 type promptKind int@@ -268,8 +270,12 @@ type filesMsg []string
268270 // saveCmd writes the worksheet atomically: to a temporary file first, then269271 // renamed over the target.270272 func saveCmd(s *sheet.Sheet, name string) tea.Cmd {273+ span := telemetry.Start("save")271274 var buf strings.Builder272275 err := s.Write(&buf)276+ if telemetry.Enabled() {277+ span.End(slog.Int("cells", s.Len()), slog.Int("bytes", buf.Len()))278+ }273279 return func() tea.Msg {274280 if err != nil {275281 return savedMsg{name, err}@@ -289,11 +295,26 @@ func loadCmd(name string) tea.Cmd {
289295 return loadedMsg{name: name, err: err}290296 }291297 defer f.Close()298+ span := telemetry.Start("open")292299 s, err := sheet.Read(f)300+ if err != nil {301+ span.Fail(err)302+ } else if telemetry.Enabled() {303+ span.End(slog.Int("cells", s.Len()), slog.Int64("bytes", openSize(f)))304+ }293305 return loadedMsg{name, s, err}294306 }295307 }296308 309+// openSize is the size of an open file, for telemetry; -1 if unknown.310+func openSize(f *os.File) int64 {311+ st, err := f.Stat()312+ if err != nil {313+ return -1314+ }315+ return st.Size()316+}317+297318 func listFilesCmd() tea.Msg {298319 files, _ := filepath.Glob("*" + sheet.FileExt)299320 slices.Sort(files)@@ -9,6 +9,7 @@ import (
99 tea "charm.land/bubbletea/v2"1010 1111 "github.com/FelineStateMachine/012/internal/sheet"12+ "github.com/FelineStateMachine/012/internal/telemetry"1213 )1314 1415 // mode is the state shown in the mode indicator.@@ -107,6 +108,8 @@ type Model struct {
107108 term terminal // what the terminal supports, see graphics.go108109 lastChart int // the chart last selected, for chart commands; -1 for none109110 111+ keyAt time.Time // when the key the next frame answers was pressed, for telemetry112+110113 th theme111114 }112115 @@ -124,6 +127,9 @@ func (m *Model) Init() tea.Cmd {
124127 125128 // Update implements tea.Model.126129 func (m *Model) Update(msg tea.Msg) (tea.Model, tea.Cmd) {130+ if _, key := msg.(tea.KeyPressMsg); key && m.keyAt.IsZero() && telemetry.Enabled() {131+ m.keyAt = time.Now()132+ }127133 if cmd, ok := m.importing(msg); ok {128134 return m, cmd129135 }@@ -6,11 +6,13 @@ import (
66 "slices"77 "strconv"88 "strings"9+ "time"910 1011 tea "charm.land/bubbletea/v2"1112 "github.com/charmbracelet/x/ansi"1213 1314 "github.com/FelineStateMachine/012/internal/sheet"15+ "github.com/FelineStateMachine/012/internal/telemetry"1416 )1517 1618 // The control panel is three lines: the menu bar with the mode indicator,@@ -19,6 +21,9 @@ import (
1921 2022 // View implements tea.Model.2123 func (m *Model) View() tea.View {24+ if telemetry.Enabled() {25+ defer m.timeFrame(time.Now())26+ }2227 lines := []string{m.menuBarLine(), m.formulaBar(), m.contextLineText(), m.headerRow()}2328 rows := m.screenRows()2429 for i := range m.visibleRows() {@@ -59,6 +64,16 @@ func (m *Model) View() tea.View {
5964 return v6065 }6166 67+// timeFrame reports a frame begun at start to telemetry, with how long68+// ago the key press it answers came in.69+func (m *Model) timeFrame(start time.Time) {70+ var key time.Duration71+ if !m.keyAt.IsZero() {72+ key, m.keyAt = time.Since(m.keyAt), time.Time{}73+ }74+ telemetry.Frame(time.Since(start), key)75+}76+6277 func (m *Model) displayName() string {6378 if m.filename == "" && m.xfer.source != "" {6479 return filepath.Base(m.xfer.source)@@ -1,12 +1,14 @@
11 package ui22 33 import (4+ "log/slog"45 "strings"56 67 tea "charm.land/bubbletea/v2"78 "github.com/charmbracelet/x/ansi"89 910 "github.com/FelineStateMachine/012/internal/sheet"11+ "github.com/FelineStateMachine/012/internal/telemetry"1012 )1113 1214 // Sorting follows Sheets' Data menu: sort the sheet or a range by the@@ -60,7 +62,9 @@ func (m *Model) sort(r sheet.Rect, keys []sheet.SortKey) tea.Cmd {
6062 m.note = "Nothing to sort"6163 return nil6264 }65+ span := telemetry.Start("sort", slog.Int("rows", r.To.Row-r.From.Row+1), slog.Int("cols", r.To.Col-r.From.Col+1), slog.Int("keys", len(keys)))6366 m.sheet.SortRange(r, keys)67+ span.End()6468 m.changed = true6569 var by []string6670 for _, k := range keys {@@ -11,6 +11,8 @@ import (
1111 "context"1212 "fmt"1313 "io"14+ "log/slog"15+ "path/filepath"1416 "testing"1517 "time"1618 @@ -18,9 +20,10 @@ import (
1820 typesafe "github.com/FelineStateMachine/typesafe-go"1921 uv "github.com/charmbracelet/ultraviolet"2022 21- "012/internal/jev"22- "012/internal/sheet"23- "012/internal/stress"23+ "github.com/FelineStateMachine/012/internal/jev"24+ "github.com/FelineStateMachine/012/internal/sheet"25+ "github.com/FelineStateMachine/012/internal/stress"26+ "github.com/FelineStateMachine/012/internal/telemetry"2427 )2528 2629 var termSizes = []struct{ w, h int }{{80, 24}, {200, 60}, {400, 120}}@@ -179,6 +182,62 @@ func BenchmarkKeystroke(b *testing.B) {
179182 }180183 }181184 185+// BenchmarkTelemetry is an arrow key through to its frame and an edit186+// that recalculates, with telemetry off and on (a JSON log in a temp187+// file): what the instrumentation costs.188+func BenchmarkTelemetry(b *testing.B) {189+ s := lazy(func() *sheet.Sheet { return stress.Dense(sheet.MaxRows, 26) })190+ for _, on := range []bool{false, true} {191+ name := "off"192+ if on {193+ name = "on"194+ }195+ b.Run("arrow/"+name, func(b *testing.B) {196+ stop := telemetryFor(b, on)197+ defer stop()198+ m := sized(s(), 200, 60)199+ t := newFakeTerm(200, 60)200+ keys := []string{"down", "up"}201+ i := 0202+ for b.Loop() {203+ m.Update(key(keys[i%2]))204+ t.frame(m)205+ i++206+ }207+ })208+ b.Run("edit/"+name, func(b *testing.B) {209+ stop := telemetryFor(b, on)210+ defer stop()211+ m := sized(s(), 200, 60)212+ keys := []string{"7", "enter", "up"}213+ i := 0214+ for b.Loop() {215+ m.Update(key(keys[i%3]))216+ i++217+ }218+ })219+ }220+}221+222+// telemetryFor turns telemetry on, logging to a temp file, when on is223+// set, the way cmd/012 does.224+func telemetryFor(b *testing.B, on bool) func() error {225+ if !on {226+ return func() error { return nil }227+ }228+ stop, err := telemetry.Setup(telemetry.Config{LogPath: filepath.Join(b.TempDir(), "log.jsonl")})229+ if err != nil {230+ b.Fatal(err)231+ }232+ sheet.OnRecalc = func(i sheet.RecalcInfo) {233+ telemetry.Event("recalc", i.Duration, slog.Int("evaluated", i.Evaluated), slog.Int("cells", i.Cells))234+ }235+ return func() error {236+ sheet.OnRecalc = nil237+ return stop()238+ }239+}240+182241 // fakeJEV answers every question at once, never touching the network.183242 type stressJEV struct{}184243