Jira (PUP-2750) expand profiler signature to support hierarchical profiling data

[Ethan Brown (JIRA)]

Title: Message Title

Ethan Brown commented on an issue   Re: expand profiler signature to support hierarchical profiling data Executed trivial profiling on Windows 2008R2 before / after the merge against simple test: bundle exec puppet apply --exec "user{'dave':ensure=>present, groups=>['Users']}" --profile --debug --logdest=c:/temp/profile.log Run against old code took about 9 seconds... run against new code also took about 9 seconds. New code additionally produces aggregate results as follows, that are quite useful: 2014-06-25 13:11:31 -0700 Puppet (debug): AGGREGATE PROFILING RESULTS: 2014-06-25 13:11:31 -0700 Puppet (debug): ---------------------------- 2014-06-25 13:11:31 -0700 Puppet (debug): compiler: 0.6718700000000001 ms (11 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> compile: 0.359372 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> compile -> production: 0.359372 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> compile -> production -> vagrant-2008r2.localdomain: 0.359372 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_main: 0.296874 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> create_settings_scope: 0.015624 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_node_classes: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_definitions: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> iterate_on_generators: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_ast_node: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_generators: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> finish_catalog: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> set_node_params: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> init_server_facts: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector -> filter: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector -> filter -> catalog: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector -> filter -> catalog -> vagrant-2008r2.localdomain: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): ---------------------------- Unfortunately it doesn't include all the information captured earlier in the log (time to apply the catalog for instance), which it probably should for the sake of completeness given a user might look to this as a concise summary of all the previous log profile output (and might be confused by missing steps in the summary). Here is the complete log for the simple test I ran: 2014-06-25 13:11:22 -0700 Puppet (debug): Runtime environment: puppet_version=3.6.2, ruby_version=1.9.3, run_mode=user, default_encoding=Windows-1252 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 1 Setup server facts for compiling: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.1 Compile: Set node parameters: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.2 Compile: Created settings scope: took 0.0156 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): Failed to load library 'shadow' for feature 'libshadow' 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.3 Compile: Evaluated main: took 0.2969 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.4 Compile: Evaluated AST node: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.5 Compile: Evaluated node classes: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.6.1.1 Evaluated definitions: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.6.1 Iterated (1) on generators: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.6 Compile: Evaluated generators: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2.7 Compile: Finished catalog: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 2 Compiled catalog for vagrant-2008r2.localdomain in environment production: took 0.3594 seconds 2014-06-25 13:11:26 -0700 Puppet (notice): Compiled catalog for vagrant-2008r2.localdomain in environment production in 0.36 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): PROFILE [apply] 3 Filtered result for catalog vagrant-2008r2.localdomain: took 0.0000 seconds 2014-06-25 13:11:26 -0700 Puppet (debug): Puppet::Type::User::ProviderDirectoryservice: file /usr/bin/uuidgen does not exist 2014-06-25 13:11:26 -0700 Puppet (debug): Puppet::Type::User::ProviderUseradd: file useradd does not exist 2014-06-25 13:11:26 -0700 Puppet (debug): Failed to load library 'ldap' for feature 'ldap' 2014-06-25 13:11:26 -0700 Puppet (debug): Puppet::Type::User::ProviderLdap: feature ldap is missing 2014-06-25 13:11:26 -0700 Puppet (debug): Puppet::Type::User::ProviderPw: file pw does not exist 2014-06-25 13:11:26 -0700 Puppet (debug): Puppet::Type::User::ProviderUser_role_add: file useradd does not exist 2014-06-25 13:11:26 -0700 /User[dave] (debug): Provider windows_adsi does not support features libuser; not managing attribute forcelocal 2014-06-25 13:11:26 -0700 Puppet (debug): Creating default schedules 2014-06-25 13:11:26 -0700 Puppet (debug): Failed to load library 'selinux' for feature 'selinux' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'confdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'vardir': 'File[C:/ProgramData/PuppetLabs/puppet/var]{:path=>"C:/ProgramData/PuppetLabs/puppet/var", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'logdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/log]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/log", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'statedir': 'File[C:/ProgramData/PuppetLabs/puppet/var/state]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state", :mode=>"1755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'rundir': 'File[C:/ProgramData/PuppetLabs/puppet/var/run]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/run", :mode=>"755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'libdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/lib]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/lib", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'certdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs", :mode=>"755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'ssldir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl", :mode=>"771", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'publickeydir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys", :mode=>"755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'requestdir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests", :mode=>"755", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'privatekeydir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'privatedir': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'hostprivkey': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/vagrant-2008r2.localdomain.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/vagrant-2008r2.localdomain.pem", :mode=>"640", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'hostpubkey': 'File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/vagrant-2008r2.localdomain.pem]{:path=>"C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/vagrant-2008r2.localdomain.pem", :mode=>"644", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'statefile': 'File[C:/ProgramData/PuppetLabs/puppet/var/state/state.yaml]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state/state.yaml", :mode=>"660", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'clientyamldir': 'File[C:/ProgramData/PuppetLabs/puppet/var/client_yaml]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/client_yaml", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'client_datadir': 'File[C:/ProgramData/PuppetLabs/puppet/var/client_data]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/client_data", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'clientbucketdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/clientbucket]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/clientbucket", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'lastrunfile': 'File[C:/ProgramData/PuppetLabs/puppet/var/state/last_run_summary.yaml]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state/last_run_summary.yaml", :mode=>"644", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'lastrunreport': 'File[C:/ProgramData/PuppetLabs/puppet/var/state/last_run_report.yaml]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state/last_run_report.yaml", :mode=>"640", :ensure=>:file, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'graphdir': 'File[C:/ProgramData/PuppetLabs/puppet/var/state/graphs]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/state/graphs", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Using settings: adding file resource 'pluginfactdest': 'File[C:/ProgramData/PuppetLabs/puppet/var/facts.d]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/facts.d", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:26 -0700 Puppet (debug): Puppet::Type::File::ProviderPosix: feature posix is missing 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/log] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/state] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/run] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/lib] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certs] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/certificate_requests] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys/vagrant-2008r2.localdomain.pem] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/private_keys] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys/vagrant-2008r2.localdomain.pem] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/etc/ssl/public_keys] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/state/state.yaml] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var/state] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/client_yaml] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/client_data] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/clientbucket] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/state/last_run_summary.yaml] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var/state] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/state/last_run_report.yaml] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var/state] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/state/graphs] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var/state] 2014-06-25 13:11:27 -0700 /File[C:/ProgramData/PuppetLabs/puppet/var/facts.d] (debug): Autorequiring File[C:/ProgramData/PuppetLabs/puppet/var] 2014-06-25 13:11:27 -0700 Puppet (debug): Finishing transaction 38617452 2014-06-25 13:11:30 -0700 Puppet (debug): Loaded state in 0.02 seconds 2014-06-25 13:11:30 -0700 Puppet (debug): Loaded state in 0.00 seconds 2014-06-25 13:11:30 -0700 Puppet (info): Applying configuration version '1403727086' 2014-06-25 13:11:31 -0700 Puppet (debug): Finishing transaction 33521736 2014-06-25 13:11:31 -0700 Puppet (debug): Storing state 2014-06-25 13:11:31 -0700 Puppet (debug): Stored state in 0.00 seconds 2014-06-25 13:11:31 -0700 Puppet (notice): Finished catalog run in 0.66 seconds 2014-06-25 13:11:31 -0700 Puppet (debug): Using settings: adding file resource 'rrddir': 'File[C:/ProgramData/PuppetLabs/puppet/var/rrd]{:path=>"C:/ProgramData/PuppetLabs/puppet/var/rrd", :mode=>"750", :ensure=>:directory, :loglevel=>:debug, :links=>:follow, :backup=>false}' 2014-06-25 13:11:31 -0700 Puppet (debug): Finishing transaction 35568864 2014-06-25 13:11:31 -0700 Puppet (debug): Received report to process from vagrant-2008r2.localdomain 2014-06-25 13:11:31 -0700 Puppet (debug): Processing report from vagrant-2008r2.localdomain with processor Puppet::Reports::Store 2014-06-25 13:11:31 -0700 Puppet (debug): AGGREGATE PROFILING RESULTS: 2014-06-25 13:11:31 -0700 Puppet (debug): ---------------------------- 2014-06-25 13:11:31 -0700 Puppet (debug): compiler: 0.6718700000000001 ms (11 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> compile: 0.359372 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> compile -> production: 0.359372 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> compile -> production -> vagrant-2008r2.localdomain: 0.359372 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_main: 0.296874 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> create_settings_scope: 0.015624 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_node_classes: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_definitions: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> iterate_on_generators: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_ast_node: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> evaluate_generators: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> finish_catalog: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> set_node_params: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): compiler -> init_server_facts: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector -> filter: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector -> filter -> catalog: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): indirector -> filter -> catalog -> vagrant-2008r2.localdomain: 0.0 ms (1 calls) 2014-06-25 13:11:31 -0700 Puppet (debug): ---------------------------- Add Comment   Puppet / PUP-2750 expand profiler signature to support hierarchical profiling data The current profiling system only accepts a String as the argument to the call to `profile`. This is useful, but limits the amount of interesting aggregation that a specific profiler implementation can achieve. If we were to expand the signature of the `profile` method to accept a "metric id", composed of basically a list of nested keys, then profiler... This message was sent by Atlassian JIRA (v6.1.4#6159-sha1:44eaede) -- 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.