Queue mode is running much slower than regular mode with Knapsack Pro about knapsack_pro-ruby HOT 23 CLOSED

Hi @Neal910
I've improved Knapsack Pro Queue API and it tracks now all ever recorded test file paths. Thanks to that when you frequently change the set of tests then our API still can use historical data about the test file path time execution to properly group in batches set of tests when knapsack_pro gem pulls the test files from the Queue API.

Please let me know if you see better results in Queue Mode now. Please run at least one CI build with all test file paths so their time execution can be tracked for the very first time before you start using a frequently changing set of test files.

from knapsack_pro-ruby.

Hi @ArturT , thanks for the improvement. I have tested, it did improve a lot. I will just need to improve my prediction file structure a little bit to make it even better. Much appreciated.

from knapsack_pro-ruby.

If you see in the output:

D, [2021-05-20T17:27:44.542380 #134] DEBUG -- : [knapsack_pro] POST https://api.knapsackpro.com/v1/build_distributions/subset

Then you must have been using the Regular Mode with the command: bundle exec rake knapsack_pro:rspec.

If you see:

D, [2021-05-20T19:52:55.641851 #134] DEBUG -- : [knapsack_pro] POST https://api.knapsackpro.com/v1/queues/queue

then you were using Queue Mode.

If you see it before each spec this means Knapsack Pro API doesn't have information about test file path execution time and each spec file is consumed from queue API one by one.

If you recorded CI build and run another one then Knapsack Pro API knows test file paths execution time from previous CI build and in Queue Mode you can consume test files in batches instead of one by one (API can group your test files in batches based on spec time execution).

I see you use KNAPSACK_PRO_TEST_FILE_LIST_SOURCE_FILE. Is this list constant or do you frequently change it? If you often add/remove test files then Knapsack Pro API may forget the test file execution time and this could cause running spec one by one.

I have on my to-do list an idea of how to improve API to better handle a frequently changing set of test files per CI build. API could remember the old recorded test files time execution. It might be useful when you run CI build for test files that were not recorded in the previous CI build but were recorded at least once in the past.

Can you share a link to your CI build in the knapsack pro user dashboard for the problematic CI build then I could check it?
You can do it here or in a private support email.

from knapsack_pro-ruby.

The file passed in via KNAPSACK_PRO_TEST_FILE_LIST_SOURCE_FILE is changing almost every time. Because it's dynamically generated. And the path for the spec on this file is something like spec_1.rb[1] or spec_2[1:2:3] etc.

I am not sure why it wan't using queue mode, but anyway it's using now. Because the queue mode is running too slow, it always timed out. I will prepare an example and send it over through the email.

from knapsack_pro-ruby.

The file passed in via KNAPSACK_PRO_TEST_FILE_LIST_SOURCE_FILE is changing almost every time.

Ok. So this means for each new CI build you may run a different set of test files than in the previous CI build. Because of that Knapsack Pro API assumes you removed previous test files and it won't know the test file time execution for the new test files list. This will lead to running test files one by one from the Queue API. This shouldn't be a big overhead because a request to our API takes ~20-30ms. It shouldn't slow down the tests that much.

Please send the output and how long does it take to run tests and what's your CI provider.
What's the expected runtime.
Please provide a link to CI build in the knapsack pro user dashboard.

Please note if you run all your test files as test examples (with paths like spec_1.rb[1:1]) then this has a high impact on RSpec memory efficiency and it could slow down your CI machine. RSpec itself has a performance issue to run a large number of test examples.
https://knapsackpro.com/faq/question/how-to-split-slow-rspec-test-files-by-test-examples-by-individual-it#why-does-knapsack_pro-not-split-all-test-files-by-test-examples

from knapsack_pro-ruby.

I have sent you the rspec results by email. Unfortunately, I can only send examples due to the fact that the list of examples is the output of another framework Crystalball we discussed before.

So are you suggesting I better use regular mode for the random rspec files? And use queue mode when input files are certain?

from knapsack_pro-ruby.

So are you suggesting I better use regular mode for the random rspec files? And use queue mode when input files are certain?

It's better to use Queue Mode even when test files execution time is unknown because it will auto balance tests between parallel CI nodes.

from knapsack_pro-ruby.

Sorry, for the late reply.

Here is what I found after I upgrade Knapsack to 2.17.
When I use Queue mode is still slow, for example a spec called: t4a_spec.rb, only one example spec/lib/tasks/t4a_spec.rb[1:1:2] takes more than 10s as shown on the log [knapsack_pro] Global time execution for tests: 13s.
However with regular mode, this whole spec only takes spec/lib/tasks/t4a_spec.rb | 0.166 seconds as shown here.

So for now I have to use regular mode and it works fine, but it would be great if we could get the queue mode working and even speed up more testing process.

from knapsack_pro-ruby.

Hi @Neal910

1. Could you check execution time with a bash time command like this:

$ time knapsack_pro:rspec

$ time knapsack_pro:queue:rspec

and then compare how long the test spec/lib/tasks/t4a_spec.rb[1:1:2] took for Regular and Queue Mode.

If the time is similar then the problem is with measuring test time in knapsack_pro gem.
If the time is different then it's problem with RSpec itself which runs your test slow (and it's not related to knapsack_pro gem).

2. How many test examples do you have inside of the file spec/lib/tasks/t4a_spec.rb? Maybe you have some before hooks that are triggered and slow down things.

If you try running the test file purely via RSpec how long does it take?

$ time rspec spec/lib/tasks/t4a_spec.rb[1:1:2]

$ time rspec spec/lib/tasks/t4a_spec.rb

from knapsack_pro-ruby.

I am using this command for the testing below:

RACK_ENV=test \
RAILS_ENV=test \
KNAPSACK_PRO_REPOSITORY_ADAPTER=git \
KNAPSACK_PRO_FIXED_QUEUE_SPLIT=false \
KNAPSACK_PRO_PROJECT_DIR=. \
KNAPSACK_PRO_CI_NODE_TOTAL=2 \
KNAPSACK_PRO_CI_NODE_INDEX=0 \
KNAPSACK_PRO_TEST_SUITE_TOKEN_RSPEC=token \
KNAPSACK_PRO_TEST_FILE_LIST_SOURCE_FILE=tmp/crystalball_prediction \
time bundle exec rake "knapsack_pro:queue:rspec[--format documentation --format RspecJunitFormatter --out tmp/rspec.xml]"

Here is some results:

Regular mode with t4a_spec.rb[1:1:2]

Finished in 1.37 seconds (files took 10.88 seconds to load)
1 example, 0 failures

   21.41 real        10.59 user         5.22 sys

Regular mode with t4a_spec.rb
Finished in 2.4 seconds (files took 10.04 seconds to load)
8 examples, 2 failures, 1 pending

   20.37 real        10.72 user         4.91 sys

Queue mode with t4a_spec.rb[1:1:2]
Global time execution for tests: 01s
Finished in 1.14 seconds
1 example, 0 failures

   16.01 real         7.73 user         3.66 sys

Queue mode with t4a_spec.rb
Global time execution for tests: 02s
Finished in 2.12 seconds
8 examples, 2 failures, 1 pending

   15.60 real         7.66 user         3.47 sys

They all finish within a very similar time. so the either the time measured in Knapsack is different or there is something wrong somewhere that I am still trying to figure out.

from knapsack_pro-ruby.

Just some info: when I use queue mode, almost all of the individual POST https://api.knapsackpro.com/v1/queues/queue requests have a significant large of execution time like more than 10 seconds. And it's really taking that much time, so my jobs are timing out in the CI.

from knapsack_pro-ruby.

They all finish within a very similar time. so the either the time measured in Knapsack is different or there is something wrong somewhere that I am still trying to figure out.

At least we know tests are running as expected without additional delay in Queue Mode.

For knapsack_pro it's only important to know more or less which test is slower than the other in order to sort them in the queue.

I recently did some improvements for tracking tests time in RSpec #145
It's not trivial due to some edge cases with RSpec hooks.
Maybe some additional time is measured as part of test example time and this makes an impression that test is slower.
But the time should be similar in regular and queue mode I guess.

Just some info: when I use queue mode, almost all of the individual POST https://api.knapsackpro.com/v1/queues/queue requests have a significant large of execution time like more than 10 seconds. And it's really taking that much time, so my jobs are timing out in the CI.

The response from API has time execution of test files recorded in the previous CI build. This is historical data. The time execution response from API is not used for anything.

If your jobs are timing out on CI when you run test examples in RSpec please note you need enough CPU/RAM. RSpec has a very bad performance to run test examples (it consumes a lot of memory and can freeze CI machine). This is an internal problem in RSpec. Please read https://knapsackpro.com/faq/question/how-to-split-slow-rspec-test-files-by-test-examples-by-individual-it#why-does-knapsack_pro-not-split-all-test-files-by-test-examples

from knapsack_pro-ruby.

The response from API has time execution of test files recorded in the previous CI build. This is historical data. The time execution response from API is not used for anything.

Here I meant the log [2021-05-31T21:35:14.865354 #462] DEBUG -- : [knapsack_pro] Global time execution for tests: 12s how is the time execution being measure here?

If your jobs are timing out on CI when you run test examples in RSpec please note you need enough CPU/RAM

And I don't think it's a CPU/RAM issue, otherwise the regular mode won't succeed, right?

from knapsack_pro-ruby.

Here I meant the log [2021-05-31T21:35:14.865354 #462] DEBUG -- : [knapsack_pro] Global time execution for tests: 12s how is the time execution being measure here?

Time is measured when RSpec hooks are called.
https://github.com/KnapsackPro/knapsack_pro-ruby/blob/24ff9b897a514d306476fc08cc22091e33f0d4d2/lib/knapsack_pro/adapters/rspec_adapter.rb#L23,L61

The total time is displayed at the end. This is what you see

If your jobs are timing out on CI when you run test examples in RSpec please note you need enough CPU/RAM

And I don't think it's a CPU/RAM issue, otherwise the regular mode won't succeed, right?

The performance problem is not related to regular or queue mode. It could be related to running test examples (paths like a_spec.rb[1:1] because RSpec takes a lot of memory if you run many paths like that). I don't know why RSpec has such bad performance when you run test examples. If you run only test file paths without test example paths then it does not take as much memory.

How many test examples paths do you run at once? Dozen or 100 probably should rather not be a problem. But running 1000 test examples (like a_spec.rb[1:1] can kill the CI machine because RSpec takes a lot of memory).

So the key question in your case is:
How many test file paths do you provide in the file KNAPSACK_PRO_TEST_FILE_LIST_SOURCE_FILE?
Are they test paths mixed up with test example paths?

Just to be explicit. This is what I mean:

• test path: a_spec.rb
• test example path: a_spec.rb[1:1]

from knapsack_pro-ruby.

How many test file paths do you provide in the file KNAPSACK_PRO_TEST_FILE_LIST_SOURCE_FILE?

They all totally random regardless test path or example path, they can be from 10 to 100 and even 1500 per each CI runner.

The performance problem is not related to regular or queue mode.

what I meant here is that when I run rspec with same amount of mixed set of paths (test path and example path), it 's always fine in regular mode, and always timeout in queue mode. So there is must be somewhere differentiate those two mode.

from knapsack_pro-ruby.

The main difference is that Queue Mode uses ::RSpec::Core::Runner to run tests.

Regular Mode uses rake task:

always timeout in queue mode.

What does it mean? What's the output? Did it freeze during specific test runtime or after tests are executed?

See FAQ for freezing issues:
https://knapsackpro.com/faq/question/why-knapsack_pro-hangs--freezes--is-stale-ie-for-codeship-in-queue-mode
https://knapsackpro.com/faq/question/why-knapsack_pro-freezes--hangs-my-ci-for-instance-travis
https://knapsackpro.com/faq/question/why-knapsack_pro-hangs-freezes-is-stale-for-tests-in-chrome-disallow-downloads-in-sandboxed-iframes

From my experience working with different users in the majority of cases the freezing issues were related to CI machine performance issues. I'm not sure if this is caused just by ::RSpec::Core::Runner, maybe it's somehow faulty. I'm not that familiar with RSpec internals.

Here I have an example repo https://github.com/ArturT/rspec-test-examples where I used to test ::RSpec::Core::Runner. Might be useful If you want to play with RSpec internals on your own.

from knapsack_pro-ruby.

What does it mean? What's the output? Did it freeze during specific test runtime or after tests are executed?

I am sorry to make unclear about this. Basically I set a timeout duration for each CI job, saying 30m. The regular mode can be run within 15 mins with amount of "mixed" tests without any problem, but queue mode is super slow so it gets timeout every time even I increase the timeout to 1h. It's not freezing just slow because I am seeing the rspec was still running right before the timeout. And I also check the node that rspec tests were running now, there is no spike for CPU and RAM.

from knapsack_pro-ruby.

My guess is that the root problem might be ::RSpec::Core::Runner and maybe you have something specific in tests that makes it slow. On knapsack_pro level I don't see what could be running slow unless you could point what part of the code is running slow in your case. My best guess is that ::RSpec::Core::Runner takes longer to run your tests. But why is that? I'm not sure. You would have to debug rspec behavior. Maybe try feed list of tests with different amount of mixed tests files and see when problem occurs.

One suspicion I have is that ::RSpec::Core::Runner runs tests slower when test files are run one by one. I guess it could be faster if test paths are grouped and passed all at once to ::RSpec::Core::Runner. I have idea in backlog to improve queue api to group tests for frequently changing test paths as in your case. Maybe this would be helpful. I'll get back to you when that improvement is done.

from knapsack_pro-ruby.

I was thinking the same, maybe I can group the example path into file path, then pass in. But for now I am good with regular mode and it's running perfectly. I will be moving forward, but when I have time, I will check back.

You have been so helpful, much appreciated. And please do let me know once you made the improvement. Please feel free to close the ticket.

from knapsack_pro-ruby.

I'll keep the issue open for now and I'm going to let you know when queue api improvements are ready.

If you would like to share your solution to run tests with crystalball that would be very helpful for other users. We are open for guest blog posts https://github.com/KnapsackPro/docs.knapsackpro.com

from knapsack_pro-ruby.

Good to hear it. Please let me know when you make progress. :)

from knapsack_pro-ruby.

Since we have now the grouping of test files done better in Queue Mode I think we can close this issue.

from knapsack_pro-ruby.

It's still possible to use KNAPSACK_PRO_TEST_FILE_LIST_SOURCE_FILE https://knapsackpro.com/faq/question/how-to-run-a-specific-list-of-test-files-or-only-some-tests-from-test-file#option-2-read-a-list-of-test-files-from-a-source-file

Please create a new commit and run a new CI build. Please provide a link to the Knapsack Pro user dashboard for a recorded CI build and logs output here or send it to [email protected] so that I could take a look. Please let me know what happened and what you expect to happen so that I could better answer your question. Thank you.

from knapsack_pro-ruby.