1
2
3
4
5
6
7
8
9
10
11
12
13
14
15
16
17
18
19
20
21
22
23
24
25
26
27
28
29
30
31
32
33
34
35
36
37
38
39
40
41
42
43
44
45
46
47
48
49
50
51
52
53
54
55
56
57
58
59
60
61
62
63
64
65
66
67
68
69
70
71
72
73
74
75
76
77
78
79
80
81
82
83
84
85
86
87
88
89
90
91
92
93
94
95
96
97
98
99
100
101
102
103
104
105
106
107
108
109
110
111
112
113
114
115
116
117
118
119
120
121
122
123
124
125
126
127
128
129
130
131
132
133
134
135
136
137
138
139
140
141
142
143
144
145
146
147
148
149
150
151
152
153
154
155
156
|
# frozen_string_literal: true
require "test_prof/ext/float_duration"
require "test_prof/ext/string_truncate"
module TestProf
module EventProf
class RSpecListener # :nodoc:
include Logging
using FloatDuration
using StringTruncate
NOTIFICATIONS = %i[
example_group_started
example_group_finished
example_started
example_finished
].freeze
def initialize
@profiler = EventProf.build
log :info, "EventProf enabled (#{@profiler.events.join(", ")})"
end
def example_group_started(notification)
return unless notification.group.top_level?
@profiler.group_started notification.group
end
def example_group_finished(notification)
return unless notification.group.top_level?
@profiler.group_finished notification.group
end
def example_started(notification)
@profiler.example_started notification.example
end
def example_finished(notification)
@profiler.example_finished notification.example
end
def print
@profiler.each(&method(:report))
end
def report(profiler)
result = profiler.results
time_percentage = time_percentage(profiler.total_time, profiler.absolute_run_time)
msgs = []
msgs <<
<<~MSG
EventProf results for #{profiler.event}
Total time: #{profiler.total_time.duration} of #{profiler.absolute_run_time.duration} (#{time_percentage}%)
Total events: #{profiler.total_count}
Top #{profiler.top_count} slowest suites (by #{profiler.rank_by}):
MSG
result[:groups].each do |group|
description = group[:id].top_level_description
location = group[:id].metadata[:location]
time = group[:time]
run_time = group[:run_time]
time_percentage = time_percentage(time, run_time)
msgs <<
<<~GROUP
#{description.truncate} (#{location}) – #{time.duration} (#{group[:count]} / #{group[:examples]}) of #{run_time.duration} (#{time_percentage}%)
GROUP
end
if result[:examples]
msgs << "\nTop #{profiler.top_count} slowest tests (by #{profiler.rank_by}):\n\n"
result[:examples].each do |example|
description = example[:id].description
location = example[:id].metadata[:location]
time = example[:time]
run_time = example[:run_time]
time_percentage = time_percentage(time, run_time)
msgs <<
<<~GROUP
#{description.truncate} (#{location}) – #{time.duration} (#{example[:count]}) of #{run_time.duration} (#{time_percentage}%)
GROUP
end
end
log :info, msgs.join
stamp!(profiler) if EventProf.config.stamp?
end
def stamp!(profiler)
result = profiler.results
stamper = RSpecStamp::Stamper.new
examples = Hash.new { |h, k| h[k] = [] }
(result[:groups].to_a + result.fetch(:examples, []).to_a)
.map { |obj| obj[:id].metadata[:location] }.each do |location|
file, line = location.split(":")
examples[file] << line.to_i
end
examples.each do |file, lines|
stamper.stamp_file(file, lines.uniq)
end
msgs = []
msgs <<
<<~MSG
RSpec Stamp results
Total patches: #{stamper.total}
Total files: #{examples.keys.size}
Failed patches: #{stamper.failed}
Ignored files: #{stamper.ignored}
MSG
log :info, msgs.join
end
def time_percentage(time, total_time)
(time / total_time * 100).round(2)
end
end
end
end
# Register EventProf listener
TestProf.activate("EVENT_PROF") do
TestProf::EventProf::CustomEvents.activate_all(ENV["EVENT_PROF"])
RSpec.configure do |config|
listener = nil
config.before(:suite) do
listener = TestProf::EventProf::RSpecListener.new
config.reporter.register_listener(
listener, *TestProf::EventProf::RSpecListener::NOTIFICATIONS
)
end
config.after(:suite) { listener&.print }
end
end
|
