Each Model keeps a Trace, given to its workbook: a command's span holds the recalculation, pivot refreshes, sort or fill it causes. A macro run is entered while its calls are served, so its commands and their recalculations nest in it. Background work takes an explicit Parent: questions to JEV, opening a file, imports and exports (through the context they already take; an import's builder recalculates under the import's span). 012 serve starts a span per session that holds its program's commands, per Model, so sessions never share a trace.
- commit
- 8a7c5a48163e0b1920242a70a008062497ec28d3
- parent
- 503499f2cb9d14df6a39999f23a8d4e0af6b4554
- author
- Dami <dami.etoile@gmail.com>
@@ -1,12 +1,14 @@
11 package fileio22 33 import (4+ "context"45 "fmt"56 "math"67 "strconv"78 "strings"89 910 "github.com/FelineStateMachine/012/internal/sheet"11+ "github.com/FelineStateMachine/012/internal/telemetry"1012 )1113 1214 // builder fills a new workbook for an importer, one sheet at a time (s@@ -34,12 +36,15 @@ type builder struct {
3436 3537 // newBuilder starts a workbook keeping at most maxCells cells; 0 means3638 // the max-cells setting, and a negative number no budget (the format's37-// own limits apply).38-func newBuilder(maxCells int) *builder {39+// own limits apply). The workbook's recalculation nests in the span ctx40+// carries: the import's.41+func newBuilder(ctx context.Context, maxCells int) *builder {3942 if maxCells == 0 {4043 maxCells = sheet.MaxCells()4144 }42- return &builder{s: sheet.New(), maxCells: maxCells}45+ s := sheet.New()46+ s.Book().SetTrace(telemetry.NewTrace(telemetry.ParentFrom(ctx)))47+ return &builder{s: s, maxCells: maxCells}4348 }4449 4550 // fits reports whether a is inside the worksheet and the budget,@@ -197,7 +197,7 @@ func readDelimited(ctx context.Context, in io.Reader, k Kind, maxCells int, prog
197197 cr.FieldsPerRecord = -1198198 cr.ReuseRecord = true199199 200- b := newBuilder(maxCells)200+ b := newBuilder(ctx, maxCells)201201 row := 0202202 for ; ; row++ {203203 // Report before reading on: a pipe may keep the next read waiting.@@ -108,8 +108,9 @@ func Import(ctx context.Context, name string, opt Options) (*Result, error) {
108108 if !ok {109109 return nil, ErrUnsupported110110 }111- span := telemetry.Start("import", slog.String("format", k.String()))112- r, err := importKind(ctx, name, k, opt)111+ span := telemetry.ParentFrom(ctx).Start("import", slog.String("format", k.String()))112+ // The builder's workbook recalculates under the span (see newBuilder).113+ r, err := importKind(telemetry.WithParent(ctx, span.Parent()), name, k, opt)113114 if err != nil {114115 span.Fail(err)115116 return nil, err@@ -155,7 +156,7 @@ type ExportResult struct {
155156 156157 // Export writes a snapshot of a sheet to name in format k.157158 func Export(ctx context.Context, name string, k Kind, snap *Snapshot, opt ExportOptions) (*ExportResult, error) {158- span := telemetry.Start("export", slog.String("format", k.String()), slog.Int("cells", len(snap.Cells)))159+ span := telemetry.ParentFrom(ctx).Start("export", slog.String("format", k.String()), slog.Int("cells", len(snap.Cells)))159160 res, err := exportKind(ctx, name, k, snap, opt)160161 if err != nil {161162 span.Fail(err)@@ -42,7 +42,7 @@ func importParquet(ctx context.Context, name string, opt Options) (*Result, erro
4242 if err != nil {4343 return nil, err4444 }45- b := newBuilder(opt.MaxCells)45+ b := newBuilder(ctx, opt.MaxCells)4646 r := &parquetReader{4747 b: b, cols: parquetHeader(b, pf.Schema()), prog: prog,4848 row: 1, total: pf.NumRows(), buf: make([]parquet.Row, 256),@@ -121,7 +121,7 @@ func importSQLite(ctx context.Context, name string, opt Options) (*Result, error
121121 return nil, sqliteErr(err)122122 }123123 124- b := newBuilder(opt.MaxCells)124+ b := newBuilder(ctx, opt.MaxCells)125125 header := sheet.Style{Bold: true}126126 for c, name := range cols {127127 b.text(sheet.Addr{Col: c}, name, sheet.Format{}, header)@@ -82,7 +82,7 @@ type wk1Reader struct {
8282 // readWK1 reads a worksheet record by record. progress gets the number8383 // of cells read so far.8484 func readWK1(ctx context.Context, r io.Reader, progress func(cells int)) (*sheet.Sheet, []string, int, error) {85- w := &wk1Reader{b: newBuilder(-1), version: wk1File} // the format's own 8192 x 25685+ w := &wk1Reader{b: newBuilder(ctx, -1), version: wk1File} // the format's own 8192 x 2568686 cells := 08787 for i := 0; ; i++ {8888 op, data, err := w.next(r, i)@@ -42,7 +42,7 @@ func importXLSXExcelize(ctx context.Context, name string, opt Options) (*Result,
4242 total += dims[i]4343 }4444 45- b := newBuilder(opt.MaxCells)45+ b := newBuilder(ctx, opt.MaxCells)4646 book := b.s.Book()4747 styles := map[int]xlsxStyle{}4848 var notes []string@@ -43,7 +43,7 @@ func (bk *xlsxBook) importBook(ctx context.Context, opt Options) (*Result, error
4343 for i := range bk.sheets {4444 total += bk.dimension(i)4545 }46- b := newBuilder(opt.MaxCells)46+ b := newBuilder(ctx, opt.MaxCells)4747 book := b.s.Book()4848 done := 04949 var err error@@ -193,7 +193,10 @@ func (s *Server) session(sess ssh.Session) {
193193 <-s.slots194194 }()195195 196- idle := s.run(sess, pty, winch)196+ // The session's span holds what its program does, in one trace.197+ span := telemetry.Start("serve.session", slog.String("term", pty.Term))198+ idle := s.run(sess, pty, winch, span.Parent())199+ span.End(slog.Bool("idle", idle))197200 d := time.Since(start)198201 s.event("ssh.session_end", append(who, slog.Duration("duration", d), slog.Bool("idle", idle))...)199202 if idle {@@ -204,8 +207,9 @@ func (s *Server) session(sess ssh.Session) {
204207 205208 // run runs the program until it quits, the client goes away or the206209 // session goes idle, which it reports.207-func (s *Server) run(sess ssh.Session, pty ssh.Pty, winch <-chan ssh.Window) (idle bool) {210+func (s *Server) run(sess ssh.Session, pty ssh.Pty, winch <-chan ssh.Window, parent telemetry.Parent) (idle bool) {208211 m := ui.New(sheet.New(), "")212+ m.TraceUnder(parent)209213 env := append(sess.Environ(), "TERM="+pty.Term)210214 m.Serve(s.root, env)211215 if s.jev != nil {@@ -0,0 +1,81 @@
1+package serve2+3+import (4+ "encoding/json"5+ "io"6+ "os"7+ "path/filepath"8+ "strings"9+ "testing"10+11+ "github.com/FelineStateMachine/012/internal/telemetry"12+)13+14+// Each session's commands nest under its own span, in a trace of its15+// own, though the sessions run in one process at once.16+func TestSessionSpans(t *testing.T) {17+ path := filepath.Join(t.TempDir(), "log.jsonl")18+ stop, err := telemetry.Setup(telemetry.Config{LogPath: path})19+ if err != nil {20+ t.Fatal(err)21+ }22+ defer stop()23+ key := newKey(t)24+ srv, addr, _ := testServer(t, nil, key)25+ c, err := dial(addr, key, srv.HostKey())26+ if err != nil {27+ t.Fatal(err)28+ }29+ defer c.Close()30+ a, b := openTerm(t, c, 80, 24), openTerm(t, c, 80, 24)31+ a.waitFor(t, "READY")32+ b.waitFor(t, "READY")33+ for range 3 {34+ io.WriteString(a.stdin, "\x02") // Ctrl+B: format.bold35+ io.WriteString(b.stdin, "\x02")36+ }37+ for _, tm := range []*term{a, b} {38+ io.WriteString(tm.stdin, "\x11") // Ctrl+Q, then discard the bold39+ tm.waitFor(t, "unsaved changes")40+ io.WriteString(tm.stdin, "d")41+ tm.waitClosed(t)42+ }43+ srv.Close()44+ stop()45+46+ data, err := os.ReadFile(path)47+ if err != nil {48+ t.Fatal(err)49+ }50+ sessions := map[string]string{} // span id -> trace id51+ var commands []map[string]any52+ for _, l := range strings.Split(strings.TrimSpace(string(data)), "\n") {53+ var ev map[string]any54+ if err := json.Unmarshal([]byte(l), &ev); err != nil {55+ t.Fatal(err)56+ }57+ switch ev["event"] {58+ case "serve.session":59+ sessions[ev["span_id"].(string)] = ev["trace_id"].(string)60+ case "command":61+ commands = append(commands, ev)62+ }63+ }64+ if len(sessions) != 2 {65+ t.Fatalf("%d session spans: %s", len(sessions), data)66+ }67+ per := map[string]int{}68+ for _, cmd := range commands {69+ parent, _ := cmd["parent_id"].(string)70+ trace, ok := sessions[parent]71+ if !ok || cmd["trace_id"] != trace {72+ t.Errorf("command %v is not under a session", cmd)73+ }74+ per[parent]++75+ }76+ for id := range sessions {77+ if per[id] == 0 {78+ t.Errorf("session %s ran no commands: %v", id, per)79+ }80+ }81+}@@ -190,7 +190,7 @@ func TestChartImages(t *testing.T) {
190190 // No kitty reply: text, and nothing sent.191191 m.runCommand("insert.chart")192192 press(t, m, "<enter>", "<esc>")193- if cmd := m.term.syncImages(m.sheet, m.displayCharts, &m.th); cmd != nil {193+ if cmd := m.term.syncImages(m.sheet, m.displayCharts, &m.th, m.spans); cmd != nil {194194 t.Error("images sent without kitty graphics")195195 }196196 // The terminal answers the query: images, and placeholders in the view.@@ -213,7 +213,7 @@ func TestChartImages(t *testing.T) {
213213 _, cmd = m.Update(nil)214214 raw = nil215215 m.term.sent[firstImageID] = "stale"216- collect(m.term.syncImages(m.sheet, m.displayCharts, &m.th))216+ collect(m.term.syncImages(m.sheet, m.displayCharts, &m.th, m.spans))217217 if len(raw) != 1 {218218 t.Errorf("changed chart not sent")219219 }@@ -226,7 +226,7 @@ func TestChartImages(t *testing.T) {
226226 // Deleting the chart frees its image.227227 raw = nil228228 m.sheet.DeleteChart(0)229- collect(m.term.syncImages(m.sheet, m.displayCharts, &m.th))229+ collect(m.term.syncImages(m.sheet, m.displayCharts, &m.th, m.spans))230230 if len(raw) != 1 || !strings.Contains(raw[0], "a=d,d=I,i=16") {231231 t.Errorf("image not freed: %q", raw)232232 }@@ -9,7 +9,6 @@ import (
99 tea "charm.land/bubbletea/v2"1010 1111 "github.com/FelineStateMachine/012/internal/sheet"12- "github.com/FelineStateMachine/012/internal/telemetry"1312 "github.com/FelineStateMachine/012/internal/ui/theme"1413 )1514 @@ -165,8 +164,9 @@ func (m *Model) runCommand(id string) tea.Cmd {
165164 panic("unknown command " + id)166165 }167166 // Sort, filter, find, fill and the rest are all commands, so this168- // one span times every one of them.169- span := telemetry.Start("command", slog.String("id", id))167+ // one span times every one of them, and holds what they cause: the168+ // recalculation, a pivot refresh, a sort.169+ span := m.spans.Start("command", slog.String("id", id))170170 defer span.End()171171 if c.edits != nil && m.refusePivot(c.edits(m)) {172172 return nil@@ -11,6 +11,7 @@ import (
1111 1212 "github.com/FelineStateMachine/012/internal/fileio"1313 "github.com/FelineStateMachine/012/internal/sheet"14+ "github.com/FelineStateMachine/012/internal/telemetry"1415 )1516 1617 // File > Download: the workbook, or for formats with tables the selection,@@ -161,8 +162,9 @@ func (m *Model) download(name, path string, k fileio.Kind, r sheet.Rect, table s
161162 if k.HoldsSheets() && r == (sheet.Rect{}) {162163 snap = fileio.SnapBook(m.sheet) // every sheet, as Sheets' .xlsx download163164 }165+ ctx := telemetry.WithParent(context.Background(), m.spans.Parent())164166 return func() tea.Msg {165- res, err := fileio.Export(context.Background(), path, k, snap, fileio.ExportOptions{Table: table})167+ res, err := fileio.Export(ctx, path, k, snap, fileio.ExportOptions{Table: table})166168 return exportedMsg{name: name, kind: k, res: res, err: err}167169 }168170 }@@ -88,7 +88,7 @@ func (m *Model) openFile(text string) tea.Cmd {
8888 if !ok {8989 return nil9090 }91- return loadCmd(name, p)91+ return loadCmd(name, p, m.spans.Parent())9292 }9393 9494 // reset starts over on s, as File > New and Open do. What belongs to the@@ -96,7 +96,8 @@ func (m *Model) openFile(text string) tea.Cmd {
9696 // state, served directory and the JEV connection.9797 func (m *Model) reset(s *sheet.Sheet, filename string) {9898 *m = Model{grid: grid{sheet: s, width: m.width, height: m.height}, filename: filename, th: m.th, term: m.term, jev: m.jev, root: m.root, charts: chartState{last: -1}, prefs: m.prefs,99- macros: macroState{machine: m.macros.machine, editor: m.macros.editor}}99+ macros: macroState{machine: m.macros.machine, editor: m.macros.editor}, spans: m.spans}100+ s.Book().SetTrace(m.spans)100101 if m.jev != nil {101102 s.Book().SetRemote(m.jev.cache)102103 }@@ -159,14 +160,14 @@ func (m *Model) saveAs(name string, check bool) tea.Cmd {
159160 if check && name == m.filename {160161 expect = &m.disk161162 }162- return saveCmd(m.sheet, name, p, expect)163+ return saveCmd(m.sheet, name, p, expect, m.spans)163164 }164165 165166 // saveCmd writes the worksheet to path atomically: to a temporary file166167 // first, then renamed over the target. With expect set, it writes only167168 // if the file on disk is still that version.168-func saveCmd(s *sheet.Sheet, name, path string, expect *stamp) tea.Cmd {169- span := telemetry.Start("save")169+func saveCmd(s *sheet.Sheet, name, path string, expect *stamp, spans *telemetry.Trace) tea.Cmd {170+ span := spans.Start("save")170171 var buf strings.Builder171172 err := s.Write(&buf)172173 if telemetry.Enabled() {@@ -211,7 +212,9 @@ func writeAtomic(path, data string) error {
211212 return err212213 }213214 214-func loadCmd(name, path string) tea.Cmd {215+// loadCmd reads the file in the background, the span of it and its216+// recalculation under parent.217+func loadCmd(name, path string, parent telemetry.Parent) tea.Cmd {215218 return func() tea.Msg {216219 f, err := os.Open(path)217220 if err != nil {@@ -222,8 +225,8 @@ func loadCmd(name, path string) tea.Cmd {
222225 if fi, err := f.Stat(); err == nil {223226 st = stampOf(fi)224227 }225- span := telemetry.Start("open")226- s, err := sheet.Read(f)228+ span := parent.Start("open")229+ s, err := sheet.ReadTraced(f, telemetry.NewTrace(span.Parent()))227230 if err != nil {228231 span.Fail(err)229232 } else if telemetry.Enabled() {@@ -6,7 +6,6 @@ import (
66 "github.com/FelineStateMachine/012/internal/macro"77 88 "github.com/FelineStateMachine/012/internal/sheet"9- "github.com/FelineStateMachine/012/internal/telemetry"109 )1110 1211 // The fill handle, as in Sheets: the bottom-right corner of the selection@@ -78,7 +77,7 @@ func (m *Model) finishFill() {
7877 return7978 }8079 m.recordFlush()81- span := telemetry.Start("fill", slog.Int("cells", (dst.To.Row-dst.From.Row+1)*(dst.To.Col-dst.From.Col+1)))80+ span := m.spans.Start("fill", slog.Int("cells", (dst.To.Row-dst.From.Row+1)*(dst.To.Col-dst.From.Col+1)))8281 got, err := m.sheet.FillSeries(src, dst)8382 span.Fail(err)8483 if err != nil {@@ -10,7 +10,6 @@ import (
1010 "github.com/sahilm/fuzzy"1111 1212 "github.com/FelineStateMachine/012/internal/sheet"13- "github.com/FelineStateMachine/012/internal/telemetry"1413 "github.com/FelineStateMachine/012/internal/ui/overlay"1514 "github.com/FelineStateMachine/012/internal/ui/theme"1615 )@@ -253,7 +252,7 @@ func (p *filterPicker) apply(m *Model) {
253252 254253 // filterColumn sets the criteria of column col of the sheet's filter.255254 func (m *Model) filterColumn(col int, cr sheet.Criteria) {256- span := telemetry.Start("filter")255+ span := m.spans.Start("filter")257256 m.sheet.FilterColumn(col, cr)258257 span.End(slog.Int("hidden", m.sheet.HiddenRows()))259258 m.changed = true@@ -27,6 +27,8 @@ type Host interface {
2727 // Line is the shared edit line the focused field is typed in.2828 Line() *lineedit.Line2929 Book() *sheet.Workbook30+ // Trace is where searches are timed, nested in what is open.31+ Trace() *telemetry.Trace3032 // At is the sheet shown and its active cell.3133 At() (*sheet.Sheet, sheet.Addr)3234 // Show shows sheet s with a as the active cell.@@ -205,7 +207,7 @@ func (f *Bar) sheets() []*sheet.Sheet {
205207 // while typing.206208 func (f *Bar) search() {207209 f.err, f.matches, f.index, f.cur = "", nil, nil, -1208- span := telemetry.Start("find")210+ span := f.h.Trace().Start("find")209211 sheets := f.sheets()210212 for _, s := range sheets {211213 found, err := s.Find(f.fields[0], f.options())@@ -362,7 +364,7 @@ func (f *Bar) replaceOne() {
362364 363365 func (f *Bar) replaceAll() {364366 // Across sheets, still one undo step.365- span := telemetry.Start("replace")367+ span := f.h.Trace().Start("replace")366368 n := 0367369 s, _ := f.h.At()368370 err := f.h.Book().Batch(sheet.Change{Label: "replace all", Sheet: s}, func() error {@@ -8,6 +8,7 @@ import (
88 "github.com/charmbracelet/x/ansi"99 1010 "github.com/FelineStateMachine/012/internal/sheet"11+ "github.com/FelineStateMachine/012/internal/telemetry"1112 "github.com/FelineStateMachine/012/internal/ui/lineedit"1213 "github.com/FelineStateMachine/012/internal/ui/overlay"1314 "github.com/FelineStateMachine/012/internal/ui/theme"@@ -46,6 +47,7 @@ func (f *fakeHost) Theme() *theme.Theme { return &f.th }
4647 func (f *fakeHost) Size() (width, height int) { return 120, 24 }4748 func (f *fakeHost) Line() *lineedit.Line { return &f.line }4849 func (f *fakeHost) Book() *sheet.Workbook { return f.s.Book() }50+func (f *fakeHost) Trace() *telemetry.Trace { return nil }4951 func (f *fakeHost) At() (*sheet.Sheet, sheet.Addr) { return f.s, f.cur }5052 func (f *fakeHost) Show(s *sheet.Sheet, a sheet.Addr) { f.s, f.cur = s, a }5153 func (f *fakeHost) Note(msg string) { f.note = msg }@@ -163,7 +163,7 @@ func (t *terminal) chartOptions() chart.Options {
163163 // drawn, asked for only on terminals that show images. Update calls it164164 // after every message, so images follow edits, recalculation, resizing165165 // and the theme.166-func (t *terminal) syncImages(s *sheet.Sheet, shown func() []sheet.Chart, th *theme.Theme) tea.Cmd {166+func (t *terminal) syncImages(s *sheet.Sheet, shown func() []sheet.Chart, th *theme.Theme, spans *telemetry.Trace) tea.Cmd {167167 if !t.images() {168168 return t.freeImages()169169 }@@ -191,7 +191,7 @@ func (t *terminal) syncImages(s *sheet.Sheet, shown func() []sheet.Chart, th *th
191191 // oldest, so a chart that grew would draw at its old size.192192 out.WriteString(chart.Delete(id, t.wrap))193193 }194- span := telemetry.Start("chart.image", slog.String("type", c.Type.String()), slog.Int("w", w), slog.Int("h", h))194+ span := spans.Start("chart.image", slog.String("type", c.Type.String()), slog.Int("w", w), slog.Int("h", h))195195 g := chart.Draw(c.Type, d, w, h, o)196196 img := chart.Image(c.Type, d, w, h, o, pal)197197 if img == nil || g.Plot.Empty() {@@ -4,6 +4,7 @@ import (
44 tea "charm.land/bubbletea/v2"55 66 "github.com/FelineStateMachine/012/internal/sheet"7+ "github.com/FelineStateMachine/012/internal/telemetry"78 "github.com/FelineStateMachine/012/internal/ui/cmdline"89 "github.com/FelineStateMachine/012/internal/ui/findbar"910 "github.com/FelineStateMachine/012/internal/ui/lineedit"@@ -114,6 +115,7 @@ func (h host) Preview(name string) {
114115 // The find bar.115116 116117 func (h host) Book() *sheet.Workbook { return h.m.book() }118+func (h host) Trace() *telemetry.Trace { return h.m.spans }117119 func (h host) At() (*sheet.Sheet, sheet.Addr) { return h.m.sheet, h.m.cur }118120 func (h host) Note(msg string) { h.m.note = msg }119121 func (h host) Edited() { h.m.changed = true }@@ -81,7 +81,8 @@ func plural(n int, one, many string) string {
8181 8282 // send starts queued questions, keeping at most jevParallel in flight8383 // so a filled-down column doesn't open hundreds of connections at once.84-func (j *jevRunner) send() tea.Cmd {84+// Their spans nest under parent.85+func (j *jevRunner) send(parent telemetry.Parent) tea.Cmd {8586 if j == nil {8687 return nil8788 }@@ -95,7 +96,7 @@ func (j *jevRunner) send() tea.Cmd {
9596 cmds[i] = func() tea.Msg {9697 ctx, cancel := context.WithTimeout(context.Background(), jevTimeout)9798 defer cancel()98- span := telemetry.Start("jev", slog.String("kind", call.Kind), slog.Int("queued", queued))99+ span := parent.Start("jev", slog.String("kind", call.Kind), slog.Int("queued", queued))99100 answer := jev.Ask(ctx, client, call)100101 outcome := "ok"101102 if answer.Failed != "" {@@ -90,7 +90,9 @@ func (m *Model) startMacro(mc sheet.Macro) tea.Cmd {
9090 }9191 r := ¯oRun{9292 name: mc.Name, calls: make(chan func()), ack: make(chan struct{}), done: make(chan macroDone, 1),93- start: time.Now(), span: telemetry.Start("macro"),93+ // Under the command that started it, which ends first; its calls94+ // are served under it (see serveMacro).95+ start: time.Now(), span: m.spans.Parent().Start("macro"),9496 }9597 r.end = m.book().Begin(sheet.Change{Label: "run macro " + mc.Name, Focus: m.selection(), Sheet: m.sheet})9698 r.run = macro.New(mc.Name, mc.Source, macro.Env{@@ -146,6 +148,7 @@ func (r *macroRun) wait() tea.Cmd {
146148 // long as the slice lasts.147149 func (m *Model) serveMacro(msg macroCallMsg) tea.Cmd {148150 r := msg.r151+ defer m.spans.Leave(m.spans.Enter(r.span.Parent()))149152 deadline := time.Now().Add(sliceBudget)150153 m.serveCall(r, msg.call)151154 idle := time.NewTimer(idleWait)@@ -108,25 +108,32 @@ type Model struct {
108108 rec *recorder // a macro being recorded: macrorec.go109109 macros macroState // a macro running, and trust in the file's macros: macrorun.go110110 111- keyAt time.Time // when the key the next frame answers was pressed, for telemetry111+ keyAt time.Time // when the key the next frame answers was pressed, for telemetry112+ spans *telemetry.Trace // the spans open, which what the model starts nests in: trace.go112113 113114 th theme.Theme114115 }115116 116117 // New returns a model editing s. filename may be empty.117118 func New(s *sheet.Sheet, filename string) *Model {118- m := &Model{grid: grid{sheet: s, width: 80, height: 24}, filename: filename, th: theme.New(true), term: newTerminal(os.Getenv), charts: chartState{last: -1}}119+ m := &Model{grid: grid{sheet: s, width: 80, height: 24}, filename: filename, th: theme.New(true), term: newTerminal(os.Getenv), charts: chartState{last: -1},120+ spans: telemetry.NewTrace(telemetry.Parent{})}121+ s.Book().SetTrace(m.spans)119122 if filename != "" {120123 m.disk = diskStamp(filename)121124 }122125 return m123126 }124127 128+// TraceUnder nests every span the model starts under p for good: 012129+// serve's session span holds each session's commands.130+func (m *Model) TraceUnder(p telemetry.Parent) { m.spans.Enter(p) }131+125132 // Init implements tea.Model. It asks the terminal for its background color126133 // so the theme can adapt to light terminals.127134 func (m *Model) Init() tea.Cmd {128135 // jev.send starts any questions queued while loading the file.129- return tea.Batch(tea.RequestBackgroundColor, tea.Raw(shiftEscapeOn), m.term.probes(), m.jev.send(), m.startupCmd())136+ return tea.Batch(tea.RequestBackgroundColor, tea.Raw(shiftEscapeOn), m.term.probes(), m.jev.send(m.spans.Parent()), m.startupCmd())130137 }131138 132139 // Update implements tea.Model.@@ -207,7 +214,7 @@ func (m *Model) Update(msg tea.Msg) (tea.Model, tea.Cmd) {
207214 m.clampView()208215 // Any edit may have queued JEV questions.209216 // Chart images follow any change, see graphics.go.210- return m, tea.Batch(cmd, m.jev.send(), m.term.syncImages(m.sheet, m.displayCharts, &m.th))217+ return m, tea.Batch(cmd, m.jev.send(m.spans.Parent()), m.term.syncImages(m.sheet, m.displayCharts, &m.th, m.spans))211218 }212219 213220 // beginUpdate prepares for an input event and returns the sheet's state@@ -7,7 +7,6 @@ import (
77 tea "charm.land/bubbletea/v2"88 99 "github.com/FelineStateMachine/012/internal/sheet"10- "github.com/FelineStateMachine/012/internal/telemetry"1110 )1211 1312 // Pivot tables follow Sheets: Data > Pivot table summarizes the@@ -128,7 +127,7 @@ func (m *Model) frequency() tea.Cmd {
128127 m.note = "Move to a column of data first: a header and the values below it"129128 return nil130129 }131- span := telemetry.Start("frequency", slog.Int("rows", r.To.Row-r.From.Row))130+ span := m.spans.Start("frequency", slog.Int("rows", r.To.Row-r.From.Row))132131 defer span.End()133132 p := sheet.FrequencyPivot(m.sheet, r, col)134133 field := m.book().FieldName(p, col)@@ -8,7 +8,6 @@ import (
88 "github.com/charmbracelet/x/ansi"99 1010 "github.com/FelineStateMachine/012/internal/sheet"11- "github.com/FelineStateMachine/012/internal/telemetry"1211 "github.com/FelineStateMachine/012/internal/ui/overlay"1312 )1413 @@ -66,7 +65,7 @@ func (m *Model) sort(r sheet.Rect, keys []sheet.SortKey) tea.Cmd {
6665 if m.refusePivot(r) {6766 return nil6867 }69- 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)))68+ span := m.spans.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)))7069 m.sheet.SortRange(r, keys)7170 span.End()7271 m.changed = true@@ -0,0 +1,106 @@
1+package ui2+3+import (4+ "encoding/json"5+ "log/slog"6+ "os"7+ "path/filepath"8+ "strings"9+ "testing"10+ "time"11+12+ "github.com/FelineStateMachine/012/internal/sheet"13+ "github.com/FelineStateMachine/012/internal/telemetry"14+)15+16+// logSpans turns telemetry on into a JSON log with the engine's hooks17+// set as cmd/012 sets them, and returns what reads the events logged.18+func logSpans(t *testing.T) func() []map[string]any {19+ t.Helper()20+ path := filepath.Join(t.TempDir(), "log.jsonl")21+ stop, err := telemetry.Setup(telemetry.Config{LogPath: path})22+ if err != nil {23+ t.Fatal(err)24+ }25+ end := func(trace any, name string, d time.Duration, attrs ...slog.Attr) {26+ if tr, ok := trace.(*telemetry.Trace); ok && tr.End(attrs...) {27+ return28+ }29+ telemetry.Event(name, d, attrs...)30+ }31+ sheet.OnBegin = func(trace any, op string) {32+ if tr, ok := trace.(*telemetry.Trace); ok {33+ tr.Begin(op)34+ }35+ }36+ sheet.OnRecalc = func(trace any, i sheet.RecalcInfo) { end(trace, "recalc", i.Duration) }37+ sheet.OnPivot = func(trace any, i sheet.PivotInfo) { end(trace, "pivot", i.Duration) }38+ t.Cleanup(func() {39+ sheet.OnBegin, sheet.OnRecalc, sheet.OnPivot = nil, nil, nil40+ stop()41+ })42+ return func() []map[string]any {43+ stop()44+ b, err := os.ReadFile(path)45+ if err != nil {46+ t.Fatal(err)47+ }48+ var evs []map[string]any49+ for _, l := range strings.Split(strings.TrimSpace(string(b)), "\n") {50+ var ev map[string]any51+ if err := json.Unmarshal([]byte(l), &ev); err != nil {52+ t.Fatal(err)53+ }54+ evs = append(evs, ev)55+ }56+ return evs57+ }58+}59+60+// under reports whether some event named child is logged under the one61+// that matches parent.62+func under(evs []map[string]any, child string, parent func(map[string]any) bool) bool {63+ for _, p := range evs {64+ if !parent(p) {65+ continue66+ }67+ for _, c := range evs {68+ if c["event"] == child && c["parent_id"] == p["span_id"] && c["trace_id"] == p["trace_id"] {69+ return true70+ }71+ }72+ }73+ return false74+}75+76+func spanNamed(event, id string) func(map[string]any) bool {77+ return func(ev map[string]any) bool { return ev["event"] == event && (id == "" || ev["id"] == id) }78+}79+80+// A trace shows what a command caused, and what a macro ran.81+func TestSpansNest(t *testing.T) {82+ read := logSpans(t)83+ m := newModel()84+ m.sheet.Set(addr("A1"), "1")85+ m.sheet.Set(addr("B1"), "=A1*2")86+ m.runCommand("clear")87+ script(t, m, `88+set("A2", 5)89+run("format.bold")90+`)91+ evs := read()92+ if !under(evs, "recalc", spanNamed("command", "clear")) {93+ t.Error("clear's recalculation is not under its command")94+ }95+ if !under(evs, "command", spanNamed("macro", "")) {96+ t.Error("the macro's command is not under the macro")97+ }98+ if !under(evs, "recalc", spanNamed("macro", "")) {99+ t.Error("the macro's recalculation is not under the macro")100+ }101+ for _, ev := range evs {102+ if ev["event"] == "command" && ev["id"] == "clear" && ev["parent_id"] != nil {103+ t.Errorf("a command from a key is a root: %v", ev)104+ }105+ }106+}@@ -259,11 +259,17 @@ func telemetryFor(b *testing.B, on bool) func() error {
259259 if err != nil {260260 b.Fatal(err)261261 }262- sheet.OnRecalc = func(i sheet.RecalcInfo) {263- telemetry.Event("recalc", i.Duration, slog.Int("evaluated", i.Evaluated), slog.Int("cells", i.Cells))262+ // As cmd/012 does: recalculations nest in the model's trace.263+ sheet.OnBegin = func(trace any, op string) {264+ t, _ := trace.(*telemetry.Trace)265+ t.Begin(op)266+ }267+ sheet.OnRecalc = func(trace any, i sheet.RecalcInfo) {268+ t, _ := trace.(*telemetry.Trace)269+ t.End(slog.Int("evaluated", i.Evaluated), slog.Int("cells", i.Cells))264270 }265271 return func() error {266- sheet.OnRecalc = nil272+ sheet.OnBegin, sheet.OnRecalc = nil, nil267273 return stop()268274 }269275 }@@ -293,7 +299,7 @@ func BenchmarkJEV(b *testing.B) {
293299 m.EnableJEV(stressJEV{}, cache)294300 m.jev.gather = 0 // answers already queued still gather; don't wait a frame295301 start := time.Now()296- drain(m, m.jev.send())302+ drain(m, m.jev.send(m.spans.Parent()))297303 if in, q := cache.Busy(); in+q > 0 {298304 b.Fatalf("%d in flight, %d queued", in, q)299305 }@@ -168,7 +168,7 @@ func (m *Model) startImport(name string, opt fileio.Options, place transfer.Plac
168168 if !ok {169169 return nil170170 }171- return m.xfer.Start(name, path, opt, place)171+ return m.xfer.Start(name, path, opt, place, m.spans.Parent())172172 }173173 174174 // importing handles input while an import runs: Esc cancels it, and@@ -17,6 +17,7 @@ import (
1717 "github.com/charmbracelet/x/ansi"1818 1919 "github.com/FelineStateMachine/012/internal/fileio"20+ "github.com/FelineStateMachine/012/internal/telemetry"2021 "github.com/FelineStateMachine/012/internal/ui/theme"2122 )2223 @@ -67,9 +68,9 @@ const tick = 100 * time.Millisecond
6768 func (x *Transfer) Busy() bool { return x.job != nil }6869 6970 // Start reads name, at path on disk, in the background, replacing any70-// import running.71-func (x *Transfer) Start(name, path string, opt fileio.Options, place Place) tea.Cmd {72- ctx, cancel := context.WithCancel(context.Background())71+// import running. Its span nests under parent.72+func (x *Transfer) Start(name, path string, opt fileio.Options, place Place, parent telemetry.Parent) tea.Cmd {73+ ctx, cancel := context.WithCancel(telemetry.WithParent(context.Background(), parent))7374 prog := fileio.NewProgress()7475 id := x.Begin(name, prog, cancel, place)7576 opt.Progress = prog@@ -10,6 +10,7 @@ import (
1010 "github.com/charmbracelet/x/ansi"1111 1212 "github.com/FelineStateMachine/012/internal/fileio"13+ "github.com/FelineStateMachine/012/internal/telemetry"1314 "github.com/FelineStateMachine/012/internal/ui/theme"1415 )1516 @@ -67,7 +68,7 @@ func TestStartReadsInTheBackground(t *testing.T) {
6768 t.Fatal(err)6869 }6970 var x Transfer70- cmd := x.Start("a.csv", path, fileio.Options{}, NewSheets)71+ cmd := x.Start("a.csv", path, fileio.Options{}, NewSheets, telemetry.Parent{})7172 var res ImportedMsg7273 for _, c := range cmd().(tea.BatchMsg) {7374 if msg, ok := c().(ImportedMsg); ok {