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!

        Attachments

          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:

                  Zendesk Support