Skip to content
New issue

Have a question about this project? # for a free GitHub account to open an issue and contact its maintainers and the community.

#

By clicking “#”, you agree to our terms of service and privacy statement. We’ll occasionally send you account related emails.

Already on GitHub? # to your account

Jump to bottom

slow unit test causing travis failures #517

Closed
jhoblitt opened this issue Mar 3, 2016 · 2 comments · Fixed by #518
Closed

slow unit test causing travis failures #517

jhoblitt opened this issue Mar 3, 2016 · 2 comments · Fixed by #518
Labels
bug Something isn't working

Comments

@jhoblitt
Copy link
Member

jhoblitt commented Mar 3, 2016

y so slow!

This cause of this slow unit test (particularly under ruby 1.9.3) needs to be hunted down and destroyed.

https://travis-ci.org/jenkinsci/puppet-jenkins/jobs/113456469#L1721-L1722
@jhoblitt jhoblitt mentioned this issue Mar 3, 2016
Merged
@petems
Copy link
Member

petems commented Mar 3, 2016

With a quick performance check:

rspec run on 1.9.3

bundle exec rspec ./spec/unit/jenkins_plugins_spec.rb:138
Puppet::Jenkins::Plugins
  .plugins_from_updatecenter
    still works when json not avaliable and uses okjson instead
      should be an instance of Hash
    should load all plugins
      should be an instance of Hash
      size
        should eql 870
PROFILE: interrupts/evictions/bytes = 4714/0/5928

Finished in 54.43 seconds (files took 1.11 seconds to load)
3 examples, 0 failures

Randomized with seed 37156

pprof results on 1.9.3

bundle exec pprof.rb --text  /tmp/rspec_profile

Using local file /opt/boxen/rbenv/versions/1.9.3-p551/bin/ruby.
Using local file /tmp/rspec_profile.
Total: 4714 samples
    3526  74.8%  74.8%     3526  74.8% garbage_collector
     997  21.1%  95.9%      997  21.1% String#[]
     153   3.2%  99.2%     1180  25.0% OkJson#lex
      10   0.2%  99.4%       10   0.2% Regexp#match
       6   0.1%  99.5%       18   0.4% OkJson#unquote
       4   0.1%  99.6%        4   0.1% Hash#[]=
       4   0.1%  99.7%        4   0.1% String#[]=
       2   0.0%  99.7%        2   0.0% JSON::Ext::Parser#parse
       2   0.0%  99.8%        2   0.0% Kernel#dup
       2   0.0%  99.8%        2   0.0% MatchData#[]
       2   0.0%  99.9%       32   0.7% OkJson#tok
       1   0.0%  99.9%        1   0.0% Comparable#<
       1   0.0%  99.9%        1   0.0% Enumerable#inject
       1   0.0%  99.9%        1   0.0% Module#method_defined?
       1   0.0% 100.0%        1   0.0% RSpec::Matchers#be_an_instance_of
       1   0.0% 100.0%        1   0.0% Range.allocate
       1   0.0% 100.0%        1   0.0% String#force_encoding
       0   0.0% 100.0%     1188  25.2% Array#map
       0   0.0% 100.0%     1187  25.2% BasicObject#instance_exec
       0   0.0% 100.0%     1188  25.2% Class#invoke
       0   0.0% 100.0%     1188  25.2% Class#run
       0   0.0% 100.0%     1188  25.2% Class#run_examples
       0   0.0% 100.0%        1   0.0% Class#with_replaced_metadata
       0   0.0% 100.0%     1186  25.2% File.open
       0   0.0% 100.0%     1186  25.2% Hash#fetch
       0   0.0% 100.0%        2   0.0% JSON#parse
       0   0.0% 100.0%     1188  25.2% Kernel#load
       0   0.0% 100.0%        4   0.1% Kernel#loop
       0   0.0% 100.0%     1186  25.2% Module#plugins_from_updatecenter
       0   0.0% 100.0%        3   0.1% OkJson#arrparse
       0   0.0% 100.0%     1184  25.1% OkJson#decode
       0   0.0% 100.0%        4   0.1% OkJson#objparse
       0   0.0% 100.0%        4   0.1% OkJson#pairparse
       0   0.0% 100.0%        1   0.0% OkJson#rubydoesenc?
       0   0.0% 100.0%       30   0.6% OkJson#strtok
       0   0.0% 100.0%        4   0.1% OkJson#textparse
       0   0.0% 100.0%        4   0.1% OkJson#valparse
       0   0.0% 100.0%        1   0.0% RSpec::Core::Configuration#configure_example
       0   0.0% 100.0%     1188  25.2% RSpec::Core::Configuration#with_suite_hooks
       0   0.0% 100.0%     1188  25.2% RSpec::Core::Example#run
       0   0.0% 100.0%     1187  25.2% RSpec::Core::Example#with_around_and_singleton_context_hooks
       0   0.0% 100.0%     1187  25.2% RSpec::Core::Example#with_around_example_hooks
       0   0.0% 100.0%        1   0.0% RSpec::Core::FilterableItemRepository::QueryOptimized#applicable_metadata_from
       0   0.0% 100.0%        1   0.0% RSpec::Core::FilterableItemRepository::QueryOptimized#items_for
       0   0.0% 100.0%     1187  25.2% RSpec::Core::Hooks::HookCollections#run
       0   0.0% 100.0%     1187  25.2% RSpec::Core::Hooks::HookCollections#run_around_example_hooks_for
       0   0.0% 100.0%     1185  25.1% RSpec::Core::MemoizedHelpers#should
       0   0.0% 100.0%     1186  25.2% RSpec::Core::MemoizedHelpers::ThreadsafeMemoized#fetch_or_store
       0   0.0% 100.0%     1186  25.2% RSpec::Core::ReentrantMutex#synchronize
       0   0.0% 100.0%     1188  25.2% RSpec::Core::Reporter#report
       0   0.0% 100.0%     1188  25.2% RSpec::Core::Runner#run
       0   0.0% 100.0%     1188  25.2% RSpec::Core::Runner#run_specs
       0   0.0% 100.0%        1   0.0% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::ShouldLoadAllPlugins::Size#should

It looks like a 1.9.3 garbage collection issue with okjson:

rspec run on 2.1.2

bundle exec rspec ./spec/unit/jenkins_plugins_spec.rb:138
Run options: include {:locations=>{"./spec/unit/jenkins_plugins_spec.rb"=>[138]}}

Randomized with seed 16414

Puppet::Jenkins::Plugins
  .plugins_from_updatecenter
    still works when json not avaliable and uses okjson instead
      should be an instance of Hash
    should load all plugins
      should be an instance of Hash
      size
        should eql 870
PROFILE: interrupts/evictions/bytes = 1382/0/11392

Finished in 15.78 seconds (files took 0.79786 seconds to load)
3 examples, 0 failures

Randomized with seed 16414

pprof run on 2.1.2

bundle exec pprof.rb --text  /tmp/rspec_profile
Using local file /opt/rubies/2.1.2/bin/ruby.
Using local file /tmp/rspec_profile.
Total: 1382 samples
     870  63.0%  63.0%      870  63.0% String#[]
     297  21.5%  84.4%     1218  88.1% OkJson#lex
     156  11.3%  95.7%      156  11.3% garbage_collector
      28   2.0%  97.8%       28   2.0% Regexp#match
       8   0.6%  98.3%       19   1.4% OkJson#unquote
       3   0.2%  98.6%        3   0.2% JSON::Ext::Parser#parse
       3   0.2%  98.8%       57   4.1% OkJson#tok
       3   0.2%  99.0%        3   0.2% String#===
       2   0.1%  99.1%        2   0.1% Array#[]
       2   0.1%  99.3%        2   0.1% String#[]=
       1   0.1%  99.3%        1   0.1% BasicObject#!=
       1   0.1%  99.4%        2   0.1% Comparable#<
       1   0.1%  99.5%        2   0.1% Kernel#dup
       1   0.1%  99.6%        4   0.3% Kernel#loop
       1   0.1%  99.6%        1   0.1% Kernel.require
       1   0.1%  99.7%        1   0.1% MatchData#[]
       1   0.1%  99.8%        3   0.2% OkJson#eat
       1   0.1%  99.9%       49   3.5% OkJson#strtok
       1   0.1%  99.9%        1   0.1% String#<=>
       1   0.1% 100.0%        1   0.1% String#initialize_copy
       0   0.0% 100.0%     1226  88.7% Array#map
       0   0.0% 100.0%     1226  88.7% BasicObject#instance_exec
       0   0.0% 100.0%     1226  88.7% Class#invoke
       0   0.0% 100.0%     1226  88.7% Class#run
       0   0.0% 100.0%     1226  88.7% Class#run_examples
       0   0.0% 100.0%     1225  88.6% File.open
       0   0.0% 100.0%     1226  88.7% Hash#fetch
       0   0.0% 100.0%        3   0.2% JSON#parse
       0   0.0% 100.0%        3   0.2% JSON.parse
       0   0.0% 100.0%        1   0.1% Kernel#initialize_dup
       0   0.0% 100.0%     1226  88.7% Kernel#load
       0   0.0% 100.0%        1   0.1% Method#call
       0   0.0% 100.0%     1226  88.7% Module#plugins_from_updatecenter
       0   0.0% 100.0%     1222  88.4% OkJson#decode
       0   0.0% 100.0%        4   0.3% OkJson#objparse
       0   0.0% 100.0%        4   0.3% OkJson#pairparse
       0   0.0% 100.0%        4   0.3% OkJson#textparse
       0   0.0% 100.0%        4   0.3% OkJson#valparse
       0   0.0% 100.0%     1226  88.7% Puppet::Jenkins::Plugins.plugins_from_updatecenter
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Configuration#with_suite_hooks
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Example#run
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Example#with_around_and_singleton_context_hooks
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Example#with_around_example_hooks
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Hooks::HookCollections#run
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Hooks::HookCollections#run_around_example_hooks_for
       0   0.0% 100.0%     1225  88.6% RSpec::Core::MemoizedHelpers#should
       0   0.0% 100.0%     1226  88.7% RSpec::Core::MemoizedHelpers::ThreadsafeMemoized#fetch_or_store
       0   0.0% 100.0%     1226  88.7% RSpec::Core::ReentrantMutex#synchronize
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Reporter#report
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Runner#run
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Runner#run_specs
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Runner.invoke
       0   0.0% 100.0%     1226  88.7% RSpec::Core::Runner.run
       0   0.0% 100.0%     1226  88.7% RSpec::ExampleGroups::PuppetJenkinsPlugins.run
       0   0.0% 100.0%     1226  88.7% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter.run
       0   0.0% 100.0%        3   0.2% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::ShouldLoadAllPlugins.run
       0   0.0% 100.0%        2   0.1% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::ShouldLoadAllPlugins.run_examples
       0   0.0% 100.0%        1   0.1% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::ShouldLoadAllPlugins::Size#should
       0   0.0% 100.0%        1   0.1% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::ShouldLoadAllPlugins::Size.run
       0   0.0% 100.0%        1   0.1% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::ShouldLoadAllPlugins::Size.run_examples
       0   0.0% 100.0%     1223  88.5% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::StillWorksWhenJsonNotAvaliableAndUsesOkjsonInstead.run
       0   0.0% 100.0%     1223  88.5% RSpec::ExampleGroups::PuppetJenkinsPlugins::PluginsFromUpdatecenter::StillWorksWhenJsonNotAvaliableAndUsesOkjsonInstead.run_examples
       0   0.0% 100.0%        1   0.1% RSpec::Mocks::AndWrapOriginalImplementation#call
       0   0.0% 100.0%        1   0.1% RSpec::Mocks::MessageExpectation::ImplementationDetails#invoke
       0   0.0% 100.0%        1   0.1% RSpec::Mocks::MessageExpectation::ImplementationDetails#invoke_incrementing_actual_calls_by
       0   0.0% 100.0%        1   0.1% RSpec::Mocks::MethodDouble#proxy_method_invoked
       0   0.0% 100.0%        1   0.1% RSpec::Mocks::PartialDoubleProxy#message_received
       0   0.0% 100.0%        1   0.1% RSpec::Mocks::Proxy#message_received

@petems petems mentioned this issue Mar 3, 2016
Merged
@jhoblitt
Copy link
Member Author

jhoblitt commented Mar 3, 2016

I suppose ruby 1.9.3 should no longer be able to surprise me at this point. Fantastic sleuthing @petems!

@jhoblitt jhoblitt added the bug Something isn't working label Mar 3, 2016
# for free to join this conversation on GitHub. Already have an account? # to comment
Assignees
No one assigned
Labels
bug Something isn't working
Projects
None yet
Milestone
No milestone
Development

Successfully merging a pull request may close this issue.

Plugins from updatecenter performance fixes petems/puppet-jenkins
2 participants
@jhoblitt @petems