diff --git a/stats/execution_outcomes.go b/stats/execution_outcomes.go index 8b25c5f..abd9f64 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 { } fmt.Fprintf(&b, - "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. + fmt.Fprintf(&b, + "\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 }