Skip to content
Draft
Show file tree
Hide file tree
Changes from all commits
Commits
File filter

Filter by extension

Filter by extension

Conversations
Failed to load comments.
Loading
Jump to
Jump to file
Failed to load files.
Loading
Diff view
Diff view
43 changes: 24 additions & 19 deletions docs/spirit_progress.md
Original file line number Diff line number Diff line change
Expand Up @@ -48,13 +48,15 @@ key to debugging stale-progress issues.
| Field | Type | Notes |
|-----------------|-------------------|-------|
| `CurrentState` | `status.State` | Atomic int32 enum: `Initial`, `CopyRows`, `WaitingOnSentinelTable`, `Checksum`, `CutOver`, `Close`, ... |
| `Summary` | `string` | `"71436/221193 32.30% copyRows ETA 5m 30s"` |
| `Summary` | `string` | Human-readable line for logs, e.g. `"71436/221193 32.30% copyRows ETA 5m 30s"`. Display-only: every value in it is also one of the structured fields below, and nothing in SchemaBot parses it. |
| `Tables[]` | `[]TableProgress` | Per-table: `TableName`, `RowsCopied` (uint64), `RowsTotal` (uint64), `IsComplete` (bool) |
| `ETA` | `status.ETA` | `State` (`""` outside the copy, `measuring`, `ready`, `due`) and `Duration` (remaining copy time, meaningful only when `State == ETAReady`). |
| `Checksum` | `status.ChecksumProgress` | `RowsChecked` / `RowsTotal` for the verify phase; zero outside it. |
| `Resume` | `bool` | True only after the runner successfully resumed from its durable checkpoint; a fresh start (or an abandoned resume attempt) reports false. |
| `Throttle` | `status.ThrottleStatus` | `Throttled` (bool), `Reason` (display-only string, `"<signal> <observed> <op> <threshold>"`), `Utilization` (float64, 0 means unknown — never render it as idle). |

Key details:
- **ETA is embedded in `Summary`**, not a separate field. Downstream layers parse it out with a regex.
- **The ETA is a structured field.** `ETA.State` says whether an estimate exists yet — `measuring` during the initial window before a copy rate is known, `due` once the copy is essentially finished — so a consumer can show "calculating" instead of a misleading zero. `ETA.Duration` is only meaningful when the state is `ready`. If Spirit reports something SchemaBot needs and it is only in `Summary`, the fix is a new field on `status.Progress` upstream, not a parser here.
- **`IsComplete`** comes from the chunker's in-memory `finalChunkSent` flag, NOT from the checkpoint table. This means `IsComplete` is lost on crash — it only exists while the runner is alive.
- **`RowsCopied` can exceed `RowsTotal`** when the initial MySQL estimate is low. Downstream renderers treat this as an active estimate-exceeded state rather than a percentage above 100%.
- **`Checksum` progress (`prog.Checksum.RowsChecked` / `RowsTotal`) is populated only while
Expand Down Expand Up @@ -111,7 +113,9 @@ Two properties matter for display:
- Each table's `State` is the raw Spirit phase string (`copyRows`, `applyChangeset`, ...).
- Calculates `Progress` percent (clamped 0–100) and preserves raw `RowsCopied`
so renderers can detect when the initial estimate was exceeded.
- Sets `ProgressDetail` = formatted summary like `"12345/50000 24% copyRows"`.
- Surfaces the runner's single `ETA` as `ETASeconds` on the tables still
copying, and only when `ETA.State` is `ready` — a still-measuring or
essentially-done estimate is not yet a number.
- When `IsComplete` is true, reconciles `RowsTotal = RowsCopied` (the estimate
was never a count; the copied total is ground truth once the copy finishes)
and sets `Progress` to 100. The table keeps the runner phase while the
Expand All @@ -133,6 +137,11 @@ Two properties matter for display:

Key types: `engine.ProgressResult`, `engine.TableProgress` (`pkg/engine/engine.go`).

`engine.TableProgress.ProgressDetail` is a free-text note for a human, never a
data channel: Spirit's `Summary` line while the runner has no per-table progress
yet, or a marker that a statement ran as native DDL outside the runner. Nothing
downstream parses it, and the drive does not persist it.

When no runner exists (engine stopped, no active schema change), returns `StatePending` with
message `"No active schema change"`.

Expand Down Expand Up @@ -280,19 +289,12 @@ adds apply-level fields: `apply_id`, `database`, `environment`.

The TUI polls the API every **2 seconds** via `tick()`.

`parseProgressResult()` converts the JSON response to internal types. For each table,
if `ProgressDetail` is non-empty, it runs `ParseSpiritProgress()` — a regex parser
in `pkg/cmd/internal/templates/progress.go` that extracts structured data from Spirit's summary string:

```
"71436/221193 32.30% copyRows ETA 5m 30s"
↓ ↓ ↓ ↓ ↓
RowsCopied RowsTotal Percent State ETA
```

The parsed values override the structured API fields (`RowsCopied`, `RowsTotal`, `Percent`)
because `ProgressDetail` comes directly from Spirit and is more current than the separately-polled
numeric fields.
`parseProgressResult()` converts the JSON response to internal types through
`templates.ParseProgressResponse()`, a field-for-field mapping of the structured
API fields (`RowsCopied`, `RowsTotal`, `PercentComplete`, `ETASeconds`, the
checksum counters, the throttle status). The renderer draws the bar, the rows
line, and the ETA from those fields alone — the same fields the PR comment
renders from, so the two surfaces always agree.

## TUI rendering reference

Expand Down Expand Up @@ -446,9 +448,12 @@ The `⠋` is a Braille spinner (animated in the TUI, static here).
applies with stale heartbeats and call `Tern.ResumeApply()`, which re-plans against the
actual DB state to determine what still needs to be done.

5. **ETA is only available via `ProgressDetail` parsing.** Spirit embeds ETA in its summary string.
The engine layer doesn't extract it into a separate field — it flows through as `ProgressDetail`
and is parsed by the CLI with a regex. If the regex fails, no ETA is shown.
5. **The ETA is structured end to end.** Spirit reports `status.ETA{State, Duration}`; the
engine surfaces it as `ETASeconds` only when the state is `ready`; the drive persists it
on the task row; the API and CLI carry it as `eta_seconds` / `ETASeconds`; and both the CLI
and the PR comment render it through `ui.FormatETA`. No layer derives it from text, so a
missing ETA means Spirit had none to give (still measuring, or essentially done), not that
a parser failed.

6. **Estimate-exceeded display.** Spirit can report `RowsCopied > RowsTotal` when MySQL's initial
estimate is low. SchemaBot preserves the raw copied count, clamps determinate percentages to 100,
Expand Down
3 changes: 1 addition & 2 deletions pkg/cmd/commands/apply_log_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -215,7 +215,7 @@ func TestLogEmitter_EmitTableStateChange(t *testing.T) {
}

func TestLogEmitter_EmitProgressHeartbeat(t *testing.T) {
t.Run("structured ETA renders alongside a Spirit progress detail", func(t *testing.T) {
t.Run("structured ETA renders alongside the row counts", func(t *testing.T) {
e := &logEmitter{applyID: "apply-test"}
ts := &tableLogState{taskID: "task-orders-1"}
tbl := &apitypes.TableProgressResponse{
Expand All @@ -224,7 +224,6 @@ func TestLogEmitter_EmitProgressHeartbeat(t *testing.T) {
RowsCopied: 99450,
RowsTotal: 221000,
ETASeconds: 330,
ProgressDetail: "99450/221000 45.00% copyRows",
}

output := captureOutput(t, func() {
Expand Down
27 changes: 13 additions & 14 deletions pkg/cmd/commands/preview_log.go
Original file line number Diff line number Diff line change
Expand Up @@ -102,22 +102,22 @@ func previewLogLarge() {

// Heartbeats at 30s intervals
heartbeats := []struct {
pct int32
copied int64
total int64
eta string
pct int32
copied int64
total int64
etaSeconds int64
}{
{12, 26543, 221193, "99450/221193 12.00% copyRows ETA 4m 10s"},
{25, 55298, 221193, "99450/221193 25.00% copyRows ETA 3m 30s"},
{45, 99537, 221193, "99450/221193 45.00% copyRows ETA 2m 15s"},
{68, 150412, 221193, "150412/221193 68.00% copyRows ETA 1m 10s"},
{89, 196861, 221193, "196861/221193 89.00% copyRows ETA 25s"},
{12, 26543, 221193, 250},
{25, 55298, 221193, 210},
{45, 99537, 221193, 135},
{68, 150412, 221193, 70},
{89, 196861, 221193, 25},
}
for _, hb := range heartbeats {
tbl.PercentComplete = hb.pct
tbl.RowsCopied = hb.copied
tbl.RowsTotal = hb.total
tbl.ProgressDetail = hb.eta
tbl.ETASeconds = hb.etaSeconds
e.emitProgressHeartbeat(tbl, ts)
}

Expand Down Expand Up @@ -213,13 +213,13 @@ func previewLogMulti() {
tblOrders.PercentComplete = 30
tblOrders.RowsCopied = 66357
tblOrders.RowsTotal = 221193
tblOrders.ProgressDetail = "66357/221193 30.00% copyRows ETA 2m 30s"
tblOrders.ETASeconds = 150
e.emitProgressHeartbeat(tblOrders, tsOrders)

tblOrders.PercentComplete = 65
tblOrders.RowsCopied = 143776
tblOrders.RowsTotal = 221193
tblOrders.ProgressDetail = "143776/221193 65.00% copyRows ETA 1m 5s"
tblOrders.ETASeconds = 65
e.emitProgressHeartbeat(tblOrders, tsOrders)

e.emitTableStateChange(tblOrders, state.Apply.Completed, tsOrders)
Expand All @@ -245,7 +245,7 @@ func previewLogCutover() {
tbl.PercentComplete = 50
tbl.RowsCopied = 110000
tbl.RowsTotal = 221193
tbl.ProgressDetail = "110000/221193 50.00% copyRows ETA 2m 30s"
tbl.ETASeconds = 150
e.emitProgressHeartbeat(tbl, ts)

// Waiting for cutover
Expand Down Expand Up @@ -276,7 +276,6 @@ func previewLogDetailed() {
RowsCopied: 148102,
RowsTotal: 221193,
ETASeconds: 45,
ProgressDetail: "148102/221193 67.00% copyRows ETA 45s",
}

e.emit(append(tableKVs("Table started", tbl, ts),
Expand Down
32 changes: 2 additions & 30 deletions pkg/cmd/internal/templates/progress.go
Original file line number Diff line number Diff line change
Expand Up @@ -672,37 +672,9 @@ func FormatTableProgressWithActivity(t TableProgress, activityBar, activityLabel
return b.String()
}

// In-progress state - try to parse Spirit's progress detail
// In-progress state — rendered from the structured copy fields, which are
// the same source the PR comment renders from.
switch {
case t.ProgressDetail != "":
if info := ParseSpiritProgress(t.ProgressDetail); info != nil {
if ui.EstimateExceeded(info.RowsCopied, info.RowsTotal) && info.State == "copyRows" {
b.WriteString(formatEstimateExceededTable(t, info.RowsCopied, activityBar, activityLabel))
return b.String()
}

// Parsed successfully - show emoji progress bar with structured data
displayPercent := ui.RowCopyDisplayPercent(info.Percent, info.RowsCopied)
bar := ui.ProgressBarRowCopy(displayPercent)
fmt.Fprintf(&b, indentTable+progressSymbol(t.ChangeType)+"%s: %s %s%s\n", t.TableName, bar,
ui.FormatRowCopyPercent(info.Percent, info.RowsCopied, info.RowsTotal), throttledSuffix(t))
if t.DDL != "" {
b.WriteString(formatProgressDDLForDialect(t.Dialect, t.DDL))
}
// Rows and ETA on the same line, rendered from the structured ETA
// so the CLI and PR comment show the same value via FormatETA.
writeStructuredRowsAndETA(&b, t)
if info.State != "" && info.State != "copyRows" {
fmt.Fprintf(&b, indentDetail+"Status: %s\n", info.State)
}
} else {
// Can't parse - show raw detail
fmt.Fprintf(&b, indentTable+progressSymbol(t.ChangeType)+"%s:\n", t.TableName)
if t.DDL != "" {
b.WriteString(formatProgressDDLForDialect(t.Dialect, t.DDL))
}
fmt.Fprintf(&b, " %s\n", t.ProgressDetail)
}
case t.RowsTotal > 0 && t.RowsCopied == 0:
// Row total is known but the copy hasn't reported progress yet
Comment thread
aparajon marked this conversation as resolved.
// (Vitess VReplication / Spirit ramp-up — can take a while on a large
Expand Down
55 changes: 0 additions & 55 deletions pkg/cmd/internal/templates/progress_parse.go
Original file line number Diff line number Diff line change
@@ -1,22 +1,13 @@
package templates

import (
"math"
"regexp"
"strconv"

"github.com/block/schemabot/pkg/apitypes"
"github.com/block/schemabot/pkg/ddl"
"github.com/block/schemabot/pkg/schema"
"github.com/block/schemabot/pkg/state"
"github.com/block/schemabot/pkg/ui"
)

// spiritProgressPattern matches the row-copy prefix of a Spirit progress
// string, e.g. "71436/221193 32.30% copyRows". The ETA is carried separately as
// a structured field, so it is not parsed out of this string.
var spiritProgressPattern = regexp.MustCompile(`(\d+)/(\d+)\s+([\d.]+)%\s+(\w+)`)

// ProgressData contains data for rendering schema change progress.
type ProgressData struct {
ApplyID string
Expand Down Expand Up @@ -78,7 +69,6 @@ type TableProgress struct {
Throttled bool
ThrottleReason string
IsInstant bool
ProgressDetail string // e.g., Spirit: "12.5% copyRows ETA 1h 30m"
Shards []ShardProgress
}

Expand All @@ -105,39 +95,6 @@ type ShardCounts struct {
Cancelled int
}

// SpiritProgressInfo contains parsed Spirit progress information.
type SpiritProgressInfo struct {
RowsCopied int64
RowsTotal int64
Percent int
State string // "copyRows", "checksum", etc.
}

// ParseSpiritProgress parses a Spirit progress string like "71436/221193 32.30% copyRows ETA TBD"
// Returns nil if the string cannot be parsed.
func ParseSpiritProgress(progress string) *SpiritProgressInfo {
if progress == "" {
return nil
}

matches := spiritProgressPattern.FindStringSubmatch(progress)
if len(matches) < 5 {
return nil
}

rowsCopied, _ := strconv.ParseInt(matches[1], 10, 64)
rowsTotal, _ := strconv.ParseInt(matches[2], 10, 64)
percentFloat, _ := strconv.ParseFloat(matches[3], 64)
state := matches[4]

return &SpiritProgressInfo{
RowsCopied: rowsCopied,
RowsTotal: rowsTotal,
Percent: int(math.Round(percentFloat)),
State: state,
}
}

// Display-only task states. These are not persisted apply states (see pkg/applystate)
// but are used for per-table rendering in sequential mode.
const (
Expand Down Expand Up @@ -198,18 +155,6 @@ func ParseProgressResponse(result *apitypes.ProgressResponse) ProgressData {
Throttled: tbl.Throttled,
ThrottleReason: tbl.ThrottleReason,
IsInstant: tbl.IsInstant,
ProgressDetail: tbl.ProgressDetail,
}
// When a table carries an engine progress string, it is fresher than
// the stored copy fields, so prefer it and keep the percent, the rows
// line, and anything aggregated from them in agreement. The live
// progress API sends ProgressDetail empty (the drive loop does not
// persist it to the task record), so this override only takes effect
// for responses that populate the field, such as log preview fixtures.
if info := ParseSpiritProgress(tp.ProgressDetail); info != nil {
tp.PercentComplete = info.Percent
tp.RowsCopied = info.RowsCopied
tp.RowsTotal = info.RowsTotal
}
for _, sh := range tbl.Shards {
pct := int(sh.PercentComplete)
Expand Down
14 changes: 6 additions & 8 deletions pkg/cmd/internal/templates/progress_parse_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -181,20 +181,18 @@ func TestParseProgressResponseFiltersSpiritInternalTables(t *testing.T) {
assert.Equal(t, "users", data.Tables[0].TableName)
}

// Spirit's progress string is the freshest copy signal: when it parses, the
// structured percent and row counts follow it so every consumer renders the
// same numbers, and raw engine statuses normalize to canonical task states.
func TestParseProgressResponsePrefersSpiritProgressStringAndNormalizesStatus(t *testing.T) {
// The structured copy fields pass through untouched, and a raw engine phase
// string normalizes to its canonical task state.
func TestParseProgressResponseCarriesCopyFieldsAndNormalizesStatus(t *testing.T) {
result := &apitypes.ProgressResponse{
State: state.Apply.Running,
Tables: []*apitypes.TableProgressResponse{
{
TableName: "users",
Status: "copyRows",
RowsCopied: 100,
RowsTotal: 200,
PercentComplete: 50,
ProgressDetail: "71436/221193 32.30% copyRows ETA TBD",
RowsCopied: 71436,
RowsTotal: 221193,
PercentComplete: 32,
},
},
}
Expand Down
54 changes: 18 additions & 36 deletions pkg/cmd/internal/templates/progress_states_test.go
Original file line number Diff line number Diff line change
Expand Up @@ -867,10 +867,9 @@ func TestFormatTableProgress_SubPercentRowCopyShowsFraction(t *testing.T) {
assert.NotContains(t, output, " 0%")
}

// A Spirit row-copy reports its detail string and a structured ETA. The CLI
// renders the ETA from the structured field (the same source and FormatETA the
// PR comment uses), so the two surfaces show an identical "Rows … · ETA …" line
// even though the detail string itself no longer carries the ETA.
// A row copy renders its ETA from the structured field (the same source and
// FormatETA the PR comment uses), so the two surfaces show an identical
// "Rows … · ETA …" line.
func TestFormatTableProgress_RowCopyShowsStructuredETA(t *testing.T) {
tp := TableProgress{
TableName: "users",
Expand All @@ -880,7 +879,6 @@ func TestFormatTableProgress_RowCopyShowsStructuredETA(t *testing.T) {
RowsTotal: 100_000,
PercentComplete: 45,
ETASeconds: 340,
ProgressDetail: "45000/100000 45% copyRows",
}

output := FormatTableProgress(tp)
Expand Down Expand Up @@ -915,38 +913,22 @@ func TestFormatTableProgress_FailedRetryableKeepsProgress(t *testing.T) {
}

func TestFormatTableProgress_EstimateExceeded(t *testing.T) {
t.Run("structured progress", func(t *testing.T) {
tp := TableProgress{
TableName: "users",
ChangeType: "alter",
Status: state.Apply.Running,
RowsCopied: 145000,
RowsTotal: 100000,
PercentComplete: 145,
}

output := FormatTableProgress(tp)
assert.Contains(t, output, ui.ProgressBarActivity()+" Finalizing copy")
assert.Contains(t, output, "Rows copied: 145,000 so far")
assert.Contains(t, output, ui.EstimateExceededTooltip)
assert.NotContains(t, output, "145%")
assert.NotContains(t, output, "100%")
assert.NotContains(t, output, "100,000 / 100,000")
})

t.Run("parsed Spirit progress", func(t *testing.T) {
tp := TableProgress{
TableName: "users",
ChangeType: "alter",
Status: state.Apply.Running,
ProgressDetail: "145000/100000 100% copyRows ETA TBD",
}
tp := TableProgress{
TableName: "users",
ChangeType: "alter",
Status: state.Apply.Running,
RowsCopied: 145000,
RowsTotal: 100000,
PercentComplete: 145,
}

output := FormatTableProgress(tp)
assert.Contains(t, output, ui.ProgressBarActivity()+" Finalizing copy")
assert.Contains(t, output, "Rows copied: 145,000 so far")
assert.NotContains(t, output, "100%")
})
output := FormatTableProgress(tp)
assert.Contains(t, output, ui.ProgressBarActivity()+" Finalizing copy")
assert.Contains(t, output, "Rows copied: 145,000 so far")
assert.Contains(t, output, ui.EstimateExceededTooltip)
assert.NotContains(t, output, "145%")
assert.NotContains(t, output, "100%")
assert.NotContains(t, output, "100,000 / 100,000")
}

func TestFormatVSchemaStatus(t *testing.T) {
Expand Down
Loading
Loading