diff --git a/README.md b/README.md index b7652ed..8514a19 100644 --- a/README.md +++ b/README.md @@ -44,6 +44,13 @@ which results will be collected. bundle exec rake rspec_profiling:install ``` +If you are planning on using `sqlite` or `pg` ensure to add the depency to your gemfile + +``` + gem 'sqlite', require: false + gem 'pg', require: false +``` + ## Usage ### Choose a version control system @@ -74,14 +81,46 @@ RspecProfiling.configure do |config| end ``` +#### Custom Event Subscriptions + +```Ruby +RspecProfiling.configure do |config| + config.events = %w[event1 event2] +end +``` + +Note that custom events are only currenly reported by the CSV collector. + +#### Custom Event Recording + +It is possible to record the event metadata for a spec. + +```Ruby + describe 'Records all active record queries', record_events: %w[sql.active_record] do + it 'Records Rails deprecations', record_events: %w[deprecation.rails] do + ... + end + it 'Records nothing' do + ... + end + end +``` + ### Choose a results collector Results are collected just by running the specs. #### SQLite3 -By default, profiles are collected in an SQL database. Make sure you've -run the installation rake task before attempting. +Make sure you've run the installation rake task before attempting. + +You can configure `RspecProfiling` to collect results in a SQL database in `config/initializers/rspec_profiling.rb`: + +```Ruby +RspecProfiling.configure do |config| + config.collector = RspecProfiling::Collectors::SQL +end +``` You can review results by running the RspecProfiling console. The console has a preloaded `results` variable. @@ -112,7 +151,7 @@ debugging, such as `exception` and `status`. #### CSV -You can configure `RspecProfiling` to collect results in a CSV in `config/initializers/rspec_profiling.rb`: +By default, profiles are collected in an a CSV file. You can configure `RspecProfiling` to collect results in a CSV in `config/initializers/rspec_profiling.rb`: ```Ruby RspecProfiling.configure do |config| diff --git a/lib/rspec_profiling.rb b/lib/rspec_profiling.rb index ad77951..4023c28 100644 --- a/lib/rspec_profiling.rb +++ b/lib/rspec_profiling.rb @@ -4,12 +4,24 @@ require "rspec_profiling/version" require "rspec_profiling/run" require "rspec_profiling/collectors/csv" -require "rspec_profiling/collectors/sql" -require "rspec_profiling/collectors/psql" require "rspec_profiling/vcs/git" require "rspec_profiling/vcs/svn" require "rspec_profiling/vcs/git_svn" +begin + require "rspec_profiling/collectors/sql" +rescue LoadError + #no op +end + +begin + require "rspec_profiling/collectors/psql" +rescue LoadError + #no op +end + + + module RspecProfiling class Railtie < Rails::Railtie railtie_name :rspec_profiling diff --git a/lib/rspec_profiling/collectors/csv.rb b/lib/rspec_profiling/collectors/csv.rb index ca7cc95..0bd253e 100644 --- a/lib/rspec_profiling/collectors/csv.rb +++ b/lib/rspec_profiling/collectors/csv.rb @@ -6,6 +6,7 @@ class CSV HEADERS = %w{ branch commit_hash + seed date file line_number @@ -17,6 +18,8 @@ class CSV query_time request_count request_time + start_memory + end_memory } def self.install @@ -31,24 +34,44 @@ def self.reset # no op end - def initialize - RspecProfiling.config.csv_path ||= 'tmp/spec_benchmarks.csv' + def initialize(config=RspecProfiling.config) + config.csv_path ||= 'tmp/spec_benchmarks.csv' + + @config = config end def insert(attributes) - output << HEADERS.map do |field| - attributes.fetch(field.to_sym) - end + output << static_cells(attributes) + event_cells(attributes) end private + attr_reader :config + def output - @output ||= ::CSV.open(path, "w").tap { |csv| csv << HEADERS } + @output ||= ::CSV.open(path, "w").tap { |csv| csv << HEADERS + event_headers } end def path - RspecProfiling.config.csv_path.call + config.csv_path.call + end + + def static_cells(attributes) + HEADERS.map do |field| + attributes.fetch(field.to_sym) + end + end + + def event_headers + config.events.flat_map do |event| + ["#{event}_count", "#{event}_time", "#{event}_events"] + end + end + + def event_cells(attributes) + config.events.flat_map do |event| + [attributes[:event_counts][event], attributes[:event_times][event], attributes[:event_events][event].to_json] + end end end end diff --git a/lib/rspec_profiling/collectors/json.rb b/lib/rspec_profiling/collectors/json.rb new file mode 100644 index 0000000..ab934cd --- /dev/null +++ b/lib/rspec_profiling/collectors/json.rb @@ -0,0 +1,70 @@ +module RspecProfiling + module Collectors + class JSON + KEYS = %w{ + branch + commit_hash + seed + date + file + line_number + description + status + exception + time + query_count + query_time + request_count + request_time + start_memory + end_memory + } + + def self.install + # no op + end + + def self.uninstall + # no op + end + + def self.reset + # no op + end + + def initialize(config=RspecProfiling.config) + config.output_file_path ||= 'tmp/spec_benchmarks.json' + + @config = config + end + + def insert(attributes) + output << merge_attributes_and_events(attributes) + "\n" + end + + private + + attr_reader :config + + def output + @output ||= ::File.open(path, "w") + end + + def path + config.output_file_path.call + end + + def merge_attributes_and_events(attributes) + config.events.flat_map do |event| + attributes["#{event}_counts"] = attributes[:event_counts][event] + attributes["#{event}_times"] = attributes[:event_times][event] + attributes["#{event}_events"] = attributes[:event_events][event] + end + + attributes.merge!(config.additional_data) + + attributes.except(:event_counts, :event_times, :event_events, :events).to_json + end + end + end +end diff --git a/lib/rspec_profiling/collectors/psql.rb b/lib/rspec_profiling/collectors/psql.rb index 9509746..48c5442 100644 --- a/lib/rspec_profiling/collectors/psql.rb +++ b/lib/rspec_profiling/collectors/psql.rb @@ -47,7 +47,7 @@ def uninstall end def insert(attributes) - results.create!(attributes.except(:created_at)) + results.create!(attributes.except(:created_at, :events, :event_counts, :event_times, :event_events)) end def results diff --git a/lib/rspec_profiling/collectors/sql.rb b/lib/rspec_profiling/collectors/sql.rb index c35e57f..fd58446 100644 --- a/lib/rspec_profiling/collectors/sql.rb +++ b/lib/rspec_profiling/collectors/sql.rb @@ -47,7 +47,7 @@ def uninstall end def insert(attributes) - results.create!(attributes.except(:created_at)) + results.create!(attributes.except(:created_at, :events, :event_counts, :event_times, :event_events)) end def results diff --git a/lib/rspec_profiling/config.rb b/lib/rspec_profiling/config.rb index 2293be9..43c5572 100644 --- a/lib/rspec_profiling/config.rb +++ b/lib/rspec_profiling/config.rb @@ -5,9 +5,11 @@ def self.configure def self.config @config ||= OpenStruct.new({ - collector: RspecProfiling::Collectors::SQL, + collector: RspecProfiling::Collectors::CSV, vcs: RspecProfiling::VCS::Git, - table_name: 'spec_profiling_results' + table_name: 'spec_profiling_results', + events: [], + additional_data: {} }) end end diff --git a/lib/rspec_profiling/example.rb b/lib/rspec_profiling/example.rb index e66514a..fac302a 100644 --- a/lib/rspec_profiling/example.rb +++ b/lib/rspec_profiling/example.rb @@ -21,6 +21,9 @@ class Example def initialize(example) @example = example @counts = Hash.new(0) + @event_counts = Hash.new(0) + @event_times = Hash.new(0) + @event_events = Hash.new() end def file @@ -38,7 +41,7 @@ def description def status execution_result.status end - + def exception execution_result.exception end @@ -63,6 +66,8 @@ def request_time counts[:request_time] end + attr_reader :event_counts, :event_times, :event_events + def log_query(query, start, finish) unless query[:sql] =~ IGNORED_QUERIES_PATTERN counts[:query_count] += 1 @@ -75,6 +80,19 @@ def log_request(request, start, finish) counts[:request_time] += request[:view_runtime].to_f end + def log_event(event_name, event, start, finish) + event_counts[event_name] += 1 + event_times[event_name] += (finish - start) + event_events[event_name] ||= [] + if verbose_record_event?(event_name) + begin + event_events[event_name] << event.as_json + rescue => e + # no op + end + end + end + private attr_reader :example, :counts @@ -90,5 +108,9 @@ def execution_result def metadata example.metadata end + + def verbose_record_event?(event_name) + metadata[:record_events].to_a.include?(event_name) + end end end diff --git a/lib/rspec_profiling/rspec.rb b/lib/rspec_profiling/rspec.rb index 53fc308..fcf2574 100644 --- a/lib/rspec_profiling/rspec.rb +++ b/lib/rspec_profiling/rspec.rb @@ -1,7 +1,7 @@ require "rspec_profiling" RSpec.configure do |config| - runner = RspecProfiling::Run.new(RspecProfiling.config.collector.new, + runner = RspecProfiling::Run.new(RspecProfiling.config.collector.new, RspecProfiling.config.vcs.new) config.reporter.register_listener( diff --git a/lib/rspec_profiling/run.rb b/lib/rspec_profiling/run.rb index 5814a0c..abd4865 100644 --- a/lib/rspec_profiling/run.rb +++ b/lib/rspec_profiling/run.rb @@ -1,26 +1,31 @@ +require "get_process_mem" require "rspec_profiling/example" require "rspec_profiling/vcs/git" require "rspec_profiling/vcs/svn" require "rspec_profiling/vcs/git_svn" -require "rspec_profiling/collectors/sql" -require "rspec_profiling/collectors/psql" require "rspec_profiling/collectors/csv" +require "rspec_profiling/collectors/json" module RspecProfiling class Run def initialize(collector = RspecProfiling.config.collector.new, - vcs = RspecProfiling.config.vcs.new) + vcs = RspecProfiling.config.vcs.new, + events = RspecProfiling.config.events) @collector = collector @vcs = vcs + @events = events + @seed = RSpec.configuration.seed end def start(*args) start_counting_queries start_counting_requests + start_counting_events end def example_started(example) + start_recording_memory example = example.example if example.respond_to?(:example) @current_example = Example.new(example) end @@ -29,6 +34,7 @@ def example_finished(*args) collector.insert({ branch: vcs.branch, commit_hash: vcs.sha, + seed: @seed, date: vcs.time, file: @current_example.file, line_number: @current_example.line_number, @@ -39,7 +45,13 @@ def example_finished(*args) query_count: @current_example.query_count, query_time: @current_example.query_time, request_count: @current_example.request_count, - request_time: @current_example.request_time + request_time: @current_example.request_time, + events: @events, + event_counts: @current_example.event_counts, + event_times: @current_example.event_times, + event_events: @current_example.event_events, + start_memory: @start_memory, + end_memory: end_memory }) end @@ -48,7 +60,15 @@ def example_finished(*args) private - attr_reader :collector, :vcs + attr_reader :collector, :vcs, :events, :seed, :start_memory + + def end_memory + GetProcessMem.new.mb + end + + def start_recording_memory + @start_memory = GetProcessMem.new.mb + end def start_counting_queries ActiveSupport::Notifications.subscribe("sql.active_record") do |name, start, finish, id, query| @@ -61,5 +81,13 @@ def start_counting_requests @current_example.try(:log_request, request, start, finish) end end + + def start_counting_events + events.each do |event_name| + ActiveSupport::Notifications.subscribe(event_name) do |name, start, finish, id, event| + @current_example.try(:log_event, event_name, event, start, finish) + end + end + end end end diff --git a/lib/rspec_profiling/vcs/git.rb b/lib/rspec_profiling/vcs/git.rb index f608c82..73ce2c0 100644 --- a/lib/rspec_profiling/vcs/git.rb +++ b/lib/rspec_profiling/vcs/git.rb @@ -12,7 +12,7 @@ def sha end def time - Time.parse `git show -s --format=%ci #{sha}` + Time.parse `git show -s --format=%ci #{sha}`.chomp end end end diff --git a/lib/rspec_profiling/version.rb b/lib/rspec_profiling/version.rb index c08fc41..09e54a9 100644 --- a/lib/rspec_profiling/version.rb +++ b/lib/rspec_profiling/version.rb @@ -1,3 +1,3 @@ module RspecProfiling - VERSION = "0.0.6" + VERSION = "0.0.7" end diff --git a/rspec_profiling b/rspec_profiling deleted file mode 100644 index d71e819..0000000 Binary files a/rspec_profiling and /dev/null differ diff --git a/rspec_profiling.gemspec b/rspec_profiling.gemspec index 3789e3d..e5a6eeb 100644 --- a/rspec_profiling.gemspec +++ b/rspec_profiling.gemspec @@ -18,12 +18,12 @@ Gem::Specification.new do |spec| spec.test_files = spec.files.grep(%r{^(test|spec|features)/}) spec.require_paths = ["lib"] - spec.add_dependency "sqlite3" spec.add_dependency "activerecord" - spec.add_dependency "pg" spec.add_dependency "rails" + spec.add_dependency "get_process_mem" spec.add_development_dependency "bundler", "> 1.3" spec.add_development_dependency "rake" spec.add_development_dependency "rspec" + spec.add_development_dependency "pry" end diff --git a/spec/run_spec.rb b/spec/run_spec.rb index 94ee6ea..195e23f 100644 --- a/spec/run_spec.rb +++ b/spec/run_spec.rb @@ -1,3 +1,4 @@ +require "active_support" require "active_support/core_ext" require "rspec_profiling/run" require "time" @@ -17,16 +18,21 @@ def simulate_request }) end + def simulate_event(name) + ActiveSupport::Notifications.instrument(name, name, 100, 150, 3, {name: 'custom', data: {key: 'value'}}) + end + describe "#run_example" do let(:collector) { CollectorDouble.new } - let(:vcs) { VcsDouble.new } - let(:run) { described_class.new(collector, vcs) } + let(:vcs) { VcsDouble.new } + let(:run) { described_class.new(collector, vcs, ["custom"]) } let(:result) { collector.results.first } let(:example) do ExampleDouble.new({ file_path: "/something_spec.rb", line_number: 15, - full_description: "should do something" + full_description: "should do something", + record_events: %w[custom] }) end @@ -36,6 +42,8 @@ def simulate_test_suite_run simulate_query "SELECT * FROM users LIMIT 1;" simulate_query "SELECT * FROM comments WHERE user_id = 1;" simulate_request + simulate_event "custom" + simulate_event "untracked" run.example_passed end @@ -64,6 +72,10 @@ def simulate_test_suite_run expect(result.request_count).to eq 1 end + it "counts one custom event" do + expect(result.event_counts["custom"]).to eq 1 + end + it "records the file" do expect(result.file).to eq "/something_spec.rb" end @@ -87,6 +99,14 @@ def simulate_test_suite_run it "records the request time" do expect(result.request_time).to eq 10 end + + it "records the custom event time" do + expect(result.event_times["custom"]).to eq 50 + end + + it "records the custom event events" do + expect(result.event_events["custom"]).to eq [{"data"=>{"key"=>"value"}, "name"=>"custom"}] + end end class CollectorDouble