'Service' type performance issues.

[Trevor Vaughan]

As I've been playing with more optimization factors, I'm noticing that
the 'service' type appears to be quite slow.

According to running puppet agent in evaltrace mode, very basic
services, that are NOT getting restarted, are taking upwards of 3
seconds to check.

However, running the same commands via irb takes around 0.4 seconds.

I've looked through the 'service' type and it seems pretty straightforward.

This is on a CentOS platform.

What am I missing?

Thanks,

Trevor

--
Trevor Vaughan
Vice President, Onyx Point, Inc
(410) 541-6699
tvau...@onyxpoint.com

-- This account not approved for unencrypted proprietary information --

[Andrew Parker]

Thanks for looking into this. Could you send the traces that you are seeing and the command that you are executing in irb?

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

[Trevor Vaughan]

Sure....

For the following manifest:

service { 'haldaemon':
ensure => 'running',
enable => 'true',
hasrestart => 'true',
hasstatus => 'true'
}

The result is:

info: /Stage[main]/Service[haldaemon]: Starting to evaluate the resource
debug: Service[haldaemon](provider=redhat): Executing '/sbin/service
haldaemon status'
debug: Puppet::Type::Service::ProviderRedhat: Executing
'/sbin/chkconfig haldaemon'
info: /Stage[main]/Service[haldaemon]: Evaluated in 2.36 seconds

For the following Ruby code:

#!/usr/bin/ruby

time_start = Time.now
%x{/sbin/service haldaemon status}
%x{/sbin/chkconfig haldaemon}
time_end = Time.now

puts "Run time is: #{time_end - time_start}"

The result is:

Run time is: 0.23108

Now, I understand that there's more going on under the hood of Puppet, but
that's all it *says* that it is doing and I'm not quite sure where 2 more
seconds of time is being lost.

The most interesting thing about this is that it's not consistent. One
time, it'll be 3 seconds, then the next, a different one will take far
longer. Very odd.

Thanks,

Trevor

[Stefan Schulte]

Just want to mention that you are not the first one who thinks the
service type is to slow:
http://projects.puppetlabs.com/issues/13575

So if you get any more insight view feel free to update the ticket :-)

I thought that it may be because puppet will not catch the output of executed
commands directly but redirects the output to a tempfile, reads the tempfile
and then deletes the tempfile again. It even handles the fact, that the tempfile
may not be present and puppet has to wait for the file to be created. But looking
at your output it seems that the `wait_for_output` method is not triggered in your
case.

It may be interesting to now if the time is really lost in the execute
method or elsewhere. Maybe adding some more debug output like:

diff --git a/lib/puppet/util.rb b/lib/puppet/util.rb
index 5b5a9d7..94c7e32 100644
--- a/lib/puppet/util.rb
+++ b/lib/puppet/util.rb
@@ -365,6 +365,8 @@ module Util
str = command
end

+ Puppet.info "Start #{command} at #{Time.now}" if command =~ /\/sbin\/(chkconfig|service)/
+
if respond_to? :debug
debug "Executing '#{str}'"
else
@@ -406,6 +408,8 @@ module Util
raise ExecutionFailure, "Execution of '#{str}' returned #{exit_status}: #{output}"
end

+ Puppet.info "Start #{command} at #{Time.now}" if command =~ /\/sbin\/(chkconfig|service)/
+
output
end

can help here?

-Stefan

[Trevor Vaughan]

Doing some more digging, it looks like it might be as simple as puppet
overwhelming the capabilities of my puny test VM.

With only one processor, the load with spike over 1.2 and I'll see the
'system' and 'exec' commands both start to show ridiculously long run
times.

I wrapped the actual call to 'service' in a timing loop and it wasn't
taking long at all (0.02 seconds) so I'm not 100% certain where all of
this random other time (3 seconds) is coming into play.

It may be, as you say, that puppet is simply hanging on an IO lock somewhere.

I have found that, if I get rid of execs with native types that do the
exact same thing, they never spike.

Hopefully this helps but I just don't have the cycles to dig deeper right now.

Thanks,

Trevor