Uploaded image for project: 'Puppet'
  1. Puppet
  2. PUP-2924

Puppet searches disk for whit classes

    Details

    • Type: Bug
    • Status: Closed
    • Priority: Normal
    • Resolution: Fixed
    • Affects Version/s: PUP 3.6.2
    • Fix Version/s: PUP 3.7.0
    • Component/s: Types and Providers
    • Labels:
      None
    • Environment:

      SmartOS, Puppet 3.6.2

    • Template:
    • Story Points:
      3
    • Sprint:
      2014-08-20

      Description

      Our Puppet instance has been pretty slow lately so we traced a puppet agent run to see what it was doing. In the trace we see a bunch of lines like this:

      stat("/opt/local/lib/ruby/site_ruby/2.0.0/puppet/vendor/semantic/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/etc/puppet/modules/admin/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/etc/puppet/modules/percona/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/etc/puppet/shared/modules/apt/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/etc/puppet/shared/modules/puppetlabs-stdlib/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/etc/puppet/external/modules/python/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/etc/puppet/external/modules/yum_puppet_plugin/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/var/lib/puppet/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/opt/local/lib/ruby/gems/2.0.0/gems/bigdecimal-1.2.0/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/opt/local/lib/ruby/gems/2.0.0/gems/bundler-1.5.3/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/opt/local/lib/ruby/gems/2.0.0/gems/byebug-3.1.2/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/opt/local/lib/ruby/gems/2.0.0/gems/columnize-0.8.9/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT
      stat("/opt/local/lib/ruby/gems/2.0.0/gems/daemons-1.1.9/lib/puppet/type/completed_stage.rb", 0xFFFFFD7FFFDFE4A0) Err#2 ENOENT

      Which means that Puppet is attempting to find a file in a bunch of different locations, which we believe is part of a process Puppet goes through when trying to find and load a class or function. In total, we see around 20,000 attempts to open files that fit the completed_ or admissible_ pattern.

      I dug in to what it was trying to find and found this: https://github.com/puppetlabs/puppet/blob/2350ed0db1264040864ad4dfc9908429d6298eb1/lib/puppet/type/whit.rb. My understanding is that a Whit is essentially a virtual graph node which appears before or after a regular graph node. I don't find any cases of us calling these in our Puppet repo, so I'm assuming that its internal Puppet code of some kind that is asking for these.

      So it appears to me that Puppet is defining a virtual class type then searching disk for it through some set of directories including every gem it sees, every time it is accessed, on every run of Puppet. Am I totally misunderstanding this or Is there something we as users could be doing to create this situation? Is this the default behavior? If so, it seems broken or insane to me. Please talk me off this ledge!

        Issue Links

          Activity

          Hide
          chuck Charlie Sharpsteen added a comment -

          Thanks for reporting this! There is definitely some wasted effort going on here.

          The core of the problem is that we have a very expensive lookup operation that determines the Type associated with a resource: Puppet::Resource#resource_type. Due to the expense, some methods set the resource_type if this information is known and available when a Resource instance is created.

          However, when retrieving the state of whits, a Resource instance is created that does not receive available type information:

          debug call: load /puppetlabs/puppet/lib/puppet/util/autoload.rb:194
          	name = :completed_stage
          	env = production
          	/puppetlabs/puppet/lib/puppet/util/autoload.rb:194:in `load'
          	/puppetlabs/puppet/lib/puppet/metatype/manager.rb:163:in `type'
          	/puppetlabs/puppet/lib/puppet/resource.rb:242:in `resource_type'
          	/puppetlabs/puppet/lib/puppet/resource.rb:163:in `builtin_type?'
          	/puppetlabs/puppet/lib/puppet/resource.rb:475:in `namevar'
          	/puppetlabs/puppet/lib/puppet/resource.rb:466:in `parameter_name'
          	/puppetlabs/puppet/lib/puppet/resource.rb:140:in `[]='
          	/puppetlabs/puppet/lib/puppet/type.rb:1032:in `retrieve'
          	/puppetlabs/puppet/lib/puppet/type.rb:1063:in `retrieve_resource'
          	/puppetlabs/puppet/lib/puppet/transaction/resource_harness.rb:223:in `from_resource'
          	/puppetlabs/puppet/lib/puppet/transaction/resource_harness.rb:19:in `evaluate'
          	/puppetlabs/puppet/lib/puppet/transaction.rb:174:in `apply'
          	/puppetlabs/puppet/lib/puppet/transaction.rb:187:in `eval_resource'
          	/puppetlabs/puppet/lib/puppet/transaction.rb:117:in `call'
          	/puppetlabs/puppet/lib/puppet/transaction.rb:117:in `block (2 levels) in evaluate'
          	/puppetlabs/puppet/lib/puppet/util.rb:327:in `block in thinmark'
          	/opt/rh/ruby193/root/usr/share/ruby/benchmark.rb:295:in `realtime'
          	/puppetlabs/puppet/lib/puppet/util.rb:326:in `thinmark'
          	/puppetlabs/puppet/lib/puppet/transaction.rb:117:in `block in evaluate'
          	/puppetlabs/puppet/lib/puppet/graph/relationship_graph.rb:118:in `traverse'
          	/puppetlabs/puppet/lib/puppet/transaction.rb:108:in `evaluate'
          	/puppetlabs/puppet/lib/puppet/resource/catalog.rb:167:in `block in apply'
          	/puppetlabs/puppet/lib/puppet/util/log.rb:149:in `with_destination'
          	/puppetlabs/puppet/lib/puppet/transaction/report.rb:112:in `as_logging_destination'
          	/puppetlabs/puppet/lib/puppet/resource/catalog.rb:166:in `apply'
          	/puppetlabs/puppet/lib/puppet/configurer.rb:117:in `block in apply_catalog'
          	/puppetlabs/puppet/lib/puppet/util.rb:161:in `block in benchmark'
          	/opt/rh/ruby193/root/usr/share/ruby/benchmark.rb:295:in `realtime'
          	/puppetlabs/puppet/lib/puppet/util.rb:160:in `benchmark'
          	/puppetlabs/puppet/lib/puppet/configurer.rb:116:in `apply_catalog'
          	/puppetlabs/puppet/lib/puppet/configurer.rb:191:in `run'
          	/puppetlabs/puppet/lib/puppet/agent.rb:47:in `block (4 levels) in run'
          	/puppetlabs/puppet/lib/puppet/agent/locker.rb:20:in `lock'
          	/puppetlabs/puppet/lib/puppet/agent.rb:47:in `block (3 levels) in run'
          	/puppetlabs/puppet/lib/puppet/agent.rb:117:in `with_client'
          	/puppetlabs/puppet/lib/puppet/agent.rb:44:in `block (2 levels) in run'
          	/puppetlabs/puppet/lib/puppet/agent.rb:82:in `run_in_fork'
          	/puppetlabs/puppet/lib/puppet/agent.rb:43:in `block in run'
          	/puppetlabs/puppet/lib/puppet/application.rb:179:in `call'
          	/puppetlabs/puppet/lib/puppet/application.rb:179:in `controlled_run'
          	/puppetlabs/puppet/lib/puppet/agent.rb:41:in `run'
          	/puppetlabs/puppet/lib/puppet/application/agent.rb:355:in `onetime'
          	/puppetlabs/puppet/lib/puppet/application/agent.rb:321:in `run_command'
          	/puppetlabs/puppet/lib/puppet/application.rb:371:in `block (2 levels) in run'
          	/puppetlabs/puppet/lib/puppet/application.rb:477:in `plugin_hook'
          	/puppetlabs/puppet/lib/puppet/application.rb:371:in `block in run'
          	/puppetlabs/puppet/lib/puppet/util.rb:479:in `exit_on_fail'
          	/puppetlabs/puppet/lib/puppet/application.rb:371:in `run'
          	/puppetlabs/puppet/lib/puppet/util/command_line.rb:137:in `run'
          	/puppetlabs/puppet/lib/puppet/util/command_line.rb:91:in `execute'
          	/puppetlabs/puppet/bin/puppet:28:in `<main>'
          

          Peter Bakkum: The following patch seems to solve the issue, if you would like to give it a try:

          type_retrieve.patch

          diff --git a/lib/puppet/type.rb b/lib/puppet/type.rb
          index f382f30..e7e2fee 100644
          --- a/lib/puppet/type.rb
          +++ b/lib/puppet/type.rb
          @@ -1027,6 +1027,7 @@ class Type
               fail "Provider #{provider.class.name} is not functional on this host" if self.provider.is_a?(Puppet::Provider) and ! provider.class.suitable?
           
               result = Puppet::Resource.new(type, title)
          +    result.resource_type = self.class
           
               # Provide the name, so we know we'll always refer to a real thing
               result[:name] = self[:name] unless self[:name] == title
          

          Show
          chuck Charlie Sharpsteen added a comment - Thanks for reporting this! There is definitely some wasted effort going on here. The core of the problem is that we have a very expensive lookup operation that determines the Type associated with a resource: Puppet::Resource#resource_type . Due to the expense, some methods set the resource_type if this information is known and available when a Resource instance is created. However, when retrieving the state of whits, a Resource instance is created that does not receive available type information : debug call: load /puppetlabs/puppet/lib/puppet/util/autoload.rb:194 name = :completed_stage env = production /puppetlabs/puppet/lib/puppet/util/autoload.rb:194:in `load' /puppetlabs/puppet/lib/puppet/metatype/manager.rb:163:in `type' /puppetlabs/puppet/lib/puppet/resource.rb:242:in `resource_type' /puppetlabs/puppet/lib/puppet/resource.rb:163:in `builtin_type?' /puppetlabs/puppet/lib/puppet/resource.rb:475:in `namevar' /puppetlabs/puppet/lib/puppet/resource.rb:466:in `parameter_name' /puppetlabs/puppet/lib/puppet/resource.rb:140:in `[]=' /puppetlabs/puppet/lib/puppet/type.rb:1032:in `retrieve' /puppetlabs/puppet/lib/puppet/type.rb:1063:in `retrieve_resource' /puppetlabs/puppet/lib/puppet/transaction/resource_harness.rb:223:in `from_resource' /puppetlabs/puppet/lib/puppet/transaction/resource_harness.rb:19:in `evaluate' /puppetlabs/puppet/lib/puppet/transaction.rb:174:in `apply' /puppetlabs/puppet/lib/puppet/transaction.rb:187:in `eval_resource' /puppetlabs/puppet/lib/puppet/transaction.rb:117:in `call' /puppetlabs/puppet/lib/puppet/transaction.rb:117:in `block (2 levels) in evaluate' /puppetlabs/puppet/lib/puppet/util.rb:327:in `block in thinmark' /opt/rh/ruby193/root/usr/share/ruby/benchmark.rb:295:in `realtime' /puppetlabs/puppet/lib/puppet/util.rb:326:in `thinmark' /puppetlabs/puppet/lib/puppet/transaction.rb:117:in `block in evaluate' /puppetlabs/puppet/lib/puppet/graph/relationship_graph.rb:118:in `traverse' /puppetlabs/puppet/lib/puppet/transaction.rb:108:in `evaluate' /puppetlabs/puppet/lib/puppet/resource/catalog.rb:167:in `block in apply' /puppetlabs/puppet/lib/puppet/util/log.rb:149:in `with_destination' /puppetlabs/puppet/lib/puppet/transaction/report.rb:112:in `as_logging_destination' /puppetlabs/puppet/lib/puppet/resource/catalog.rb:166:in `apply' /puppetlabs/puppet/lib/puppet/configurer.rb:117:in `block in apply_catalog' /puppetlabs/puppet/lib/puppet/util.rb:161:in `block in benchmark' /opt/rh/ruby193/root/usr/share/ruby/benchmark.rb:295:in `realtime' /puppetlabs/puppet/lib/puppet/util.rb:160:in `benchmark' /puppetlabs/puppet/lib/puppet/configurer.rb:116:in `apply_catalog' /puppetlabs/puppet/lib/puppet/configurer.rb:191:in `run' /puppetlabs/puppet/lib/puppet/agent.rb:47:in `block (4 levels) in run' /puppetlabs/puppet/lib/puppet/agent/locker.rb:20:in `lock' /puppetlabs/puppet/lib/puppet/agent.rb:47:in `block (3 levels) in run' /puppetlabs/puppet/lib/puppet/agent.rb:117:in `with_client' /puppetlabs/puppet/lib/puppet/agent.rb:44:in `block (2 levels) in run' /puppetlabs/puppet/lib/puppet/agent.rb:82:in `run_in_fork' /puppetlabs/puppet/lib/puppet/agent.rb:43:in `block in run' /puppetlabs/puppet/lib/puppet/application.rb:179:in `call' /puppetlabs/puppet/lib/puppet/application.rb:179:in `controlled_run' /puppetlabs/puppet/lib/puppet/agent.rb:41:in `run' /puppetlabs/puppet/lib/puppet/application/agent.rb:355:in `onetime' /puppetlabs/puppet/lib/puppet/application/agent.rb:321:in `run_command' /puppetlabs/puppet/lib/puppet/application.rb:371:in `block (2 levels) in run' /puppetlabs/puppet/lib/puppet/application.rb:477:in `plugin_hook' /puppetlabs/puppet/lib/puppet/application.rb:371:in `block in run' /puppetlabs/puppet/lib/puppet/util.rb:479:in `exit_on_fail' /puppetlabs/puppet/lib/puppet/application.rb:371:in `run' /puppetlabs/puppet/lib/puppet/util/command_line.rb:137:in `run' /puppetlabs/puppet/lib/puppet/util/command_line.rb:91:in `execute' /puppetlabs/puppet/bin/puppet:28:in `<main>' Peter Bakkum : The following patch seems to solve the issue, if you would like to give it a try: type_retrieve.patch diff --git a/lib/puppet/type.rb b/lib/puppet/type.rb index f382f30..e7e2fee 100644 --- a/lib/puppet/type.rb +++ b/lib/puppet/type.rb @@ -1027,6 +1027,7 @@ class Type fail "Provider #{provider.class.name} is not functional on this host" if self.provider.is_a?(Puppet::Provider) and ! provider.class.suitable? result = Puppet::Resource.new(type, title) + result.resource_type = self.class # Provide the name, so we know we'll always refer to a real thing result[:name] = self[:name] unless self[:name] == title
          Hide
          chuck Charlie Sharpsteen added a comment -

          Kylo Ginsberg: The patch above appears to resolve this issue, however we do pass typing information to Puppet::Resource.new. If we can use that to eliminate the need to set resource_type on instances after creation, it might be a better long term solution.

          On a CentOS 6 test box, a vanilla Puppet agent makes 1080 calls to stat caused by 40 erroneous whit lookups for 1 node, 1 class and 1 stage. Eliminating the whit lookups shaves 0.1 seconds off of an empty catalog run. Each Class added to the catalog appears to generate 270 additional stat calls. These numbers will be sensitive to the size of the Ruby LOAD_PATH and, by extension, the Puppet MODULE_PATH.

          It seems like there are some good performance gains we could get here, kicking this one to you for a scheduling decision.

          Show
          chuck Charlie Sharpsteen added a comment - Kylo Ginsberg : The patch above appears to resolve this issue, however we do pass typing information to Puppet::Resource.new . If we can use that to eliminate the need to set resource_type on instances after creation, it might be a better long term solution. On a CentOS 6 test box, a vanilla Puppet agent makes 1080 calls to stat caused by 40 erroneous whit lookups for 1 node, 1 class and 1 stage. Eliminating the whit lookups shaves 0.1 seconds off of an empty catalog run. Each Class added to the catalog appears to generate 270 additional stat calls. These numbers will be sensitive to the size of the Ruby LOAD_PATH and, by extension, the Puppet MODULE_PATH . It seems like there are some good performance gains we could get here, kicking this one to you for a scheduling decision.
          Hide
          kylo Kylo Ginsberg added a comment -

          I'd like to see if we can get this done for 3.7, so I'm optimistically scheduling it for 3.7. That release is running tight though, so no guarantees on that.

          Meanwhile Peter Bakkum if you get a chance to try out Charlie's patch that would be nice confirmation.

          Show
          kylo Kylo Ginsberg added a comment - I'd like to see if we can get this done for 3.7, so I'm optimistically scheduling it for 3.7. That release is running tight though, so no guarantees on that. Meanwhile Peter Bakkum if you get a chance to try out Charlie's patch that would be nice confirmation.
          Hide
          pbbakkum Peter Bakkum added a comment -

          Tried this out by running

          time puppet apply --verbose --debug oursite.pp

          before and after applying the patch. I ran 5 times and averaged the output, here is the improvement we see.

          real  19.9044 -> 18.5814     6.6%
          user  10.3344 ->  9.7594     5.9%
          sys    3.999  ->  3.4408    16.2%
          

          So system time went from 4s to 3.44s for a 16% improvement. Not a massive win but definitely in the right direction.

          What IS nice is the number of stat calls for our instance went from 49,936 before to 39,100 after, so big improvement there. That probably explains why there's so much less system time. This seems like an easy win, hope you guys can release it soon. Thanks for digging in.

          Show
          pbbakkum Peter Bakkum added a comment - Tried this out by running time puppet apply --verbose --debug oursite.pp before and after applying the patch. I ran 5 times and averaged the output, here is the improvement we see. real 19.9044 -> 18.5814 6.6% user 10.3344 -> 9.7594 5.9% sys 3.999 -> 3.4408 16.2% So system time went from 4s to 3.44s for a 16% improvement. Not a massive win but definitely in the right direction. What IS nice is the number of stat calls for our instance went from 49,936 before to 39,100 after, so big improvement there. That probably explains why there's so much less system time. This seems like an easy win, hope you guys can release it soon. Thanks for digging in.
          Hide
          chuck Charlie Sharpsteen added a comment -

          Seems like this one line patch provides a pretty decent benefit. Submitted as a pull request.

          If accepted, I'll open a new ticket for refactoring Resource.new to be smarter about setting `resource_type` during initialization.

          Show
          chuck Charlie Sharpsteen added a comment - Seems like this one line patch provides a pretty decent benefit. Submitted as a pull request. If accepted, I'll open a new ticket for refactoring Resource.new to be smarter about setting `resource_type` during initialization.
          Hide
          adrien Adrien Thebo added a comment -

          Merged into master in cb26e23; this should be released in 3.7.0.

          Show
          adrien Adrien Thebo added a comment - Merged into master in cb26e23; this should be released in 3.7.0.
          Hide
          erict Eric Thompson added a comment - - edited

          via Charlie Sharpsteen "there should be no stat() calls looking for files that match the pattern of admissible_*.rb or completed_*.rb"

          tried this from centos6 on SHA c6ba27e
          $> sudo strace -o strace.out puppet apply -e "user

          { 'erict': ensure=>present }

          "
          $> grep -c '^stat.*admissible_.*\.rb strace.out
          96
          eg:
          stat64("/usr/lib/ruby/gems/1.8/gems/bundler-1.6.5/lib/puppet/type/admissible_stage.rb", 0xbf7e9540) = -1 ENOENT (No such file or directory)

          i get 9899 total stat calls on above sha
          and i get 9819 on sha 3471447 (just before cb26e23)

          Show
          erict Eric Thompson added a comment - - edited via Charlie Sharpsteen "there should be no stat() calls looking for files that match the pattern of admissible_*.rb or completed_*.rb" tried this from centos6 on SHA c6ba27e $> sudo strace -o strace.out puppet apply -e "user { 'erict': ensure=>present } " $> grep -c '^stat.*admissible_.*\.rb strace.out 96 eg: stat64("/usr/lib/ruby/gems/1.8/gems/bundler-1.6.5/lib/puppet/type/admissible_stage.rb", 0xbf7e9540) = -1 ENOENT (No such file or directory) i get 9899 total stat calls on above sha and i get 9819 on sha 3471447 (just before cb26e23)
          Hide
          chuck Charlie Sharpsteen added a comment -

          What happened here is that PR 2492 added a call to resource_type directly to Puppet::Resource#initialize.

          So, my patch moved us one step forward and that PR moved us one step back. To completely fix this problem, we'll need to go all the way and re-factor Resource.new .

          Show
          chuck Charlie Sharpsteen added a comment - What happened here is that PR 2492 added a call to resource_type directly to Puppet::Resource#initialize . So, my patch moved us one step forward and that PR moved us one step back. To completely fix this problem, we'll need to go all the way and re-factor Resource.new .
          Hide
          kylo Kylo Ginsberg added a comment -

          Charlie Sharpsteen your last comment sounds like the scope of this has increased. Are you actively working this? Or should we punt it out of 3.7?

          Show
          kylo Kylo Ginsberg added a comment - Charlie Sharpsteen your last comment sounds like the scope of this has increased. Are you actively working this? Or should we punt it out of 3.7?
          Hide
          chuck Charlie Sharpsteen added a comment -

          Yes I am. I have a decent patch that solves the problem, what is slowing me down is adding documentation around the behavior and arguments passed to Puppet::Resource#initialize. I should have that wrapped up by the end of the week.

          Show
          chuck Charlie Sharpsteen added a comment - Yes I am. I have a decent patch that solves the problem, what is slowing me down is adding documentation around the behavior and arguments passed to Puppet::Resource#initialize . I should have that wrapped up by the end of the week.
          Hide
          chuck Charlie Sharpsteen added a comment -

          New pull request submitted that allows Resource to be initialized with Type classes instead of just the symbolic name of the class. This should eliminate the fruitless searches triggered later in the constructor since resource_type will be set up front.

          Show
          chuck Charlie Sharpsteen added a comment - New pull request submitted that allows Resource to be initialized with Type classes instead of just the symbolic name of the class. This should eliminate the fruitless searches triggered later in the constructor since resource_type will be set up front.
          Hide
          adrien Adrien Thebo added a comment -

          Merged GH-2979 in 69310a8.

          Show
          adrien Adrien Thebo added a comment - Merged GH-2979 in 69310a8.
          Hide
          adrien Adrien Thebo added a comment -

          Verified:

          On 3.6.2:

          strace -o strace.out -e trace=stat -- bundle exec puppet apply -e 'notify { "hello": message => "world" }'; echo "Admissible:"; grep -c admissible strace.out ; echo "Completed:"; grep -c completed strace.out
          Unable to open /dev/zfs: Permission denied.
          Unable to open /dev/zfs: Permission denied.
          Notice: Compiled catalog for grey.somethingsinistral.net in environment production in 0.03 seconds
          Notice: world
          Notice: /Stage[main]/Main/Notify[hello]/message: defined 'message' as 'world'
          Notice: Finished catalog run in 0.18 seconds
          Admissible:
          648
          Completed:
          648
          

          On master (dbf3021):

          strace -o strace.out -e trace=stat -- bundle exec puppet apply -e 'notify { "hello": message => "world" }'; echo "Admissible:"; grep -c admissible strace.out ; echo "Completed:"; grep -c completed strace.out
          Unable to open /dev/zfs: Permission denied.
          Unable to open /dev/zfs: Permission denied.
          Notice: Compiled catalog for grey.somethingsinistral.net in environment production in 0.02 seconds
          Notice: world
          Notice: /Stage[main]/Main/Notify[hello]/message: defined 'message' as 'world'
          Notice: Finished catalog run in 0.13 seconds
          Admissible:
          0
          Completed:
          0
          

          For this trivial example it looks like catalog application time is roughly the same.

          Show
          adrien Adrien Thebo added a comment - Verified: On 3.6.2: strace -o strace.out -e trace=stat -- bundle exec puppet apply -e 'notify { "hello": message => "world" }'; echo "Admissible:"; grep -c admissible strace.out ; echo "Completed:"; grep -c completed strace.out Unable to open /dev/zfs: Permission denied. Unable to open /dev/zfs: Permission denied. Notice: Compiled catalog for grey.somethingsinistral.net in environment production in 0.03 seconds Notice: world Notice: /Stage[main]/Main/Notify[hello]/message: defined 'message' as 'world' Notice: Finished catalog run in 0.18 seconds Admissible: 648 Completed: 648 On master (dbf3021): strace -o strace.out -e trace=stat -- bundle exec puppet apply -e 'notify { "hello": message => "world" }'; echo "Admissible:"; grep -c admissible strace.out ; echo "Completed:"; grep -c completed strace.out Unable to open /dev/zfs: Permission denied. Unable to open /dev/zfs: Permission denied. Notice: Compiled catalog for grey.somethingsinistral.net in environment production in 0.02 seconds Notice: world Notice: /Stage[main]/Main/Notify[hello]/message: defined 'message' as 'world' Notice: Finished catalog run in 0.13 seconds Admissible: 0 Completed: 0 For this trivial example it looks like catalog application time is roughly the same.
          Hide
          erict Eric Thompson added a comment -

          tested on centos6 at SHA 18dbf802a4a351eb3a3336ba91c4c556043b4745

          [root@centos-6 ~]# strace -o strace.out -e trace=stat -- puppet apply -e 'notify { "hello": message => "world" }'; echo "Admissible:"; grep -c admissible strace.out ; echo "Completed:"; grep -c completed strace.out
          Notice: Compiled catalog for centos-6.4-64 in environment production in 0.23 seconds
          Notice: world
          Notice: /Stage[main]/Main/Notify[hello]/message: defined 'message' as 'world'
          Notice: Finished catalog run in 0.10 seconds
          Admissible:
          0
          Completed:
          0
          

          Show
          erict Eric Thompson added a comment - tested on centos6 at SHA 18dbf802a4a351eb3a3336ba91c4c556043b4745 [root@centos-6 ~]# strace -o strace.out -e trace=stat -- puppet apply -e 'notify { "hello": message => "world" }'; echo "Admissible:"; grep -c admissible strace.out ; echo "Completed:"; grep -c completed strace.out Notice: Compiled catalog for centos-6.4-64 in environment production in 0.23 seconds Notice: world Notice: /Stage[main]/Main/Notify[hello]/message: defined 'message' as 'world' Notice: Finished catalog run in 0.10 seconds Admissible: 0 Completed: 0

            People

            • Assignee:
              Unassigned
              Reporter:
              pbbakkum Peter Bakkum
              QA Contact:
              Eric Thompson
            • Votes:
              0 Vote for this issue
              Watchers:
              5 Start watching this issue

              Dates

              • Created:
                Updated:
                Resolved:

                Agile