Skip to content

HTTPS clone URL

Subversion checkout URL

You can clone with HTTPS or Subversion.

Download ZIP

Loading…

Reporting load time to formatters #841

Closed
wants to merge 6 commits into from

4 participants

@JonRowe
Owner

This is the start of an implementation of measuring load time and reporting it via formatters. I wanted to get feedback on roughly how this works before I went much further along with it. Basically the idea is to store the start time as soon as possible in config (which allows it to be overridden by spork or anything else), and then compare that to the start time on start.

At the moment this is a breaking change (because of the extra argument to start). I weighed this up against having an extra method, or adding in if's to work around it, but I think in the longer run it'd be better just to do this even if it means waiting until RSpec 3.

Thoughts? If this is generally agreeable I'll continue and start on the formatters.

This is in reference to #489

lib/rspec/core/formatters/base_formatter.rb
@@ -39,9 +39,10 @@ def initialize(output)
# is {#example_group_started}.
#
# @param example_count
- def start(example_count)
+ def start(example_count,load_time)
@myronmarston Owner

Spaces,please.

(andbelowaswell)

Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
@samphippen
Collaborator

This implementation seems fine, but I don't see any way to get output, is there a way to do this that I'm missing?

@JonRowe
Owner

Nope, wanted an OK on this before implementing it in the formatters.

@samphippen
Collaborator

@JonRowe I took a look through this. It looks good, can you add the formatters so we can try it out?

@JonRowe
Owner

I've rebased this and added an example of how load time could be reported to the base text formatter. As it stands this is a breaking change because of the whole protocol change on formatters. But I have an idea, rather than adding in additional paramters, if we changed the reporter to check for implementation before sending notifications:

def notify(method, *args, &block)
  @formatters.each do |formatter|
    formatter.send(method, *args, &block) if formatter.respond_to? method
  end
end

Then we could implement these extra details as new notifications, and thus make the protocol slightly more flexible at the cost of including another conditional... Thought? @samphippen @myronmarston ?

@samphippen
Collaborator

oooooh, I'm not sure if this is necessary. I like this because it means we can add new notifications as and when we want to as it not being a breaking change. My other thought would be to have formatters take a details hash and add keys as necessary. I don't have strong thoughts either way though.

@JonRowe
Owner

I prefer sending messages over using an arguments hash, because I feel we'd have similar issues with changing the hash keys required/desired, also we'd still have to make a breaking change to switch to the hash.

@soulcutter
Collaborator

New notifications rather than adding parameters to an existing notification... I don't know about this. I feel notifications should be event-based rather than content-based. Still, you can add a new notification without breaking existing formatters if you add that new notification to BaseFormatter as a no-op... the only people that would break for are those not inheriting from BaseFormatter -- are there actually people doing this?

What can a formatter do to be compatible with adding params? def start(example_count, *extra_args) extra_args here would capture any junk you don't care about.

While it would be a breaking change, the more I think about it, the more I think that any notification should receive one argument, which would be an event object. This event object could be a Struct or Hash or some derivative, but that object would give us a place where we could put deprecation warnings when we do want to change things.

But that will be a massive breaking change, you say? I am thinking that if you made it so that any formatter uses new syntax that registers it to receive specific notifications could receive event objects. That could be the migration path, essentially. Then any formatter that does not register itself for events will get a deprecation message, but get the old variable-number-of-params methods invoked.

@JonRowe
Owner

I would like the option of not having to inherit when writing formatters, I'm in favour of making a breaking chance in RSpec 3 surrounding formatters to make it a more event based system, but I'd still like to get the couple of PR's currently existing out for the next RSpec release (given as RSpec 3 could be a way off) it just seems a more community orientated approach to say 'lets do this non breaking now, and then refactor into a better way for 3'

@soulcutter
Collaborator

I think I can code up a compromise/alternative in the next couple of days.

@samphippen
Collaborator

@JonRowe did the formatter api changes get merged, can this be updated for that now?

@JonRowe
Owner

Not yet, don't worry, it's on my to do list :P

@JonRowe JonRowe closed this
Sign up for free to join this conversation on GitHub. Already have an account? Sign in to comment
This page is out of date. Refresh to see the latest.
View
4 lib/rspec/core/configuration.rb
@@ -170,6 +170,9 @@ def self.add_setting(name, opts={})
# end
add_setting :treat_symbols_as_metadata_keys_with_true_values
+ # Record the start time of the spec suite to measure load time
+ add_setting :start_time
+
# @private
add_setting :tty
# @private
@@ -184,6 +187,7 @@ def self.add_setting(name, opts={})
attr_reader :backtrace_cleaner
def initialize
+ @start_time = Time.now
@expectation_frameworks = []
@include_or_extend_modules = []
@mock_framework = nil
View
6 lib/rspec/core/formatters/base_formatter.rb
@@ -13,7 +13,7 @@ module Formatters
class BaseFormatter
include Helpers
attr_accessor :example_group
- attr_reader :duration, :examples, :output
+ attr_reader :duration, :examples, :output, :load_time
attr_reader :example_count, :pending_count, :failure_count
attr_reader :failed_examples, :pending_examples
@@ -27,6 +27,7 @@ def initialize(output)
@failed_examples = []
@pending_examples = []
@example_group = nil
+ @load_time = 0
end
# @api public
@@ -39,9 +40,10 @@ def initialize(output)
# is {#example_group_started}.
#
# @param example_count
- def start(example_count)
+ def start(example_count, load_time)
start_sync_output
@example_count = example_count
+ @load_time = load_time
end
# @api public
View
2  lib/rspec/core/formatters/base_text_formatter.rb
@@ -45,7 +45,7 @@ def colorise_summary(summary)
def dump_summary(duration, example_count, failure_count, pending_count)
super(duration, example_count, failure_count, pending_count)
dump_profile unless mute_profile_output?(failure_count)
- output.puts "\nFinished in #{format_duration(duration)}\n"
+ output.puts "\nFinished in #{format_duration(duration)} (Files took #{format_duration(load_time)} to load)\n"
output.puts colorise_summary(summary_line(example_count, failure_count, pending_count))
dump_commands_to_rerun_failed_examples
end
View
4 lib/rspec/core/formatters/html_formatter.rb
@@ -33,8 +33,8 @@ def example_number
@example_number
end
- def start(example_count)
- super(example_count)
+ def start(example_count, load_time)
+ super(example_count, load_time)
@printer.print_html_start
@printer.flush
end
View
7 lib/rspec/core/reporter.rb
@@ -37,9 +37,10 @@ def report(expected_example_count, seed=nil)
end
end
- def start(expected_example_count)
- @start = RSpec::Core::Time.now
- notify :start, expected_example_count
+ def start(expected_example_count, time = RSpec::Core::Time.now)
+ @start = time
+ load_time = (@start - RSpec.configuration.start_time).to_f
+ notify :start, expected_example_count, load_time
end
def message(message)
View
11 spec/rspec/core/configuration_spec.rb
@@ -1516,5 +1516,16 @@ def metadata_hash(*args)
expect(groups.ordered).to eq([4, 3, 2, 1])
end
end
+
+ describe 'recording spec start time (for measuring load)' do
+ it 'returns a time' do
+ expect(config.start_time).to be_a Time
+ end
+ it 'is configuratble' do
+ time = Time.new - 5
+ config.start_time = time
+ expect(config.start_time).to eq time
+ end
+ end
end
end
View
14 spec/rspec/core/formatters/base_formatter_spec.rb
@@ -26,6 +26,20 @@
end
end
+ describe "start" do
+ before do
+ formatter.start 42, 3.234
+ end
+
+ it 'has captured example_count' do
+ expect(formatter.example_count).to eq 42
+ end
+
+ it 'has captured load_time' do
+ expect(formatter.load_time).to eq 3.234
+ end
+ end
+
describe "read_failed_line" do
it "deals gracefully with a heterogeneous language stack trace" do
exception = double(:Exception, :backtrace => [
View
4 spec/rspec/core/formatters/progress_formatter_spec.rb
@@ -6,7 +6,7 @@
before do
@output = StringIO.new
@formatter = RSpec::Core::Formatters::ProgressFormatter.new(@output)
- @formatter.start(2)
+ @formatter.start(2, 0)
@formatter.stub(:color_enabled?).and_return(false)
end
@@ -23,7 +23,7 @@
end
it "pushes nothing on start" do
- @formatter.start(4)
+ @formatter.start(4, 0)
expect(@output.string).to eq("")
end
View
12 spec/rspec/core/reporter_spec.rb
@@ -15,6 +15,18 @@ module RSpec::Core
end
end
+ describe 'start' do
+ it 'notifies the formatter of start with example count and load time' do
+ formatter = double("formatter")
+ example = double("example")
+ reporter = Reporter.new(formatter)
+
+ formatter.should_receive(:start).with(0,5)
+ RSpec.configuration.start_time = 5
+ reporter.start 0, 10
+ end
+ end
+
context "given one formatter" do
it "passes messages to that formatter" do
formatter = double("formatter")
Something went wrong with that request. Please try again.