Long time from starting pdk test unit until unit tests start

[tuxmea]

Describe the bug When running pdk test unit it takes a very long time where PDK is doing something prior the unit tests start

To Reproduce run time pdk test unit

Expected behavior Unit tests start immediately after running pdk test unit

Additional context Installed via DEB Package v1.13.0 on Debian 9

[glennsarti]

Hi @tuxmea , I have you tried running with --debug to see where it's taking time. Also when you say a long time, how long is this taking?

Thanks.

[tuxmea]

pdk (DEBUG): Executing '/home/alfkem/puppet/control-repository/site/profile/bin/rake spec_standalone'
pdk (DEBUG): Command environment:
pdk (DEBUG):   TERM: xterm
pdk (DEBUG):   PUPPET_GEM_VERSION: 5.5.16
pdk (DEBUG):   FACTER_GEM_VERSION:
pdk (DEBUG):   HIERA_GEM_VERSION:
pdk (DEBUG):   CI_SPEC_OPTIONS: --format j
pdk (DEBUG):   BUNDLE_IGNORE_CONFIG: 1
pdk (DEBUG):   GEM_HOME: /home/alfkem/.pdk/cache/ruby/2.4.0
pdk (DEBUG):   GEM_PATH: /opt/puppetlabs/pdk/private/ruby/2.4.5/lib/ruby/gems/2.4.0:/opt/puppetlabs/pdk/share/cache/ruby/2.4.0:/opt/puppetlabs/pdk/private/puppet/ruby/2.4.0
pdk (DEBUG):   PATH: /opt/puppetlabs/pdk/private/ruby/2.4.5/bin:/home/alfkem/.pdk/cache/ruby/2.4.0/bin:/opt/puppetlabs/pdk/private/ruby/2.4.5/lib/ruby/gems/2.4.0/bin:/opt/puppetlabs/pdk/share/cache/ruby/2.4.0/bin:/opt/puppetlabs/pdk/private/puppet/ruby/2.4.0/bin:/opt/puppetlabs/pdk/bin:/opt/puppetlabs/pdk/private/git/bin:/home/alfkem/bin:/usr/local/bin:/usr/bin:/bin:/usr/local/games:/usr/games:/opt/puppetlabs/bin:/home/alfkem/bin

Hangs for 4-5 minutes.

Then the next output shows up:

pdk (DEBUG): Execution of '/home/alfkem/puppet/control-repository/site/profile/bin/rake spec_standalone' complete (duration: 318.774192893s; exit code: 0) A large hash and afterwards the result:

Run options: exclude {:bolt=>true}
  Evaluated 328 tests in 318.774192893 seconds: 0 failures, 0 pending.

real    5m22,428s
user    5m14,332s
sys     0m7,452s

[tuxmea]

When running pdk bundle exec rake spec the following happens: (Hint: the bin/gitlab_unit_tests.sh sript changes into site/profile directory and rund pdk bundle exec ...)

12:34 $ ./bin/gitlab_unit_tests.sh
Profile Unit Tests
~/puppet/control-repository/site/profile ~/puppet/control-repository
pdk (INFO): Using Ruby 2.4.5
pdk (INFO): Using Puppet 5.5.16
/opt/puppetlabs/pdk/private/ruby/2.4.5/bin/ruby -I/opt/puppetlabs/pdk/share/cache/ruby/2.4.0/gems/rspec-core-3.8.2/lib:/opt/puppetlabs/pdk/share/cache/ruby/2.4.0/gems/rspec-support-3.8.2/lib /opt/puppetlabs/pdk/share/cache/ruby/2.4.0/gems/rspec-core-3.8.2/exe/rspec --pattern spec/\{aliases,classes,defines,functions,hosts,integration,plans,tasks,type_aliases,types,unit\}/\*\*/\*_spec.rb

Hangs up to 3-4 minutes.

Then we see the rspec results. Afterwards the summary:

Finished in 1 minute 34.86 seconds (files took 3 minutes 42.5 seconds to load)
328 examples, 0 failures

real    5m19,756s
user    5m11,932s
sys     0m7,196s

[tuxmea]

Running pdk --debug bundle exec rake spec:

pdk (DEBUG): Analytics opt-out is set, analytics will be disabled
pdk (DEBUG): Skipping submission of 'bundle' screenview because analytics is disabled
pdk (INFO): Using Ruby 2.4.5
pdk (INFO): Using Puppet 5.5.16
pdk (DEBUG): Using '/opt/puppetlabs/pdk/private/ruby/2.4.5/bin/bundle' from PDK package.
pdk (DEBUG): Executing '/opt/puppetlabs/pdk/private/ruby/2.4.5/bin/bundle exec rake spec' interactively
I, [2019-09-20T12:40:54.656846 #3604]  INFO -- : Creating symlink from spec/fixtures/modules/site to ../../../../../modules
I, [2019-09-20T12:40:54.657226 #3604]  INFO -- : Creating symlink from spec/fixtures/modules/profile to /home/alfkem/puppet/control-repository/site/profile
/opt/puppetlabs/pdk/private/ruby/2.4.5/bin/ruby -I/opt/puppetlabs/pdk/share/cache/ruby/2.4.0/gems/rspec-core-3.8.2/lib:/opt/puppetlabs/pdk/share/cache/ruby/2.4.0/gems/rspec-support-3.8.2/lib /opt/puppetlabs/pdk/share/cache/ruby/2.4.0/gems/rspec-core-3.8.2/exe/rspec --pattern spec/\{aliases,classes,defines,functions,hosts,integration,plans,tasks,type_aliases,types,unit\}/\*\*/\*_spec.rb

No output for 3-4 minutes. Then the rspec results show up. Then:

Finished in 1 minute 34.34 seconds (files took 3 minutes 42.6 seconds to load)
328 examples, 0 failures

pdk (DEBUG): Execution of '/opt/puppetlabs/pdk/private/ruby/2.4.5/bin/bundle exec rake spec' complete (duration:                               318.71149404s; exit code: 0)

real    5m19,404s
user    5m11,940s
sys     0m6,940s

[tuxmea]

pdk: 318 seconds rspec-puppet: 34 seconds. What is happening within the missing 280 seconds?

[tuxmea]

Hint from Rob Nelson:

What happens if you add —tests \<single file>? Is it any faster when not enumerating the filesystem? 

[logicminds]

This command should be running rake spec_prep too IRC. Is there any chance you specified a private repo that is prompting for credentials and then times out?

[tuxmea]

pdk --debug bundle exec rake spec_prep finished within 1.3 seconds:

pdk (DEBUG): Execution of '/opt/puppetlabs/pdk/private/ruby/2.4.5/bin/bundle exec rake spec_prep' complete (duration:  1.389028238s; exit code: 0)

@rnelson0: pdk running fast, when using --testsand specifying a single test: time pdk test unit --tests spec/classes/php7_spec.rb

pdk (INFO): Using Ruby 2.4.5
pdk (INFO): Using Puppet 5.5.16
[✔] Preparing to run the unit tests.
[✔] Running unit tests.
Run options: exclude {:bolt=>true}
  Evaluated 6 tests in 7.527297058 seconds: 0 failures, 0 pending.

real    0m11,067s
user    0m9,944s
sys     0m1,076s

There are 69 tests in the module:

find spec/ -type f -name *_spec.rb | wc -l
69

[tuxmea]

Note: running with --parallel reduced time. Still wondering why pdk needs more time when runing on a single CPU.

[rnelson0]

The only other thing I can think of is that I believe pdk test unit runs some form of bundle update, which could be slow even when nothing needs to update because it still needs to parse the dependency tree. That’s my last gasp at this though.

[cmusik]

From my tests I can tell that it does something with the spec files. But strace does not tell me what. It takes around one second per file. So the more files you have, the longer it takes. After that the tests start and it takes some seconds to complete them.

[tuxmea]

still an open issue. we have two modules: one with 110 spec test files (classes and defines) and a second one with 66 spec files. First module needs 6 minutes to run pdk test unit --list second one needs at least 3 minutes.

So number of spec tests file have a huge impact. What is happening when pdk parses the spec files?

[tuxmea]

Note: when runnign without PDK (only using Gemfile, Rakefile, spec/spec_helper.rb, .fixtures.yml) tests also take a very long time to start.

[cmusik]

There is also a ticket open at puppetlabs: https://tickets.puppetlabs.com/browse/PDK-1638

I let it open some weeks ago and there is a little progress.

[tuxmea]

Downgrading to PDK 1.10 reduce ci time from 7 to 2 minutes.

[github-actions[bot]]

This issue has been marked stale because it is open with no recent activity. The PDK Team is actively prioritizing existing bugs and new features, if this issue is still important to you please comment and we will add this to our backlog to complete.

[github-actions[bot]]

This issue was closed because it is open with no recent activity. The PDK Team is actively prioritizing existing bugs and new features, if this issue is still important to you please comment and we will add this to our backlog to complete.

[dazzafg]

It's still an issue for me, if it helps. pdk is incredibly slow to start running unit tests