Skip to content

Commit 385d9ea

Browse files
chore(spec): per-test wall-clock timing + documentation reporter
The default rspec progress (dots) hides which test is in flight when a runner stalls. Last week's CI on Ruby 3.4 spent 41 minutes silently between two examples — the log only shows DEPRECATION warnings before and after, so the culprit was unidentifiable. Adds .rspec config (--format documentation, --profile 25) and a support/timing.rb hook that warns: [timing] start <full description> [timing] N.NN s <pass|fail> <full description> on each example. Two effects: * A hung runner now leaves a 'start ...' breadcrumb so the next person knows exactly which spec was mid-flight. * End-of-run --profile output lists the 25 slowest, which surfaces the flake culprits without having to scan the whole transcript.
1 parent 0d2214b commit 385d9ea

2 files changed

Lines changed: 33 additions & 0 deletions

File tree

‎.rspec‎

Lines changed: 3 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,3 @@
1+
--require spec_helper
2+
--format documentation
3+
--profile 25

‎spec/support/timing.rb‎

Lines changed: 30 additions & 0 deletions
Original file line numberDiff line numberDiff line change
@@ -0,0 +1,30 @@
1+
# frozen_string_literal: true
2+
3+
# Per-test wall-clock timing emitted to STDOUT so CI logs surface which
4+
# example is in flight when a runner stalls. The default `--format
5+
# documentation` reporter prints test names but not timing; `--profile`
6+
# only summarises at the end (no help when the run hangs before reaching
7+
# the summary). This hook fills the gap: every example logs
8+
# `[timing] start ...` on enter and `[timing] N.NN s ...` on exit with
9+
# its full description path, so an unattended runner stuck mid-test
10+
# leaves a clear breadcrumb.
11+
RSpec.configure do |config|
12+
config.before(:each) do |example|
13+
example.metadata[:timing_started_at] = Process.clock_gettime(Process::CLOCK_MONOTONIC)
14+
warn "[timing] start #{example.full_description}"
15+
end
16+
17+
config.after(:each) do |example|
18+
started_at = example.metadata[:timing_started_at]
19+
next unless started_at
20+
21+
elapsed = Process.clock_gettime(Process::CLOCK_MONOTONIC) - started_at
22+
status = example.exception ? 'fail' : 'pass'
23+
warn format(
24+
'[timing] %<elapsed>.2f s %<status>s %<description>s',
25+
elapsed: elapsed,
26+
status: status,
27+
description: example.full_description
28+
)
29+
end
30+
end

0 commit comments

Comments
 (0)