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

Add catalog apply time to Puppet::Util::Metric "time" category

    Details

    • Type: Improvement
    • Status: Closed
    • Priority: Normal
    • Resolution: Fixed
    • Affects Version/s: None
    • Fix Version/s: PUP 5.5.0
    • Component/s: None
    • Labels:
      None
    • CS Priority:
      Reviewed
    • Release Notes:
      New Feature
    • Release Notes Summary:
      Time metrics recorded in the run report now include the time it takes to apply the catalog.
    • QA Risk Assessment:
      No Action

      Description

      When running `puppet agent -t`, the output displays the catalog apply time, but this value is not represented in the Puppet::Util::Metric "time" array. If a user wants to track this value in a custom report, they are forced to extract it from Puppet::Transaction::Report logs array. Since it is a time metric, and is in fact the only one displayed at run-time, it seems as though it should be part of the time metric array.

      Re-create steps:

      # 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
      

      The 9.18 seconds reported as the time to apply the catalog is not represented in the self.metrics['time'] array. It does not appear to be a function of any values reported either.

        Attachments

          Activity

            jsd-sla-details-panel

              People

              • Assignee:
                melissa Melissa Stone
                Reporter:
                adam.bottchen Adam Bottchen
              • Votes:
                0 Vote for this issue
                Watchers:
                4 Start watching this issue

                Dates

                • Created:
                  Updated:
                  Resolved:

                  Zendesk Support