Skip to content

Commit 1e4aeff

Browse files
committed
feat: name the region that would not settle, and what the waiting cost (#271)
Stabilisation failures printed a bare list of attempt paths. Diagnosing one meant opening N PNGs and eyeballing them -- so `sleep 2` won, and suites got SLOWER as a consequence of diagnosis being hard. A maintainer reported a 10-minute suite dominated by stabilisation waiting, with sleeps adopted deliberately "to avoid debugging as much as possible". The information was already here and thrown away: AttemptsReporter compares every consecutive pair of attempts, and that comparison knows the region that changed. Print it, with the escape hatch: Could not get stable screenshot for 'index-with-ticker' within 1.2s (5 attempts). The page kept changing in 1 area, over 4 attempt pairs: [67,50,213,68] (left,top,right,bottom edges) -- 0.55% of the 800x600 image, changed in 4 of 4 pairs Always the same area, in every pair: that is an animation, clock, carousel or live counter. Exclude it and the page is stable without waiting: assert_matches_screenshot "index-with-ticker", skip_area: [67,50,213,68] <attempt paths> Animation vs churn is decided by count, not by shape: regions are clustered by overlap, and a cluster present in EVERY attempt pair is animating -- skip_area fixes it. Anything less is the page still rendering, where masking would hide real content, so the message says so and suggests nothing to mask. The suggested coordinates are the ones just measured. Guarded by following the advice on a real browser and a really unstable page (test/fixtures/app/ index-with-ticker.html): the failing run's own suggestion, pasted back in, makes the page stable. Fabricating the coordinate reds that test -- which is the check this gem lacked when it shipped RECORD_SCREENSHOTS=1 in its own error message for years while nothing read it. Success path: the run-level summary now reports the worst stabilisation it saw. A user who set `stability_time_limit: 2` had no way to learn their pages settle on the first retry, and without evidence tuning it down is guesswork. Run-level rather than per-assertion (per-test noise is the last thing a slow suite needs) and silent when nothing waited -- the same rule as the never-matched-selector line. It rides the fork-parallel fragment, since a run-level line that vanishes under Rails' default parallelize is #269 again; counts add, worst cases max. Pairs with #272 (masking is instant) and #279 (dead selectors are surfaced): "here is the region, mask it" is finally a complete workflow.
1 parent 7809756 commit 1e4aeff

12 files changed

Lines changed: 535 additions & 10 deletions

docs/configuration.md

Lines changed: 47 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -356,6 +356,53 @@ test 'stability_time_limit' do
356356
end
357357
```
358358

359+
### When the page will not settle
360+
361+
The failure names the area that kept changing, and hands you the command that
362+
fixes it:
363+
364+
```
365+
Could not get stable screenshot for 'index-with-ticker' within 1.2s (5 attempts).
366+
The page kept changing in 1 area, over 4 attempt pairs:
367+
[67,50,213,68] (left,top,right,bottom edges) -- 0.55% of the 800x600 image, changed in 4 of 4 pairs
368+
Always the same area, in every pair: that is an animation, clock, carousel or live counter.
369+
Exclude it and the page is stable without waiting:
370+
assert_matches_screenshot "index-with-ticker", skip_area: [67,50,213,68]
371+
<one annotated attempt image per line>
372+
```
373+
374+
The coordinates are measured, not guessed: they come from the comparisons the
375+
gem just ran between consecutive attempts, so pasting the suggested `skip_area`
376+
in works.
377+
378+
Read the "changed in N of N pairs" line before acting on it:
379+
380+
- **N of N — one area, every single pair.** Something is animating in one place:
381+
a clock, a carousel, a spinner, a live counter. `skip_area` is the fix, and
382+
since masking no longer waits it costs nothing.
383+
- **Fewer than N, or several areas each changing once.** The page is still
384+
*rendering*, not animating. Masking those areas would hide real content. The
385+
message says so and suggests nothing to mask — settle the page in a
386+
[readiness block](#the-readiness-block) instead, or raise `wait:`.
387+
388+
### Knowing what the waiting cost
389+
390+
Every run that waited for stability ends with what it actually paid:
391+
392+
```
393+
[snap_diff] 34 screenshots waited for the page to settle: 0.19s and 2 attempts at worst. Every screenshot settled on its first retry, so a lower stability_time_limit would cost less per screenshot.
394+
```
395+
396+
Two attempts is the floor — one capture, plus the retry that matched it. Hitting
397+
the floor across the whole run means no page was ever still moving when the
398+
retry was taken, so every `stability_time_limit` sleep was spent on a page that
399+
had already stopped. That is the evidence for tuning it *down*; without it,
400+
lowering the setting is guesswork, and guesswork loses to `sleep`.
401+
402+
Run-level and silent when nothing waited, for the same reason as the
403+
never-matched-selector line: a line printed on every screenshot is a line
404+
people learn to skip.
405+
359406
### Maximum wait limit
360407

361408
When the `stability_time_limit` is set, but no stable screenshot can be taken, a timeout occurs.

lib/snap_diff/attempts_reporter.rb

Lines changed: 134 additions & 4 deletions
Original file line numberDiff line numberDiff line change
@@ -1,23 +1,48 @@
11
# frozen_string_literal: true
22

33
require "fileutils"
4+
require "json"
45

56
require "snap_diff/comparison"
7+
require "snap_diff/region"
68

79
module SnapDiff
10+
# The message a user reads when a page would not hold still.
11+
#
12+
# It used to be a bare list of attempt paths (#271). That made diagnosis a
13+
# matter of opening N PNGs and eyeballing them, and faced with that versus
14+
# `sleep 2`, sleep wins -- so the suite got SLOWER as a consequence of the
15+
# diagnosis being hard. The information needed was already here and thrown
16+
# away: every consecutive pair of attempts is compared, and that comparison
17+
# knows the region that changed.
18+
#
19+
# So name it, and hand over the escape hatch that removes the need to sleep.
820
class AttemptsReporter
21+
# One place on the page that changed between attempts, and how many of
22+
# the attempt pairs it showed up in. `pairs == total` means it changed
23+
# EVERY time -- an animation, and `skip_area` is the fix. Fewer means the
24+
# page was still rendering there, and masking would hide a real change.
25+
Area = Struct.new(:region, :pairs)
26+
927
def initialize(snapshot, comparison_options, stability_options = {})
1028
@snapshot = snapshot
1129
@comparison_options = comparison_options
1230
@wait = stability_options[:wait]
1331
end
1432

1533
def generate
16-
attempts_screenshot_paths = @snapshot.find_attempts_paths
34+
# Sorted: `attempt_%02i` sorts lexically in capture order, and the
35+
# reader wants oldest-first regardless of what the glob hands back.
36+
attempts_screenshot_paths = @snapshot.find_attempts_paths.sort
1737

18-
annotate_attempts(attempts_screenshot_paths)
38+
areas, dimensions = annotate_attempts(attempts_screenshot_paths)
1939

20-
"Could not get stable screenshot within #{@wait}s:\n#{attempts_screenshot_paths.join("\n")}"
40+
[
41+
"Could not get stable screenshot for '#{@snapshot.full_name}' within #{@wait}s " \
42+
"(#{attempts_screenshot_paths.size} attempts).",
43+
*diagnosis_lines(areas, dimensions),
44+
*attempts_screenshot_paths
45+
].join("\n")
2146
end
2247

2348
def build_comparison_for(attempt_path, previous_attempt_path)
@@ -26,14 +51,25 @@ def build_comparison_for(attempt_path, previous_attempt_path)
2651

2752
private
2853

54+
# Annotates each attempt with its diff against the next one -- and keeps
55+
# the regions, which is the whole point of #271.
56+
#
57+
# @return [Array(Array<Area>, Array(Integer, Integer))] the clustered
58+
# changed areas and the [width, height] of the attempts.
2959
def annotate_attempts(attempts_screenshot_paths)
60+
regions = []
61+
dimensions = nil
3062
previous_file = nil
63+
3164
attempts_screenshot_paths.reverse_each do |file_name|
3265
if previous_file && File.exist?(previous_file)
3366
attempts_comparison = build_comparison_for(file_name, previous_file)
3467

3568
if attempts_comparison.different?
3669
FileUtils.mv(attempts_comparison.reporter.annotated_base_image_path, previous_file, force: true)
70+
region = attempts_comparison.difference.region
71+
regions << region if region
72+
dimensions ||= dimensions_of(attempts_comparison)
3773
else
3874
warn "[capybara-screenshot-diff] Some attempts was stable, but mistakenly marked as not: " \
3975
"#{previous_file} and #{file_name} are equal"
@@ -45,7 +81,101 @@ def annotate_attempts(attempts_screenshot_paths)
4581
previous_file = file_name
4682
end
4783

48-
previous_file
84+
# Worst offender first: the area that changed in the most pairs is the
85+
# one to act on, and a stable order keeps the message diffable.
86+
areas = cluster(regions).sort_by { |area| [-area.pairs, -area.region.size] }
87+
88+
[areas, dimensions]
89+
end
90+
91+
def dimensions_of(comparison)
92+
images = comparison.difference.comparison
93+
comparison.driver.dimension(images.base_image) if images&.base_image
94+
end
95+
96+
# Groups the per-pair regions into the places on the page they occupy: a
97+
# region that overlaps one we have already seen is the same place, moved
98+
# or resized, so the place grows to cover both.
99+
#
100+
# ponytail: first-overlap wins, so a chain of regions that each overlap
101+
# the next merges into one area. That is the right answer for the case
102+
# this message exists for (something animating in one spot) and only ever
103+
# UNDER-counts areas, which cannot turn churn into a masking suggestion.
104+
def cluster(regions)
105+
regions.each_with_object([]) do |region, areas|
106+
existing = areas.find { |area| area.region.intersect?(region) }
107+
if existing
108+
existing.region = union(existing.region, region)
109+
existing.pairs += 1
110+
else
111+
areas << Area.new(region, 1)
112+
end
113+
end
114+
end
115+
116+
def union(one, other)
117+
Region.from_edge_coordinates(
118+
[one.left, other.left].min,
119+
[one.top, other.top].min,
120+
[one.right, other.right].max,
121+
[one.bottom, other.bottom].max
122+
)
123+
end
124+
125+
def diagnosis_lines(areas, dimensions)
126+
return [] if areas.empty? || dimensions.nil?
127+
128+
total_pairs = areas.sum(&:pairs)
129+
# An area that changed in EVERY pair is animating. One that did not is
130+
# the page still rendering -- masking it would hide a real change.
131+
animating, settling = areas.partition { |area| area.pairs == total_pairs }
132+
133+
[
134+
" The page kept changing in #{count(areas.size, "area")}, over #{count(total_pairs, "attempt pair")}:",
135+
*areas.map { |area| " #{area_line(area, total_pairs, dimensions)}" },
136+
*animating_lines(animating),
137+
*settling_lines(settling, animating)
138+
]
139+
end
140+
141+
def area_line(area, total_pairs, dimensions)
142+
width, height = dimensions
143+
share = area.region.size.to_f / (width * height)
144+
145+
"#{area.region.to_edge_coordinates.to_json} (left,top,right,bottom edges) " \
146+
"-- #{Reporters::Default.percent(share)} of the #{width}x#{height} image, " \
147+
"changed in #{area.pairs} of #{total_pairs} pairs"
148+
end
149+
150+
# The escape hatch. Every coordinate here came off the comparison that
151+
# just ran -- never a placeholder, and never a knob nothing reads.
152+
def animating_lines(animating)
153+
return [] if animating.empty?
154+
155+
skip_area = animating.map { |area| area.region.to_edge_coordinates }
156+
skip_area = skip_area.first if skip_area.size == 1
157+
158+
[
159+
" Always the same area, in every pair: that is an animation, clock, carousel or live counter.",
160+
" Exclude it and the page is stable without waiting:",
161+
" assert_matches_screenshot #{@snapshot.full_name.to_s.inspect}, skip_area: #{skip_area.to_json}"
162+
]
163+
end
164+
165+
def settling_lines(settling, animating)
166+
return [] if settling.empty?
167+
168+
subject = animating.empty? ? "D" : "The other #{count(settling.size, "area")}: d"
169+
170+
[
171+
" #{subject}ifferent areas at different times -- the page is still rendering, not animating in one place.",
172+
" skip_area masks a fixed area and will not help here: settle the page first (a readiness",
173+
" block on the assertion -- see docs/configuration.md) or raise wait:."
174+
]
175+
end
176+
177+
def count(number, noun)
178+
"#{number} #{noun}#{"s" unless number == 1}"
49179
end
50180
end
51181
end

lib/snap_diff/reporters/default.rb

Lines changed: 9 additions & 2 deletions
Original file line numberDiff line numberDiff line change
@@ -61,6 +61,14 @@ def build_error_for_different_dimensions
6161

6262
NEW_LINE = "\n"
6363

64+
# The one place the gem turns a fraction of the image into prose.
65+
# Public because AttemptsReporter reports the same kind of number and
66+
# must say it the same way (#264 vocabulary).
67+
def self.percent(fraction)
68+
value = fraction * 100
69+
(value.positive? && value < 0.01) ? "<0.01%" : format("%.2f%%", value)
70+
end
71+
6472
# The thresholds a comparison is judged against, in the order they read
6573
# best. Only the ones actually set are printed -- see #thresholds.
6674
THRESHOLDS = [
@@ -146,8 +154,7 @@ def display_path(path)
146154
end
147155

148156
def percent(fraction)
149-
value = fraction * 100
150-
(value.positive? && value < 0.01) ? "<0.01%" : format("%.2f%%", value)
157+
self.class.percent(fraction)
151158
end
152159

153160
def base_image_path

lib/snap_diff/reporting.rb

Lines changed: 70 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -23,6 +23,9 @@ module Reporting
2323
@unmatched_selectors = Set.new
2424
@verified = 0
2525
@changed = 0
26+
@stable_captures = 0
27+
@worst_settle_seconds = 0.0
28+
@worst_settle_attempts = 0
2629

2730
class << self
2831
attr_reader :reporters, :mutex
@@ -74,6 +77,19 @@ def record_selector_use(selector, matched:)
7477
end
7578
end
7679

80+
# Remembers what a capture that DID settle cost (#271).
81+
#
82+
# Only the worst case is kept, because that is the number the setting
83+
# has to cover: an average would suggest a `stability_time_limit` that
84+
# is too low for the slowest page in the suite.
85+
def record_stable_capture(seconds, attempts)
86+
@mutex.synchronize do
87+
@stable_captures += 1
88+
@worst_settle_seconds = seconds if seconds > @worst_settle_seconds
89+
@worst_settle_attempts = attempts if attempts > @worst_settle_attempts
90+
end
91+
end
92+
7793
# @api private
7894
# Per-test isolation for this gem's own suite: everything {finalize!}
7995
# reports, cleared in one call. One surface rather than one reset per
@@ -86,6 +102,9 @@ def reset_run_totals!
86102
@unmatched_selectors.clear
87103
@verified = 0
88104
@changed = 0
105+
@stable_captures = 0
106+
@worst_settle_seconds = 0.0
107+
@worst_settle_attempts = 0
89108
end
90109
end
91110

@@ -222,6 +241,10 @@ def finalize!
222241
if (msg = never_matched_selectors_summary)
223242
$stdout.puts msg
224243
end
244+
245+
if (msg = stable_captures_summary)
246+
$stdout.puts msg
247+
end
225248
end
226249

227250
# --- fork-parallel reports (issue #258) ---------------------------
@@ -279,6 +302,9 @@ def dump_parallel_fragment
279302
"unmatched_selectors" => @mutex.synchronize { @unmatched_selectors.to_a },
280303
"verified" => @verified,
281304
"changed" => @changed,
305+
"stable_captures" => @stable_captures,
306+
"worst_settle_seconds" => @worst_settle_seconds,
307+
"worst_settle_attempts" => @worst_settle_attempts,
282308
"reporters" => @mutex.synchronize { @reporters.dup }
283309
.map { |reporter| reporter.dump_state if reporter.respond_to?(:dump_state) }
284310
}
@@ -315,6 +341,11 @@ def merge_parallel_fragments!
315341
payload.fetch("unmatched_selectors", []).each { |selector| @unmatched_selectors << selector }
316342
@verified += payload.fetch("verified", 0)
317343
@changed += payload.fetch("changed", 0)
344+
# Counts add up; worst cases do not -- the slowest page in the
345+
# run is the slowest page in whichever worker happened to run it.
346+
@stable_captures += payload.fetch("stable_captures", 0)
347+
@worst_settle_seconds = [@worst_settle_seconds, payload.fetch("worst_settle_seconds", 0.0)].max
348+
@worst_settle_attempts = [@worst_settle_attempts, payload.fetch("worst_settle_attempts", 0)].max
318349
end
319350

320351
reporters_snapshot = @mutex.synchronize { @reporters.dup }
@@ -383,6 +414,45 @@ def never_matched_selectors_summary
383414
"#{names.map(&:inspect).join(", ")}. " \
384415
"A selector that matches nothing masks nothing -- check for a typo or a stale selector."
385416
end
417+
418+
# What waiting for the page to settle actually cost, on the runs where
419+
# it WORKED (#271).
420+
#
421+
# The failure path names the region that would not settle; this is the
422+
# other half. A maintainer who set `stability_time_limit: 2` on the
423+
# docs' recommendation has no way to learn their pages settle on the
424+
# first retry -- and without evidence, tuning it down is guesswork,
425+
# which loses to `sleep`. The measurement is free: the stable
426+
# screenshoter already knows both numbers at the moment it succeeds.
427+
#
428+
# Run-level rather than per-assertion, and silent when nothing waited:
429+
# the same reasoning as {never_matched_selectors_summary}. A line
430+
# printed on every screenshot of every run is a line users learn to
431+
# skip, and per-test noise is exactly what a debugging aid must not
432+
# add to a suite already too slow.
433+
#
434+
# @return [String, nil] nil when no capture waited for stability
435+
def stable_captures_summary
436+
captures, seconds, attempts = @mutex.synchronize {
437+
[@stable_captures, @worst_settle_seconds, @worst_settle_attempts]
438+
}
439+
return if captures.zero?
440+
441+
label = (captures == 1) ? "1 screenshot" : "#{captures} screenshots"
442+
line = "[snap_diff] #{label} waited for the page to settle: " \
443+
"#{format("%.2f", seconds)}s and #{attempts} attempts at worst."
444+
445+
# Two attempts is the floor -- one capture, then the retry that
446+
# matched it. Hitting the floor everywhere means no page in the run
447+
# was ever still moving, so every sleep between attempts was spent
448+
# on a page that had already stopped.
449+
if attempts <= 2
450+
line += " Every screenshot settled on its first retry, so a lower " \
451+
"stability_time_limit would cost less per screenshot."
452+
end
453+
454+
line
455+
end
386456
end
387457
end
388458
end

0 commit comments

Comments
 (0)