Improve test time execution tracking for RSpec

CHANGELOG.md

@@ -1,5 +1,13 @@
 # Change Log
 
+### 2.16.0
+
+* Improve test time execution tracking for RSpec
+
+    https://github.com/KnapsackPro/knapsack_pro-ruby/pull/145
+
+https://github.com/KnapsackPro/knapsack_pro-ruby/compare/v2.15.0...v2.16.0
+
 ### 2.15.0
 
 * Do not allow to use the RSpec tag option together with the RSpec split by test examples feature

lib/knapsack_pro/adapters/rspec_adapter.rb

@@ -26,6 +26,10 @@ def bind_time_tracker
           end
 
           config.around(:each) do |example|
+            # stop timer to update time for a previously run test example
+            # this way we count time spend in runtime for the previous test example after around(:each) is already done
+            KnapsackPro.tracker.stop_timer
+
             current_example_group =
               if ::RSpec.respond_to?(:current_example)
                 ::RSpec.current_example.metadata[:example_group]
@@ -46,6 +50,8 @@ def bind_time_tracker
           end
 
           config.append_after(:context) do
+            # after(:context) hook is run one time only, after all of the examples in a group
+            # stop timer to count time for the very last executed test example
             KnapsackPro.tracker.stop_timer
           end
 

lib/knapsack_pro/tracker.rb

@@ -19,23 +19,28 @@ def reset!
     end
 
     def start_timer
+      @start_time ||= now_without_mock_time.to_f
+    end
+
+    def reset_timer
       @start_time = now_without_mock_time.to_f
     end
 
     def stop_timer
       execution_time = @start_time ? now_without_mock_time.to_f - @start_time : 0.0
 
-      if current_test_path
+      if @current_test_path
         update_global_time(execution_time)
         update_test_file_time(execution_time)
-        @current_test_path = nil
+        reset_timer
       end
 
       execution_time
     end
 
     def current_test_path
-      KnapsackPro::TestFileCleaner.clean(@current_test_path) if @current_test_path
+      raise("current_test_path needs to be set by Knapsack Pro Adapter's bind method") unless @current_test_path
+      KnapsackPro::TestFileCleaner.clean(@current_test_path)
     end
 
     def set_prerun_tests(test_file_paths)

spec/knapsack_pro/adapters/rspec_adapter_spec.rb

@@ -87,16 +87,20 @@
 
         it 'records time for current test path' do
           expect(config).to receive(:prepend_before).with(:context).and_yield
+
+          allow(KnapsackPro).to receive(:tracker).and_return(tracker)
+          expect(tracker).to receive(:start_timer).ordered
+
           expect(config).to receive(:around).with(:each).and_yield(example)
           expect(config).to receive(:append_after).with(:context).and_yield
           expect(config).to receive(:after).with(:suite).and_yield
           expect(::RSpec).to receive(:configure).and_yield(config)
 
+          expect(tracker).to receive(:stop_timer).ordered
+
           expect(::RSpec).to receive(:current_example).twice.and_return(current_example)
           expect(described_class).to receive(:test_path).with(example_group).and_return(test_path)
 
-          allow(KnapsackPro).to receive(:tracker).and_return(tracker)
-          expect(tracker).to receive(:start_timer).ordered
           expect(tracker).to receive(:current_test_path=).with(test_path).ordered
 
           expect(example).to receive(:run)
@@ -127,16 +131,20 @@
             expect(example).to receive(:id).and_return(test_example_path)
 
             expect(config).to receive(:prepend_before).with(:context).and_yield
+
+            allow(KnapsackPro).to receive(:tracker).and_return(tracker)
+            expect(tracker).to receive(:start_timer).ordered
+
             expect(config).to receive(:around).with(:each).and_yield(example)
             expect(config).to receive(:append_after).with(:context).and_yield
             expect(config).to receive(:after).with(:suite).and_yield
             expect(::RSpec).to receive(:configure).and_yield(config)
 
+            expect(tracker).to receive(:stop_timer).ordered
+
             expect(::RSpec).to receive(:current_example).twice.and_return(current_example)
             expect(described_class).to receive(:test_path).with(example_group).and_return(test_path)
 
-            allow(KnapsackPro).to receive(:tracker).and_return(tracker)
-            expect(tracker).to receive(:start_timer).ordered
             expect(tracker).to receive(:current_test_path=).with(test_example_path).ordered
 
             expect(example).to receive(:run)
@@ -158,6 +166,10 @@
 
           it 'records time for current test path' do
             expect(config).to receive(:prepend_before).with(:context).and_yield
+
+            allow(KnapsackPro).to receive(:tracker).and_return(tracker)
+            expect(tracker).to receive(:start_timer).ordered
+
             expect(config).to receive(:around).with(:each).and_yield(example)
             expect(config).to receive(:append_after).with(:context).and_yield
             expect(config).to receive(:after).with(:suite).and_yield
@@ -166,8 +178,8 @@
             expect(::RSpec).to receive(:current_example).twice.and_return(current_example)
             expect(described_class).to receive(:test_path).with(example_group).and_return(test_path)
 
-            allow(KnapsackPro).to receive(:tracker).and_return(tracker)
-            expect(tracker).to receive(:start_timer).ordered
+            expect(tracker).to receive(:stop_timer).ordered
+
             expect(tracker).to receive(:current_test_path=).with(test_path).ordered
 
             expect(example).to receive(:run)

spec/knapsack_pro/tracker_spec.rb

@@ -12,7 +12,9 @@
     subject { tracker.current_test_path }
 
     context 'when current_test_path not set' do
-      it { expect(subject).to be_nil }
+      it do
+        expect { subject }.to raise_error("current_test_path needs to be set by Knapsack Pro Adapter's bind method")
+      end
     end
 
     context 'when current_test_path set' do
@@ -56,9 +58,6 @@
       it { expect(tracker.test_files_with_time.keys.size).to eql 2 }
       it { expect(tracker.test_files_with_time['a_spec.rb'][:time_execution]).to be_within(delta).of(0.1) }
       it { expect(tracker.test_files_with_time['b_spec.rb'][:time_execution]).to be_within(delta).of(0.2) }
-      it 'resets current_test_path after time is measured' do
-        expect(tracker.current_test_path).to be_nil
-      end
       it_behaves_like '#to_a'
     end
 
@@ -84,9 +83,6 @@
       it { expect(tracker.test_files_with_time.keys.size).to eql 2 }
       it { expect(tracker.test_files_with_time['a_spec.rb'][:time_execution]).to be_within(delta).of(0) }
       it { expect(tracker.test_files_with_time['b_spec.rb'][:time_execution]).to be_within(delta).of(0) }
-      it 'resets current_test_path after time is measured' do
-        expect(tracker.current_test_path).to be_nil
-      end
       it_behaves_like '#to_a'
     end
 
@@ -99,10 +95,12 @@
         end
       end
 
-      it { expect(tracker.global_time).to eq 0 }
+      it { expect(tracker.global_time).to be > 0 }
       it { expect(tracker.test_files_with_time.keys.size).to eql 2 }
       it { expect(tracker.test_files_with_time['a_spec.rb'][:time_execution]).to eq 0 }
-      it { expect(tracker.test_files_with_time['b_spec.rb'][:time_execution]).to eq 0 }
+      it '2nd spec (b_spec.rb) should have recorded time execution - because start_time was set during first call of stop_timer for the first spec (a_spec.rb)' do
+        expect(tracker.test_files_with_time['b_spec.rb'][:time_execution]).to be > 0
+      end
       it_behaves_like '#to_a'
     end
   end