diff --git a/TEMPLATES.md b/TEMPLATES.md index 8ae908346..8fcec83bc 100644 --- a/TEMPLATES.md +++ b/TEMPLATES.md @@ -2861,7 +2861,7 @@ _Last updated: 2026-01-01 00:00:0 ALTER TABLE `users` ADD INDEX `idx_email`(`email`); ``` - Rows: 914,707 / 1,466,232 · ETA: 3m 15s -- ℹ️ _Throttled: commit-latency 112.4ms >= 100ms_ +- ℹ️ _Throttled: commit-latency 112.4ms >= 100ms · backing off while database writes commit slowly ([docs](https://github.com/block/schemabot/blob/main/docs/throttle.md))_ **`products`**: ⏳ Queued @@ -5039,7 +5039,7 @@ Sequential mode: First complete, second paused by the engine's throttler ~ orders: 🟦🟦🟦🟦🟦🟦🟦🟦🟦🟦🟦🟦⬜⬜⬜⬜⬜⬜⬜⬜ 62% (throttled) ALTER TABLE `orders` ADD INDEX `idx_user_status`(`user_id`, `status`); • Rows: 3,100,000 / 5,000,000 - • ℹ️ Throttled: commit-latency 112.4ms >= 100ms + • ℹ️ Throttled: commit-latency 112.4ms >= 100ms · backing off while database writes commit slowly ~ products: ⏳ Queued ALTER TABLE `products` ADD COLUMN `weight_grams` int DEFAULT 0; diff --git a/docs/throttle.md b/docs/throttle.md new file mode 100644 index 000000000..1ee9cf39b --- /dev/null +++ b/docs/throttle.md @@ -0,0 +1,94 @@ +# Throttle reference + + + +## Table of Contents + +- [redo-aware](#redo-aware) +- [threads-running](#threads-running) +- [commit-latency](#commit-latency) +- [Throttled with no reason](#throttled-with-no-reason) + + + +When a schema change's progress bar carries a `(throttled)` annotation, the +engine's throttler is deliberately pausing the copy or the checksum verify to +protect the database. Throttling is backpressure, not a hang: the work resumes +on its own as soon as the pressure signal clears. A brief throttle needs no +attention; only a sustained one is worth the per-signal checks below. + +The annotation's tooltip shows the raw reason reported by the engine and a +short tip; the PR comment version also links this document. Reasons follow +the grammar ` `. When several signals +throttle at the same time, the reasons are joined with `; `. + +This page explains each signal: what it measures, why the engine pauses on it, +and what to look at when the throttle lasts longer than expected. + +## redo-aware + +``` +redo-aware 4 > 3 +``` + +Read this as: active threads greater than the instance's threshold. The +engine selects this algorithm when it detects an Aurora source. It counts +threads actively executing queries (from `performance_schema`) and subtracts +threads parked on Aurora's redo-log flush wait, which consume no CPU. When +the active count exceeds the instance's budget (vCPUs plus headroom), the +copy pauses until threads free up. The count deliberately includes the +copy's own read and apply threads, which are genuine CPU load, so on a small +instance the copy throttles against its own footprint. In the example, 4 +active threads exceed a budget of 3 on a 2-vCPU instance, a state the copy's +own threads can reach with little or no application load. + +**When to act.** Usually nothing: the throttle is self-limiting, trading copy +speed for CPU headroom. Because the copy's own threads count toward the +budget, a throttled copy on a small or even idle instance is normal and is +not evidence of application overload. If the copy must finish sooner, move +to a larger instance class; raising the copy's own concurrency does not help +while this signal is active, since the extra threads count against the same +budget. + +## threads-running + +``` +threads-running 21 > 18 +``` + +The same thread-budget protection as [redo-aware](#redo-aware), measured more +coarsely: the global `Threads_running` counter compared against the +instance's budget. The engine falls back to this signal when it lacks the +`performance_schema` access the redo-aware signal needs. Unlike redo-aware, +threads parked on redo-log waits count as load, so this signal is more +conservative. In the example, 21 running threads exceed a budget of 18 on a +16-vCPU instance. + +**When to act.** Same as redo-aware. Granting the engine's user read access +to `performance_schema` upgrades the signal to redo-aware. + +## commit-latency + +``` +commit-latency 112.4ms >= 100ms +``` + +The average commit latency on the database has crossed the engine's +threshold, the right-hand value in the reason (SchemaBot configures 100ms, +auto-enabled on Aurora). Slow commits mean the storage layer is saturating, +so the copy backs off before write latency degrades for the application. + +**When to act.** A sustained throttle points at storage pressure: check the +instance's write IOPS and commit latency metrics. Do not expect a +co-occurring redo-aware reason as confirmation: redo-aware subtracts exactly +the threads parked on redo-log waits, so a saturated redo log makes its +count fall rather than rise, and commit-latency is the signal designed to +notice. A sustained commit-latency throttle on its own says the instance is +undersized for the combined application and copy write load. + +## Throttled with no reason + +A throttler that predates reason reporting, or one that implements no reason +extension, reports the throttled flag with an empty reason. The progress +surfaces show the bare `(throttled)` annotation with no tooltip. The +backpressure semantics are the same; only the explanation is missing. diff --git a/pkg/cmd/internal/templates/progress.go b/pkg/cmd/internal/templates/progress.go index 3529c6adb..7524ebfc6 100644 --- a/pkg/cmd/internal/templates/progress.go +++ b/pkg/cmd/internal/templates/progress.go @@ -788,6 +788,13 @@ func writeThrottleTooltip(b *strings.Builder, t TableProgress) { if !t.Throttled || t.ThrottleReason == "" { return } + // The raw reason names the engine signal; the tip says what the pause + // protects. A reason whose signal has no tip renders alone so a new + // engine signal degrades to raw text rather than a wrong explanation. + if tip := ui.ThrottleTip(t.ThrottleReason); tip != "" { + fmt.Fprintf(b, indentDetail+"%sℹ️ Throttled: %s · %s%s\n", ANSIDim, t.ThrottleReason, tip, ANSIReset) + return + } fmt.Fprintf(b, indentDetail+"%sℹ️ Throttled: %s%s\n", ANSIDim, t.ThrottleReason, ANSIReset) } diff --git a/pkg/cmd/internal/templates/progress_states_test.go b/pkg/cmd/internal/templates/progress_states_test.go index ef4c7b4e3..cc6991e40 100644 --- a/pkg/cmd/internal/templates/progress_states_test.go +++ b/pkg/cmd/internal/templates/progress_states_test.go @@ -389,18 +389,19 @@ func TestFormatTableProgress_Checksumming(t *testing.T) { // A table slowed by the engine's throttler carries a "(throttled)" annotation // on its header line with the trigger explained in a dimmed tooltip, so a slow -// progress bar reads as deliberate backpressure (e.g. replica lag) rather than -// a hang. The annotation renders for the active copy and checksum phases only — -// a throttled flag on a terminal table would be stale. +// progress bar reads as deliberate backpressure (e.g. thread pressure) rather +// than a hang. The annotation renders for the active copy and checksum phases +// only — a throttled flag on a terminal table would be stale. A reason with an +// unrecognized signal still renders raw, with no tip attached. func TestFormatTableProgress_Throttled(t *testing.T) { copying := FormatTableProgress(TableProgress{ TableName: "orders", ChangeType: "alter", Status: state.Apply.Running, RowsCopied: 45000, RowsTotal: 100000, PercentComplete: 45, - Throttled: true, ThrottleReason: "replica-lag 12s > 10s", + Throttled: true, ThrottleReason: "redo-aware 4 > 3", }) assert.Contains(t, copying, "45% (throttled)", "the annotation lands on the header line next to the percent") - assert.Contains(t, copying, "ℹ️ Throttled: replica-lag 12s > 10s") + assert.Contains(t, copying, "ℹ️ Throttled: redo-aware 4 > 3 · backing off while the database's active threads exceed its budget") noReason := FormatTableProgress(TableProgress{ TableName: "orders", ChangeType: "alter", Status: state.Apply.Running, @@ -410,13 +411,22 @@ func TestFormatTableProgress_Throttled(t *testing.T) { assert.Contains(t, noReason, "45% (throttled)") assert.NotContains(t, noReason, "ℹ️ Throttled", "no tooltip without a reason") + unknownSignal := FormatTableProgress(TableProgress{ + TableName: "orders", ChangeType: "alter", Status: state.Apply.Running, + RowsCopied: 45000, RowsTotal: 100000, PercentComplete: 45, + Throttled: true, ThrottleReason: "disk-usage 95% > 90%", + }) + assert.Contains(t, unknownSignal, "ℹ️ Throttled: disk-usage 95% > 90%", + "an unrecognized signal still surfaces its raw reason") + assert.NotContains(t, unknownSignal, "·", "no tip separator without a recognized tip") + checksumming := FormatTableProgress(TableProgress{ TableName: "orders", ChangeType: "alter", Status: state.Task.Checksumming, ChecksumRowsChecked: 321450, ChecksumRowsTotal: 1466232, - Throttled: true, ThrottleReason: "threads-running 130 > 128", + Throttled: true, ThrottleReason: "threads-running 21 > 18", }) assert.Contains(t, checksumming, "🔍 Checksumming to verify data (21%) (throttled)") - assert.Contains(t, checksumming, "ℹ️ Throttled: threads-running 130 > 128") + assert.Contains(t, checksumming, "ℹ️ Throttled: threads-running 21 > 18 · backing off while the database's active threads exceed its budget") notThrottled := FormatTableProgress(TableProgress{ TableName: "orders", ChangeType: "alter", Status: state.Apply.Running, diff --git a/pkg/ui/throttle.go b/pkg/ui/throttle.go new file mode 100644 index 000000000..7661004db --- /dev/null +++ b/pkg/ui/throttle.go @@ -0,0 +1,58 @@ +package ui + +import "strings" + +// ThrottleDocURL points at the throttle reference doc, which explains each +// throttle signal and how to remediate it. Rendered next to a throttle tip so +// an operator can jump from the one-line tip to the full prose. The URL is +// deliberately the project's canonical public home, not derived from the +// configured GitHub host: that host serves users' schema repos, which do not +// carry this project's docs, so a host-derived link would always be broken. +const ThrottleDocURL = "https://github.com/block/schemabot/blob/main/docs/throttle.md" + +// ThrottleTip translates an engine throttle reason into a short operator-facing +// tip. Reasons follow the grammar " ", with +// several concurrently-throttling signals joined by "; ", so the tip is keyed +// on each part's leading signal token. Signals that read the same to a user +// (the two active-thread variants) share a tip, and duplicate tips collapse. +// A reason containing any unrecognized signal yields no tip at all — a partial +// explanation would silently bind to signals it does not cover, so an +// unrecognized signal always degrades the whole reason to its raw text rather +// than a wrong explanation. +func ThrottleTip(reason string) string { + seen := map[string]bool{} + var tips []string + for part := range strings.SplitSeq(reason, ";") { + part = strings.TrimSpace(part) + if part == "" { + continue + } + tip := throttleSignalTip(part) + if tip == "" { + return "" + } + if seen[tip] { + continue + } + seen[tip] = true + tips = append(tips, tip) + } + return strings.Join(tips, "; ") +} + +// throttleSignalTip maps one reason part to its tip by the leading signal +// token. The wording states what the pause protects, so a user reads a slowed +// bar as deliberate backpressure rather than a hang. The thread-budget tip +// stays neutral about whose load crossed the threshold: the engine counts its +// own copy threads toward the budget, so the pause is not evidence of +// application overload. +func throttleSignalTip(part string) string { + signal, _, _ := strings.Cut(part, " ") + switch signal { + case "redo-aware", "threads-running": + return "backing off while the database's active threads exceed its budget" + case "commit-latency": + return "backing off while database writes commit slowly" + } + return "" +} diff --git a/pkg/ui/throttle_test.go b/pkg/ui/throttle_test.go new file mode 100644 index 000000000..f9ab84b8b --- /dev/null +++ b/pkg/ui/throttle_test.go @@ -0,0 +1,41 @@ +package ui + +import ( + "testing" + + "github.com/stretchr/testify/assert" +) + +// TestThrottleTip verifies that every throttle signal the engine can emit maps +// to a short operator-facing tip, composite reasons collapse shared meanings, +// and any unrecognized signal suppresses the whole tip so the raw reason +// stands alone rather than binding a partial explanation to the wrong signal. +func TestThrottleTip(t *testing.T) { + tests := []struct { + name string + reason string + want string + }{ + {"redo-aware threads", "redo-aware 4 > 3", + "backing off while the database's active threads exceed its budget"}, + {"threads-running fallback shares the thread-budget tip", "threads-running 21 > 18", + "backing off while the database's active threads exceed its budget"}, + {"commit latency", "commit-latency 112.4ms >= 100ms", + "backing off while database writes commit slowly"}, + {"composite reasons join their tips", "redo-aware 4 > 3; commit-latency 112.4ms >= 100ms", + "backing off while the database's active threads exceed its budget; backing off while database writes commit slowly"}, + {"composite duplicate meanings collapse", "redo-aware 4 > 3; threads-running 21 > 18", + "backing off while the database's active threads exceed its budget"}, + {"unrecognized signal yields no tip", "mock throttler (always throttled)", ""}, + {"unrecognized segment suppresses the whole tip", "disk-usage 95% > 90%; commit-latency 112.4ms >= 100ms", ""}, + {"signal token must match exactly", "redo-awareness 4 > 3", ""}, + {"empty segments are ignored", "commit-latency 112.4ms >= 100ms; ", + "backing off while database writes commit slowly"}, + {"empty reason yields no tip", "", ""}, + } + for _, tt := range tests { + t.Run(tt.name, func(t *testing.T) { + assert.Equal(t, tt.want, ThrottleTip(tt.reason)) + }) + } +} diff --git a/pkg/webhook/templates/apply.go b/pkg/webhook/templates/apply.go index 8b0109c0e..84a4d299a 100644 --- a/pkg/webhook/templates/apply.go +++ b/pkg/webhook/templates/apply.go @@ -988,6 +988,14 @@ func writeThrottleTooltip(sb *strings.Builder, table TableProgressData) { if !table.Throttled || table.ThrottleReason == "" { return } + // The raw reason names the engine signal; the tip says what the pause + // protects, and links the reference doc for remediation prose. A reason + // whose signal has no tip renders alone so a new engine signal degrades + // to raw text rather than a wrong explanation. + if tip := ui.ThrottleTip(table.ThrottleReason); tip != "" { + fmt.Fprintf(sb, "- ℹ️ _Throttled: %s · %s ([docs](%s))_\n", escapeInlineMarkdown(table.ThrottleReason), tip, ui.ThrottleDocURL) + return + } fmt.Fprintf(sb, "- ℹ️ _Throttled: %s_\n", escapeInlineMarkdown(table.ThrottleReason)) } diff --git a/pkg/webhook/templates/apply_test.go b/pkg/webhook/templates/apply_test.go index 06de086ca..2f3493157 100644 --- a/pkg/webhook/templates/apply_test.go +++ b/pkg/webhook/templates/apply_test.go @@ -263,9 +263,10 @@ func TestRenderApplyStatusComment_Checksumming(t *testing.T) { // A table slowed by the engine's throttler carries a "(throttled)" annotation // on its header line — right where the eye checks progress — with the trigger // explained in a tooltip bullet, so a slow bar reads as deliberate backpressure -// (e.g. replica lag) rather than a hang. The reason is sanitized at the engine -// boundary, and the annotation renders only on active tables — a throttled flag -// on a terminal table would be stale. +// (e.g. thread pressure) rather than a hang. The reason is sanitized at the +// engine boundary, and the annotation renders only on active tables — a +// throttled flag on a terminal table would be stale. Composite reasons join +// their tips, and a reason with an unrecognized signal renders raw with no tip. func TestRenderApplyStatusComment_Throttled(t *testing.T) { data := ApplyStatusCommentData{ Database: "testapp", @@ -276,7 +277,7 @@ func TestRenderApplyStatusComment_Throttled(t *testing.T) { Tables: []TableProgressData{ {TableName: "orders", DDL: "ALTER TABLE `orders` ADD INDEX `idx_user_id` (`user_id`)", Status: "running", RowsCopied: 45000, RowsTotal: 100000, PercentComplete: 45, - Throttled: true, ThrottleReason: "replica-lag 12s > 10s"}, + Throttled: true, ThrottleReason: "redo-aware 4 > 3"}, {TableName: "users", DDL: "ALTER TABLE `users` ADD INDEX `idx_email` (`email`)", Status: "pending"}, }, } @@ -285,8 +286,18 @@ func TestRenderApplyStatusComment_Throttled(t *testing.T) { assert.Contains(t, result, "45% (throttled)", "the annotation lands on the header line next to the percent") - assert.Contains(t, result, "- ℹ️ _Throttled: replica-lag 12s > 10s_", - "the reason renders as a tooltip bullet under the detail list") + assert.Contains(t, result, "- ℹ️ _Throttled: redo-aware 4 > 3 · backing off while the database's active threads exceed its budget ([docs](https://github.com/block/schemabot/blob/main/docs/throttle.md))_", + "the reason renders as a tooltip bullet with its tip and the doc link") + + data.Tables[0].ThrottleReason = "redo-aware 4 > 3; commit-latency 112.4ms >= 100ms" + composite := RenderApplyStatusComment(data) + assert.Contains(t, composite, "- ℹ️ _Throttled: redo-aware 4 > 3; commit-latency 112.4ms >= 100ms · backing off while the database's active threads exceed its budget; backing off while database writes commit slowly ([docs](https://github.com/block/schemabot/blob/main/docs/throttle.md))_", + "concurrently-throttling signals join their tips in reason order") + + data.Tables[0].ThrottleReason = "commit-latency 112.4ms >= `100ms` [gradual]" + escapedWithTip := RenderApplyStatusComment(data) + assert.Contains(t, escapedWithTip, "- ℹ️ _Throttled: commit-latency 112.4ms >= \\`100ms\\` \\[gradual\\] · backing off while database writes commit slowly ([docs](https://github.com/block/schemabot/blob/main/docs/throttle.md))_", + "a recognized reason is escaped before its tip is appended") data.Tables[0].ThrottleReason = "" noReason := RenderApplyStatusComment(data) @@ -302,7 +313,7 @@ func TestRenderApplyStatusComment_Throttled(t *testing.T) { data.Tables[0].ThrottleReason = "signal_a 1_000ms >= `500ms` [gradual]" escaped := RenderApplyStatusComment(data) assert.Contains(t, escaped, "- ℹ️ _Throttled: signal\\_a 1\\_000ms >= \\`500ms\\` \\[gradual\\]_", - "markdown delimiters in an engine reason are escaped so they cannot cut the italic span short") + "markdown delimiters in an unrecognized reason are escaped and render with no tip") } // A throttled checksum verify carries the same header annotation and tooltip @@ -318,14 +329,14 @@ func TestRenderApplyStatusComment_ThrottledChecksumming(t *testing.T) { Tables: []TableProgressData{ {TableName: "orders", DDL: "ALTER TABLE `orders` ADD INDEX `idx_user_id` (`user_id`)", Status: "checksumming", ChecksumRowsChecked: 321450, ChecksumRowsTotal: 1466232, - Throttled: true, ThrottleReason: "threads-running 130 > 128"}, + Throttled: true, ThrottleReason: "threads-running 21 > 18"}, }, } result := RenderApplyStatusComment(data) assert.Contains(t, result, "🔍 Checksumming to verify data (21%) (throttled)") - assert.Contains(t, result, "- ℹ️ _Throttled: threads-running 130 > 128_") + assert.Contains(t, result, "- ℹ️ _Throttled: threads-running 21 > 18 · backing off while the database's active threads exceed its budget ([docs](https://github.com/block/schemabot/blob/main/docs/throttle.md))_") } func TestUnsafeDropIndexUsageTargets(t *testing.T) {