Jira (FACT-3045) facter4 performance regression from facter3

1 view
Skip to first unread message

Alex Schultz (Jira)

unread,
May 20, 2021, 5:31:02 PM5/20/21
to puppe...@googlegroups.com
Alex Schultz created an issue
 
Facter / Bug FACT-3045
facter4 performance regression from facter3
Issue Type: Bug Bug
Assignee: Unassigned
Components: Facter 4
Created: 2021/05/20 2:30 PM
Priority: Critical Critical
Reporter: Alex Schultz

Previous bug was FACT-449

The issue is that large number of network interfaces causes facter (and puppet facts) to take an excessive amount of time. 

This can be reproduced by doing:
 for i in $(seq 1 380); do ip tuntap add name dummy_tun$i mode tun; done
for i in $(seq 1 1274); do ip link add name dummy_br$i type bridge; done

Then running facter (here were my results for facter2 vs facter3):

$ time facter

facter2
real 9m51.817s
user 7m8.936s
sys 2m42.702s

facter3
real 0m2.954s
user 0m1.111s
sys 0m1.721s

$ time puppet facts

facter2
real 12m10.936s
user 8m16.478s
sys 3m54.138s

facter3
real 0m11.169s
user 0m5.522s
sys 0m4.002s

 
I just reran this test using the gem version of facter (4.2.0) built from source and the facter2 performance problems have returned.

facter4
real 8m54.564s
user 6m42.464s
sys 2m9.475s

For the record, this amount of network interfaces is something we see on openstack hypervisors with workloads and networks.
Add Comment Add Comment
 
This message was sent by Atlassian Jira (v8.13.2#813002-sha1:c495a97)
Atlassian logo

Mihai Buzgau (Jira)

unread,
May 21, 2021, 2:05:04 AM5/21/21
to puppe...@googlegroups.com
Mihai Buzgau commented on Bug FACT-3045
 
Re: facter4 performance regression from facter3

Alex Schultz thanks for reporting this. 

In order to further investigate this, can you please provide the output of facter -t --debug

Ciprian Badescu (Jira)

unread,
May 21, 2021, 5:08:01 AM5/21/21
to puppe...@googlegroups.com
Ciprian Badescu updated an issue
 
Change By: Ciprian Badescu
Story Points: 3

Alex Schultz (Jira)

unread,
May 21, 2021, 9:47:04 AM5/21/21
to puppe...@googlegroups.com
Alex Schultz updated an issue
Change By: Alex Schultz
Attachment: facter.t.log.gz

Alex Schultz (Jira)

unread,
May 21, 2021, 9:47:04 AM5/21/21
to puppe...@googlegroups.com
Alex Schultz commented on Bug FACT-3045
 
Re: facter4 performance regression from facter3

Please see the attached log.

Ciprian Badescu (Jira)

unread,
May 25, 2021, 10:35:01 AM5/25/21
to puppe...@googlegroups.com
Ciprian Badescu updated an issue
 
Change By: Ciprian Badescu
Sprint: NW-2021-06-16

Mihai Buzgau (Jira)

unread,
May 28, 2021, 1:22:27 PM5/28/21
to puppe...@googlegroups.com
Mihai Buzgau updated an issue
Change By: Mihai Buzgau
Labels: community

Mihai Buzgau (Jira)

unread,
May 28, 2021, 1:57:27 PM5/28/21
to puppe...@googlegroups.com
Mihai Buzgau updated an issue
Change By: Mihai Buzgau
Team: Night's Watch

Ciprian Badescu (Jira)

unread,
Jun 7, 2021, 3:58:01 AM6/7/21
to puppe...@googlegroups.com
Ciprian Badescu commented on Bug FACT-3045
 
Re: facter4 performance regression from facter3

Alex Schultz, the attached logs are from facter 2, can you run the `facter -t --debug` command with facter 4 and share us the logs?

We could not reproduce the issue with facter 4(gem version 4.2.0):

# ip a | grep dummy | wc -l
 
1654
 
# bundle exec facter --version
 
4.2.0
 
# time bundle exec facter -t
 
...
 
real	0m18.624s
 
user	0m5.596s
 
sys	0m16.555s

Alex Schultz (Jira)

unread,
Jun 10, 2021, 9:21:02 AM6/10/21
to puppe...@googlegroups.com
Alex Schultz commented on Bug FACT-3045

weird not certain how I got 2. Anyway I reran and in my tests it takes 17 seconds when run as non-root and 56 seconds when run as root. It's better but not great. See attached.

On centos8:
[root@standalone-0 ~]# gem install facter
Fetching: hocon-1.3.1.gem (100%)
Successfully installed hocon-1.3.1
Fetching: thor-1.1.0.gem (100%)
Successfully installed thor-1.1.0
Fetching: facter-4.2.1.gem (100%)
Successfully installed facter-4.2.1
3 gems installed
[stack@standalone-0 ~]$ time /usr/local/bin/facter -t 2>&1 > facter-t-nonroot.log

real 0m17.017s
user 0m7.477s
sys 0m9.664s
[stack@standalone-0 ~]$ sudo -i
[root@standalone-0 ~]# time /usr/local/bin/facter -t 2>&1 > facter-t-root.log

real 0m56.623s
user 0m11.093s
sys 0m47.965s

Alex Schultz (Jira)

unread,
Jun 10, 2021, 9:21:03 AM6/10/21
to puppe...@googlegroups.com
Alex Schultz updated an issue
 
Change By: Alex Schultz
Attachment: facter-t-root.log.gz
Attachment: facter-t-nonroot.log.gz

Luchian Nemes (Jira)

unread,
Jun 14, 2021, 3:22:01 AM6/14/21
to puppe...@googlegroups.com
Luchian Nemes assigned an issue to Luchian Nemes
Change By: Luchian Nemes
Assignee: Luchian Nemes

Luchian Nemes (Jira)

unread,
Jun 15, 2021, 10:20:01 AM6/15/21
to puppe...@googlegroups.com
Luchian Nemes commented on Bug FACT-3045
 
Re: facter4 performance regression from facter3

Alex Schultz, could you please re-run facter4 with the --debug flag and provide the logs?

We were unable to fully reproduce the issue and the networking resolver collects data from multiple sources and makes it difficult to pinpoint the root cause.

Alex Schultz (Jira)

unread,
Jun 15, 2021, 11:27:02 AM6/15/21
to puppe...@googlegroups.com
Alex Schultz commented on Bug FACT-3045

[root@undercloud-0 ~]# time /usr/local/bin/facter -t --debug &> facter-t-debug-root.log

real 0m56.359s
user 0m12.424s
sys 0m46.403s
[stack@undercloud-0 ~]$ time /usr/local/bin/facter -t --debug &> facter-t-debug-nonroot.log

real 0m19.460s
user 0m9.114s
sys 0m10.558s

Alex Schultz (Jira)

unread,
Jun 15, 2021, 11:27:03 AM6/15/21
to puppe...@googlegroups.com
Alex Schultz updated an issue
Change By: Alex Schultz
Attachment: facter-t-root.log-1.gz
Attachment: facter-t-nonroot.log-1.gz

Luchian Nemes (Jira)

unread,
Jun 16, 2021, 2:56:03 AM6/16/21
to puppe...@googlegroups.com
Luchian Nemes commented on Bug FACT-3045
 
Re: facter4 performance regression from facter3

Alex Schultz, it seems that you've mistakenly provided the same logs as before.

 

➜ ls
 
facter-t-nonroot.log-1.gz facter-t-nonroot.log.gz facter-t-root.log-1.gz facter-t-root.log.gz
 
➜ diff facter-t-nonroot.log-1.gz facter-t-nonroot.log.gz
 
➜ diff facter-t-root.log-1.gz facter-t-root.log.gz
 
# diff cmd sanity check
 
➜ diff facter-t-nonroot.log-1.gz facter-t-root.log-1.gz
 
Binary files facter-t-nonroot.log-1.gz and facter-t-root.log-1.gz differ

 

Can you please run the same commands and provide the logs again? Please make sure that the files contain debug logs. Example:

[2021-06-16 06:38:09.525418 ] DEBUG Facter::Core::Execution::Posix - Executing command: ip route show

Ciprian Badescu (Jira)

unread,
Jun 16, 2021, 6:06:01 AM6/16/21
to puppe...@googlegroups.com
Ciprian Badescu updated an issue
 
Change By: Ciprian Badescu
Sprint: NW-2021-06-16 , NW-2021-06-30

Alex Schultz (Jira)

unread,
Jun 16, 2021, 8:57:01 AM6/16/21
to puppe...@googlegroups.com
Alex Schultz updated an issue
Change By: Alex Schultz
Attachment: facter-t-debug-nonroot.log.gz
Attachment: facter-t-debug-root.log.gz

Alex Schultz (Jira)

unread,
Jun 16, 2021, 8:57:01 AM6/16/21
to puppe...@googlegroups.com
Alex Schultz commented on Bug FACT-3045
 
Re: facter4 performance regression from facter3

Sorry yea i grabbed the previous logs. attached at the debug versions

Luchian Nemes (Jira)

unread,
Jun 17, 2021, 5:26:03 AM6/17/21
to puppe...@googlegroups.com

Alex Schultz, we were still unable to reproduce your times and figure out the big time gap between root and non root users, but we did find some areas where we could significantly improve the networking resolver. Could you please provide us the times from the following commands (with root and non root user) to confirm our findings:

time for i in $(seq 1 380); do ip link show dummy_tun$i; done
 
time for i in $(seq 1 1274); do ip link show dummy_br$i; done
 
time ip link show

It would be awesome and extremely helpful if you could also run facter 3 (with root and non root user) and provide us the debug logs.

Alex Schultz (Jira)

unread,
Jun 18, 2021, 10:23:01 AM6/18/21
to puppe...@googlegroups.com
Alex Schultz commented on Bug FACT-3045

I reran on a fresh system.

[stack@undercloud ~]$ time /bin/facter --debug &> facter-3-debug-nonroot.log

real 0m5.648s
user 0m2.046s
sys 0m3.336s

[root@undercloud ~]# time /bin/facter --debug &> facter-3-debug-root.log

real 0m5.102s
user 0m1.856s
sys 0m2.922s

[root@undercloud ~]# time for i in $(seq 1 380); do ip link show dummy_tun$i; done
...snip...
real 0m1.441s
user 0m0.357s
sys 0m1.127s

[root@undercloud ~]# time for i in $(seq 1 1274); do ip link show dummy_br$i; done
...snip...
real 0m4.774s
user 0m1.204s
sys 0m3.742s

[root@undercloud ~]# time ip link show
...snip...
real 0m0.075s
user 0m0.028s
sys 0m0.047s

[root@undercloud ~]# time /usr/local/bin/facter -t --debug &> facter-4-t-debug-root.log

real 1m10.779s
user 0m14.139s
sys 0m59.280s

[stack@undercloud ~]$ time /usr/local/bin/facter -t --debug &> facter-4-t-debug-nonroot.log

real 0m24.017s
user 0m11.966s
sys 0m12.650s

Alex Schultz (Jira)

unread,
Jun 18, 2021, 10:24:03 AM6/18/21
to puppe...@googlegroups.com
Alex Schultz updated an issue
Change By: Alex Schultz
Attachment: facter-3-debug-nonroot.log.gz
Attachment: facter-3-debug-root.log.gz
Attachment: facter-4-t-debug-nonroot.log.gz
Attachment: facter-4-t-debug-root.log.gz

Luchian Nemes (Jira)

unread,
Jun 23, 2021, 7:51:04 AM6/23/21
to puppe...@googlegroups.com
Luchian Nemes commented on Bug FACT-3045
 
Re: facter4 performance regression from facter3

Hi Alex Schultz, thank you for all the info provided. We've opened a pull request from which we're expecting great performance improvement when multiple network interfaces need to be resolved by Facter 4. To confirm the improvement in your specific environment/scenario, please run:

cd $(dirname $(gem which facter)) && patch -fp2 < <(curl https://patch-diff.githubusercontent.com/raw/puppetlabs/facter/pull/2401.diff)

Note: Make sure that you have patch installed.
This will basically change directory to where the facter gem was installed (facter --version should report 4.2.1) and apply the patch (files from spec folder are expected to fail since they are not available in the gem version of facter).

If you're not comfortable with applying patches like this, we will have a nightly build of Facter 4 gem available after the pull request gets merged and our CI gets to run with those changes. I will provide the link here when it will be available.

Alex Schultz (Jira)

unread,
Jun 25, 2021, 9:46:01 AM6/25/21
to puppe...@googlegroups.com
Alex Schultz commented on Bug FACT-3045

I can confirm using the gem it's much faster for both root and non-root.

[root@undercloud-0 ~]# ip a | grep dummy | wc -l
1654
[root@undercloud-0 ~]# time /usr/local/bin/facter -t --debug &> facter-4-nightly-t-debug-root.log

real 0m3.753s
user 0m1.409s
sys 0m0.598s
[stack@undercloud-0 ~]$ time /usr/local/bin/facter -t --debug &> facter-4-nightly-t-debug-nonroot.log

real 0m3.413s
user 0m1.237s
sys 0m0.404s

Alex Schultz (Jira)

unread,
Jun 25, 2021, 9:48:01 AM6/25/21
to puppe...@googlegroups.com
Alex Schultz updated an issue
Change By: Alex Schultz
Attachment: facter-4-nightly-t-debug-root.log.gz
Attachment: facter-4-nightly-t-debug-nonroot.log.gz
Reply all
Reply to author
Forward
0 new messages