From 04764c3eef5baa60dc344498963aa1a6ded7abad Mon Sep 17 00:00:00 2001 From: bdchatham Date: Sat, 29 Aug 2026 10:22:21 -0700 Subject: [PATCH] feat(stats): state both goodput ratios, per run and per operation TOT-005 through TOT-008. Reporting one ratio hides whichever layer it divides away, so the run states both: committed over every send it attempted, and committed over the sends an endpoint accepted. The first answers what the profile asked for. A run whose endpoint refuses half shows a halved number rather than a healthy one measured over the survivors. The second isolates chain execution, which is the number to read when the RPC layer is not under test. The gap between them is the rejection share, so the report names that too. An indeterminate status counts in the denominator and never in the numerator. Counting it in the numerator reports a success nobody saw; dropping it from the denominator reports a healthy ratio over the survivors, which is the defect this feature removes one layer up. Every operation carries its own ledger. The run-level total cannot separate a revert rate spread evenly across operations from one concentrated in a single call, and those point at different things: the chain, or the workload. A run reporting 46% goodput where one operation sits at 0% and another at 98% now says so. It prints as a second line under each operation rather than widening the first, so anything parsing the existing format keeps working. Co-Authored-By: Claude Opus 5 (1M context) --- stats/execution_outcomes.go | 54 +++++++++++++++++++++++++++--- stats/execution_outcomes_test.go | 57 ++++++++++++++++++++++++++++++++ stats/logger.go | 35 +++++++++++++++++++- 3 files changed, 141 insertions(+), 5 deletions(-) diff --git a/stats/execution_outcomes.go b/stats/execution_outcomes.go index b4e1d81..1d4f2cb 100644 --- a/stats/execution_outcomes.go +++ b/stats/execution_outcomes.go @@ -23,8 +23,11 @@ type ExecutionOutcomes struct { // set by hand. A bool that can disagree with the counts beside it is the // defect this type exists to prevent. Tracked bool - // Accepted is the denominator: sends an endpoint took. A send that returned - // an error never reached the chain, so it cannot have an outcome. + // Attempted is every send the run made. Accepted is the subset an endpoint + // took; a send that returned an error never reached the chain, so it cannot + // have an outcome. The two are separate denominators and the report states + // both ratios, because each divides a different layer away. + Attempted uint64 `json:"attempted"` Accepted uint64 `json:"accepted"` Committed uint64 `json:"committed"` Reverted uint64 `json:"reverted"` @@ -40,6 +43,41 @@ type ExecutionOutcomes struct { ReapAfter time.Duration `json:"reap_after"` } +// Rejected is a send an endpoint refused. It is a fact about the RPC layer, and +// the gap between the two goodput ratios below is exactly its share. +func (e ExecutionOutcomes) Rejected() uint64 { + if e.Attempted < e.Accepted { + return 0 + } + return e.Attempted - e.Accepted +} + +// GoodputOfAttempted is committed over every send the run made. It answers what +// the profile asked for: a run whose endpoint refuses half shows a halved +// number here rather than a healthy one measured over the survivors. +func (e ExecutionOutcomes) GoodputOfAttempted() float64 { + return ratio(e.Committed, e.Attempted) +} + +// GoodputOfAccepted is committed over the sends an endpoint took. It isolates +// chain execution, which is the number to read when the RPC layer is not what +// is under test. +// +// An indeterminate status counts in this denominator and never in the +// numerator. A run that could not observe four tenths of its transactions +// reports a lower ratio and a separate unavailable count, so a reader can tell +// that apart from four tenths that failed. +func (e ExecutionOutcomes) GoodputOfAccepted() float64 { + return ratio(e.Committed, e.Accepted) +} + +func ratio(n, d uint64) float64 { + if d == 0 { + return 0 + } + return float64(n) / float64(d) +} + // executed is the transactions a receipt spoke for. It is the honest // denominator for a revert share: dividing reverts by Accepted understates the // problem in proportion to how much of the run went unobserved. @@ -135,8 +173,9 @@ func (e ExecutionOutcomes) String() string { } b.WriteString(fmt.Sprintf( - "Accepted by an endpoint: %d. Every count below is a share of that number.\n"+ - "A send that returned an error never reached the chain.\n\n", e.Accepted)) + "Offered %d, accepted %d, rejected %d. Every count below is a share of the\n"+ + "%d accepted: a send that returned an error never reached the chain.\n\n", + e.Attempted, e.Accepted, e.Rejected(), e.Accepted)) b.WriteString(" Execution: a receipt said what the chain did.\n") e.row(&b, "committed", e.Committed, "") @@ -155,6 +194,13 @@ func (e ExecutionOutcomes) String() string { e.row(&b, "unrecorded", e.Unrecorded, "") e.row(&b, "unaccounted", e.unaccounted(), "") + // Both ratios, never one. Reporting one alone hides whichever layer it + // divides away, and the gap between them is the endpoint's rejection share. + b.WriteString(fmt.Sprintf( + "\nGoodput: %.2f%% of the %d offered, %.2f%% of the %d accepted.\n", + e.GoodputOfAttempted()*100, e.Attempted, + e.GoodputOfAccepted()*100, e.Accepted)) + var coverage float64 if e.Accepted > 0 { coverage = float64(e.executed()) / float64(e.Accepted) * 100 diff --git a/stats/execution_outcomes_test.go b/stats/execution_outcomes_test.go index 592f3f4..8962317 100644 --- a/stats/execution_outcomes_test.go +++ b/stats/execution_outcomes_test.go @@ -115,3 +115,60 @@ func TestReapAfterReachesTheReport(t *testing.T) { "(reaped after 7s)", "expired was printed without the deadline that produced it") } + +// TestBothRatiosAreStated covers TOT-007. Reporting one alone hides whichever +// layer it divides away, so the run states both and never leaves the second to +// the reader's arithmetic. +func TestBothRatiosAreStated(t *testing.T) { + // An endpoint refused half. Chain execution was perfect on what got through. + e := ExecutionOutcomes{Tracked: true, Attempted: 200, Accepted: 100, Committed: 100} + + require.InDelta(t, 0.5, e.GoodputOfAttempted(), 0.001, + "the offered ratio read as healthy while the endpoint refused half the run") + require.InDelta(t, 1.0, e.GoodputOfAccepted(), 0.001, + "the accepted ratio blamed the chain for the endpoint's refusals") + + got := e.String() + require.Contains(t, got, "50.00% of the 200 offered") + require.Contains(t, got, "100.00% of the 100 accepted") + require.Contains(t, got, "rejected 100", + "the gap between the two ratios is the rejection share, so the report names it") +} + +// TestAnUnobservedTransactionLowersTheRatio covers the clarification that an +// indeterminate status counts in the denominator and never in the numerator. +// +// The alternative reads worse either way. Counting it in the numerator reports a +// success the run never saw. Dropping it from the denominator reports a healthy +// ratio measured over the survivors, which is the same defect this feature +// removes one layer up. +func TestAnUnobservedTransactionLowersTheRatio(t *testing.T) { + e := ExecutionOutcomes{Tracked: true, Attempted: 100, Accepted: 100, Committed: 60, StatusUnavailable: 40} + + require.InDelta(t, 0.6, e.GoodputOfAccepted(), 0.001, + "an unobserved transaction was excused from the denominator") + require.Contains(t, e.String(), "status_unavailable", + "the ratio dropped with no count beside it saying whether the chain or the run caused it") +} + +// TestARevertAndADropStaySeparate covers TOT-008. The system under test produces +// a revert. The mempool or this run's own timeout produces a drop. One count +// covering both would report a chain problem for a deadline the run chose. +func TestARevertAndADropStaySeparate(t *testing.T) { + got := ExecutionOutcomes{ + Tracked: true, Attempted: 100, Accepted: 100, Reverted: 40, Expired: 60, ReapAfter: 30 * time.Second, + }.String() + + require.Regexp(t, `reverted\s+40`, got) + require.Regexp(t, `expired\s+60`, got) + require.Less(t, strings.Index(got, "Execution: a receipt said what the chain did."), + strings.Index(got, "Delivery only, run gave up"), + "a revert and a drop were printed under one heading, so a reader cannot tell which layer caused what") +} + +// TestRejectedNeverGoesNegative guards the subtraction. Attempted and Accepted +// are summed from the same snapshot, but a future caller could pass them apart. +func TestRejectedNeverGoesNegative(t *testing.T) { + require.Zero(t, ExecutionOutcomes{Attempted: 1, Accepted: 5}.Rejected(), + "an inverted pair underflowed into a huge rejection count") +} diff --git a/stats/logger.go b/stats/logger.go index cf71ea1..0ff117c 100644 --- a/stats/logger.go +++ b/stats/logger.go @@ -37,6 +37,11 @@ type OperationReport struct { LatencyP99 time.Duration `json:"latency_p99_ns"` SampleCount int `json:"sample_count"` Window time.Duration `json:"window_ns"` + // Outcomes is this operation's share of the run's ledger. The run-level + // totals cannot separate a revert rate spread evenly across operations from + // one concentrated in a single call, and those are different findings: the + // first points at the chain, the second at the workload. + Outcomes ExecutionOutcomes `json:"outcomes"` } // LoadTestStatistics represents basic load test metrics @@ -110,6 +115,15 @@ func (fs *FinalStats) String() string { op.LatencyP99.Round(time.Millisecond), op.SampleCount, op.Successes, op.Window.Round(time.Millisecond)) + // A second line rather than a wider first one. The line above is at + // its readable limit, and anything parsing it keeps working. + if op.Outcomes.Tracked { + result += fmt.Sprintf( + " outcomes: committed=%d reverted=%d expired=%d unobserved=%d | goodput %.2f%% offered, %.2f%% accepted\n", + op.Outcomes.Committed, op.Outcomes.Reverted, op.Outcomes.Expired, + op.Outcomes.StatusUnavailable, + op.Outcomes.GoodputOfAttempted()*100, op.Outcomes.GoodputOfAccepted()*100) + } } } @@ -200,6 +214,11 @@ func (l *Logger) BuildFinalStats( scenarioDistribution[scenario] = count } + // Read before the loop below: every per-operation ledger carries it, and a + // report whose operations disagree with its totals about whether the run + // measured anything is worse than one that reports nothing. + incl, tracked := inclusion.Get() + // Sorted by scenario then operation: Go map iteration order is unspecified, and // a report whose lines move cannot be compared against another run. operations := l.collector.GetOperationStats() @@ -215,6 +234,19 @@ func (l *Logger) BuildFinalStats( LatencyP99: op.P99Latency, SampleCount: op.SampleCount, Window: op.Window, + Outcomes: ExecutionOutcomes{ + Tracked: tracked, + Attempted: op.Count, + Accepted: op.Successes, + Committed: op.Committed, + Reverted: op.Reverted, + Expired: op.Expired, + DroppedAtCap: op.DroppedAtCap, + DroppedAtHandoff: op.DroppedAtHandoff, + StatusUnavailable: op.StatusUnavailable, + Unrecorded: op.Unrecorded, + ReapAfter: reapAfter, + }, }) } @@ -260,6 +292,7 @@ func (l *Logger) BuildFinalStats( // feature removes; only InflightAtShutdown is the tracker's alone. execution := ExecutionOutcomes{ReapAfter: reapAfter} for _, op := range operations { + execution.Attempted += op.Count execution.Accepted += op.Successes execution.Committed += op.Committed execution.Reverted += op.Reverted @@ -269,7 +302,7 @@ func (l *Logger) BuildFinalStats( execution.StatusUnavailable += op.StatusUnavailable execution.Unrecorded += op.Unrecorded } - if incl, ok := inclusion.Get(); ok { + if tracked { execution.Tracked = true execution.InflightAtShutdown = incl.InflightAtShutdown }