[Rspec] Track execution times with formatter#229
Conversation
3v0k4
force-pushed
the
rspec-time-tracker
branch
4 times, most recently
from
f8b786c to
61b3bcc
Compare
The pending test
A real example other than a pending test that could lead to problem for the user: |
It's by design. We want to track the actual time spent on executing the test file path so that we can better order test files on the API side (from slow to fast in Queue API). If the test fails (for example, test cases are failing) OR there was a syntax error and the test failed. In both scenarios, we want to report the test file path with execution time to API so that the test file can be run on a retried CI build.
But I would not use 0s for failed tests. This could be confusing in the user dashboard and when the spec is returned with 0s execution time in the API response. It would be returned first from the Queue API (possibly good). But if you have many test files like that, how can you know which one is potentially slower.
|
Nice catch. I'll look into it. I haven't seen that the report (artifact.txt) in the last node shows the recording only for the old tracker, but not the new one: https://app.circleci.com/pipelines/github/KnapsackPro/knapsack-pro-api/5999/workflows/574d7647-ec28-4599-8691-4d44c28a2f3e/jobs/8765/artifacts
Does RSpec even start with a file containing a syntax error? I'll try tomorrow.
As soon as we start sending the status, we can mark them as failed ;) Thanks for the CR! |
Yes. You would typically see an error like: if you make a typo ( I also recall a customer making something that prevented I don't know how to reproduce such a crash. |
|
If you would be doing clean up of the if example.metadata[:focus] && KnapsackPro::Adapters::RSpecAdapter.rspec_configuration.filter.rules[:focus]
raise "We detected a test file path #{current_test_path} with a test using the metadata `:focus` tag. RSpec might not run some tests in the Queue Mode (causing random tests skipping problem). Please remove the `:focus` tag from your codebase. See more: #{KnapsackPro::Urls::RSPEC__SKIPS_TESTS}"
end |
We could if it's easy to do. I think you would need to add the new formatter to and change the KnapsackPro::Report#save method to use new tracker data like you did for the save_node_queue_to_api method.
After doing that we could remove |
We can release a major version of the gem. One unknown thing is Turnip. I don't recall anyone using it for years. I checked and there are no Turnip users so I think it's safe to ignore it and don't dig into it. The |
This problem is gone now thanks to using I can imagine if there is a delayed response from our API this was impacting the execution time of the first spec fetched from Queue API, I guess? So it would be nice to not have this issue.
If we use the |
Just an idea. Maybe there is a better way to make it convenient for the developers. Maybe Also we would need to exclude knapsack_pro-ruby/knapsack_pro.gemspec Line 24 in b0505b7 |
I was wondering if we need to track files like So But so far we were tracking it spec/controllers/shared.rb and it's visible in the user dashboard for a CI build. I think we were tracking it by accident and it was like that because I did not fix it and it did no harm anyone. The test file pattern that we use by default to detect files on the disk should not detect the The A similar case is with |
|
Just answering to the direct questions in this comment. I'll address the rest in code.
Correct. It's fixed.
I don't have a good answer to this one TBH. The new implementation does not track it. |
Great.
Ok, let's not track it then. The new implementation will fix the old bug that was never fixed. |
3v0k4
force-pushed
the
rspec-time-tracker
branch
2 times, most recently
from
0ebf242 to
c3c32c8
Compare
There was a problem hiding this comment.
I added a few tiny comments. Other than that code looks good.
I found issues while running tests in Queue Mode.
I've updated the bin script:
https://github.com/KnapsackPro/rails-app-with-knapsack_pro/blob/master/bin/knapsack_pro_queue_rspec_record_first_run
I do:
# CI node 0 for commit-v1
$ bin/knapsack_pro_queue_rspec_record_first_run 0 2 commit-v1
# CI node 1 for commit-v2
$ bin/knapsack_pro_queue_rspec_record_first_run 1 2 commit-v1
To run just the whole test suite on a single node I do:
$ bin/knapsack_pro_queue_rspec_record_first_run 0 2 commit-v2
then I get an error at the end of the tests run:
...previous tests executed here
D, [2023-11-24T20:31:05.860983 #66876] DEBUG -- : [knapsack_pro] POST http://api.knapsackpro.test:3000/v1/queues/queue
D, [2023-11-24T20:31:05.861009 #66876] DEBUG -- : [knapsack_pro] API request UUID: 5fcf20bb-0932-48e7-9447-c15b284cc246
D, [2023-11-24T20:31:05.861021 #66876] DEBUG -- : [knapsack_pro] API response:
D, [2023-11-24T20:31:05.861043 #66876] DEBUG -- : [knapsack_pro] {"queue_name"=>"130:5f3a66e9a970e50eb2c246b6e3e6ef8b", "build_subset_id"=>nil, "test_files"=>[{"path"=>"spec/time_helpers_spec.rb", "time_execution"=>3.04385900031775}]}
----------Before Subset Queue Hook - run before the subset of the test suite----------
2nd KnapsackPro::Hooks::Queue.before_subset_queue
before suite
Time travel with ActiveSupport::Testing::TimeHelpers
before all
travel_back
around each start
before each
after each
around each stop
is expected to eq 2004 (FAILED - 1)
travel_to block
around each start
before each
after each
around each stop
is expected to eq 23 (FAILED - 2)
travel_to block 2014
around each start
before each
after each
around each stop
is expected to eq 2004 (FAILED - 3)
after all
after suite
D, [2023-11-24T20:31:08.913764 #66876] DEBUG -- : [knapsack_pro] Global time execution for tests: 03s
W, [2023-11-24T20:31:08.945243 #66876] WARN -- : [knapsack_pro] RSpec wants to quit.
I, [2023-11-24T20:31:08.946545 #66876] INFO -- : [knapsack_pro] To retry the last batch of tests fetched from the API Queue, please run the following command on your machine:
I, [2023-11-24T20:31:08.946577 #66876] INFO -- : [knapsack_pro] bundle exec rspec --format d --default-path spec "spec/time_helpers_spec.rb"
----------After Subset Queue Hook - run after the subset of the test suite----------
2nd KnapsackPro::Hooks::Queue.after_subset_queue
rake aborted!
Knapsack Pro process was terminated!
/Users/artur/Documents/github/knapsack-pro/knapsack_pro-ruby/lib/knapsack_pro/runners/queue/base_runner.rb:45:in `handle_signal!'
/Users/artur/Documents/github/knapsack-pro/knapsack_pro-ruby/lib/knapsack_pro/runners/queue/rspec_runner.rb:44:in `run'
/Users/artur/Documents/github/knapsack-pro/knapsack_pro-ruby/lib/tasks/queue/rspec.rake:19:in `block (3 levels) in <top (required)>'
/Users/artur/.rvm/gems/ruby-3.2.2/bin/ruby_executable_hooks:22:in `eval'
/Users/artur/.rvm/gems/ruby-3.2.2/bin/ruby_executable_hooks:22:in `<main>'
Tasks: TOP => knapsack_pro:queue:rspec_go
(See full trace by running task with --trace)
Coverage report generated for RSpec, rspec_ci_node_0, rspec_ci_node_1 to /Users/artur/Documents/github/knapsack-pro/rails-app-with-knapsack_pro/coverage. 331 / 361 LOC (91.69%) covered.
SimpleCov failed with exit 1%
Maybe this is something you are already working on. You mentioned some edge cases to be resolved during the daily call. I wasn't digging what is causing the process termination.
When I updated the bin script to use Regular Mode bundle exec rake "knapsack_pro:rspec[--format d]" then tests are passing fine for CI node 0, but for the CI node 1 I get an error:
Error on CI node 1:
bin/knapsack_pro_queue_rspec_record_first_run 1 2 commit-v8
D, [2023-11-24T20:38:13.596701 #68131] DEBUG -- : [knapsack_pro] POST http://api.knapsackpro.test:3000/v1/build_distributions/subset
D, [2023-11-24T20:38:13.596749 #68131] DEBUG -- : [knapsack_pro] API request UUID: d5a7e290-8f9e-43ee-9ed0-ceefd6a0da07
D, [2023-11-24T20:38:13.596764 #68131] DEBUG -- : [knapsack_pro] API response:
D, [2023-11-24T20:38:13.596777 #68131] DEBUG -- : [knapsack_pro] {"code"=>"TEST_SUITE_SPLIT_CACHE_MISS"}
D, [2023-11-24T20:38:13.655467 #68131] DEBUG -- : [knapsack_pro] POST http://api.knapsackpro.test:3000/v1/build_distributions/subset
D, [2023-11-24T20:38:13.655500 #68131] DEBUG -- : [knapsack_pro] API request UUID: 73369113-e66e-4d70-876f-4e79853fab8a
D, [2023-11-24T20:38:13.655517 #68131] DEBUG -- : [knapsack_pro] Test suite split seed: f8e88847-95ac-490f-8cd5-84deccccdbda
D, [2023-11-24T20:38:13.655525 #68131] DEBUG -- : [knapsack_pro] API response:
D, [2023-11-24T20:38:13.655619 #68131] DEBUG -- : [knapsack_pro] {"build_distribution_id"=>"f8e88847-95ac-490f-8cd5-84deccccdbda", "node_index"=>1, "test_files"=>[{"path"=>"spec/slow_shared_examples_spec.rb", "time_execution"=>3.556496000150219}, {"path"=>"spec/time_helpers_spec.rb", "time_execution"=>3.058004999998957}, {"path"=>"spec/controllers/articles_controller_spec.rb", "time_execution"=>0.05578099982813001}, {"path"=>"spec/services/meme_spec.rb", "time_execution"=>0.006351000396534801}, {"path"=>"spec/rake_tasks/dummy_rake_spec.rb", "time_execution"=>0.002675000112503767}, {"path"=>"spec/bar_spec.rb", "time_execution"=>0.001302000135183334}, {"path"=>"spec/dir with spaces/foobar_spec.rb", "time_execution"=>0.001229000044986606}, {"path"=>"spec/foo_spec.rb", "time_execution"=>0.0007069997955113649}, {"path"=>"spec/retry_spec.rb", "time_execution"=>0.0005779999773949385}, {"path"=>"spec/system_exit_spec.rb", "time_execution"=>0.0005030001047998667}, {"path"=>"spec/async/reactor_spec.rb", "time_execution"=>0.0}, {"path"=>"spec/controllers/dashboard/pending_controller_spec.rb", "time_execution"=>0.0}, {"path"=>"spec/controllers/shared_articles_controller_spec.rb", "time_execution"=>0.0}, {"path"=>"spec/controllers/welcome_controller_spec.rb", "time_execution"=>0.0}, {"path"=>"spec/pending_spec.rb", "time_execution"=>0.0}, {"path"=>"spec/vcr_spec.rb", "time_execution"=>0.0}]}
/Users/artur/.rvm/rubies/ruby-3.2.2/bin/ruby -I/Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-core-3.12.1/lib:/Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-support-3.12.0/lib /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-core-3.12.1/exe/rspec --format d --format documentation --format KnapsackPro::Formatters::TimeTracker --default-path spec "spec/slow_shared_examples_spec.rb" "spec/time_helpers_spec.rb" "spec/controllers/articles_controller_spec.rb" "spec/services/meme_spec.rb" "spec/rake_tasks/dummy_rake_spec.rb" "spec/bar_spec.rb" "spec/dir with spaces/foobar_spec.rb" "spec/foo_spec.rb" "spec/retry_spec.rb" "spec/system_exit_spec.rb" "spec/async/reactor_spec.rb" "spec/controllers/dashboard/pending_controller_spec.rb" "spec/controllers/shared_articles_controller_spec.rb" "spec/controllers/welcome_controller_spec.rb" "spec/pending_spec.rb" "spec/vcr_spec.rb"
D, [2023-11-24T20:38:14.001102 #68144] DEBUG -- : [knapsack_pro] Test suite time execution recording enabled.
rspec pid: 68144
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
RSpec before suite hook called only once
Run this only when not using Knapsack Pro Queue Mode
before suite
Example of slow shared examples
before all
around each start
before each
after each
around each stop
is expected to equal true
behaves like slow shared example test
around each start
before each
after each
around each stop
is expected to equal true
after all
Time travel with ActiveSupport::Testing::TimeHelpers
before all
travel_back
around each start
before each
after each
around each stop
is expected to eq 2004 (FAILED - 1)
travel_to block
around each start
before each
after each
around each stop
is expected to eq 23 (FAILED - 2)
travel_to block 2014
around each start
before each
after each
around each stop
is expected to eq 2004 (FAILED - 3)
after all
after suite
D, [2023-11-24T20:38:21.941070 #68144] DEBUG -- : [knapsack_pro] POST http://api.knapsackpro.test:3000/v1/build_subsets
D, [2023-11-24T20:38:21.941107 #68144] DEBUG -- : [knapsack_pro] API request UUID: 128cd314-3248-4d5e-8780-8d2fc082f715
D, [2023-11-24T20:38:21.941118 #68144] DEBUG -- : [knapsack_pro] API response:
D, [2023-11-24T20:38:21.941129 #68144] DEBUG -- : [knapsack_pro]
D, [2023-11-24T20:38:21.941142 #68144] DEBUG -- : [knapsack_pro] Saved time execution report on Knapsack Pro API server.
D, [2023-11-24T20:38:21.941190 #68144] DEBUG -- : [knapsack_pro] Global time execution for tests: 06s
++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++++
after suite hook called only once
Run this only when not using Knapsack Pro Queue Mode
Failures:
1) Time travel with ActiveSupport::Testing::TimeHelpers travel_back is expected to eq 2004
Failure/Error: expect(Time.raw_now.year).to be >= 2017
NoMethodError:
undefined method `raw_now' for Time:Class
# ./spec/time_helpers_spec.rb:18:in `block (3 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/webmock-3.18.1/lib/webmock/rspec.rb:37:in `block (2 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:124:in `block in run'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `loop'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `run'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:37:in `block (2 levels) in setup'
# ./spec/spec_helper.rb:185:in `block (2 levels) in <top (required)>'
# /Users/artur/Documents/github/knapsack-pro/knapsack_pro-ruby/lib/knapsack_pro/adapters/rspec_adapter.rb:148:in `block (2 levels) in bind_time_tracker2'
2) Time travel with ActiveSupport::Testing::TimeHelpers travel_to block is expected to eq 23
Failure/Error: expect(Time.raw_now.year).to be >= 2017
NoMethodError:
undefined method `raw_now' for Time:Class
# ./spec/time_helpers_spec.rb:30:in `block (4 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/activesupport-6.1.7.3/lib/active_support/testing/time_helpers.rb:169:in `travel_to'
# ./spec/time_helpers_spec.rb:26:in `block (3 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/webmock-3.18.1/lib/webmock/rspec.rb:37:in `block (2 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:124:in `block in run'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `loop'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `run'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:37:in `block (2 levels) in setup'
# ./spec/spec_helper.rb:185:in `block (2 levels) in <top (required)>'
# /Users/artur/Documents/github/knapsack-pro/knapsack_pro-ruby/lib/knapsack_pro/adapters/rspec_adapter.rb:148:in `block (2 levels) in bind_time_tracker2'
3) Time travel with ActiveSupport::Testing::TimeHelpers travel_to block 2014 is expected to eq 2004
Failure/Error: expect(Time.raw_now.year).to be >= 2017
NoMethodError:
undefined method `raw_now' for Time:Class
# ./spec/time_helpers_spec.rb:43:in `block (4 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/activesupport-6.1.7.3/lib/active_support/testing/time_helpers.rb:169:in `travel_to'
# ./spec/time_helpers_spec.rb:39:in `block (3 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/webmock-3.18.1/lib/webmock/rspec.rb:37:in `block (2 levels) in <top (required)>'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:124:in `block in run'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `loop'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:110:in `run'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec_ext/rspec_ext.rb:12:in `run_with_retry'
# /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-retry-0.6.2/lib/rspec/retry.rb:37:in `block (2 levels) in setup'
# ./spec/spec_helper.rb:185:in `block (2 levels) in <top (required)>'
# /Users/artur/Documents/github/knapsack-pro/knapsack_pro-ruby/lib/knapsack_pro/adapters/rspec_adapter.rb:148:in `block (2 levels) in bind_time_tracker2'
Finished in 6.64 seconds (files took 1.47 seconds to load)
5 examples, 3 failures
Failed examples:
rspec ./spec/time_helpers_spec.rb:10 # Time travel with ActiveSupport::Testing::TimeHelpers travel_back is expected to eq 2004
rspec ./spec/time_helpers_spec.rb:25 # Time travel with ActiveSupport::Testing::TimeHelpers travel_to block is expected to eq 23
rspec ./spec/time_helpers_spec.rb:38 # Time travel with ActiveSupport::Testing::TimeHelpers travel_to block 2014 is expected to eq 2004
Coverage report generated for RSpec, rspec_ci_node_0, rspec_ci_node_1 to /Users/artur/Documents/github/knapsack-pro/rails-app-with-knapsack_pro/coverage. 249 / 316 LOC (78.8%) covered.
SimpleCov failed with exit 1/Users/artur/.rvm/rubies/ruby-3.2.2/bin/ruby -I/Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-core-3.12.1/lib:/Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-support-3.12.0/lib /Users/artur/.rvm/gems/ruby-3.2.2/gems/rspec-core-3.12.1/exe/rspec --format d --format documentation --format KnapsackPro::Formatters::TimeTracker --default-path spec "spec/slow_shared_examples_spec.rb" "spec/time_helpers_spec.rb" "spec/controllers/articles_controller_spec.rb" "spec/services/meme_spec.rb" "spec/rake_tasks/dummy_rake_spec.rb" "spec/bar_spec.rb" "spec/dir with spaces/foobar_spec.rb" "spec/foo_spec.rb" "spec/retry_spec.rb" "spec/system_exit_spec.rb" "spec/async/reactor_spec.rb" "spec/controllers/dashboard/pending_controller_spec.rb" "spec/controllers/shared_articles_controller_spec.rb" "spec/controllers/welcome_controller_spec.rb" "spec/pending_spec.rb" "spec/vcr_spec.rb" failed
|
@ArturT just documenting our private chat here:
This is unrelated to the changes introduced in this PR, and will be dealt separately. Also, the test fails because |
3v0k4
force-pushed
the
rspec-time-tracker
branch
from
91a22c3 to
03a1b78
Compare
3v0k4
force-pushed
the
rspec-time-tracker
branch
from
03a1b78 to
ff4a774
Compare
3v0k4
force-pushed
the
rspec-time-tracker
branch
from
ff4a774 to
246ac3e
Compare
|
When you use: RANDOM_CI_BUILD_ID=$(openssl rand -base64 32)
CI_BUILD_ID=${3:-$RANDOM_CI_BUILD_ID}
COMMIT_HASH=$(ruby -e "require 'securerandom'; puts SecureRandom.hex")
BRANCH_NAME=fake-branch
export EXTRA_TEST_FILES_DELAY=10 # seconds
export KNAPSACK_PRO_RSPEC_SPLIT_BY_TEST_EXAMPLES=true
KNAPSACK_PRO_ENDPOINT=http://api.knapsackpro.test:3000 \
KNAPSACK_PRO_TEST_SUITE_TOKEN_RSPEC=fec3c641a3c4d2e720fe1b6d9dd780bc \
KNAPSACK_PRO_CI_NODE_BUILD_ID=$CI_BUILD_ID \
KNAPSACK_PRO_COMMIT_HASH=${3:-$COMMIT_HASH} \
KNAPSACK_PRO_BRANCH=$BRANCH_NAME \
KNAPSACK_PRO_CI_NODE_TOTAL=${2:-2} \
KNAPSACK_PRO_CI_NODE_INDEX=${1:-0} \
bundle exec rake "knapsack_pro:queue:rspec[--format d]"Run this with a new commit and a new CI build ID: CI node 0 (start this command first): It would detect a slow test CI node 1: In the user dashboard both specs are recorded with their timing: That's good and expected. But when I use regular mode then only This can lead to a problem. When I retry CI node then |
| end | ||
|
|
||
| def rspec_split_by_test_example?(file) | ||
| return false unless KnapsackPro::Config::Env.queue_recording_enabled? |
There was a problem hiding this comment.
| return false unless KnapsackPro::Config::Env.queue_recording_enabled? |
I think this line is not needed and it would solve the issue #229 (comment)
Co-authored-by: Riccardo <riccardo.odone@gmail.com>
…gular Mode so that we could recorded execution time for test examples like a_spec.rb[1:1] in Regular Mode
…nclude bin/test). Update docs url. Update support email. Use ' over " for consistency.
…se an exception for an example tagged with focus
ArturT
changed the title
2 participants
This PR introduces an RSpec formatter to track
execution_times for both Queue Mode and Regular Mode: ticket.As a result, the long-standing issues we have been fighting with are gone. Also, we now can record test outcomes (not only times) and generalize this pattern to all the test runners, effectively allowing Knapsack Pro to work with any language/test runner.
A quick way to test locally with
rails-app-with-knapsack_pro:VERBOSE=1 bin/knapsack_pro_queue_rspec 0 2 2023-11-08-01VERBOSE=1 NEW_TIME_TRACKER=1 bin/knapsack_pro_queue_rspec 0 2 2023-11-08-01Also, I run a build on CircleCI with:
export VERBOSE=1Details
https://app.circleci.com/pipelines/github/KnapsackPro/knapsack-pro-api/6050/workflows/bd5166e6-971b-4f7e-9a54-7e56495268ed/jobs/8864
https://knapsackpro.com/dashboard/organizations/54/projects/730/test_suites/3201/builds/35c9d4d3-9552-4a9e-b659-0d21c4d73d7a
node 0
node 1
node 2
node 3
node 4
node 5
node 6
node 7
node 8
node 9
node 10
node 11
node 12
node 13
node 14
node 15
node 16
node 17
node 18
node 19
node 20
node 21
node 22
node 23
export VERBOSE=1 NEW_TIME_TRACKER=1Details
https://knapsackpro.com/dashboard/organizations/54/projects/730/test_suites/3201/builds/9d327bbb-1a16-4434-8e73-a830e7cf47c6#tab-test-files
https://app.circleci.com/pipelines/github/KnapsackPro/knapsack-pro-api/6051/workflows/be830bcb-5646-4214-96b4-d173f130e2d9/jobs/8866
export VERBOSE=1 NEW_TIME_TRACKER=1and retriedDetails
https://app.circleci.com/pipelines/github/KnapsackPro/knapsack-pro-api/6052
https://knapsackpro.com/dashboard/organizations/54/projects/730/test_suites/3201/builds/34b9b526-a05f-45e0-9334-9ce181a90e89
While working on this change, I noticed the following bugs in the current tracker:
spec/controllers/shared_articles_controller_spec.rbis counted as:spec/track_context_time_spec.rbdoes not account for the hooks properly (it should be ~5.3s and ~5.4s):This PR fixes them all for RSpec in both Regular and Queue Mode.
I didn't manage to test the new tracker inside RSpec. When I try to run it as part of
bundle exec rspec spec/it keeps calling itself in an infinite loop. That's why I kept it separate (_specs.rbfile). In theory, it's doable because in RSpec they test formatters like the json one.You'll notice the following code:
We need it because of some edge cases I noticed by running the tests in rails-app-with-knapsack_pro.
In particular, we need
example.id.match(/\A(.*?)(?:\[([\d\s:,]+)\])?\z/).captures.firstfor:or for:
We need
example.metadata[:file_path]for:I didn't find a need for the others, but I think it makes sense to try paths in order of specificity, and id -> example -> group -> top level group seemed to make sense.
Notice that this also fixes the problem with
spec/controllers/shared_articles_controller_spec.rbmentioned above.Questions for Artur:
I noticed we currently send times for failed specs. Is it by design? Or should we filter them out?Artur: By designShould we apply this to Regular mode? I can look at doing it as part of this PR.DoneHow would you bump this one?Artur: Major