Jira (PUP-10823) Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

37 views
Skip to first unread message

Ben Ford (Jira)

unread,
Dec 15, 2020, 12:03:02 PM12/15/20
to puppe...@googlegroups.com
Ben Ford moved an issue
 
Puppet / Bug PUP-10823
Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25
Change By: Ben Ford
Key: IAC PUP - 1324 10823
Method Found: Needs Assessment
Sub-team: Performance
Issue Type: Improvement Bug
Project: Infrastructure Automation Content Puppet
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v8.5.2#805002-sha1:a66f935)
Atlassian logo

Gheorghe Popescu (Jira)

unread,
Jan 11, 2021, 8:51:04 AM1/11/21
to puppe...@googlegroups.com
Gheorghe Popescu commented on Bug PUP-10823
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

This is also affecting puppet-agent module(and many other i guess) https://github.com/puppetlabs/puppetlabs-puppet_agent/runs/1679329961?check_suite_focus=true

Tracked the slowness to an update of facterdb(1.5.0) which loosen dependency on facter from <4 to <5, allowing the install of facter 4 when running unit test.

Gheorghe Popescu (Jira)

unread,
Jan 11, 2021, 9:27:07 AM1/11/21
to puppe...@googlegroups.com

Running a dummy test(` it

{ is_expected.to compile.with_all_deps }

`) seems that 41% of the runtime is lost in Facter 4 `block (2 levels) in execute_command - /usr/local/rvm/gems/ruby-2.6.6/gems/facter-4.0.47/lib/facter/custom_facts/core/execution/base.rb:77 `

Added a puts in the Facter.execute:

puppet_agent
 
  when PE on RedHat
 
command: /usr/bin/apt-get -s -o Debug::NoLocking=true upgrade 2>&1
 
0.8899572720001743
 
command: /usr/bin/apt-get -s -o Debug::NoLocking=true dist-upgrade 2>&1
 
1.1139524899990647
 
command: ip link show
 
0.003986699997767573
 
command: ip link show lo
 
0.0033200580000993796
 
command: dhcpcd -U lo
 
0.0021536759995797183
 
command: ip link show ens192
 
0.003247942000598414
 
command: ip link show lo
 
0.002922425999713596
 
command: dhcpcd -U lo
 
0.0019498269975883886
 
command: ip link show lo
 
0.00314002300001448
 
command: dhcpcd -U lo
 
0.0020072980005352292
 
command: ip route show
 
0.003145973998471163
 
command: ip -6 route show
 
0.0029445619984471705
 
command: uname -m &&
 
            uname -n &&
 
            uname -p &&
 
            uname -r &&
 
            uname -s &&
 
            uname -v
 
0.005702127000404289
 
command: which lsb_release
 
0.003496238998195622
 
command: lsb_release -a
 
0.044373783999617444
 
    is expected to compile into a catalogue without dependency cycles
 
 
 
Finished in 3.06 seconds (files took 1.1 seconds to load)
 
1 example, 0 failures

Gheorghe Popescu (Jira)

unread,
Jan 11, 2021, 9:45:02 AM1/11/21
to puppe...@googlegroups.com

I would expect the test to use the facts from facterdb trough the rspec-puppet/rspec-puppet-facts/facterdb combination.

Gheorghe Popescu (Jira)

unread,
Jan 12, 2021, 2:39:04 AM1/12/21
to puppe...@googlegroups.com

rspec-puppet creates custom facts to overwrite core facts with the data from facterdb: https://github.com/rodjek/rspec-puppet/blob/master/lib/rspec-puppet/support.rb#L479-L483. This works well with facter 2 but facter 4 will still resolve facts, resulting in the observed general slowness.

Gheorghe Popescu (Jira)

unread,
Jan 12, 2021, 5:36:04 AM1/12/21
to puppe...@googlegroups.com

for puppetlabs-puppet_agent module the slowness is generated because facter 4 evaluates all the code that is outside `setcode` in custom facts. The tests were running with puppetlabs-apt 7.0.1 which didn't contain the custom facts fixes from: https://github.com/puppetlabs/puppetlabs-apt/commit/6786d506e373c08df8ad0b00c5a9d7275ba0ed1a

Updating the the test dependecy to newer puppetlabs-apt version, decreases the test runtime from 55 mins to 10 minutes on Linux: https://github.com/puppetlabs/puppetlabs-puppet_agent/actions/runs/479945403

Mihai Buzgau (Jira)

unread,
Jan 12, 2021, 10:54:02 AM1/12/21
to puppe...@googlegroups.com
Mihai Buzgau updated an issue
 
Change By: Mihai Buzgau
Sprint: Triaged tickets

Mihai Buzgau (Jira)

unread,
Jan 12, 2021, 10:54:04 AM1/12/21
to puppe...@googlegroups.com
Mihai Buzgau updated an issue
Change By: Mihai Buzgau
Team: Night's Watch

Josh Cooper (Jira)

unread,
Jan 12, 2021, 11:08:03 AM1/12/21
to puppe...@googlegroups.com
Josh Cooper commented on Bug PUP-10823
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

One way to avoid accidentally calling facter is to set the fact terminus to :memory like we do when running puppet tests:

https://github.com/puppetlabs/puppet/blob/0f9a5d709614c11e27214b84b7ab0f7b9a209fe5/lib/puppet/test/test_helper.rb#L150-L152

Note this won't help if a module accesses facter directly (Facter.values) or if the module defines custom or external facts and you want to test that they work, such as the lib/facter/apt_updates.rb custom fact in the apt module.

Gheorghe Popescu (Jira)

unread,
Jan 13, 2021, 1:33:04 AM1/13/21
to puppe...@googlegroups.com

The slowness on puppet-nginx seems to be related to the small perfromance gap on `Facter.value` between Facter 2 and Facter 4.
Because puppet-niginx has a lot of tests, the full test suite is considerably slower with Facter 4.
Another thing to note is that some facts are passing trough rspec-puppet stubbing and end-up being resolved on the running system.

cc: Bogdan Irimie

Josh Cooper (Jira)

unread,
May 13, 2021, 12:23:03 PM5/13/21
to puppe...@googlegroups.com
Josh Cooper commented on Bug PUP-10823

In facter 2.5, if a custom fact had a higher weight than a core fact, then the core fact was never resolved. For example:

$ cat /tmp/facts/ipaddress.rb
 
Facter.add(:ipaddress, weight: 999) do
 
  setcode do
 
    $stderr.puts "resolved custom ipaddress fact"
 
    "127.0.0.1"
 
  end
 
end
 
$ bundle exec facter --version
 
2.5.7
 
$ FACTERLIB=/tmp/facts strace -fi -e trace=execve bundle exec facter ipaddress
 
..
 
[00007f22d18fe2fb] execve("/home/josh/.rbenv/versions/2.5.8/bin/bundle", ["bundle", "exec", "facter", "ipaddress"], 0x55d65f08b150 /* 66 vars */) = 0
 
[pid 2221958] [00007fa4525472fb] execve("/bin/uname", ["/bin/uname", "-s"], 0x555857ef11b0 /* 84 vars */) = 0
 
..
 
resolved custom ipaddress fact
 
127.0.0.1

rspec-puppet relies on this "feature" so it can override core facts with a higher weight (999). However, in facter 4, the core fact is always resolved:

$ strace -fi -e trace=execve bundle exec facter --custom-dir /tmp/facts ipaddress 2>&1
 
...
 
[pid 2226940] [00007fcf73acc2fb] execve("/usr/bin/head", ["head", "-1"], 0x55f5fea630d0 /* 66 vars */) = 0
 
[00007f63b89bb2fb] execve("/home/josh/.rbenv/versions/2.5.8/bin/bundle", ["bundle", "exec", "facter", "--custom-dir", "/tmp/facts", "ipaddress"], 0x56176a3ef010 /* 65 vars */) = 0
 
[pid 2226942] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "lo"], 0x559350170630 /* 83 vars */) = 0
 
[pid 2226946] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "enp0s31f6"], 0x5593500caab0 /* 83 vars */) = 0
 
[pid 2226950] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "wlp0s20f3"], 0x55934fe64320 /* 83 vars */) = 0
 
[pid 2226954] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "vmnet1"], 0x55934f0e4c00 /* 83 vars */) = 0
 
[pid 2226958] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "vmnet8"], 0x55934f0d9ff0 /* 83 vars */) = 0
 
[pid 2226962] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "docker0"], 0x55934f115a20 /* 83 vars */) = 0
 
[pid 2226966] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "ens1"], 0x55934f121e20 /* 83 vars */) = 0
 
[pid 2226970] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "tun0"], 0x5593502b8650 /* 83 vars */) = 0
 
[pid 2226974] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "lo"], 0x5593502d1220 /* 83 vars */) = 0
 
[pid 2226978] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "tun0"], 0x5593501156f0 /* 83 vars */) = 0
 
[pid 2226982] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "lo"], 0x559350313a70 /* 83 vars */) = 0
 
[pid 2226986] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show", "tun0"], 0x559350353fe0 /* 83 vars */) = 0
 
[pid 2226990] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "link", "show"], 0x5593503716e0 /* 83 vars */) = 0
 
[pid 2227002] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "route", "show"], 0x5593503bdfd0 /* 83 vars */) = 0
 
[pid 2227006] [00007f6257c3c2fb] execve("/sbin/ip", ["ip", "-6", "route", "show"], 0x559350123090 /* 83 vars */) = 0...
 
resolved custom ipaddress fact
 
127.0.0.1

The ip related commands are triggered when puppet's compiler trying to add server facts https://github.com/puppetlabs/puppet/blob/93c86d6dc8e9a0d84032e46b1d4c632df5254c00/lib/puppet/indirector/catalog/compiler.rb#L418.

So this looks like a facter bug to me. I would think the core fact wouldn't be resolved if it's weight is less than an already resolved custom fact with a higher weight. But maybe that was done intentionally Bogdan Irimie Gheorghe Popescu? In any case, I'm going to move this to the FACT project.
This message was sent by Atlassian Jira (v8.13.2#813002-sha1:c495a97)
Atlassian logo
Reply all
Reply to author
Forward
0 new messages