turbo_test waits to long before executing tests

[ilyazub]

turbo_test starts execution, prints debug info, and then nothing happens. It works well if I execute only part of tests (for example, spec/models.)

I guess the problem is with tests that make external requests. I'll debug it soon, but maybe there are assumptions to check?

Full spec

turbo_test output

$ bundle exec turbo_test ./spec/
  0.0s     info: TurboTest::Command::Run [oid=0x2300] [pid=612405] [2021-03-01 21:00:01 +0200]
               | TurboTest v0.1.1 preparing for maximum thrust!
 0.12s     info: Async::Container::Forked [oid=0x24b8] [pid=612405] [2021-03-01 21:00:01 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612424 exit 0
 0.24s     info: Async::Container::Forked [oid=0x24b8] [pid=612405] [2021-03-01 21:00:01 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612423 exit 0
 0.57s     info: Async::Container::Forked [oid=0x24b8] [pid=612405] [2021-03-01 21:00:01 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612427 exit 0
 0.67s     info: Async::Container::Forked [oid=0x24b8] [pid=612405] [2021-03-01 21:00:02 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612428 exit 0
 0.84s     info: Async::Container::Forked [oid=0x24b8] [pid=612405] [2021-03-01 21:00:02 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612426 exit 0
 0.86s     info: Async::Container::Forked [oid=0x24b8] [pid=612405] [2021-03-01 21:00:02 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612421 exit 0
 0.87s     info: Async::Container::Forked [oid=0x24b8] [pid=612405] [2021-03-01 21:00:02 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612425 exit 0

rbspy output

Time since start: 56s. Press Ctrl+C to stop.
Summary of profiling data so far:
% self  % total  name
 89.97    89.98  <c function> - select
  8.95     8.96  <c function> - sleep
  0.55     0.75  <c function> - unknown
  0.08     0.08  <c function> - read_memory
  0.05     0.05  <c function> - join
  0.02     0.02  <c function> - write
  0.02     0.02  <c function> - to_s
  0.02     0.02  <c function> - []=
  0.01    33.43  <c function> - new
  0.01     0.03  block in deserialize_array - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.0/lib/mongo/protocol/message.rb
  0.01     0.02  log_debug - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.0/lib/mongo/loggable.rb
  0.01     0.01  <c function> - public_send
  0.01     0.01  <c function> - name
  0.01    23.26  read_from_socket - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.0/lib/mongo/socket.rb
  0.01    18.01  dispatch - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.0/lib/mongo/server/connection_base.rb
  0.01     0.20  process - /home/ilyazub/Workspace/serpapi/app/lib/search_splitter.rb
  0.01     0.04  normalize_component - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/addressable-2.7.0/lib/addressable/uri.rb
  0.01     0.03  []= - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/bson-4.10.0/lib/bson/document.rb
  0.01     0.02  started - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.0/lib/mongo/monitoring/command_log_subscriber.rb
  0.01     0.02  serialize - /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/gems/mongo-2.13.0/lib/mongo/protocol/message.rb

ps output

ilyazub   612405  0.3  0.2 317432 37288 pts/0    S+   21:00   0:00  |   |   \_ /home/ilyazub/.rbenv/versions/2.7.2/lib/ruby/gems/2.7.0/bin/turbo_test ./spec/
ilyazub   612420  0.0  0.1 317568 31764 pts/0    S+   21:00   0:00  |   |       \_ TurboTest::Server Host
ilyazub   612422 12.3  3.6 1689840 594748 pts/0  Sl+  21:00   0:18  |   |       \_ TurboTest::Server Worker

Part of spec files works well

turbo_test

$ bundle exec turbo_test ./spec/models/
  0.0s     info: TurboTest::Command::Run [oid=0x2300] [pid=612099] [2021-03-01 20:57:00 +0200]
               | TurboTest v0.1.1 preparing for maximum thrust!
 0.09s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:00 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612119 exit 0
 0.12s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:00 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612117 exit 0
 0.18s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:00 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612120 exit 0
 0.19s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:00 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612113 exit 0
 0.23s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:00 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612116 exit 0
 0.53s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:00 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612115 exit 0
 0.56s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:00 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612114 exit 0
24.17s     info: Queue [pid=612112] [2021-03-01 20:57:24 +0200]
               | 1/1 completed in 24.15s, 0.0s remaining.
               | ██████████████████████████████████████████████████████████████████████ 100.00%
24.18s     info: Writing results [pid=612112] [2021-03-01 20:57:24 +0200]
24.19s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:24 +0200]
               | #<Async::Container::Process TurboTest::Server Host> exited with pid 612112 exit 0
 24.2s     warn: Async::Container::Process [oid=0x2440] [pid=612099] [2021-03-01 20:57:24 +0200]
               | Process 612118 is blocking, has it exited?
24.22s     info: Async::Container::Forked [oid=0x24b8] [pid=612099] [2021-03-01 20:57:24 +0200]
               | #<Async::Container::Process TurboTest::Server Worker> exited with pid 612118 exit 0

rspec

$ bundle exec rspec ./spec/models/
...................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................................

Finished in 19.46 seconds (files took 2.38 seconds to load)
517 examples, 0 failures

[ioquatix]

Try running with

bundle exec turbo_test ./spec/models/**/*_spec.rb

Also, are you using 0.1.1 which was released yesterday?

[ilyazub]

Yes, I use 0.1.1.

Thank you, it works with the explicit wildcard path.

$ bundle exec turbo_test ./spec/**/*_spec.rb

But some tests are failing that do not fail with RSpec.

turbo_test

RSpec

[ilyazub]

Just a note that glob paths are not recursive by default. I guess it's by the design of samovar.

Default

Recursive

With the recursive glob, it opens to many connections. The limit of open files is low on my system, but this is not a problem with other gems that parallelize RSpec.

@ioquatix How to split all spec files in a number of groups equal to a number of workers like ParallelTests::Test::Runner#tests_in_groups? I'd be happy to make a PR if you consider this is useful.

[ioquatix]

It will make one worker per processor core by default.

The glob issue is odd, it should be expanded by your shell.

Regarding the failed specs, is it because it’s using some shared state?

[ilyazub]

The glob issue was fixed after I enabled it by default in the .bashrc.

Failed specs are for sure because of the shared state. The test was using User.last which could be changed in some other test. I'll fix it on my side.

before :all do
  @user = User.last
  @search = Search.create!(user: @user, q: "expensive query", status: "Success")
end

It will make one worker per processor core by default.

I understand, but I mean executing RSpec tests in groups on each worker instead of one by one. For example, it spawns 8 workers and executes RSpec 304 times. I'm asking about spawning 8 workers and executing RSpec eight times with 38 spec files per each RSpec execution.

To rephrase, now:

bundle exec rspec spec/file_1_spec.rb # Worker 1
bundle exec rspec spec/file_2_spec.rb # Worker 5
# ...
bundle exec rspec spec/file_304_spec.rb # Worker 3

Wish:

bundle exec rspec spec/file_1_spec.rb spec/file_2_spec.rb spec/file_38_spec.rb # Worker 1
bundle exec rspec spec/file_39_spec.rb spec/file_40_spec.rb spec/file_76_spec.rb # Worker 2
# ...
bundle exec rspec spec/file_266_spec.rb spec/file_267_spec.rb spec/file_304_spec.rb # Worker 8

This could decrease test execution time when the time to load files is more than a few seconds. Haven't checked this assumption actually.

[ioquatix]

Can you check your assumption about performance? I think the execution overhead of RSpec is relatively small.

[ilyazub]

Can you check your assumption about performance? I think the execution overhead of RSpec is relatively small.

Yes, I'll check it and reply here.