Jira (PUP-6344) metrics.time.total does not correlate to time reported in log

[Adam Bottchen (JIRA)]

Title: Message Title

Adam Bottchen created an issue   Puppet / PUP-6344 metrics.time.total does not correlate to time reported in log Issue Type: Bug Assignee: Unassigned Created: 2016/05/23 4:16 PM Priority: Normal Reporter: Adam Bottchen The time reported by a `puppet agent -t` run for "Applied catalog in" does not appear to correlate to the times reported in the Puppet::Util::Metric "time" array. The applied catalog time should be the time used to apply the resources in the catalog, and the times returned to the report processor in the Puppet::Util::Metric "time" array should be the amount of time spent applying each resource, yet the two do not add up. Sometimes the applied catalog line is larger and sometimes the total time is larger. # cat lib/puppet/reports/myreport.rb require 'puppet' Puppet::Reports.register_report(:myreport) do desc "Testing"   def process Puppet.notice "METRICS: Process Puppet Report" Puppet.notice "METRICS: self.logs.last.message: #{self.logs.last.message}" self.metrics['time'].values.each { |val| Puppet.notice "METRICS: #{val[1]} : #{val[2]}" } end # puppet agent -t Info: Using configured environment 'production' Info: Retrieving pluginfacts Info: Retrieving plugin Info: Loading facts Info: Caching catalog for pe-201612-master.puppetdebug.vlan Info: Applying configuration version '1464042693' Notice: Applied catalog in 9.18 seconds # tail -n 21 /var/log/puppetlabs/puppetserver/puppetserver.log 2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Process Puppet Report 2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: self.logs.last.message: Applied catalog in 9.18 seconds 2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Augeas : 1.017779943 2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Config retrieval : 10.645895659 2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Cron : 0.001115222 2016-05-23 22:31:53,920 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Exec : 0.169413854 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: File : 0.45819617799999984 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Filebucket : 0.000103239 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Group : 0.000411452 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Package : 0.7939065209999999 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe anchor : 7.1151e-05 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe file line : 0.0023166209999999996 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe hocon setting : 1.4407772629999998 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe ini setting : 0.020410037 2016-05-23 22:31:53,921 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe ini subsetting : 0.0049442060000000005 2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe java ks : 1.454764838 2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Pe puppet authorization hocon rule : 1.8567533360000004 2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Schedule : 0.00041616200000000003 2016-05-23 22:31:53,922 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Service : 0.35225476499999997 2016-05-23 22:31:53,923 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: Total : 18.221604979000002 2016-05-23 22:31:53,923 INFO [qtp1308528397-63] [puppet-server] Puppet METRICS: User : 0.002074532 In this case, the catalog applied in 9.18 seconds, but the (Total) - (Config retrieval) is 7.57 even though the documentation would seem to indicate they are measuring the same thing. Add Comment   This message was sent by Atlassian JIRA (v6.4.13#64028-sha1:b7939e9) -- 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 https://groups.google.com/group/puppet-bugs. For more options, visit https://groups.google.com/d/optout.