A workbook holds its owner's trace, opaque to the engine (SetTrace, ReadTraced), and hands it to the hooks, which now pair up: OnBegin as a recalculation or pivot refresh starts, OnRecalc or OnPivot as it ends. A recalculation now includes the pivot refreshes it causes, so cmd/012 nests pivot spans in recalc spans in whatever the owner has open.
- commit
- 503499f2cb9d14df6a39999f23a8d4e0af6b4554
- parent
- 801c083827a1b477e7e3c620aecd55456857c87e
- author
- Dami <dami.etoile@gmail.com>
| M | cmd/ | 27 | +++++++++++++++++++---- |
| M | internal/ | 13 | +++++++++--- |
| M | internal/ | 35 | ++++++++++++++++++++++++------ |
| A | internal/ | 34 | +++++++++++++++++++++++++++++ |
| M | internal/ | 2 | +- |
| M | internal/ | 9 | +++++--- |
| M | internal/ | 8 | +++--- |
| M | internal/ | 1 | + |
| M | internal/ | 2 | +- |
@@ -4,6 +4,7 @@ import (
44 "log/slog"55 "os"66 "runtime/debug"7+ "time"78 89 "github.com/FelineStateMachine/012/internal/config"910 "github.com/FelineStateMachine/012/internal/sheet"@@ -37,7 +38,8 @@ func telemetryFlags(args []string) (telemetry.Config, []string, error) {
3738 return telemetryConfig(config.Load(path, os.Getenv, flags)), rest, nil3839 }3940 40-// startTelemetry opens the log and reports every recalculation to it.41+// startTelemetry opens the log and reports every recalculation and pivot42+// refresh to it, as spans nested in their workbook's trace.4143 func startTelemetry(c telemetry.Config) (func() error, error) {4244 if info, ok := debug.ReadBuildInfo(); ok {4345 c.Version = info.Main.Version@@ -51,15 +53,30 @@ func startTelemetry(c telemetry.Config) (func() error, error) {
5153 if err != nil || !telemetry.Enabled() {5254 return stop, err5355 }54- sheet.OnRecalc = func(i sheet.RecalcInfo) {56+ sheet.OnBegin = func(trace any, op string) {57+ if t, ok := trace.(*telemetry.Trace); ok {58+ t.Begin(op)59+ }60+ }61+ sheet.OnRecalc = func(trace any, i sheet.RecalcInfo) {5562 telemetry.Set("cells", int64(i.Cells))56- telemetry.Event("recalc", i.Duration,63+ endSpan(trace, "recalc", i.Duration,5764 slog.Bool("full", i.Full), slog.Int("evaluated", i.Evaluated), slog.Int("cells", i.Cells),5865 slog.Int("volatile", i.Volatile), slog.Bool("circular", i.Circular))5966 }60- sheet.OnPivot = func(i sheet.PivotInfo) {61- telemetry.Event("pivot", i.Duration,67+ sheet.OnPivot = func(trace any, i sheet.PivotInfo) {68+ endSpan(trace, "pivot", i.Duration,6269 slog.Int("records", i.Records), slog.Int("groups", i.Groups), slog.Int("cells", i.Cells), slog.Bool("failed", i.Failed))6370 }6471 return stop, nil6572 }73+74+// endSpan ends the span sheet.OnBegin began in the workbook's trace, or75+// logs the operation as a root span of its own when the workbook has no76+// trace (one read before the UI took it, say).77+func endSpan(trace any, name string, d time.Duration, attrs ...slog.Attr) {78+ if t, ok := trace.(*telemetry.Trace); ok && t.End(attrs...) {79+ return80+ }81+ telemetry.Event(name, d, attrs...)82+}@@ -355,8 +355,12 @@ func (s *Sheet) writeObjects(b *bytes.Buffer, indent string) error {
355355 356356 // Read loads a file written by Write, of this or an earlier version, and357357 // returns the sheet that was shown when it was saved.358-func Read(r io.Reader) (*Sheet, error) {359- w, err := ReadBook(r)358+func Read(r io.Reader) (*Sheet, error) { return ReadTraced(r, nil) }359+360+// ReadTraced is Read giving the workbook trace (see SetTrace) before it361+// recalculates, so that recalculation nests in the caller's span.362+func ReadTraced(r io.Reader, trace any) (*Sheet, error) {363+ w, err := readBook(r, trace)360364 if err != nil {361365 return nil, err362366 }@@ -365,7 +369,9 @@ func Read(r io.Reader) (*Sheet, error) {
365369 366370 // ReadBook loads a workbook written by Write, of this or an earlier367371 // version.368-func ReadBook(r io.Reader) (*Workbook, error) {372+func ReadBook(r io.Reader) (*Workbook, error) { return readBook(r, nil) }373+374+func readBook(r io.Reader, trace any) (*Workbook, error) {369375 var f fileFormat370376 if err := json.NewDecoder(r).Decode(&f); err != nil {371377 return nil, err@@ -384,6 +390,7 @@ func ReadBook(r io.Reader) (*Workbook, error) {
384390 return nil, fmt.Errorf("the file has no sheets")385391 }386392 w := emptyBook()393+ w.trace = trace387394 for _, body := range bodies {388395 if err := w.checkName(nil, body.Name); err != nil {389396 return nil, fmt.Errorf("sheet %q: %w", body.Name, err)@@ -10,20 +10,41 @@ type RecalcInfo struct {
1010 Cells int // cells stored on every sheet, including formatting-only ones1111 Volatile int // volatile formulas on every sheet, recomputed every time1212 Circular bool13- Duration time.Duration13+ // Duration includes the pivot tables the recalculation refreshed,14+ // and the recalculation of what reads their results.15+ Duration time.Duration1416 }1517 16-// OnRecalc, when set, is called after every recalculation of any workbook.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)18+// The engine knows nothing of logging; cmd/012 points these hooks at19+// telemetry. They run on the goroutine that changed the workbook and20+// must be cheap. trace is the workbook's (see SetTrace), handed back so21+// the engine's work is timed as spans nested in whatever the workbook's22+// owner has open: a command, an import, a macro run.23+var (24+ // OnBegin, when set, is called as a recalculation ("recalc") or a25+ // pivot table refresh ("pivot") begins; OnRecalc or OnPivot as it26+ // ends. They pair up like parentheses: a recalculation holds the27+ // pivot refreshes it causes, which follow its own evaluation.28+ OnBegin func(trace any, op string)29+ // OnRecalc, when set, is called after every recalculation of any30+ // workbook.31+ OnRecalc func(trace any, i RecalcInfo)32+)33+34+// SetTrace gives the workbook its owner's trace, opaque to the engine:35+// a *telemetry.Trace from the program or import that holds the workbook,36+// which only its goroutine uses, as with the workbook itself.37+func (w *Workbook) SetTrace(trace any) { w.trace = trace }2038 2139 // recalcStart is when a recalculation began, or zero when nobody is2240 // watching, so an unobserved recalculation doesn't read the clock.23-func recalcStart() time.Time {41+func (w *Workbook) recalcStart() time.Time {2442 if OnRecalc == nil {2543 return time.Time{}2644 }45+ if OnBegin != nil {46+ OnBegin(w.trace, "recalc")47+ }2748 return time.Now()2849 }2950 @@ -37,5 +58,5 @@ func (w *Workbook) observe(full bool, start time.Time, evaluated int) {
3758 info.Volatile += len(s.volatile)3859 }3960 info.Duration = time.Since(start)40- OnRecalc(info)61+ OnRecalc(w.trace, info)4162 }@@ -0,0 +1,34 @@
1+package sheet2+3+import (4+ "strings"5+ "testing"6+)7+8+// The hooks pair up like parentheses, a recalculation holding the pivot9+// refreshes it causes, and get the workbook's trace back.10+func TestTelemetryHooksNest(t *testing.T) {11+ w := sales(t)12+ newPivot(t, w, func(p *Pivot) {13+ p.Rows = []PivotGroup{{Col: 0}}14+ p.Values = []PivotValue{{Col: 3, Summarize: SumBy}}15+ })16+ trace := new(int)17+ w.SetTrace(trace)18+ var got []string19+ var traces []any20+ OnBegin = func(tr any, op string) { got, traces = append(got, "("+op), append(traces, tr) }21+ OnRecalc = func(tr any, _ RecalcInfo) { got, traces = append(got, "recalc)"), append(traces, tr) }22+ OnPivot = func(tr any, _ PivotInfo) { got, traces = append(got, "pivot)"), append(traces, tr) }23+ defer func() { OnBegin, OnRecalc, OnPivot = nil, nil, nil }()24+ w.Lookup("Sales").Set(at("D2"), "100")25+ want := "(recalc (pivot pivot) (recalc recalc) recalc)"26+ if s := strings.Join(got, " "); s != want {27+ t.Errorf("hooks ran %s, want %s", s, want)28+ }29+ for _, tr := range traces {30+ if tr != trace {31+ t.Errorf("hook got trace %v, want the workbook's", tr)32+ }33+ }34+}@@ -484,7 +484,7 @@ func TestPivotDuplicate(t *testing.T) {
484484 485485 func TestPivotTelemetry(t *testing.T) {486486 var got []PivotInfo487- OnPivot = func(i PivotInfo) { got = append(got, i) }487+ OnPivot = func(_ any, i PivotInfo) { got = append(got, i) }488488 defer func() { OnPivot = nil }()489489 w := sales(t)490490 newPivot(t, w, func(p *Pivot) {@@ -188,8 +188,8 @@ type PivotInfo struct {
188188 }189189 190190 // OnPivot, when set, is called after every pivot recomputation, like191-// OnRecalc.192-var OnPivot func(PivotInfo)191+// OnRecalc (see OnBegin).192+var OnPivot func(trace any, i PivotInfo)193193 194194 // maxPivotChain bounds pivots reading pivots that are refreshed in turn195195 // after one change.@@ -264,6 +264,9 @@ func (w *Workbook) refreshPivots(sheets []*Sheet) {
264264 func (w *Workbook) refreshPivot(s *Sheet) []loc {265265 var start time.Time266266 if OnPivot != nil {267+ if OnBegin != nil {268+ OnBegin(w.trace, "pivot")269+ }267270 start = time.Now()268271 }269272 s.pivot.stale = false@@ -289,7 +292,7 @@ func (w *Workbook) refreshPivot(s *Sheet) []loc {
289292 if calc != nil {290293 info.Records, info.Groups = calc.records, calc.groups()291294 }292- OnPivot(info)295+ OnPivot(w.trace, info)293296 }294297 return changed295298 }@@ -26,7 +26,7 @@ func (w *Workbook) RecalcAll() {
2626 // propagate: tracing dependents from each cell cost O(cells x range2727 // users).2828 func (w *Workbook) recalcAll() {29- start := recalcStart()29+ start := w.recalcStart()3030 n := 03131 for _, s := range w.sheets {3232 s.calc = make(map[Addr]int, s.cells.len())@@ -36,8 +36,8 @@ func (w *Workbook) recalcAll() {
3636 n += len(s.calc)3737 }3838 w.evaluate()39- w.observe(true, start, n)4039 w.refreshPivots(w.allPivots())40+ w.observe(true, start, n)4141 }4242 4343 // Recalculation states of a cell.@@ -56,12 +56,12 @@ func (w *Workbook) recalc(changed []loc) { w.recalcFrom(changed, true) }
5656 // transitively depends on them, and the volatile formulas with theirs5757 // when volatiles is set.5858 func (w *Workbook) recalcFrom(changed []loc, volatiles bool) {59- start := recalcStart()59+ start := w.recalcStart()6060 n := w.affected(changed, volatiles)6161 stale := w.stalePivots()6262 w.evaluate()63- w.observe(false, start, n)6463 w.refreshPivots(stale)64+ w.observe(false, start, n)6565 }6666 6767 // affected marks dirty, in each sheet's calc, the changed cells, volatile@@ -41,6 +41,7 @@ type Workbook struct {
4141 Circular bool4242 4343 remote RemoteSource // answers JEV functions, see remote.go44+ trace any // the owner's telemetry trace, see observe.go4445 // waiting are the formulas that were shown Loading… by question key,4546 // so an answer recalculates only them; evaluating is the formula4647 // being evaluated, which a question is asked for (see remote.go).@@ -121,7 +121,7 @@ func TestJEVAnswersRecalculateOncePerFrame(t *testing.T) {
121121 t.Fatalf("%d questions in flight, want 3", in)122122 }123123 recalcs := 0124- sheet.OnRecalc = func(sheet.RecalcInfo) { recalcs++ }124+ sheet.OnRecalc = func(any, sheet.RecalcInfo) { recalcs++ }125125 defer func() { sheet.OnRecalc = nil }()126126 var answers []jevAnswerMsg127127 for _, cmd := range cmds {