Performance regression between 3.2.1-rc1 and 3.1.1?

[Wil Cooley]

I am noticing a ~10s slow down with 3.2.1-rc1 running 'puppet apply' with a manifest that is a single notice() function. I think I noticed it first w/'puppet resource' and maybe also with other sub-commands. This slow down might be just statistical noise in runs with a non-trivial manifest, but it's intrusive while doing development.

I can provide the outputs of the 'puppet apply' below, but the pause seems to happen before any output starts and all of the times that are reported look normal (0.00s for a bunch of built-in automatic resources), with catalog runs ending with "Finished catalog run in 0.0[56] seconds".

In fact, it almost looks like someone put in a sleep(10) somewhere while debugging and forgot to take it out.

This is on Mac OS X 10.7.5.

$ uname -a

Darwin coolair 11.4.2 Darwin Kernel Version 11.4.2: Thu Aug 23 16:25:48 PDT 2012; root:xnu-1699.32.7~1/RELEASE_X86_64 x86_64

$ ruby --version

ruby 1.8.7 (2012-02-08 patchlevel 358) [universal-darwin11.0]

$ facter --version

1.7.1

$ shasum puppet-3.{1,2}*.dmg

2a35e1f2c77049a9cacb5446be1417fa4c69a082  puppet-3.1.1.dmg

995f48bae1d86b6195d2beff30848af1eecf41ff  puppet-3.2.1-rc1.dmg

$ cat test.pp

# Test manifest that does nothing but a little output

notice("This is here.")

`time` outputs:

$ puppet apply --color=false --evaltrace --debug --verbose test.pp

# 3.1.1

real 0m3.392s

user 0m1.580s

sys 0m1.033s

# 3.2.1-rc1

real 0m13.064s

user 0m1.576s

sys 0m0.947s

Wil

[Wil Cooley]

On Mon, May 20, 2013 at 10:22 PM, Wil Cooley <wco...@nakedape.cc> wrote:

I am noticing a ~10s slow down with 3.2.1-rc1 running 'puppet apply' with a manifest that is a single notice() function.

 

After realizing that even 'puppet --version' took ~10s, I ran the ruby profiler, noticed there were differences in the number of  calls, extracted & diff'd those, noticed the addition of Socket#gethostbyname and Socket#gethostname. Eventually I noticed that my /etc/hosts had myhostname.local instead of just myhostname which (I presume) was causing a DNS/mDNS lookup.

So unless anyone else has this problem, forget I said anything.

Wil

 

[Wil Cooley]

On Tue, May 21, 2013 at 9:53 AM, Charlie Sharpsteen
<ch...@puppetlabs.com> wrote:

> Could you provide a bit more information on what the entry in your /etc/hosts file looked like? It would be interesting to reproduce this behavior and see if everything is functioning as intended.


Sure; in my /etc/hosts I had the following for my host-only vbox net:

192.168.56.1 coolair.local coolair

With that in place:

$ time ruby -rsocket -e "Socket.gethostbyname(Socket.gethostname)"
real 0m10.013s

And when I change it to:

192.168.56.1 coolair

I get:

$ time ruby -rsocket -e "Socket.gethostbyname(Socket.gethostname)"
real 0m0.032s

After a little tracing, it looks like it's the result of loading
webrick in puppet/util/monkey_patches.rb:

/Library/Ruby/Site/1.8/puppet/util/monkey_patches.rb:419::-: require 'webrick'

Which was added in ec462b7b: (#18781) Be more tolerant of old clients
in WEBrick server

Since this is just twiddling a constant (does that count as
monkey-patching?), wouldn't this maybe be better done in
lib/puppet/network/http/webrick.rb? If I understand it correctly,
these monkey-patches get applied for every invocation of puppet, even
if it's just "puppet --version", so it seems like it should be as
minimal as possible.

For that matter, the two previous sections that monkey-patch openssl
seem like they would be better off elsewhere; for example, the section
"if Puppet::Util::Platform.windows?" that starts on line 398 seems
like it might be better off somewhere in lib/puppet/util/windows*.

(Sorry to gripe w/o a patch; I haven't a Windows system to test on nor
do I know if I have a working setup for running the Puppet unit
tests.)

Wil

[Brice Figureau]

On Tue, 2013-05-21 at 15:03 -0700, Wil Cooley wrote:
[snip]

> After a little tracing, it looks like it's the result of loading
> webrick in puppet/util/monkey_patches.rb:
>
> /Library/Ruby/Site/1.8/puppet/util/monkey_patches.rb:419::-: require 'webrick'
>
> Which was added in ec462b7b: (#18781) Be more tolerant of old clients
> in WEBrick server
>
> Since this is just twiddling a constant (does that count as
> monkey-patching?), wouldn't this maybe be better done in
> lib/puppet/network/http/webrick.rb? If I understand it correctly,
> these monkey-patches get applied for every invocation of puppet, even
> if it's just "puppet --version", so it seems like it should be as
> minimal as possible.

Yes, I concur that it's a bad thing to load webrick on a command-line
puppet (or even the agent if it doesn't listen). Those monkey patches
should be splitted depending on the puppet use case.

I suggest you file a redmine ticket about this issue (and I'm sure
you'll certainly won't be the first to be hit by this dns resolution
issue).

> [snip again]

--
Brice Figureau
Follow the latest Puppet Community evolutions on www.planetpuppet.org!

[Josh Cooper]

I agree this should be restricted to code paths that actually use webrick

For that matter, the two previous sections that monkey-patch openssl
seem like they would be better off elsewhere; for example, the section
"if Puppet::Util::Platform.windows?" that starts on line 398 seems
like it might be better off somewhere in lib/puppet/util/windows*.

In the case of the windows-specific monkey patches for openssl, there is no difference putting them in lib/puppet/util/monkey_patches.rb or lib/puppet/util/windows.rb, as both are always loaded via require 'puppet'.

The reason for not moving them to the puppet's http client code, e.g. lib/puppet/network/http/connection.rb, is because not all modules use puppet's http client for making connections. For example, the module tool uses open-uri, as do other providers. With that said, we could move the code to only load the root certs if we're going to launch an application, and do so before we invoke the application.

(Sorry to gripe w/o a patch; I haven't a Windows system to test on nor
do I know if I have a working setup for running the Puppet unit
tests.)

Wil

--
You received this message because you are subscribed to the Google Groups "Puppet Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to puppet-dev+...@googlegroups.com.
To post to this group, send email to puppe...@googlegroups.com.
Visit this group at http://groups.google.com/group/puppet-dev?hl=en.
For more options, visit https://groups.google.com/groups/opt_out.

Josh

--

Josh Cooper

Developer, Puppet Labs

Join us at PuppetConf 2013, August 22-23 in San Francisco - http://bit.ly/pupconf13
Register now and take advantage of the Early Bird discount - save 25%!

[Charlie Sharpsteen]

On Tuesday, May 21, 2013 3:03:28 PM UTC-7, Wil Cooley wrote:

On Tue, May 21, 2013 at 9:53 AM, Charlie Sharpsteen
<ch...@puppetlabs.com> wrote:

> Could you provide a bit more information on what the entry in your /etc/hosts file looked like? It would be interesting to reproduce this behavior and see if everything is functioning as intended.


Sure; in my /etc/hosts I had the following for my host-only vbox net:

192.168.56.1   coolair.local coolair

With that in place:

$ time ruby -rsocket -e "Socket.gethostbyname(Socket.gethostname)"
real 0m10.013s

Thanks a bunch for the info Wil! One additional question: What is the hostname that Ruby is using to perform the lookup? I.E., what is the return value  of:

  ruby -rsocket -e 'puts Socket.gethostname'

-Charlie 

[Wil Cooley]

On Wed, May 22, 2013 at 10:10 AM, Charlie Sharpsteen
<ch...@puppetlabs.com> wrote:

> Thanks a bunch for the info Wil! One additional question: What is the
> hostname that Ruby is using to perform the lookup? I.E., what is the return
> value of:
>
> ruby -rsocket -e 'puts Socket.gethostname'

Regardless of which state /etc/hosts is in, it always returns the
short name: "coolair".

Wil

[Andy Parker]

On Tue, May 21, 2013 at 3:03 PM, Wil Cooley <wco...@nakedape.cc> wrote:

On Tue, May 21, 2013 at 9:53 AM, Charlie Sharpsteen
<ch...@puppetlabs.com> wrote:

> Could you provide a bit more information on what the entry in your /etc/hosts file looked like? It would be interesting to reproduce this behavior and see if everything is functioning as intended.

Sure; in my /etc/hosts I had the following for my host-only vbox net:

192.168.56.1   coolair.local coolair

With that in place:

$ time ruby -rsocket -e "Socket.gethostbyname(Socket.gethostname)"
real 0m10.013s

And when I change it to:

192.168.56.1 coolair

I get:

$ time ruby -rsocket -e "Socket.gethostbyname(Socket.gethostname)"
real 0m0.032s

After a little tracing, it looks like it's the result of loading
webrick in puppet/util/monkey_patches.rb:

/Library/Ruby/Site/1.8/puppet/util/monkey_patches.rb:419::-: require 'webrick'

Which was added in ec462b7b: (#18781) Be more tolerant of old clients
in WEBrick server

Thanks for tracking it down to that. Charlie and I traced it a bit further and found that inside webrick it loads webrick/config.rb which sets up a hash that contains the servername that is determined by calling WEBrick::Util.getservername which does these reverse lookups. That explains the mystery of simply loading some code causing a DNS lookup to occur.

Looking at that patch, I'm not certain if we should simply revert it or move that to another place in the code. My current thinking is that we should simply revert it because it is only needed to support 2.6 and earlier clients, which Puppet 3 does not support anyway (the policy is that a master only supports one "major" version back for agents, and in the case of 2.6 and 2.7 that means only 2.7 is supported, not 2.6).

 

Since this is just twiddling a constant (does that count as
monkey-patching?), wouldn't this maybe be better done in
lib/puppet/network/http/webrick.rb? If I understand it correctly,
these monkey-patches get applied for every invocation of puppet, even
if it's just "puppet --version", so it seems like it should be as
minimal as possible.

For that matter, the two previous sections that monkey-patch openssl
seem like they would be better off elsewhere; for example, the section
"if Puppet::Util::Platform.windows?" that starts on line 398 seems
like it might be better off somewhere in lib/puppet/util/windows*.

(Sorry to gripe w/o a patch; I haven't a Windows system to test on nor
do I know if I have a working setup for running the Puppet unit
tests.)

Wil

--
You received this message because you are subscribed to the Google Groups "Puppet Developers" group.
To unsubscribe from this group and stop receiving emails from it, send an email to puppet-dev+...@googlegroups.com.
To post to this group, send email to puppe...@googlegroups.com.
Visit this group at http://groups.google.com/group/puppet-dev?hl=en.
For more options, visit https://groups.google.com/groups/opt_out.

--

Andrew Parker

an...@puppetlabs.com

Freenode: zaphod42

Twitter: @aparker42

Software Developer

[Josh Cooper]

On Thu, May 23, 2013 at 11:08 AM, Andy Parker <an...@puppetlabs.com> wrote:

On Tue, May 21, 2013 at 3:03 PM, Wil Cooley <wco...@nakedape.cc> wrote:

On Tue, May 21, 2013 at 9:53 AM, Charlie Sharpsteen
<ch...@puppetlabs.com> wrote:

> Could you provide a bit more information on what the entry in your /etc/hosts file looked like? It would be interesting to reproduce this behavior and see if everything is functioning as intended.

Sure; in my /etc/hosts I had the following for my host-only vbox net:

192.168.56.1   coolair.local coolair

With that in place:

$ time ruby -rsocket -e "Socket.gethostbyname(Socket.gethostname)"
real 0m10.013s

And when I change it to:

192.168.56.1 coolair

I get:

$ time ruby -rsocket -e "Socket.gethostbyname(Socket.gethostname)"
real 0m0.032s

After a little tracing, it looks like it's the result of loading
webrick in puppet/util/monkey_patches.rb:

/Library/Ruby/Site/1.8/puppet/util/monkey_patches.rb:419::-: require 'webrick'

Which was added in ec462b7b: (#18781) Be more tolerant of old clients
in WEBrick server

Thanks for tracking it down to that. Charlie and I traced it a bit further and found that inside webrick it loads webrick/config.rb which sets up a hash that contains the servername that is determined by calling WEBrick::Util.getservername which does these reverse lookups. That explains the mystery of simply loading some code causing a DNS lookup to occur.

Looking at that patch, I'm not certain if we should simply revert it or move that to another place in the code. My current thinking is that we should simply revert it because it is only needed to support 2.6 and earlier clients, which Puppet 3 does not support anyway (the policy is that a master only supports one "major" version back for agents, and in the case of 2.6 and 2.7 that means only 2.7 is supported, not 2.6).

Filed as https://projects.puppetlabs.com/issues/20901 and targeted for 3.2.2

Josh

--

Josh Cooper

Developer, Puppet Labs