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

9 views
Skip to first unread message

Josh Cooper (Jira)

unread,
May 13, 2021, 12:23:03 PM5/13/21
to puppe...@googlegroups.com
Josh Cooper moved an issue
 
Facter / Bug FACT-3039
Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25
Change By: Josh Cooper
Key: PUP FACT - 10823 3039
Project: Puppet Facter
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v8.13.2#813002-sha1:c495a97)
Atlassian logo

Gheorghe Popescu (Jira)

unread,
May 14, 2021, 1:52:03 AM5/14/21
to puppe...@googlegroups.com
Gheorghe Popescu commented on Bug FACT-3039
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

So this looks like a Facter bug to me. I would think the core fact wouldn't be resolved if its weight is less than an already resolved custom fact

The complication here is that Facter 4 implementation follows Facter 3, but modules unit tests were never run with Facter 3, and rspec-puppet was developed around Facter 2. Maybe this is an improvement that we can do but needs to be extensively tested.

Running ` facter --custom-dir /tmp/facts ipaddress` on Facter 3 will end up resolving the whole networking fact

2021-05-14 08:28:46.824626 DEBUG puppetlabs.facter - resolving networking facts.
2021-05-14 08:28:46.824754 DEBUG puppetlabs.facter - using the FQDN returned by gethostname
2021-05-14 08:28:46.825142 DEBUG leatherman.execution:93 - executing command: /sbin/route -n get default
2021-05-14 08:28:46.829662 DEBUG leatherman.execution:93 - executing command: /usr/sbin/ipconfig getoption
2021-05-14 08:28:46.885004 DEBUG puppetlabs.facter - fact "dhcp_servers" has resolved to 
...
127.0.0.1

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

Recently changed `Facter.value` on Facter 4 to behave like Facter 3 in order to avoid issues like: https://tickets.puppetlabs.com/browse/FACT-2956
Running `Facter.value(:ipaddress)` on Facter 3 will resolve the whole networking fact.

The discrepancy is between Facter 2 and (Facter 3 / Facter 4). I don't think this is an easy thing to fix and I'm concerned about the things we might break in the AIO.

Beth Glenfield (Jira)

unread,
Jun 15, 2021, 5:12:02 AM6/15/21
to puppe...@googlegroups.com

Ciprian Badescu (Jira)

unread,
Aug 2, 2021, 7:13:05 AM8/2/21
to puppe...@googlegroups.com

Ciprian Badescu (Jira)

unread,
Aug 2, 2021, 7:14:03 AM8/2/21
to puppe...@googlegroups.com

Ciprian Badescu (Jira)

unread,
Aug 11, 2021, 4:23:02 AM8/11/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 17, 2021, 3:33:03 AM8/17/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 18, 2021, 9:02:05 AM8/18/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 18, 2021, 9:03:02 AM8/18/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 18, 2021, 9:04:02 AM8/18/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 18, 2021, 9:11:02 AM8/18/21
to puppe...@googlegroups.com
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

So I did a profiling on calling `Facter.value(:kernel)` on Facter 4 and Facter 2 and Facter 4 is noticeably slower(0.13s vs 0.01s). From the call tree seems that the execution API is slower in Facter 4.
Attached are the traces for each call:

facter2.html - trace for calling `Facter.value(:kernel) with facter 2
Thread: 1580, Fiber: 1560 (100.00% ~ 0.010857273999135941)

facter4.html - trace for calling `Facter.value(:kernel) with facter 4
Thread: 2160, Fiber: 2140 (37.49% ~ 0.13846525101689622)
Thread: 2200, Fiber: 2180 (20.90% ~ 0.13846525101689622)
Thread: 2240, Fiber: 2220 (20.83% ~ 0.13846525101689622)
Thread: 2280, Fiber: 2260 (20.78% ~ 0.13846525101689622)

facter4_patched.html - trace for calling `Facter.value(:kernel) with facter 4 without hitting the resolver. Monkey patching the BaseResolver class
Thread: 2160, Fiber: 2140 (100.00% ~ 0.01828752097208053)

if defined? Facter::Resolvers::BaseResolver
  Facter::Resolvers::BaseResolver.class_eval do
    def self.resolve(_fact_name, _options = {}); end
  end
end

Having rspec-puppet to monkey patch Facter 4(https://github.com/gimmyxd/rspec-puppet/commit/49a0c2128ff079a97d2322446098f09cdf6185b1), does not seem to improve the full test suite speed when running on gh actions. Locally I managed to get an improvement of around 20% when running a single test file from puppet-nginx module, for a single OS

Gheorghe Popescu (Jira)

unread,
Aug 19, 2021, 4:24:03 AM8/19/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 19, 2021, 4:25:02 AM8/19/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 19, 2021, 4:25:02 AM8/19/21
to puppe...@googlegroups.com
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

Running without a dummy Facter::Core::Execution.execute:
Thread: 2160, Fiber: 2140 (100.00% ~ 0.016681278008036315)

facter4_no_exec.html

Gheorghe Popescu (Jira)

unread,
Aug 19, 2021, 4:35:03 AM8/19/21
to puppe...@googlegroups.com

Gheorghe Popescu (Jira)

unread,
Aug 19, 2021, 4:51:02 AM8/19/21
to puppe...@googlegroups.com
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

Given that when running tests with rspec-puppet/rspec-puppet-facts/facterdb the system facts should not matter(should not be resolved), I suggest moving on with monkey patching Facter 4 to not call the resolvers in the context of running specs. This will ensure that Facter 4 does not try to resolve facts for the current system when running modules unit tests(eg. platform specific catalog compilation)

Ewoud Kohl van Wijngaarden (Jira)

unread,
Aug 19, 2021, 5:24:02 AM8/19/21
to puppe...@googlegroups.com

Would it make sense to make hooks in Puppet itself to say "use these as facts" and bypass Facter altogether? Perhaps as a fact indirector? It may need to be disabled for real fact testing, but on the other hand: that directly uses Facter APIs, not Puppet.

 

So then we would need to modify rspec-puppet to set a fact indirector in catalog compilation.

Gheorghe Popescu (Jira)

unread,
Aug 19, 2021, 8:09:02 AM8/19/21
to puppe...@googlegroups.com

I think the issue here is caused by direct calls to `Facter.value` which are made in compiler.rb and in the providers. So Puppet calls Facter API directly. As Josh Cooper suggested here, there is the :memory indirector that can be used for facts but this is not for `Facter.value` calls.

Ewoud Kohl van Wijngaarden (Jira)

unread,
Aug 19, 2021, 9:59:03 AM8/19/21
to puppe...@googlegroups.com

Right, I missed that since it's a fairly long discussion by now. It feels weird that Puppet has a Fact indirector, but doesn't use it everywhere. I can also appreciate that a change in Puppet itself doesn't immediately solve it since we always want to be able to test on multiple versions.

 

We should be careful though. People do call Facter.value in their custom fact tests. Perhaps we should add first class custom fact support to rspec-puppet to provide a sane alternative. Perhaps even with let(:facts) support.

Josh Cooper (Jira)

unread,
Aug 19, 2021, 1:52:03 PM8/19/21
to puppe...@googlegroups.com
Josh Cooper commented on Bug FACT-3039

It feels weird that Puppet has a Fact indirector, but doesn't use it everywhere

Yep very true. We made some progress during Facter 3 development to eliminate places where we were calling facter directly, such as https://github.com/puppetlabs/puppet/commit/f41800ab4c0a928ff4f38ad5d1f6bd1e2b5619cd. But there are still places where we need to access facter while bootstrapping puppet, such as resolving the certname -> fqdn.

Also puppetserver wants the ability to load puppet without loading facter, see PUP-9686.

One idea is to allow a caller to register a facter implementation, similar to how callers (like puppetserver) register an http client implementation today:

facter_impl = FacterTestImpl.new
Puppet.initialize_settings([], true, true, http: ..., facter: facter_impl)

where FacterTestImpl implements the Facter API but always returns a canned set of values.

Then modify puppet so that all calls to Facter go through the runtime:

Puppet.runtime[:facter].get(:osversion)

Then something like rspec-puppet-facts could register the test facter implementation based on facts in facterdb?

Gheorghe Popescu (Jira)

unread,
Aug 20, 2021, 8:31:02 AM8/20/21
to puppe...@googlegroups.com

If i understand this correctly, the plan for this would be to:

1. add support for multiple Facter implementations in Puppet(Puppet.runtime[:facter])
2. implement the default Facter implementation(which delegates to Facter API)
3. update Puppet to use Puppet.runtime[:facter].get(:fact_name) internally instead of Facter.value(:fact_name)
4. implement a TestFacterImpl in rspec-puppet-facts which interfaces with FacterDB

While(3) resolves the Facter.value usage in Puppet, what are we going to do with modules that are writing their custom facts and are used in manifests? We are now having 2 ways of querying fact values which will put us in the same spot of as_ never going away legacy facts_.

As Ewoud said, there is also the complication that rspec-puppet must be able to test with multiple Puppet versions and provide support for controlling the values of custom facts written in modules.

Points 1, 2, 3 would be a good general improvement for Puppet interaction with Facter but the transition from Facter.value to Puppet.runtime[:facter] could prove troublesome

Ewoud Kohl van Wijngaarden (Jira)

unread,
Aug 20, 2021, 9:13:03 AM8/20/21
to puppe...@googlegroups.com

The alternative path would be for Facter itself to implement multiple backends, but that also feels very tricky.

Without considering implementation time and complexities like migration to that and supporting older versions, I think `Puppet.runtime[:facter]` feels cleanest. It would be a very good way to really isolate the compiler from the system you run on which allows you to really pretend you're some other system (different OS, kernel etc).

As for testing custom facts: I'd really like it if we could somehow make that work as well. Sadly, many custom facts use things like `Facter.value` directly. So then you're back to multiple backends in Facter itself. However, I think we can make it easier to test custom facts with better rspec-puppet integration instead.

Ciprian Badescu (Jira)

unread,
Aug 25, 2021, 5:24:02 AM8/25/21
to puppe...@googlegroups.com

Ciprian Badescu (Jira)

unread,
Aug 25, 2021, 5:25:03 AM8/25/21
to puppe...@googlegroups.com

Ciprian Badescu (Jira)

unread,
Oct 6, 2021, 4:54:02 AM10/6/21
to puppe...@googlegroups.com
Ciprian Badescu commented on Bug FACT-3039
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

It remains: 4. implement a TestFacterImpl in rspec-puppet-facts which interfaces with FacterDB

Ciprian Badescu (Jira)

unread,
Oct 6, 2021, 4:55:03 AM10/6/21
to puppe...@googlegroups.com
Ciprian Badescu updated an issue
Change By: Ciprian Badescu
Sprint: NW - 2021-08-25 , NW - 2021-10-20

Ciprian Badescu (Jira)

unread,
Oct 20, 2021, 4:20:03 AM10/20/21
to puppe...@googlegroups.com
Ciprian Badescu updated an issue
Change By: Ciprian Badescu
Sprint: NW - 2021-08-25, NW - 2021-10-20 , NW - 2021-11-03

Gabriel Nagy (Jira)

unread,
Oct 29, 2021, 6:03:02 AM10/29/21
to puppe...@googlegroups.com
Gabriel Nagy assigned an issue to Gabriel Nagy
Change By: Gabriel Nagy
Assignee: Gheorghe Popescu Gabriel Nagy

Ciprian Badescu (Jira)

unread,
Nov 3, 2021, 5:56:03 AM11/3/21
to puppe...@googlegroups.com
Ciprian Badescu updated an issue
Change By: Ciprian Badescu
Sprint: NW - 2021-08-25, NW - 2021-10-20, NW - 2021-11-03 , NW - 2021-11-17

Gabriel Nagy (Jira)

unread,
Nov 3, 2021, 10:43:03 AM11/3/21
to puppe...@googlegroups.com
Gabriel Nagy commented on Bug FACT-3039
 
Re: Puppet6/ruby2.5 runs in 42 minutes, where Puppet5/ruby2.4 runs in 25

I did a first pass of the rspec-puppet Facter implementation: https://github.com/GabrielNagy/rspec-puppet/commit/7ad4c36b2abdffe0017e4cb1b928969708549d9c

With this commit puppet-nginx unit tests drop by around 10 minutes (before: https://github.com/GabrielNagy/puppet-nginx/pull/2 after: https://github.com/GabrielNagy/puppet-nginx/pull/1).

The runtimes still seemed long, so I also triggered some runs with puppet 5, where the total runtime drops by another 10 minutes: https://github.com/GabrielNagy/puppet-nginx/pull/4

So the slowness is caused by both Puppet 6 and Facter 4. I'm assuming catalog compilation is a bit slower on puppet 6 than on puppet 5, but I'm not sure how to start debugging this. Josh Cooper do you have any idea if this is the case?

Gabriel Nagy (Jira)

unread,
Nov 5, 2021, 7:43:02 AM11/5/21
to puppe...@googlegroups.com
Reply all
Reply to author
Forward
0 new messages