external facts cause puppet apply to take inordinately longer to run

[Glenn Poston]

My external fact script takes 5s to run.

With external fact...

puppet takes 2.5m to run

facter takes 33s to run

Without external fact...

puppet takes 27s to run

facter takes 0.68s

Bottom line... there's no significant change in facter runtime when parsing the external fact, but the puppet runtime quadruples.

From watching the logs in real time I can see that the extra time is taken before puppet outputs its first response line (compilation time).  Also note that the compilation time that puppet reports is ~2s even though (when watching the output realtime) it takes 2 minutes for that line to return when puppet is parsing the external fact script.

Note: This script generates 36 custom facts

Should I submit a bug for this?

#Time of external fact script

[root@fisheye-10-0-2-15 manifests]# time /etc/facter/facts.d/service_discovery.sh

environment=test

...

service_discovery_script=ran

real 0m5.478s

user 0m0.053s

sys 0m0.111s

# Time of puppet run with external fact

[root@fisheye-10-0-2-15 manifests]# time FACTER_environment='vagrant' FACTER_role='fisheye' puppet apply --modulepath '/etc/puppet/modules:/tmp/vagrant-puppet/modules-0' site.ppNotice: Compiled catalog for fisheye-10-0-2-15.inin.com in environment production in 2.22 seconds

Notice: Finished catalog run in 30.76 seconds

real 2m25.856s

user 0m5.124s

sys 0m3.830s

#Time of facter with external fact

[root@fisheye-10-0-2-15 manifests]# time facter

analyticsapisegmentindexconsusmerwaittimeseconds => 1

architecture => x86_64

...

uptime_hours => 0

uptime_seconds => 2529

real 0m33.587s

user 0m0.658s

sys 0m0.849s

#Removing external fact script

[root@fisheye-10-0-2-15 manifests]# rm /etc/facter/facts.d/service_discovery.sh

rm: remove regular file `/etc/facter/facts.d/service_discovery.sh'? y

[root@fisheye-10-0-2-15 manifests]# ls /etc/facter/facts.d/

#Time of puppet run without external fact script

[root@fisheye-10-0-2-15 manifests]# time FACTER_environment='vagrant' FACTER_role='fisheye' puppet apply --modulepath '/etc/puppet/modules:/tmp/vagrant-puppet/modules-0' site.pp

Notice: Compiled catalog for fisheye-10-0-2-15.inin.com in environment production in 2.06 seconds

Notice: /Stage[main]/System::Facts/Facter::Fact[service_discovery]/File[/etc/facter/facts.d/service_discovery.sh]/ensure: created

Notice: Finished catalog run in 23.22 seconds

real 0m27.550s

user 0m4.408s

sys 0m2.292s

# Removing script again (cuz puppet run put it back)

[root@fisheye-10-0-2-15 manifests]# rm /etc/facter/facts.d/service_discovery.sh

rm: remove regular file `/etc/facter/facts.d/service_discovery.sh'? y

[root@fisheye-10-0-2-15 manifests]# ls /etc/facter/facts.d/

#Time of facter run without external script

[root@fisheye-10-0-2-15 manifests]# time facter

architecture => x86_64

augeasversion => 0.9.0

...

virtual => virtualbox

real 0m0.687s

user 0m0.324s

sys 0m0.287s

[Glenn Poston]

Any ideas anyone?

[vagrant@fisheye-10-0-2-15 ~]$ facter --version

1.7.3

[vagrant@fisheye-10-0-2-15 ~]$ puppet --version

3.3.2

[jcbollinger]

On Wednesday, November 27, 2013 11:17:44 PM UTC-6, Glenn Poston wrote:

My external fact script takes 5s to run.

With external fact...

puppet takes 2.5m to run

facter takes 33s to run

Without external fact...

puppet takes 27s to run

facter takes 0.68s

Bottom line... there's no significant change in facter runtime when parsing the external fact, but the puppet runtime quadruples.

Well, no significant change in facter's runtime give or take a factor of x50.  What's two orders of magnitude between friends?

Really, a five-second runtime for a fact is pretty extreme, but even that seems not to match the timings you report -- it looks more like your external fact takes 32 seconds to run.

In the past, Puppet has sometimes had issues with unnecessarily evaluating facts more than once, so perhaps such an issue is magnifying the effect of your slow fact.  Or perhaps the fact value is extremely large.  Or maybe evaluating the fact leaves the node in a state that slows or delays communication with the master.

It is probably worth your while to run the agent with the "--test --evaltrace" options to get a more detailed breakdown of how the time is being consumed.  Please post the whole timing report.

Also, it might be helpful to know what your external fact script is actually doing.  Are you at liberty to post that?

 

From watching the logs in real time I can see that the extra time is taken before puppet outputs its first response line (compilation time).  Also note that the compilation time that puppet reports is ~2s even though (when watching the output realtime) it takes 2 minutes for that line to return when puppet is parsing the external fact script.

Note: This script generates 36 custom facts

Should I submit a bug for this?

I think that would be premature at this time.  The issue is likely to be tied to details of your external fact script, so although there may indeed be a bug to report, I don't think we know yet what it might be.

John

[Glenn Poston]

On Tuesday, December 3, 2013 11:08:33 AM UTC-5, jcbollinger wrote:

On Wednesday, November 27, 2013 11:17:44 PM UTC-6, Glenn Poston wrote:

My external fact script takes 5s to run.

With external fact...

puppet takes 2.5m to run

facter takes 33s to run

Without external fact...

puppet takes 27s to run

facter takes 0.68s

Bottom line... there's no significant change in facter runtime when parsing the external fact, but the puppet runtime quadruples.

Well, no significant change in facter's runtime give or take a factor of x50.  What's two orders of magnitude between friends?

Really, a five-second runtime for a fact is pretty extreme, but even that seems not to match the timings you report -- it looks more like your external fact takes 32 seconds to run.

When I run the external fact script by itself it takes 5s to run.  Facter takes 32 seconds longer to run.

Here's the timing data for the run of the script outside of facter:

#Time of external fact script

[root@fisheye-10-0-2-15 manifests]# time /etc/facter/facts.d/service_discovery.sh

environment=test

...

service_discovery_script=ran

real 0m5.478s

user 0m0.053s

sys 0m0.111s

 

In the past, Puppet has sometimes had issues with unnecessarily evaluating facts more than once, so perhaps such an issue is magnifying the effect of your slow fact.  Or perhaps the fact value is extremely large.  Or maybe evaluating the fact leaves the node in a state that slows or delays communication with the master.

I would agree that a good theory is that puppet is unnecessarily evaluating facts more than once.  Also, these puppet runs are in standalone mode, so the master is not an issue.  The script will resolve 32 facts.  Each fact has a key that is less than 20 characters and a value that is less than 100 characters.

 

It is probably worth your while to run the agent with the "--test --evaltrace" options to get a more detailed breakdown of how the time is being consumed.  Please post the whole timing report.

Since we're running puppet in standalone mode, --test and --evaltrace aren't available.  I ran in --debug mode, but there's nothing being output about facter resolution so that wasn't very helpful.

 

Also, it might be helpful to know what your external fact script is actually doing.  Are you at liberty to post that?

The fact is making a curl request to a static file in AWS S3 that contains the key/value pairs.  Here is the external fact script (URL's have been changed)

#!/bin/bash

curl -s https://s3.amazonaws.com/blah/blah/blah | while read line; do

  key=`echo $line | cut -d = -f 1 | sed 's/\./_/g'`

  val=`echo $line | cut -d = -f 2`

  echo $key=$val

done

echo "service_discovery_script=ran"

[R.I.Pienaar]

there was either a thread here or a ticket files that puppet will run external facts
as much as 5 times over for a single run, might be worth adding some debug logging
to a file or something you in your fact to see if this is the case?

[Stuart Cracraft]

Scary.

[Glenn Poston]

I was curious how much of an effect the long running external fact was effecting the timing, so I updated the external fact script to simply echo the content (instead of fetching it from s3).  The facts it produced were the same as if it had fetched the facts from S3.

I then introduced a 'sleep x' before the echo statement in the script.  Now we see some compounding delays.  I think this adds a bit of support to the theory that puppet is unnecessarily re-evaluating facts, but it appears that facter may have some compounding delays as well.

Bottom Line:

When the script resolves instantaneously (echo statment only)

script takes .004s

facter takes .754s

puppet takes 1m

When the script takes 1s (sleep 1, then echo)

script takes 1s

facter takes 6s

puppet takes 1m12s

When the script takes 5s (sleep 5, then echo)

script takes 5s

facter takes 30s

puppet takes 2m38s

[Josh Cooper]

--
You received this message because you are subscribed to the Google Groups "Puppet Users" group.
To unsubscribe from this group and stop receiving emails from it, send an email to puppet-users...@googlegroups.com.

To view this discussion on the web visit https://groups.google.com/d/msgid/puppet-users/15127c27-91d5-452a-b322-af2b783d42fa%40googlegroups.com.

For more options, visit https://groups.google.com/groups/opt_out.

This is https://projects.puppetlabs.com/issues/22944. Facter will execute external facts multiple times. I've seen it as little as 6 on Mac and 19 on Windows. We are working on a fix for this to be released in 1.7.4.

Josh

--

Josh Cooper

Developer, Puppet Labs

[Glenn Poston]

This bug has been reported, but I think it's severity is understated.  Please vote for these bugs.

https://projects.puppetlabs.com/issues/22944 -> original

https://projects.puppetlabs.com/issues/23335 -> mine (duplicate)

[Glenn Poston]

I hope no one takes this personally, but I've got to ask.  

I've been using external facts for 3 years.  I started with facts-dot-d (which I'm sure you're familiar with :).  This issue did not exist when I was using that beautiful little gem.  Why the re-write/integration when it worked perfectly fine?

[Glenn Poston]

Thanks Josh... I made some comments on that ticket and added a vote.