Jira (PUP-5013) Improve the code for profiling resource evaluation?

[Josh Cooper (JIRA)]

Title: Message Title

Josh Cooper commented on PUP-5013   Re: Improve the code for profiling resource evaluation? Sean Griffin and I looked into this, and it does appear we do now track time evaluating resources, however, the time we compute is incorrect and misleading. So given site.pp with: class common { notify { 'test': message => generate("/Users/josh/work/puppet/exec_sleep.sh"), } } and an enc: #!/usr/bin/env ruby # require 'yaml'   puts YAML.dump({ 'classes' => ['common'] }) running the master with an ENC in 4.2.1: $ be puppet master --no-daemonize --dns_alt_names arcturus --debug --profile --node_terminus=exec --external_nodes=/Users/josh/work/puppet/classifier.rb ... Debug: compiler: 50.859158 s (16 calls) Debug: compiler -> compile: 10.386795 s (1 calls) Debug: compiler -> compile -> production: 10.386795 s (1 calls) Debug: compiler -> compile -> production -> arcturus.corp.puppetlabs.net: 10.386795 s (1 calls) The total time compiler: 50.859158 is incorrect, but it does include the time spent evaluating the resource, which the profile incorrectly omits due to this bug. When running without an ENC in 4.2.1, and site.pp: class common { notify { 'test': message => generate("/Users/josh/work/puppet/exec_sleep.sh"), } }   node default { include common } The total compiler time doesn't not include the resource evaluation time as described in this bug. Debug: compiler: 20.41088 s (13 calls) Debug: compiler -> compile: 10.349374 s (1 calls) Debug: compiler -> compile -> production: 10.349374 s (1 calls) Debug: compiler -> compile -> production -> arcturus.corp.puppetlabs.net: 10.349374 s (1 calls) Note the total time has dropped by 30 seconds due to not including the resource eval time. However, the profiler is triple counting the resource time, it should have only dropped the overall compiler time by 10 seconds, not 30. When running against 0f3c32fdf7, with an ENC, it correctly reports the time spent evaluating the resource: $ be puppet master --no-daemonize --dns_alt_names arcturus --debug --profile --node_terminus=exec --external_nodes=/Users/josh/work/puppet/classifier.rb ... Debug: compiler: 50.799932000000005 s (17 calls) Debug: compiler -> compile: 10.343555 s (1 calls) Debug: compiler -> compile -> production: 10.343555 s (1 calls) Debug: compiler -> compile -> production -> arcturus.corp.puppetlabs.net: 10.343555 s (1 calls) Debug: compiler -> evaluate_resource: 10.026539 s (2 calls) Debug: compiler -> evaluate_resource -> Class[Common]: 10.025437 s (1 calls) Debug: compiler -> evaluate_resource -> Class[main]: 0.001102 s (1 calls) Debug: compiler -> evaluate_generators: 10.026031 s (1 calls) When running against the same SHA without an ENC, it also includes the time spent evaluating the resource, but the {{ evaluate_resource}} time is incorrectly doubled likely because it's counting Node[default] and Class[Common], while the overall compiler time is reduced by 10 seconds! Debug: compiler: 40.458013 s (16 calls) Debug: compiler -> evaluate_resource: 20.045053000000003 s (3 calls) Debug: compiler -> evaluate_resource -> Node[default]: 10.023599 s (1 calls) Debug: compiler -> evaluate_resource -> Class[Common]: 10.020284 s (1 calls) Debug: compiler -> evaluate_resource -> Class[main]: 0.00117 s (1 calls) Debug: compiler -> compile: 10.346585 s (1 calls) Debug: compiler -> compile -> production: 10.346585 s (1 calls) Debug: compiler -> compile -> production -> arcturus.corp.puppetlabs.net: 10.346585 s (1 calls) So with this fix we are including the evaluate_resource time when not using an ENC, but the actual time computed is wrong. Add Comment   This message was sent by Atlassian JIRA (v6.4.11#64026-sha1:78f6ec4) -- You received this message because you are subscribed to the Google Groups "Puppet Bugs" group. To unsubscribe from this group and stop receiving emails from it, send an email to puppet-bugs+unsubscr...@googlegroups.com. To post to this group, send email to puppet-bugs@googlegroups.com. Visit this group at http://groups.google.com/group/puppet-bugs. For more options, visit https://groups.google.com/d/optout.